Skip to content

feat(cron): logger + per-step debug instrumentation#32

Merged
n2p5 merged 7 commits intomainfrom
feat/cron-logger
May 3, 2026
Merged

feat(cron): logger + per-step debug instrumentation#32
n2p5 merged 7 commits intomainfrom
feat/cron-logger

Conversation

@n2p5
Copy link
Copy Markdown
Contributor

@n2p5 n2p5 commented May 3, 2026

Summary

Replaces the hand-rolled makeCronLogger with a pino singleton (src/lib/log.ts). Level comes from LOG_LEVEL env at startup; pretty-printed via pino-pretty in dev (or LOG_PRETTY=1), raw JSON in production.

Each cron route binds a child logger with its event: name. Library code (stats.ts, ingest.ts, sync-geoip.ts) owns its own module-level child and emits log.debug between every await — every SQL query, blob get/put, streamToBuffer, Reader.openBuffer, MaxMind fetch, tar extract, per-blob ingest fetch.

ingestNewEvents keeps its onProgress callback so the existing CLI script continues to work unchanged.

Diagnostic intent

Open for the preview deploy. Set LOG_LEVEL=debug on the preview env, curl each cron endpoint with the bearer, and the runtime logs will show exactly which step is the last one before the production hang. Patches to address whatever the trace reveals will land on this branch before merge.

Local baseline (against prod blob + prod Neon):

cron local prod
tripwire-build-stats 4.0s 120s timeout
tripwire-ingest 0.5s (no work) occasional success
tripwire-asn-update 9.7s never works

@vercel
Copy link
Copy Markdown

vercel Bot commented May 3, 2026

The latest updates on your projects. Learn more about Vercel for GitHub.

Project Deployment Actions Updated (UTC)
func-lol Ready Ready Preview, Comment May 3, 2026 6:39pm

Request Review

src/lib/log.ts ships a tiny Logger interface plus a console-backed
provider that emits one JSON line per call via console.log. Vercel
auto-parses JSON in stdout into searchable fields, so this is the
platform's idiomatic shape — no external deps.

Cron routes bind a child logger with their event name. Library code
(stats.ts, ingest.ts, sync-geoip.ts) holds a module-level child and
emits log.debug between every await — every SQL query, blob get/put,
MaxMind fetch, tar extract, per-blob ingest fetch.
VERCEL_ENV=production keeps the existing info default. Preview, dev,
and local all default to debug, so per-step cron traces show up on
preview deploys without a manual env var. LOG_LEVEL still overrides.
@n2p5 n2p5 changed the title feat(cron): pino logger + per-step debug instrumentation feat(cron): logger + per-step debug instrumentation May 3, 2026
The chunk-loop helper in src/lib/blob-stream.ts was a workaround for
a Vercel Fluid Compute (Node.js) hang. vercel.json now pins
bunVersion: "1.x" and the chunk loop hangs on Bun instead — confirmed
on the build-stats cron at the asn.stream_to_buffer_start step.

The Response().arrayBuffer() / .text() pattern is what the scripts
have been using directly for months and what the helper's own comment
said works on Bun. Inline it at the three call sites and delete the
helper. One drain pattern, used everywhere.
The Vercel Blob SDK's get() returns response.body as a stream and
lets the underlying Response go out of scope. Under Bun on Vercel
the body stream then never reaches EOF for large bodies — neither
the chunk-loop nor Response.arrayBuffer() drain the 12MB mmdb.

Switch to head() for the URL (small metadata, no body-stream issue)
plus a direct fetch with the bearer token. The response stays in
scope across arrayBuffer(), and the read uses Next's data cache via
next.tags=[ASN_BLOB_TAG]. tripwire-asn-update calls revalidateTag
after a successful upload, so subsequent build-stats runs serve the
mmdb from cache and only refetch when the data actually changed.
Same root cause as the ASN cron fix: @vercel/blob's get() returns
response.body and lets the Response go out of scope, which under Bun
on Vercel can leave the body stream stuck waiting for EOF — that's
the most likely source of the ingest cron's flakiness on big runs.

ingest.ts: per-event JSON read uses fetch with cache: "no-store"
since each event is read exactly once.

aggregates.ts: page-side loader uses head() + fetch with the
STATS_BLOB_TAG cache tag. The build-stats cron already invalidates
that tag after publishing, so warm pages flip to fresh aggregates
without polling. The 2-min module-level singleton stays in front as
an instance-local burst absorber.

Also moves the literal "tripwire-aggregates" tag string into
aggregate-shape.ts so producer (cron) and consumer (page) import
the same constant.
The ingest cron was hanging at list.page_start with no progress: same
root cause as the get() and head() drain hangs. requestApi inside
@vercel/blob ends with await apiResponse.json(), which under Bun on
Vercel leaves the body stream stuck waiting for EOF after the SDK's
internal Response goes out of scope.

Inline a direct fetch against the public list endpoint with the same
auth + x-api-version headers the SDK sends. The Response stays in
scope across .json() and the call completes.
The cron was listing the entire events/ prefix every 5 minutes, which
grows linearly with the lifetime event count. Switch to listing today
+ yesterday by exact UTC-date prefix (events/<YYYY-MM-DD>/), bounded
by INGEST_WINDOW_DAYS=2.

Events older than the window are not auto-ingested by the cron path;
the CLI script (scripts/tripwire/ingest-events.ts) still walks the
full events/ prefix and can backfill manually if a longer outage
happens.
@n2p5 n2p5 merged commit 1b5dbde into main May 3, 2026
6 checks passed
@n2p5 n2p5 deleted the feat/cron-logger branch May 3, 2026 18:52
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants