Skip to content

Commit 7e79983

Browse files
authored
improvement(logs): move correlation ids from message tags into metadata and enforce it (#9724)
* improvement(logs): move correlation ids from message tags into metadata and enforce it Log messages no longer open with an interpolated [${id}] tag or interpolate a request id. The id moves into the line's metadata, so messages group in queries and lines filter by field. Inside withRouteHandler a generateRequestId() id is already stamped on every line by the request context, so those tags are dropped without a field. Routes, table runners, the Sim event emitter and the poll orchestrator that minted their own correlation ids now use generateRequestId(), so their lines carry the request's id. Each webhook poll logs through a logger bound to its webhook id, so concurrent polls in one tick stay distinguishable. check:source-conventions gains log-message-tag: it covers every app and package that imports @sim/logger, follows a message through concatenation, ternaries, local consts and helpers handed the caller's logger, and starts at zero. * fix(logger): let the request context own requestId and keep absent fields from erasing it An explicit requestId on a line, or one bound with withMetadata, replaced the request context's id in the JSON line, and an undefined one deleted it, so a line could stop correlating with its request. Inside a request context the context's id is now authoritative, matching the OpenTelemetry export; a requestId passed with a line names the request only outside one. Undefined fields no longer erase fields the line already carries. v2 chat logs its mothership request id as simRequestId. Request ids that defaulted to 'unknown' default to generateRequestId(). log-message-tag now sees optional calls, computed levels, withMetadata-derived loggers and log-named receivers, follows let prefixes, resolves names per function, and only treats an interpolated requestId or reqId, and log* helpers or .call(logger), as message sources. * fix(logs): keep a unique request id per webhook poll and per emitted event Executions started by one poll tick, or by one parent request, would otherwise share a request id, and tool code that keys idempotency on it (deployments) could replay one execution's result in another. The logger now owns requestId on the line, so these ids no longer need to match the request to correlate. * fix(logs): export call fields to OpenTelemetry and tell concurrent polls apart Scalar fields passed with a log line now become OpenTelemetry attributes, matching their top-level keys in the JSON line, so ids moved out of message text stay filterable in both sinks. Nested values stay in log.args. The request context still owns requestId. The polled-webhook processor logs through a logger bound to the webhook id, so lines from concurrent polls in one tick stay distinguishable. Test expectations follow the new metadata shape. * fix(lint): check reqId-only modules and skip reassigned let messages in log-message-tag The cheap pre-filter now admits a module whose only request id is reqId, and a let binding reassigned before it is logged is no longer followed to its initializer.
1 parent 79dbf14 commit 7e79983

331 files changed

Lines changed: 4152 additions & 3299 deletions

File tree

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

‎.agents/skills/add-trigger/SKILL.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -411,7 +411,7 @@ export const {service}PollingHandler: PollingProviderHandler = {
411411
await markWebhookSuccess(webhookId, logger)
412412
return 'success'
413413
} catch (error) {
414-
logger.error(`[${requestId}] Error processing {service} webhook ${webhookId}:`, error)
414+
logger.error('Error processing {service} webhook:', error)
415415
await markWebhookFailed(webhookId, logger)
416416
return 'failure'
417417
}

‎AGENTS.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ This file (also `AGENTS.md`) holds the repo-wide rules. Area detail lives in `.c
55
## Global Standards
66

77
- **Package manager**: `bun` and `bunx`, never `npm` and `npx`.
8-
- **Logging**: `createLogger` from `@sim/logger`; `logger.info` / `logger.warn` / `logger.error`, never `console.log`. Inside `withRouteHandler` the logger already carries the request ID — no manual `withMetadata({ requestId })`.
8+
- **Logging**: `createLogger` from `@sim/logger`; `logger.info` / `logger.warn` / `logger.error`, never `console.log`. Messages are static text; ids go in metadata (`logger.info('Sync started', { requestId, documentId })`), never a `[${requestId}]` tag or an interpolated request id, so lines group and filter by field (`check:source-conventions` rule `log-message-tag`). Inside `withRouteHandler` every line already carries the request ID, so a `generateRequestId()` id there needs no field and no manual `withMetadata({ requestId })`.
99
- **Comments**: name things so the code explains itself. TSDoc documents exported APIs and non-obvious modules. An inline `//` is only for a terse, non-obvious *why*, or for a script-enforced `// <tag>: <reason>` annotation (`boundary-raw-fetch`, `double-cast-allowed`, `boundary-raw-json`, `untyped-response`, `rq-lint-allow`, `client-boundary-allow`, `utils-lint-allow`, …). History belongs in the commit message. No `====` separators, commented-out code, or ESLint directives (`eslint-disable`/`eslint-enable`; nothing runs ESLint; `check:comment-hygiene` enforces all three). The `/you-might-not-need-a-comment` skill applies this to a diff.
1010
- **ID generation**: `generateId()` (UUID v4, the default) or `generateShortId(size?)` (URL-safe, 21 chars by default) from `@sim/utils/id` — never `crypto.randomUUID()`, `nanoid`, or `uuid`. Both use `crypto.getRandomValues()`, so they also work in non-secure (HTTP) browsers. For other randomness, `@sim/utils/random` (`randomInt`, `randomFloat`, `randomItem`, `generateRandomBytes`, `generateRandomHex`) — never `Math.random()` or `crypto.randomBytes()`.
1111
- **Common utilities**: use the shared helpers from the `@sim/utils/<module>` subpaths instead of inline implementations (`check:utils` bans most of the inline forms below):

‎CLAUDE.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ This file (also `AGENTS.md`) holds the repo-wide rules. Area detail lives in `.c
55
## Global Standards
66

77
- **Package manager**: `bun` and `bunx`, never `npm` and `npx`.
8-
- **Logging**: `createLogger` from `@sim/logger`; `logger.info` / `logger.warn` / `logger.error`, never `console.log`. Inside `withRouteHandler` the logger already carries the request ID — no manual `withMetadata({ requestId })`.
8+
- **Logging**: `createLogger` from `@sim/logger`; `logger.info` / `logger.warn` / `logger.error`, never `console.log`. Messages are static text; ids go in metadata (`logger.info('Sync started', { requestId, documentId })`), never a `[${requestId}]` tag or an interpolated request id, so lines group and filter by field (`check:source-conventions` rule `log-message-tag`). Inside `withRouteHandler` every line already carries the request ID, so a `generateRequestId()` id there needs no field and no manual `withMetadata({ requestId })`.
99
- **Comments**: name things so the code explains itself. TSDoc documents exported APIs and non-obvious modules. An inline `//` is only for a terse, non-obvious *why*, or for a script-enforced `// <tag>: <reason>` annotation (`boundary-raw-fetch`, `double-cast-allowed`, `boundary-raw-json`, `untyped-response`, `rq-lint-allow`, `client-boundary-allow`, `utils-lint-allow`, …). History belongs in the commit message. No `====` separators, commented-out code, or ESLint directives (`eslint-disable`/`eslint-enable`; nothing runs ESLint; `check:comment-hygiene` enforces all three). The `/you-might-not-need-a-comment` skill applies this to a diff.
1010
- **ID generation**: `generateId()` (UUID v4, the default) or `generateShortId(size?)` (URL-safe, 21 chars by default) from `@sim/utils/id` — never `crypto.randomUUID()`, `nanoid`, or `uuid`. Both use `crypto.getRandomValues()`, so they also work in non-secure (HTTP) browsers. For other randomness, `@sim/utils/random` (`randomInt`, `randomFloat`, `randomItem`, `generateRandomBytes`, `generateRandomHex`) — never `Math.random()` or `crypto.randomBytes()`.
1111
- **Common utilities**: use the shared helpers from the `@sim/utils/<module>` subpaths instead of inline implementations (`check:utils` bans most of the inline forms below):

‎apps/sim/app/api/auth/oauth/credentials/route.ts‎

Lines changed: 5 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@ import { type NextRequest, NextResponse } from 'next/server'
77
import { oauthCredentialsQuerySchema } from '@/lib/api/contracts/credentials'
88
import { getValidationErrorMessage } from '@/lib/api/server'
99
import { AuthType, type AuthTypeValue, checkSessionOrInternalAuth } from '@/lib/auth/hybrid'
10-
import { generateRequestId } from '@/lib/core/utils/request'
1110
import { withRouteHandler } from '@/lib/core/utils/with-route-handler'
1211
import { canUseCredential, getCredentialActorContext } from '@/lib/credentials/access'
1312
import { syncWorkspaceOAuthCredentialsForUser } from '@/lib/credentials/oauth'
@@ -84,8 +83,6 @@ async function integrationsWithheldFromSession(
8483
* Get credentials for a specific provider
8584
*/
8685
export const GET = withRouteHandler(async (request: NextRequest) => {
87-
const requestId = generateRequestId()
88-
8986
try {
9087
const { searchParams } = new URL(request.url)
9188
const rawQuery = {
@@ -100,11 +97,11 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
10097
if (!parseResult.success) {
10198
const refinementError = parseResult.error.issues.find((err) => err.code === 'custom')
10299
if (refinementError) {
103-
logger.warn(`[${requestId}] Invalid query parameters: ${refinementError.message}`)
100+
logger.warn(`Invalid query parameters: ${refinementError.message}`)
104101
return NextResponse.json({ error: refinementError.message }, { status: 400 })
105102
}
106103

107-
logger.warn(`[${requestId}] Invalid query parameters`, {
104+
logger.warn('Invalid query parameters', {
108105
errors: parseResult.error.issues,
109106
})
110107

@@ -119,7 +116,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
119116
// Authenticate requester (supports session and internal JWT)
120117
const authResult = await checkSessionOrInternalAuth(request)
121118
if (!authResult.success || !authResult.userId) {
122-
logger.warn(`[${requestId}] Unauthenticated credentials request rejected`)
119+
logger.warn('Unauthenticated credentials request rejected')
123120
return NextResponse.json({ error: 'User not authenticated' }, { status: 401 })
124121
}
125122
const requesterUserId = authResult.userId
@@ -132,7 +129,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
132129
action: 'read',
133130
})
134131
if (!workflowAuthorization.allowed) {
135-
logger.warn(`[${requestId}] Forbidden credentials request for workflow`, {
132+
logger.warn('Forbidden credentials request for workflow', {
136133
requesterUserId,
137134
workflowId,
138135
status: workflowAuthorization.status,
@@ -378,7 +375,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
378375

379376
return NextResponse.json({ credentials: [] }, { status: 200 })
380377
} catch (error) {
381-
logger.error(`[${requestId}] Error fetching OAuth credentials`, error)
378+
logger.error('Error fetching OAuth credentials', error)
382379
return NextResponse.json({ error: 'Internal server error' }, { status: 500 })
383380
}
384381
})

‎apps/sim/app/api/auth/oauth/token/route.ts‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ const logger = createLogger('OAuthTokenAPI')
3333
export const POST = withRouteHandler(async (request: NextRequest) => {
3434
const requestId = generateRequestId()
3535

36-
logger.info(`[${requestId}] OAuth token API POST request received`)
36+
logger.info('OAuth token API POST request received')
3737

3838
try {
3939
const parsed = await parseRequest(
@@ -42,7 +42,7 @@ export const POST = withRouteHandler(async (request: NextRequest) => {
4242
{},
4343
{
4444
validationErrorResponse: (error) => {
45-
logger.warn(`[${requestId}] Invalid token request`, { errors: error.issues })
45+
logger.warn('Invalid token request', { errors: error.issues })
4646
return NextResponse.json(
4747
{ error: getValidationErrorMessage(error, 'Validation failed') },
4848
{ status: 400 }
@@ -64,14 +64,14 @@ export const POST = withRouteHandler(async (request: NextRequest) => {
6464
const callerUserId = parsed.data.query.userId
6565

6666
if (credentialAccountUserId && providerId) {
67-
logger.info(`[${requestId}] Fetching token by credentialAccountUserId + providerId`, {
67+
logger.info('Fetching token by credentialAccountUserId + providerId', {
6868
credentialAccountUserId,
6969
providerId,
7070
})
7171

7272
const auth = await checkSessionOrInternalAuth(request, { requireWorkflowId: false })
7373
if (!auth.success || auth.authType !== AuthType.SESSION || !auth.userId) {
74-
logger.warn(`[${requestId}] Unauthorized request for credentialAccountUserId path`, {
74+
logger.warn('Unauthorized request for credentialAccountUserId path', {
7575
success: auth.success,
7676
authType: auth.authType,
7777
})
@@ -80,7 +80,7 @@ export const POST = withRouteHandler(async (request: NextRequest) => {
8080

8181
if (auth.userId !== credentialAccountUserId) {
8282
logger.warn(
83-
`[${requestId}] User ${auth.userId} attempted to access credentials for ${credentialAccountUserId}`
83+
`User ${auth.userId} attempted to access credentials for ${credentialAccountUserId}`
8484
)
8585
return NextResponse.json({ error: 'Unauthorized' }, { status: 403 })
8686
}
@@ -117,7 +117,7 @@ export const POST = withRouteHandler(async (request: NextRequest) => {
117117
return NextResponse.json({ accessToken }, { status: 200 })
118118
} catch (error) {
119119
const message = getErrorMessage(error, 'Failed to get OAuth token')
120-
logger.warn(`[${requestId}] OAuth token error: ${message}`)
120+
logger.warn(`OAuth token error: ${message}`)
121121
return NextResponse.json({ error: message }, { status: 403 })
122122
}
123123
}
@@ -148,7 +148,7 @@ export const POST = withRouteHandler(async (request: NextRequest) => {
148148

149149
return NextResponse.json(result.token, { status: 200 })
150150
} catch (error) {
151-
logger.error(`[${requestId}] Error getting access token`, error)
151+
logger.error('Error getting access token', error)
152152
return NextResponse.json({ error: 'Internal server error' }, { status: 500 })
153153
}
154154
})
@@ -166,7 +166,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
166166
{},
167167
{
168168
validationErrorResponse: (error) => {
169-
logger.warn(`[${requestId}] Invalid query parameters`, { errors: error.issues })
169+
logger.warn('Invalid query parameters', { errors: error.issues })
170170
return NextResponse.json(
171171
{ error: getValidationErrorMessage(error, 'Validation failed') },
172172
{ status: 400 }
@@ -203,7 +203,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
203203
}
204204

205205
if (!credential.accessToken) {
206-
logger.warn(`[${requestId}] No access token available for credential`)
206+
logger.warn('No access token available for credential')
207207
return NextResponse.json({ error: 'No access token available' }, { status: 400 })
208208
}
209209

@@ -225,7 +225,7 @@ export const GET = withRouteHandler(async (request: NextRequest) => {
225225

226226
return NextResponse.json(result.token, { status: 200 })
227227
} catch (error) {
228-
logger.error(`[${requestId}] Error fetching access token`, error)
228+
logger.error('Error fetching access token', error)
229229
return NextResponse.json({ error: 'Internal server error' }, { status: 500 })
230230
}
231231
})

‎apps/sim/app/api/billing/update-cost/route.ts‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -196,12 +196,12 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
196196
const startTime = Date.now()
197197

198198
try {
199-
logger.debug(`[${requestId}] Update cost request started`)
199+
logger.debug('Update cost request started')
200200

201201
// Check authentication (internal API key)
202202
const authResult = checkInternalApiKey(req)
203203
if (!authResult.success) {
204-
logger.warn(`[${requestId}] Authentication failed: ${authResult.error}`)
204+
logger.warn(`Authentication failed: ${authResult.error}`)
205205
span.setAttribute(TraceAttr.BillingOutcome, BillingRouteOutcome.AuthFailed)
206206
span.setAttribute(TraceAttr.HttpStatusCode, 401)
207207
return NextResponse.json(
@@ -234,7 +234,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
234234
{},
235235
{
236236
validationErrorResponse: (error) => {
237-
logger.warn(`[${requestId}] Invalid request body`, {
237+
logger.warn('Invalid request body', {
238238
errors: error.issues,
239239
})
240240
span.setAttribute(TraceAttr.BillingOutcome, BillingRouteOutcome.InvalidBody)
@@ -324,7 +324,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
324324
...(idempotencyKey ? { [TraceAttr.BillingIdempotencyKey]: idempotencyKey } : {}),
325325
})
326326

327-
logger.debug(`[${requestId}] Processing cost update`, {
327+
logger.debug('Processing cost update', {
328328
userId,
329329
cost,
330330
model,
@@ -408,7 +408,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
408408
}
409409
: undefined
410410

411-
logger.debug(`[${requestId}] Billing payer resolved`, {
411+
logger.debug('Billing payer resolved', {
412412
userId,
413413
billingProtocol: protocol,
414414
billingResolution: getBillingResolution(isMarkerlessLegacy, billingAttribution),
@@ -441,7 +441,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
441441
...(rolloverSubscriptionId ? { payerSubscriptionId: rolloverSubscriptionId } : {}),
442442
})
443443
const billed = result.billed
444-
logger.info(`[${requestId}] Cumulative cost top-up`, {
444+
logger.info('Cumulative cost top-up', {
445445
userId,
446446
billingPayer: billingContext?.billingEntity ?? { type: 'user', id: userId },
447447
workspaceId: resolvedWorkspaceId,
@@ -476,7 +476,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
476476
) {
477477
throw error
478478
}
479-
logger.info(`[${requestId}] Charge landed in a period that has since rolled over`, {
479+
logger.info('Charge landed in a period that has since rolled over', {
480480
billingPeriodEnd: result.billingPeriod.end.toISOString(),
481481
})
482482
}
@@ -494,7 +494,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
494494
// Same-or-lower cumulative than already recorded: nothing new to bill.
495495
// Reconciliation has completed, so preserve Go's established 409 outcome.
496496
if (!billed) {
497-
logger.info(`[${requestId}] Duplicate/non-increasing cumulative cost; no new charge`, {
497+
logger.info('Duplicate/non-increasing cumulative cost; no new charge', {
498498
idempotencyKey,
499499
userId,
500500
cost,
@@ -514,7 +514,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
514514
)
515515
}
516516

517-
logger.info(`[${requestId}] Cost update completed successfully`, {
517+
logger.info('Cost update completed successfully', {
518518
userId,
519519
duration,
520520
cost,
@@ -539,7 +539,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
539539

540540
const isMarkerlessLegacy = !req.headers.get(COPILOT_BILLING_PROTOCOL_HEADER)
541541
if (error instanceof CumulativeUsageContextMismatchError && !isMarkerlessLegacy) {
542-
logger.error(`[${requestId}] Billing context mismatch`, {
542+
logger.error('Billing context mismatch', {
543543
eventKey: error.eventKey,
544544
mismatchedFields: error.mismatchedFields,
545545
duration,
@@ -563,7 +563,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
563563
* the caller resends later, and the monotonic top-up applies the higher cumulative once.
564564
*/
565565
if (error instanceof CumulativeUsageInFlightError) {
566-
logger.info(`[${requestId}] Cost update already in flight for this request`, {
566+
logger.info('Cost update already in flight for this request', {
567567
eventKey: error.eventKey,
568568
duration,
569569
})
@@ -596,7 +596,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
596596

597597
/** Old markerless clients treat every 409 as a successful duplicate. */
598598
if (reconciliationOutcome && !isMarkerlessLegacy) {
599-
logger.warn(`[${requestId}] Billing callback requires reconciliation`, {
599+
logger.warn('Billing callback requires reconciliation', {
600600
code: reconciliationOutcome.code,
601601
duration,
602602
billingProtocol:
@@ -618,7 +618,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
618618
}
619619

620620
if (error instanceof ThresholdSettlementError) {
621-
logger.error(`[${requestId}] Retryable threshold settlement failure`, {
621+
logger.error('Retryable threshold settlement failure', {
622622
settlementErrorCode: error.code,
623623
retryable: error.retryable,
624624
duration,
@@ -646,7 +646,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
646646
// lock timeout) — Drizzle's "Failed query" wrapper alone cannot
647647
// distinguish them, which made the dead-workspace incident undiagnosable
648648
// from logs.
649-
logger.error(`[${requestId}] Cost update failed`, {
649+
logger.error('Cost update failed', {
650650
error: toError(error).message,
651651
...(pgCode && { pgCode }),
652652
...(pgConstraint && { pgConstraint }),

0 commit comments

Comments
 (0)