celilo/gascity

Fork 0

The daily digest's Agent Health reports "1 drain, no orphaned pool releases" for a window that contained 11 drains, 7 of them orphaned — supervisor.log drain lines carry no timestamp, so they cannot be windowed #33

New issue

Open

opened 2026-09-22 04:42:16 +00:00 by forgejo-admin · 1 comment

forgejo-admin commented

2026-09-22 04:42:16 +00:00

Owner

The 2026-09-21 digest (gs-wisp-5xwj6, delivered 2026-09-22 04:40Z) says:

Agent Health

Supervisor log over the window: 1 drain, no fresh-mode cycles, no
pool trigger worktree evidence invalid, no orphaned pool releases.

celilo pool steady; refinery scaled to 1 at window close.

Measured against ~/.gc/supervisor.log for the same window (00:00Z 2026-09-21 → 00:00Z 2026-09-22, i.e. local 2026-09-20 17:00 → 2026-09-21 17:00, log stamps are local):

drains inside the digest window: 11
   furiosa    orphaned           6
   furiosa    no-wake-reason     3
   nux        no-wake-reason     1
   nux        orphaned           1

So 7 orphaned drains, against a reported zero, and 11 total against a reported 1.

This matters more than an off-by-N. Agent Health is the daily signal a human reads to learn the pool is unhealthy, and this is the exact window in which the celilo pool was in a spawn/drain loop that cost a mayor session most of an evening (furiosa was drained ~19 times consecutively with zero work completed, recorded in gs-wisp-zl4wm and its corrections). The digest reported that evening as healthy.

Root cause: the lines it must count are untimestamped

Most supervisor lines carry a 2026/09/21 20:01:34 prefix. The lifecycle lines do not. Real excerpt:

poolDesired: gastown.mayor = 1
2026/09/21 20:01:34 beads cache: reconciled rig=gs beads=76 adds=3 updates=1 removes=4 took=38ms cadence=default
2026/09/21 20:01:34 api: GET /v0/city/gc-scratch/beads 200 4.537ms [memory] req_id=ab41875e01ee4361
Draining session 'celilo--gastown__rictus': orphaned
2026/09/21 20:01:36 api: GET /api/city/gc-scratch/runs/summary 200 1.13627s [memory] req_id=fa2040ac703689a4

Draining session ..., poolDesired: ... and scaleCheck: ... are all bare. A drain can only be dated from the nearest preceding timestamped line. Any windowing that filters drain lines by a date on the line itself matches nothing, and any count that does not window at all answers about the whole file — which holds 138 drains going back to rigs that were removed on 2026-08-30.

Neither failure mode announces itself: both produce a small, well-formed, confident number.

Two things to fix, and the first is the cheap one

Timestamp the lifecycle lines at the source. Draining session, poolDesired and scaleCheck should carry the same 2026/09/21 20:01:34 prefix every other line has. This makes every downstream consumer — the digest, flow-stall-check, any mayor's watcher — able to ask a windowed question at all. Today none of them can.
Until then, the digest must date a drain from the nearest preceding timestamped line, and say so. Working measurement:

import re, datetime, os
ts = re.compile(r'^(\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}) ')
last = None
with open(os.path.expanduser('~/.gc/supervisor.log'), 'rb') as f:
    for raw in f:
        line = raw.decode('utf-8', 'replace')
        m = ts.match(line)
        if m:
            last = datetime.datetime.strptime(m.group(1), '%Y/%m/%d %H:%M:%S')
            continue
        if 'Draining session' in line and last and lo <= last < hi:
            ...  # count it, keyed by session name and reason

Two neighbouring traps worth recording while someone is in here

Count the specific string, per session. "Draining session 'celilo--gastown__<name>': orphaned". A counter that matches bare orphaned across all sessions cried wolf three times for one mayor on 2026-09-21; twice the truth was better than the alarm and once it was worse.
rg vs the NUL byte. CLAUDE.md warns that plain rg stops at the first NUL in this file (currently byte 8650003, line 125258 of 588739) and so answers only about old lines. Measured here on 2026-09-22, plain rg -c and rg -ac both returned 138 for Draining session, so this particular file/version is not truncating today. -a remains the safe habit, but the NUL is not the cause of this issue — the missing timestamps are.

Filed with no bead, per the city rule that a defect in gc or the pinned pack gets an issue and not a bead: no polecat in this city can change the supervisor binary or the pinned pack, so a bead would strand while reading as tracked.

Measured 2026-09-22 04:45Z by gastown.mayor.

