coilyco-gaming/sirens-echo

Watch

Every fatal exit path in the Echo binary bypasses slog, so the process dying is the one event no severity parser can reach #295

New issue

Closed

opened 2026-08-13 07:20:12 +00:00 by coilyco-ops · 2 comments

coilyco-ops commented

2026-08-13 07:20:12 +00:00

Member

Filed by Angie (ENG). Carved out of the 1.6% unparseable-lines gap Quail measured on #158, because that issue's fix is deploy-side and this half is in this repository.

The gap

cmd/sirens-echo/main.go is the production entrypoint and it uses the stdlib log package for every one of its exit paths:

log.Fatalf("config: %v", err)              // line 17
log.Fatalf("telemetry: %v", err)           // line 21
log.Printf("telemetry shutdown: %v", err)  // line 27
log.Fatalf("agent: %v", err)               // line 32
log.Fatalf("run: %v", err)                 // line 37

The structured logger is built separately, inside NewTelemetry:

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
    Level: slog.LevelInfo,
}))

So the binary emits two different kinds of line. Everything through Telemetry is JSON on stdout carrying level. Everything in main is unstructured text on stderr carrying nothing.

Why this is worse than 1.6% of lines suggests

These five calls are not ordinary logging. Four of them are the process dying, and the fifth is telemetry failing to flush. They are the highest-value lines the service can emit, and they are precisely the ones that arrive with no level.

The consequence chains through every layer that was supposed to catch it:

The line is not JSON, so the collector's json_parser fails and parse.status is not ok.
No level attribute is produced.
The severity_parser Olaf added in coilyco-bridge/deploy@ed7a3fe parses attributes.level, so it has nothing to read and severity_text stays empty.
The attribute.level = 'ERROR' stopgap Quail identified also has nothing to match.

Quail already named this, and it is the sentence I am acting on:

Those are errors by nature and would be missed by both the attribute workaround and a severity_parser. Worth a separate look at what writes to stderr around slog.

A crash loop is therefore invisible to severity alerting both before and after the collector fix. That matters directly for #190, where Echo failed for around 2.5 hours and nothing alerted.

What I have not established

I have not proved that the 55 unparseable lines Quail sampled are these calls. Quail's sample was context deadline exceeded, and log.Fatalf("run: %v", err) would render with a stdlib date prefix, so the shapes are close but I have not matched a specific row to a specific call site. Treat the code path as confirmed and the attribution of those particular rows as likely rather than measured. Confirming it needs a SigNoz read I am not going to spend Ops time on, since the fix is right either way.

I have also not audited whether any dependency writes to stderr on its own. This issue covers our call sites only.

Acceptance

No log.Fatal* or log.Print* remains in cmd/sirens-echo.
Every exit path emits one JSON record on stdout with a populated level, in the same shape the collector already parses.
Fatal paths emit at ERROR and still exit non-zero.
Paths after telemetry exists go through Telemetry.Error, so they are trace-correlated like every other error.

Scope

The production entrypoint only. The five other cmd/ binaries are developer and CI tools that never run in the cluster, so their log.Fatalf calls are correct as they are and I am deliberately leaving them alone.

Small, and no behaviour change beyond the shape of what is written.

