BE-517: Stop double-stringifying log payloads#8669
Conversation
`logger.X(JSON.stringify(obj))` round-trips through Winston's JSON
formatter, leaving an escaped string in the OTLP log body and empty
attributes — fields cannot be searched in Loki without re-parsing the
body string.
Replace the antipattern with `logger.X("description", payload)`:
- body: a short identifier-rich description (e.g. `query GetMe`,
`mutation CreateEntity failed`, `GET /health-check`,
`llm openai extract-entities`)
- attributes: the structured payload, directly searchable
Also clean up the same shape elsewhere — error objects, large
stringified payloads, and IDs embedded in template strings — moving
them out of the body and into attributes. Catch parameters renamed
`err` → `error` so the shorthand `{ error }` works.
Apollo Server's `ctx.logger` is a 1-arg Logger interface, so the
graphql plugin now uses our Winston logger directly via closure
instead of going through `ctx.logger`.
The `activity-logger.ts` JSON.parse workaround that existed solely to
recover from the antipattern is no longer needed; signature extended
to accept an optional meta object.
…gh request-scoped logger The Express request middleware was logging every request including POST /graphql, which the Apollo plugin already logs at the operation level (query/mutation name) — duplicate and less informative. Skip /graphql in the middleware. requestId still gets generated and set on the response header for downstream correlation. In the Apollo plugin, switch from the closure-captured logger to ctx.contextValue.logger, which is the per-request child logger that already carries requestId in its metadata. Each operation log now correlates with the request that produced it.
|
The latest updates on your projects. Learn more about Vercel for GitHub. |
PR SummaryLow Risk Overview Updates the Temporal Enhances the shared backend logger with Reviewed by Cursor Bugbot for commit 1e50d75. Bugbot is set up for automated code reviews on this repo. Configure here. |
github-actions
Bot
added
area/apps > hash*
🤖 Augment PR SummarySummary: This PR improves backend and worker logging by removing the anti-pattern of stringifying payload objects before passing them to Winston, so OTLP logs carry structured attributes instead of an escaped JSON blob in the log body. Changes:
Technical Notes: The new pattern keeps log bodies short and human-readable while preserving queryable fields in OTLP/Winston attributes (important for Loki search and correlation). 🤖 Was this summary useful? React with 👍 or 👎 |
![augmentcode[bot]](https://avatars.githubusercontent.com/in/1027498?s=60&v=4){kind=small}
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## main #8669 +/- ##
=======================================
Coverage 62.49% 62.49%
=======================================
Files 1318 1318
Lines 134235 134232 -3
Branches 5521 5524 +3
=======================================
Hits 83894 83894
+ Misses 49426 49423 -3
Partials 915 915
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
…refs
Naive JSON.stringify on log payloads loses information (Error own
properties are non-enumerable so an Error serialises to `{}`) or
throws (BigInts, circular references). Both shapes appeared after the
move to `logger.X("desc", meta)`, e.g. `{ error }` from `catch (error)`.
Add `expandLogValue` and `safeStringify` to `hash-backend-utils/logger`:
- `expandLogValue` recursively replaces Errors with `{ name, message,
stack, cause? }` and BigInts with their string form, then descends
into arrays and plain objects.
- `safeStringify` runs `JSON.stringify` over the expanded value,
catching anything that still throws (e.g. circular refs) and
returning a marker rather than crashing the call site.
Wire the helpers into:
- The Winston logger pipeline via a new `expandLogValuesFormat()` that
runs before `format.json()` on the logger-level format chain. This
fixes nested Errors in the OTLP/Datadog/console outputs without
touching individual call sites.
- `OpenTelemetryLogTransport.toAnyValue` non-primitive path.
- `rewriteForConsole`'s console-prefix path.
- The flow-run log file in `activity-logger.ts`.
Drop newly-unused `stringify` imports in three files; tighten two
`.catch((err) => ...)` parameters to `(error: unknown)` to satisfy
the no-unsafe-assignment rule on the `{ error }` shorthand.
github-actions
Bot
added
the
area/libs
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
Three valid findings on the previous commit: 1. `rewriteForConsole` only stripped `detailedFields` from object-shaped `info.message`. Activity-logger now passes the message as a string and spreads the structured payload onto the info object directly, so the detailed payload (request/response/transformedRequest blobs) was ending up in the dev console. Filter `detailedFields` from the top-level info metadata as well, and treat `detailedFields` itself as a control field that shouldn't appear in console output. 2. `expandLogValue` rebuilt every object via `Object.entries`, which silently dropped values relying on `toJSON` — most importantly Date, but also Buffer and decimal/ID types. Pass through anything with a `toJSON` method so JSON.stringify can call it. 3. `expandLogValue` had no cycle guard, so a circular payload would cause infinite recursion. `safeStringify` caught that, but `expandLogValuesFormat` (used as a Winston format) did not, so a cyclic value reaching the logger pipeline would throw out of it. Track visited objects in a WeakSet (replace with `[Circular]`) and wrap the format invocation in try/catch as a backstop.
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 7373fdd. Configure here.
Round of review-agent / bugbot follow-ups on the safe-stringify work:
- expandLogValue: WeakSet was added to but never popped, so any object
reused across sibling positions (not a true cycle) was being labelled
`[Circular]` in console / file / OTLP output. Switched to a path-scoped
Set with try/finally cleanup so genuine self-references are still
caught while shared references serialise normally.
- expandLogValue: Object.entries only enumerates string keys, so
rebuilding the info object stripped Winston's symbol-keyed metadata
(Symbol.for("level"), "message", "splat"). Carry symbol properties
through unchanged.
- JSDoc tightened: explain why Errors serialise to `{}` accurately
(no toJSON, non-enumerable own/inherited members), and stop claiming
unconditional circular-ref safety in safeStringify — only plain-object
cycles get the `[Circular]` rewrite, anything else falls through to
the try/catch marker.
- Drop a stale comment in activity-logger.ts (referenced consolePrefix
in a code path that no longer uses one) and a redundant inline comment
in expandLogValuesFormat. Trim the `logger.child` implementation
detail from the Apollo plugin comment.
- Rename `result` → `cleanedInfo` in rewriteForConsole.
1 participant
🌟 What is the purpose of this PR?
logger.X(JSON.stringify(obj))round-trips through Winston's JSON formatter. The OTLP log record ends up with the entire payload as an escaped string inbodyand an emptyattributesmap — fields cannot be searched in Loki without re-parsing the body. Tim already worked around this on the Grafana ingestion side; this PR removes the workaround at the source.🔗 Related links
🔍 What does this change?
logger.X("description", payload). Identifier-rich descriptions:${req.method} ${req.path}for Express requests (e.g.GET /health-check)${operationType} ${operationName}for GraphQL ops (e.g.query GetMe,mutation CreateEntity failed)llm ${provider} ${taskName}for LLM logs (e.g.llm openai extract-entities)catch (err)→catch (error)so{ error }shorthand works/graphqlin the Express request log — Apollo's plugin logs operation-level detail which is more useful than the genericPOST /graphql.requestIdis still generated and set on the response header for downstream correlationctx.contextValue.logger(the request-scoped child logger that already carriesrequestId) so each operation log correlates with its requestactivity-logger.ts: signature extended to accept an optional meta object. Removed the legacyJSON.parse(message)workaround that existed solely to recover from the antipattern this PR removesApollo Server's
ctx.loggeris a 1-argLoggerinterface, soctx.contextValue.logger(typed as our WinstonLogger) is used in the plugin instead.Pre-Merge Checklist 🚀
🚢 Has this modified a publishable library?
📜 Does this require a change to the docs?
🕸️ Does this require a change to the Turbo Graph?
hash-ai-worker-ts,hash-integration-worker) still have no OTEL setup, so their structured log calls are invisible in Loki until BE-519 lands. This PR upgrades the call-site quality regardless — once OTEL is wired up, the value is unlocked without further code changes.Listening on port ${port},Iteration ${count} begun). Tracked in BE-518 to keep this PR focused.🐾 Next steps
logger.X(JSON.stringify(...))regression and ano-consolerule for production code (catchesconsole.infoinhash-integration-worker/src/main.ts)🛡 What tests cover this?
No new tests — change is to logging shape only, no behavioural change. Verified locally with a Winston harness that the new
logger.X("desc", obj)pattern produces structured OTLP records (body=description, attributes=payload).❓ How to test this?
yarn dev:backendand hit a few GraphQL queries / make a recovery / send a test emailbodyset to a short description andattributescontaining the structured payload (operation,elapsed, etc.)info: query GetMe {operation:"GetMe",elapsed:"5ms",...})📹 Demo