feat(observability): add structured http.* event family for inbound HTTP boundary (webhook entry, HMAC failure, scheduler endpoint)

[chrisleekr]

Finding

The HTTP boundary in src/app.ts:194-243 ships without a structured access log. Every inbound request — the GitHub webhook delivery itself, the /healthz / /readyz probes, the operator /api/scheduler/run endpoint, and the dev /api/test/webhook endpoint — flows through the http.createServer((req, res) => …) block, but only two paths emit a log line: /readyz at debug level when 503ing (src/app.ts:208) and the webhooks.onError callback when something inside @octokit/webhooks throws (src/app.ts:178-180). Neither carries an event: discriminator, so the failure modes that matter most to an on-call operator are unattributable.

The single biggest hole is HMAC-signature failure. createNodeMiddleware(app.webhooks, { path: "/api/github/webhooks" }) (src/app.ts:186-188) verifies the X-Hub-Signature-256 header per GitHub's webhook security docs; on mismatch @octokit/webhooks rejects with an error event that lands inside the existing app.webhooks.onError((error) => { logger.error({ err: error }, "Webhook processing error"); }) block at src/app.ts:178-180. That line has no event: field, no delivery_id, no event_name, no verification_failed flag. A deploy that ships a stale GITHUB_WEBHOOK_SECRET therefore drops 100% of deliveries while emitting plain-text "Webhook processing error" lines that look identical to a runtime handler exception — there is no greppable discriminator and no way for an alert to fire on "signature verification failing >N times per minute" vs "downstream handler threw."

The operator endpoint handleSchedulerRun (src/app.ts:530-612) has the same shape: of its six terminal outcomes (404 disabled, 401 bad token, 413 body cap, 400 bad JSON, 400 missing-field, 500 internal, 202 enqueued / 409 dedup), five emit nothing at all and the 500 path emits logger.error({ err }, "scheduler: manual run endpoint failed") (src/app.ts:607) without an event: field. The dev-only /api/test/webhook (src/app.ts:254-340) follows the same pattern: the [test-webhook] Dispatching info log at src/app.ts:324 and the [test-webhook] Failed to parse request error at src/app.ts:336 are both unstructured. The fix is to mirror the canonical pattern issue #166 (pipeline.stage), issue #207 (dispatcher.offer.*), and issue #225 (retry.*) established for this repo: a small dot-namespaced http.* event family covering the webhook entry, the verification-failure surface, the readiness probe 503, and the operator endpoint outcomes — same event: + delta_ms shape, no new infrastructure.

Diagram

flowchart TD
    GH[GitHub delivers webhook<br/>POST /api/github/webhooks] --> HTTP[http.createServer handler<br/>src/app.ts:194]
    HTTP --> Health{path}
    Health -- /healthz --> HZ[200 ok no log<br/>app.ts:197]:::silent
    Health -- /readyz --> RZ[200 or 503 debug only on 503<br/>app.ts:208]:::partial
    Health -- /api/github/webhooks --> Mid[webhookMiddleware<br/>app.ts:186 and 242]
    Health -- /api/scheduler/run --> SR[handleSchedulerRun<br/>app.ts:530]
    Mid --> Sig{HMAC signature ok}
    Sig -- yes --> Handler[event handler dispatch<br/>src/webhook/events/]
    Sig -- no --> OnErr[webhooks.onError<br/>app.ts:178-180]:::silent
    Handler --> HOK[handler logs include event and deliveryId<br/>per-handler entry log]:::structured
    SR --> SRCheck{outcome}
    SRCheck -- 404 disabled --> S404[404 no log<br/>app.ts:535]:::silent
    SRCheck -- 401 bad token --> S401[401 no log<br/>app.ts:539]:::silent
    SRCheck -- 413 body cap --> S413[413 no log<br/>app.ts:554]:::silent
    SRCheck -- 400 bad JSON --> S400[400 no log<br/>app.ts:574-595]:::silent
    SRCheck -- 500 internal --> S500[error log no event field<br/>app.ts:607]:::partial
    SRCheck -- 202 enqueued --> S202[202 no log<br/>app.ts:603-605]:::silent

    classDef silent fill:#922b21,color:#ffffff,stroke:#7b241c
    classDef partial fill:#b9770e,color:#ffffff,stroke:#9c640c
    classDef structured fill:#196f3d,color:#ffffff,stroke:#145a32

Loading

Rationale

Why HMAC failure is the highest-value detection gap. Per GitHub's webhook security guidance, the only operator-side signal that a webhook secret rotation went wrong is a stream of dropped deliveries. Today that stream is invisible at the HTTP boundary — the webhooks.onError line at src/app.ts:179 lacks the event: discriminator + kind field that would let an operator distinguish kind: "signature_mismatch" from kind: "handler_threw". The webhook handlers themselves already emit structured per-entity logs via createChildLogger({ deliveryId, owner, repo, entityNumber }) (e.g. src/webhook/events/issue-comment.ts:66,119,143), so the asymmetry is concrete: every dispatched delivery is greppable, every dropped delivery (the one operators care about during an incident) is not.

Why this is the lowest-cost observability win. The seam is one file (src/app.ts) and three handler functions (webhooks.onError, the http.createServer block, handleSchedulerRun). No new infrastructure, no new dependency, no schema migration. The existing pattern is already in this file at src/app.ts:454 (logger.info({ event: "ship.tickle.started" }, …)) and dozens of times across src/orchestrator/, so emitter parity is a matter of adding event: + a couple of fields per call site. The cost-to-coverage ratio is favourable: ~8 events cover the entire inbound HTTP surface (http.webhook.received + http.webhook.error + http.scheduler.run.{rejected_unauth,rejected_disabled,rejected_payload,enqueued,failed} + http.readyz.unready), each emitted at info or warn so the LOG_LEVEL=info baseline picks them up.

Why this complements existing observability instead of duplicating it. Issue #166 covers pipeline stage timing once a job is dispatched into runPipeline. Issue #207 covers the dispatcher inside the orchestrator, after the webhook handler has already received the event. Issue #170 (feat(observability): add duration_ms + github.api.slow to octokit hooks for per-request GitHub latency visibility) covers Octokit's outbound request hooks — the dual problem of http.webhook.received here, which is the inbound surface no existing finding addresses. The child-logger field-name drift fix (closed) made handler-side logs uniform once dispatch reached them; it did not touch the pre-dispatch HTTP layer.

References

Internal:

• src/app.ts:178-180 (app.webhooks.onError — only surfaces HMAC + handler errors, no event: field)
• src/app.ts:186-188 (createNodeMiddleware(app.webhooks, { path: "/api/github/webhooks" }) — webhook entry, no per-receipt log)
• src/app.ts:194-243 (http.createServer((req, res) => …) — HTTP router, only /readyz 503 logs at debug)
• src/app.ts:197 (/healthz 200 — silent)
• src/app.ts:208 (/readyz returning 503 debug log, no event:)
• src/app.ts:217-220 (!isReady 503 fallthrough — silent)
• src/app.ts:530-612 (handleSchedulerRun — 404/401/413/400/202 silent, 500 unstructured at src/app.ts:607)
• src/app.ts:324,336 ([test-webhook] info + error lines — no event: field)
• src/app.ts:454 (logger.info({ event: "ship.tickle.started" }, …) — existing canonical event shape to mirror)
• src/webhook/events/issue-comment.ts:66,119,143 (handler-side logs that do carry deliveryId via createChildLogger, by contrast)
• src/core/log-fields.ts:18-23 (CORE_PIPELINE_LOG_EVENTS — Zod-pinned event-shape pattern to mirror, issue feat(observability): structured pipeline.stage events with delta_ms for runPipeline #166)
• src/orchestrator/log-fields.ts:28 (DISPATCHER_LOG_EVENTS) referenced via src/orchestrator/job-dispatcher.ts:164,237,373,574 (issue feat(observability): add queue_wait_ms to dispatcher offer/no-daemon logs #207 — the dot-namespaced family pattern)
• Issue feat(observability): structured pipeline.stage events with delta_ms for runPipeline #166 (canonical event: + delta_ms timing pattern)
• Issue feat(observability): add queue_wait_ms to dispatcher offer/no-daemon logs #207 (dot-namespaced dispatcher.offer.* family)
• Issue feat(observability): add structured retry.* events #225 (dot-namespaced retry.* family)

External:

• GitHub Docs: Validating webhook deliveries (HMAC-SHA256 signature) — describes the X-Hub-Signature-256 failure surface this finding makes observable
• @octokit/webhooks README — Node middleware and onError — documents that onError is the single failure surface for verification + handler exceptions, motivating the per-error kind field
• Pino HTTP request logger (pino-http) — reference convention for structured per-request access logging in Node servers (we don't need pino-http itself, just its method/url/status/responseTime field shape)
• Pino logger tutorial: structured event-key conventions (Dash0) — same dot-namespace + event: convention this finding adopts
• Hookdeck: How to implement SHA-256 webhook signature verification — industry context for why signature-mismatch alerting is treated as a first-class operational signal

Suggested Next Steps

1. Add an event: "http.webhook.received" info log emitted from a thin wrapper around webhookMiddleware at src/app.ts:242, carrying delivery_id (from X-GitHub-Delivery), event_name (from X-GitHub-Event), installation_id (parsed lazily from the body or left out and added by the handler), and duration_ms (HTTP-handler wall-clock measured around the void webhookMiddleware(req, res) call).
2. Rewrite the webhooks.onError callback at src/app.ts:178-180 to emit event: "http.webhook.error" with a kind: "signature_mismatch" | "handler_threw" | "other" discriminator derived from error.name / error.event (per @octokit/webhooks types), plus delivery_id when available on error.request. This is the single point where the HMAC-failure signal becomes alertable.
3. Add event: "http.scheduler.run.{rejected_disabled,rejected_unauth,rejected_payload,enqueued,failed}" emissions at the five res.writeHead(…) sites in handleSchedulerRun (src/app.ts:535,539,554,574-595,607) — at warn for the rejected paths, info for enqueued, error for failed — each carrying status + a body-free reason field so the rejection rates become queryable for alerting on credential typos or oversize payloads.
4. Promote the existing /readyz returning 503 debug log at src/app.ts:208 to info with event: "http.readyz.unready" and the two failing flags (isReady, valkeyHealthy), so startup races and Valkey reconnect storms are visible at the default LOG_LEVEL=info. /healthz should remain silent (k8s liveness probes hammer it).
5. Pin the new event family with a Zod .strict() schema in a new src/app-log-fields.ts co-located with src/core/log-fields.ts (issue feat(observability): structured pipeline.stage events with delta_ms for runPipeline #166's pattern), so a future emitter that mistypes a field name trips a unit test the way PipelineStageLogSchema does today.

Areas Evaluated

• src/app.ts HTTP-server entry, webhook middleware wiring, webhooks.onError callback, /healthz + /readyz probes, /api/test/webhook and /api/scheduler/run operator endpoints.
• src/webhook/events/issue-comment.ts and the canonical createChildLogger({ deliveryId, owner, repo, entityNumber }) pattern handlers use post-dispatch.
• src/core/log-fields.ts and src/orchestrator/job-dispatcher.ts for the existing structured-event conventions (PIPELINE_LOG_EVENTS, DISPATCHER_LOG_EVENTS) to mirror.
• src/utils/github-output-guard.ts for the existing event: "secret_redacted" / event: "llm_scanner_*" discriminator-on-error pattern.
• Existing research-labelled issues to confirm no overlap with pipeline.stage (feat(observability): structured pipeline.stage events with delta_ms for runPipeline #166), dispatcher.offer.* (feat(observability): add queue_wait_ms to dispatcher offer/no-daemon logs #207), retry.* (feat(observability): add structured retry.* events #225), Octokit outbound hooks (feat(observability): log octokit rate-limit headers via hook.after for per-installation quota visibility #170 open), claimDelivery idempotency (feat(observability): emit structured idempotency events on all 4 claimDelivery outcomes #242), or the workspace.* family (open).

Generated by the scheduled research action on 2026-06-21