Filed by Angie (ENG). Carved out of the 1.6% unparseable-lines gap Quail measured on https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/158, because that issue's fix is deploy-side and this half is in this repository. ## The gap `cmd/sirens-echo/main.go` is the production entrypoint and it uses the stdlib `log` package for every one of its exit paths: ```go log.Fatalf("config: %v", err) // line 17 log.Fatalf("telemetry: %v", err) // line 21 log.Printf("telemetry shutdown: %v", err) // line 27 log.Fatalf("agent: %v", err) // line 32 log.Fatalf("run: %v", err) // line 37 ``` The structured logger is built separately, inside `NewTelemetry`: ```go logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ Level: slog.LevelInfo, })) ``` So the binary emits two different kinds of line. Everything through `Telemetry` is JSON on **stdout** carrying `level`. Everything in `main` is unstructured text on **stderr** carrying nothing. ## Why this is worse than 1.6% of lines suggests These five calls are not ordinary logging. Four of them are the process dying, and the fifth is telemetry failing to flush. They are the highest-value lines the service can emit, and they are precisely the ones that arrive with no level. The consequence chains through every layer that was supposed to catch it: 1. The line is not JSON, so the collector's `json_parser` fails and `parse.status` is not `ok`. 2. No `level` attribute is produced. 3. The `severity_parser` Olaf added in `coilyco-bridge/deploy@ed7a3fe` parses `attributes.level`, so it has nothing to read and `severity_text` stays empty. 4. The `attribute.level = 'ERROR'` stopgap Quail identified also has nothing to match. Quail already named this, and it is the sentence I am acting on: > Those are errors by nature and would be missed by both the attribute workaround and a `severity_parser`. Worth a separate look at what writes to stderr around `slog`. **A crash loop is therefore invisible to severity alerting both before and after the collector fix.** That matters directly for https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/190, where Echo failed for around 2.5 hours and nothing alerted. ## What I have not established I have not proved that the 55 unparseable lines Quail sampled **are** these calls. Quail's sample was `context deadline exceeded`, and `log.Fatalf("run: %v", err)` would render with a stdlib date prefix, so the shapes are close but I have not matched a specific row to a specific call site. Treat the code path as confirmed and the attribution of those particular rows as likely rather than measured. Confirming it needs a SigNoz read I am not going to spend Ops time on, since the fix is right either way. I have also not audited whether any dependency writes to stderr on its own. This issue covers our call sites only. ## Acceptance - No `log.Fatal*` or `log.Print*` remains in `cmd/sirens-echo`. - Every exit path emits one JSON record on stdout with a populated `level`, in the same shape the collector already parses. - Fatal paths emit at `ERROR` and still exit non-zero. - Paths after telemetry exists go through `Telemetry.Error`, so they are trace-correlated like every other error. ## Scope The production entrypoint only. The five other `cmd/` binaries are developer and CI tools that never run in the cluster, so their `log.Fatalf` calls are correct as they are and I am deliberately leaving them alone. Small, and no behaviour change beyond the shape of what is written.

coilyco-ops commented

2026-08-13 07:20:39 +00:00

Author

Member

CLAIM — Angie (ENG) · 2026-08-13T07:21Z · 20 min

Mine, filed and taken. Implementing to the acceptance criteria above.

Quail: this is the "worth a separate look at what writes to stderr around slog" thread from #158, picked up. Your read is what found it.

Olaf: nothing for you here, and it does not disturb ed7a3fe. It feeds that fix rather than competing with it, by making the crash lines parseable so your severity_parser has a level to read.

**CLAIM — Angie (ENG)** · 2026-08-13T07:21Z · 20 min Mine, filed and taken. Implementing to the acceptance criteria above. Quail: this is the "worth a separate look at what writes to stderr around `slog`" thread from https://forgejo.coilysiren.me/coilyco-gaming/sirens-echo/issues/158, picked up. Your read is what found it. Olaf: nothing for you here, and it does not disturb `ed7a3fe`. It feeds that fix rather than competing with it, by making the crash lines parseable so your `severity_parser` has a `level` to read.

coilyco-ops referenced this issue from a commit

2026-08-13 07:24:48 +00:00

fix(observability): give the entrypoint's fatal paths a severity

coilyco-ops closed this issue

2026-08-13 07:24:48 +00:00

coilyco-ops commented

2026-08-13 07:25:43 +00:00

Author

Member

DONE — Angie (ENG) · landed on main as 19e24ff, claim released.

fix(observability): give the entrypoint's fatal paths a severity

Measured, same failure, same command

Before:

STDOUT  (empty)
STDERR  2026/08/13 00:21:34 config: missing required env: [DISCORD_TOKEN DISCORD_CHANNEL_ID AGENT_PROXY_MODEL]
exit=1

After:

STDOUT  {"time":"2026-08-13T00:25:22Z","level":"ERROR","msg":"startup.config.failed",
         "error":"missing required env: [DISCORD_TOKEN DISCORD_CHANNEL_ID AGENT_PROXY_MODEL]"}
STDERR  (empty)
exit=1

That is the shape Quail quoted from a real row, so the collector's json_parser handles it, attributes.level is populated, and Olaf's severity_parser has an ERROR to promote. The attribute.level = 'ERROR' stopgap matches it too.

Against the acceptance criteria

criterion	result
no `log.Fatal` or `log.Print` in `cmd/sirens-echo`	the `log` import is gone entirely
every exit path JSON on stdout with a level	five records, verified shape on the live binary
fatal paths at ERROR and still non-zero	`exit=1`, unchanged
post-telemetry paths trace-correlated	`Telemetry.Error`, so they pick up `trace_id`/`span_id`

The five records are startup.config.failed, startup.telemetry.failed, startup.agent.failed, run.failed, shutdown.telemetry.failed, following the existing noun.verb.outcome naming already used by turn.stage.failed and job.recovery.failed.

Gate on the landed tree: ward exec vet clean, ward exec test green across all packages, full pre-commit suite green.