The 2026-09-21 digest (`gs-wisp-5xwj6`, delivered 2026-09-22 04:40Z) says: > ## Agent Health > - Supervisor log over the window: 1 drain, no fresh-mode cycles, no > `pool trigger worktree evidence invalid`, no orphaned pool releases. > - celilo pool steady; refinery scaled to 1 at window close. Measured against `~/.gc/supervisor.log` for the same window (00:00Z 2026-09-21 → 00:00Z 2026-09-22, i.e. local 2026-09-20 17:00 → 2026-09-21 17:00, log stamps are local): ``` drains inside the digest window: 11 furiosa orphaned 6 furiosa no-wake-reason 3 nux no-wake-reason 1 nux orphaned 1 ``` So **7 orphaned drains**, against a reported zero, and 11 total against a reported 1. This matters more than an off-by-N. Agent Health is the daily signal a human reads to learn the pool is unhealthy, and this is the exact window in which the celilo pool was in a spawn/drain loop that cost a mayor session most of an evening (furiosa was drained ~19 times consecutively with zero work completed, recorded in `gs-wisp-zl4wm` and its corrections). The digest reported that evening as healthy. ## Root cause: the lines it must count are untimestamped Most supervisor lines carry a `2026/09/21 20:01:34 ` prefix. The lifecycle lines do **not**. Real excerpt: ``` poolDesired: gastown.mayor = 1 2026/09/21 20:01:34 beads cache: reconciled rig=gs beads=76 adds=3 updates=1 removes=4 took=38ms cadence=default 2026/09/21 20:01:34 api: GET /v0/city/gc-scratch/beads 200 4.537ms [memory] req_id=ab41875e01ee4361 Draining session 'celilo--gastown__rictus': orphaned 2026/09/21 20:01:36 api: GET /api/city/gc-scratch/runs/summary 200 1.13627s [memory] req_id=fa2040ac703689a4 ``` `Draining session ...`, `poolDesired: ...` and `scaleCheck: ...` are all bare. A drain can only be dated from the nearest preceding timestamped line. Any windowing that filters drain lines by a date on the line itself matches nothing, and any count that does not window at all answers about the whole file — which holds 138 drains going back to rigs that were removed on 2026-08-30. Neither failure mode announces itself: both produce a small, well-formed, confident number. ## Two things to fix, and the first is the cheap one 1. **Timestamp the lifecycle lines at the source.** `Draining session`, `poolDesired` and `scaleCheck` should carry the same `2026/09/21 20:01:34 ` prefix every other line has. This makes every downstream consumer — the digest, `flow-stall-check`, any mayor's watcher — able to ask a windowed question at all. Today none of them can. 2. **Until then, the digest must date a drain from the nearest preceding timestamped line**, and say so. Working measurement: ```python import re, datetime, os ts = re.compile(r'^(\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}) ') last = None with open(os.path.expanduser('~/.gc/supervisor.log'), 'rb') as f: for raw in f: line = raw.decode('utf-8', 'replace') m = ts.match(line) if m: last = datetime.datetime.strptime(m.group(1), '%Y/%m/%d %H:%M:%S') continue if 'Draining session' in line and last and lo <= last < hi: ... # count it, keyed by session name and reason ``` ## Two neighbouring traps worth recording while someone is in here - **Count the specific string, per session.** `"Draining session 'celilo--gastown__<name>': orphaned"`. A counter that matches bare `orphaned` across all sessions cried wolf three times for one mayor on 2026-09-21; twice the truth was better than the alarm and once it was worse. - **`rg` vs the NUL byte.** CLAUDE.md warns that plain `rg` stops at the first NUL in this file (currently byte 8650003, line 125258 of 588739) and so answers only about old lines. Measured here on 2026-09-22, plain `rg -c` and `rg -ac` both returned 138 for `Draining session`, so this particular file/version is not truncating today. `-a` remains the safe habit, but the NUL is **not** the cause of this issue — the missing timestamps are. Filed with no bead, per the city rule that a defect in `gc` or the pinned pack gets an issue and not a bead: no polecat in this city can change the supervisor binary or the pinned pack, so a bead would strand while reading as tracked. Measured 2026-09-22 04:45Z by gastown.mayor.

forgejo-admin commented

2026-09-23 04:47:40 +00:00

Author

Owner

The digest now emits a false ALL-CLEAR, not just an undercount — and it names the hazard while doing it

Measured 2026-09-22 9:45 PM PDT by gastown.mayor, on the digest for window 2026-09-22T00:00:00Z → 2026-09-23T00:00:00Z.

The digest's Agent Health section says:

No Draining session or Cycled fresh-mode lines in ~/.gc/supervisor.log for 2026-09-22. The self-draining-batch hazard did not fire today.

There are 24 Draining session lines inside that window, 12 of them orphaned. Dated the only way these lines can be dated — by the nearest preceding timestamped line — and noting that supervisor.log timestamps are LOCAL, so the UTC window maps to local 2026/09/21 17:00 → 2026/09/22 17:00:

in window: 24   orphaned: 12   no-wake-reason: 12
first:  2026/09/21 17:02:34  no-wake-reason
last:   2026/09/22 00:17:38  orphaned
(148 Draining lines in the file overall)

This is worse than the original report in two ways.

It escalated from undercounting to a negative claim. The first observation here was 11 drains reported as 1. This digest reports zero and then asserts that a named hazard "did not fire". A reader who trusts it concludes the batch-drain problem is dormant on a day it fired a dozen orphaned drains.
A no-wake-reason drain of an idle polecat is normal, so the raw count alone would overstate the fault. The actionable number is the orphaned half — 12 — because those are the ones that release a live claim. A fixed digest should report the two separately rather than either a single total or nothing.

Two digests for the same window disagree

Two digests arrived from gastown__dog-1-pool four minutes apart (9:41 PM and 9:45 PM PDT) for the same 2026-09-22 window, with different numbers:

field	9:41 PM digest	9:45 PM digest
celilo filed	22	24
celilo closed	55	55
celilo open backlog	66	69
drain accounting	section absent	"no Draining lines … hazard did not fire"

Same window, same generator, two answers. Only the second makes the drain claim, so whether a reader gets a false all-clear depends on which copy they open. Worth deciding whether a duplicate run should be suppressed, since a digest is the one artifact here that a person reads instead of measuring.

Suggested shape for the fix

Drain, poolDesired and scaleCheck lines cannot be windowed because they carry no timestamp of their own. Either stamp them at the source, or have the digest attribute each one to the nearest preceding timestamped line (as above) and split the count into orphaned versus no-wake-reason. Until one of those lands, the Agent Health section should say "not measurable" rather than zero: a blind instrument reporting an all-clear is worse than one reporting nothing, and this city has been bitten by exactly that shape more than once.

No bead filed, per the standing rule that a gc/supervisor defect no polecat here can fix gets an issue and no bead.

## The digest now emits a false ALL-CLEAR, not just an undercount — and it names the hazard while doing it Measured 2026-09-22 9:45 PM PDT by gastown.mayor, on the digest for window `2026-09-22T00:00:00Z → 2026-09-23T00:00:00Z`. The digest's Agent Health section says: > No `Draining session` or `Cycled fresh-mode` lines in `~/.gc/supervisor.log` for 2026-09-22. The self-draining-batch hazard did not fire today. **There are 24 `Draining session` lines inside that window, 12 of them `orphaned`.** Dated the only way these lines can be dated — by the nearest preceding timestamped line — and noting that `supervisor.log` timestamps are LOCAL, so the UTC window maps to local `2026/09/21 17:00` → `2026/09/22 17:00`: ``` in window: 24 orphaned: 12 no-wake-reason: 12 first: 2026/09/21 17:02:34 no-wake-reason last: 2026/09/22 00:17:38 orphaned (148 Draining lines in the file overall) ``` This is worse than the original report in two ways. 1. **It escalated from undercounting to a negative claim.** The first observation here was 11 drains reported as 1. This digest reports **zero** and then asserts that a named hazard "did not fire". A reader who trusts it concludes the batch-drain problem is dormant on a day it fired a dozen orphaned drains. 2. **A `no-wake-reason` drain of an idle polecat is normal**, so the raw count alone would overstate the fault. The actionable number is the `orphaned` half — 12 — because those are the ones that release a live claim. A fixed digest should report the two separately rather than either a single total or nothing. ### Two digests for the same window disagree Two digests arrived from `gastown__dog-1-pool` four minutes apart (9:41 PM and 9:45 PM PDT) for the same 2026-09-22 window, with different numbers: | field | 9:41 PM digest | 9:45 PM digest | |---|---|---| | celilo filed | 22 | 24 | | celilo closed | 55 | 55 | | celilo open backlog | 66 | 69 | | drain accounting | section absent | "no Draining lines … hazard did not fire" | Same window, same generator, two answers. Only the second makes the drain claim, so whether a reader gets a false all-clear depends on which copy they open. Worth deciding whether a duplicate run should be suppressed, since a digest is the one artifact here that a person reads instead of measuring. ### Suggested shape for the fix Drain, `poolDesired` and `scaleCheck` lines cannot be windowed because they carry no timestamp of their own. Either stamp them at the source, or have the digest attribute each one to the nearest preceding timestamped line (as above) and split the count into `orphaned` versus `no-wake-reason`. Until one of those lands, the Agent Health section should say **"not measurable"** rather than zero: a blind instrument reporting an all-clear is worse than one reporting nothing, and this city has been bitten by exactly that shape more than once. No bead filed, per the standing rule that a gc/supervisor defect no polecat here can fix gets an issue and no bead.

No labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

celilo/gascity#33

No description provided.

Rows
Columns