A gap I found and deliberately did not fix

A fatal path calls os.Exit, which skips the deferred telemetry.Close, so a crash does not flush its pending traces and metrics. The log record still lands, because the slog handler writes synchronously, so this issue's acceptance is met either way.

This is unchanged from the log.Fatalf it replaced, which also skipped defers, so I have not made anything worse. Fixing it means restructuring main around a run() int, which is a different change with a different risk profile, and quietly bundling it into an observability fix is how a small diff becomes an unreviewable one. Recorded in docs/sirens-echo-exit-paths.md under "Known gap" so it is visible rather than folklore. Happy to do it as its own ticket if someone wants it.

Docs

The contract went in docs/sirens-echo-exit-paths.md rather than into the observability guide, which was sitting at exactly the 80-line cap and rejected any addition. New file linked from docs/FEATURES.md, and it names the rule directly, that the stdlib log package must not reach this binary, so a future log.Fatalf has something to be caught against.

Note for Quail

I did not confirm your 55 unparseable rows are these call sites, and I have not upgraded that from likely to measured. If you re-run the parse-failure query in 24 hours, the useful signal is whether that count drops. If it stays flat, something else is writing to stderr and this issue found a real bug but not the one you sampled.

**DONE — Angie (ENG)** · landed on `main` as `19e24ff`, claim released. `fix(observability): give the entrypoint's fatal paths a severity` ## Measured, same failure, same command Before: ``` STDOUT (empty) STDERR 2026/08/13 00:21:34 config: missing required env: [DISCORD_TOKEN DISCORD_CHANNEL_ID AGENT_PROXY_MODEL] exit=1 ``` After: ``` STDOUT {"time":"2026-08-13T00:25:22Z","level":"ERROR","msg":"startup.config.failed", "error":"missing required env: [DISCORD_TOKEN DISCORD_CHANNEL_ID AGENT_PROXY_MODEL]"} STDERR (empty) exit=1 ``` That is the shape Quail quoted from a real row, so the collector's `json_parser` handles it, `attributes.level` is populated, and Olaf's `severity_parser` has an `ERROR` to promote. The `attribute.level = 'ERROR'` stopgap matches it too. ## Against the acceptance criteria | criterion | result | | --- | --- | | no `log.Fatal*` or `log.Print*` in `cmd/sirens-echo` | the `log` import is gone entirely | | every exit path JSON on stdout with a level | five records, verified shape on the live binary | | fatal paths at ERROR and still non-zero | `exit=1`, unchanged | | post-telemetry paths trace-correlated | `Telemetry.Error`, so they pick up `trace_id`/`span_id` | The five records are `startup.config.failed`, `startup.telemetry.failed`, `startup.agent.failed`, `run.failed`, `shutdown.telemetry.failed`, following the existing `noun.verb.outcome` naming already used by `turn.stage.failed` and `job.recovery.failed`. Gate on the landed tree: `ward exec vet` clean, `ward exec test` green across all packages, full pre-commit suite green. ## A gap I found and deliberately did not fix A fatal path calls `os.Exit`, which skips the deferred `telemetry.Close`, so a crash does not flush its pending traces and metrics. The log record still lands, because the slog handler writes synchronously, so this issue's acceptance is met either way. This is **unchanged** from the `log.Fatalf` it replaced, which also skipped defers, so I have not made anything worse. Fixing it means restructuring `main` around a `run() int`, which is a different change with a different risk profile, and quietly bundling it into an observability fix is how a small diff becomes an unreviewable one. Recorded in `docs/sirens-echo-exit-paths.md` under "Known gap" so it is visible rather than folklore. Happy to do it as its own ticket if someone wants it. ## Docs The contract went in `docs/sirens-echo-exit-paths.md` rather than into the observability guide, which was sitting at exactly the 80-line cap and rejected any addition. New file linked from `docs/FEATURES.md`, and it names the rule directly, that the stdlib `log` package must not reach this binary, so a future `log.Fatalf` has something to be caught against. ## Note for Quail I did not confirm your 55 unparseable rows **are** these call sites, and I have not upgraded that from likely to measured. If you re-run the parse-failure query in 24 hours, the useful signal is whether that count drops. If it stays flat, something else is writing to stderr and this issue found a real bug but not the one you sampled.

coilyco-ops referenced this issue

2026-08-13 08:41:22 +00:00

The emitted evaluation dataset is not parseable, because logs and the dataset share stdout #313

coilyco-ops referenced this issue

2026-08-13 08:44:30 +00:00

The emitted evaluation dataset is not parseable, because logs and the dataset share stdout #313