Skip to content

Commit 72c8f70

Browse files
committed
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.
1 parent 6feaafe commit 72c8f70

7 files changed

Lines changed: 60 additions & 14 deletions

File tree

‎.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(`Error processing {service} webhook ${webhookId}:`, error, { requestId })
414+
logger.error('Error processing {service} webhook:', error)
415415
await markWebhookFailed(webhookId, logger)
416416
return 'failure'
417417
}

‎apps/sim/background/knowledge-connector-sync.test.ts‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -76,7 +76,8 @@ describe('knowledge connector sync worker', () => {
7676
processingDispatch: { failed: 1 },
7777
})
7878
expect(mockWarn).toHaveBeenCalledWith(
79-
expect.stringContaining('1 source failures, 1 dispatch failures')
79+
expect.stringContaining('1 source failures, 1 dispatch failures'),
80+
{ requestId: 'request-1' }
8081
)
8182
})
8283

‎apps/sim/lib/mothership/chat/project-file-context.integration.ts‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -694,7 +694,7 @@ describe('open tabs that no longer resolve', () => {
694694
})
695695
expect(contexts[1]?.content).toContain(browserTab.url)
696696
expect(logs.calls('info', 'Skipped resource attachment that no longer exists')).toEqual([
697-
{ resourceType: 'file' },
697+
{ requestId: expect.any(String), resourceType: 'file' },
698698
])
699699
expect(logs.calls('error', 'Failed to resolve resource attachment')).toHaveLength(1)
700700
expect(
@@ -737,7 +737,7 @@ describe('open tabs that no longer resolve', () => {
737737
expect(contexts[0]?.content).toContain(browserTab.url)
738738
expect(
739739
logs.calls('warn', 'Skipped resource attachment the user can no longer access')
740-
).toEqual([{ resourceType: 'file' }])
740+
).toEqual([{ requestId: expect.any(String), resourceType: 'file' }])
741741
expect(logs.calls('info', 'Skipped resource attachment that no longer exists')).toEqual([])
742742
expect(logs.calls('error', 'Failed to resolve resource attachment')).toEqual([])
743743
} finally {

‎apps/sim/lib/webhooks/processor.ts‎

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1011,11 +1011,13 @@ export async function processPolledWebhookEvent(
10111011
return { success: false, error: 'Webhook has no provider', statusCode: 400 }
10121012
}
10131013
const provider = foundWebhook.provider
1014+
// Concurrent polls in one tick share a request; the webhook id tells their lines apart.
1015+
const log = logger.withMetadata({ webhookId: foundWebhook.id })
10141016

10151017
const ticket = tryAdmit()
10161018
if (!ticket) {
10171019
const gateFailure = ADMISSION_ERROR_DESCRIPTOR.GATE_CAPACITY
1018-
logger.warn('Admission gate rejected polled webhook event', { requestId })
1020+
log.warn('Admission gate rejected polled webhook event', { requestId })
10191021
return {
10201022
success: false,
10211023
error: 'Server at capacity',
@@ -1032,7 +1034,7 @@ export async function processPolledWebhookEvent(
10321034
if (foundWebhook.blockId) {
10331035
const blockExists = await blockExistsInDeployment(foundWorkflow.id, foundWebhook.blockId)
10341036
if (!blockExists) {
1035-
logger.info(
1037+
log.info(
10361038
`Trigger block ${foundWebhook.blockId} not found in deployment for workflow ${foundWorkflow.id}`,
10371039
{ requestId }
10381040
)
@@ -1052,7 +1054,7 @@ export async function processPolledWebhookEvent(
10521054
typeof errorBody.error === 'string'
10531055
? errorBody.error
10541056
: 'Preprocessing failed'
1055-
logger.warn('Polled webhook preprocessing failed', {
1057+
log.warn('Polled webhook preprocessing failed', {
10561058
requestId,
10571059
statusCode,
10581060
error: errorMessage,
@@ -1084,7 +1086,7 @@ export async function processPolledWebhookEvent(
10841086
const billingAttribution = preprocessResult.billingAttribution
10851087
const workspaceId = foundWorkflow.workspaceId ?? undefined
10861088
if (!actorUserId || !billingAttribution || !workspaceId) {
1087-
logger.error(`Missing billing context for webhook ${foundWebhook.id}`, { requestId })
1089+
log.error(`Missing billing context for webhook ${foundWebhook.id}`, { requestId })
10881090
return { success: false, error: 'Unable to resolve billing account', statusCode: 500 }
10891091
}
10901092

@@ -1146,7 +1148,7 @@ export async function processPolledWebhookEvent(
11461148
maxDurationSeconds,
11471149
})
11481150
reservationTransferred = true
1149-
logger.info(
1151+
log.info(
11501152
`Queued polling webhook execution task ${jobId} for ${provider} webhook via job queue`,
11511153
{ requestId }
11521154
)
@@ -1164,12 +1166,12 @@ export async function processPolledWebhookEvent(
11641166
executeWebhookJob(payload, signal),
11651167
})
11661168
reservationTransferred = true
1167-
logger.info(`Queued ${provider} webhook execution ${jobId} via inline backend`, { requestId })
1169+
log.info(`Queued ${provider} webhook execution ${jobId} via inline backend`, { requestId })
11681170
}
11691171

11701172
return { success: true, executionId }
11711173
} catch (error: unknown) {
1172-
logger.error('Failed to process polled webhook event:', error, { requestId })
1174+
log.error('Failed to process polled webhook event:', error, { requestId })
11731175
return { success: false, error: 'Internal server error', statusCode: 500 }
11741176
} finally {
11751177
if (!reservationTransferred && reservedExecutionId) {

‎apps/sim/lib/workflows/streaming/streaming.test.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1444,7 +1444,7 @@ describe('createStreamingResponse agent-events-v1', () => {
14441444
)
14451445
)
14461446
expect(
1447-
workflowStreamingLogger.error.mock.calls.some(([message]) => message === 'Stream error')
1447+
workflowStreamingLogger.error.mock.calls.some((call: unknown[]) => call[0] === 'Stream error')
14481448
).toBe(false)
14491449
})
14501450

‎packages/logger/src/index.test.ts‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -137,6 +137,29 @@ describe('Logger', () => {
137137
expect(lines()[0]).toMatchObject({ requestId: 'task-run' })
138138
})
139139

140+
test('exports scalar fields passed with a line as OpenTelemetry attributes', () => {
141+
const emit = vi.fn()
142+
const getLoggerSpy = vi
143+
.spyOn(logs, 'getLogger')
144+
.mockReturnValue({ emit, enabled: () => true })
145+
try {
146+
const logger = jsonLogger()
147+
logger.info('Outside a request', { requestId: 'task-run', documentId: 'doc-1' })
148+
runWithRequestContext({ requestId: 'req-context' }, () => {
149+
logger.info('Inside a request', { requestId: 'replay-key', attempt: 2, nested: { a: 1 } })
150+
})
151+
const attributes = emit.mock.calls.map(
152+
([record]) => (record as { attributes: Record<string, string> }).attributes
153+
)
154+
expect(attributes[0]).toMatchObject({ requestId: 'task-run', documentId: 'doc-1' })
155+
expect(attributes[1]).toMatchObject({ requestId: 'req-context', attempt: '2' })
156+
expect(attributes[1]).not.toHaveProperty('nested')
157+
expect(attributes[1]['log.args']).toContain('"nested"')
158+
} finally {
159+
getLoggerSpy.mockRestore()
160+
}
161+
})
162+
140163
test('never lets an absent optional field erase one the line carries', () => {
141164
const logger = jsonLogger().withMetadata({ workflowId: 'workflow-1' })
142165
runWithRequestContext({ requestId: 'req-context' }, () => {

‎packages/logger/src/index.ts‎

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -504,7 +504,7 @@ export class Logger {
504504
const effectiveMetadata = reqCtx
505505
? { ...requestContextMetadata(reqCtx), ...this.metadata, ...owned }
506506
: this.metadata
507-
emitOtelLogRecord(level, this.module, message, effectiveMetadata, args)
507+
emitOtelLogRecord(level, this.module, message, effectiveMetadata, args, owned)
508508
const metadataEntries = Object.entries(filterUndefined(effectiveMetadata))
509509
const metadataStr =
510510
metadataEntries.length > 0
@@ -638,6 +638,12 @@ const OTEL_LOG_SEVERITY: Record<LogLevel, { number: SeverityNumber; text: string
638638

639639
const OTEL_LOG_ARG_MAX_CHARS = 2000
640640

641+
const isOtelScalar = (value: unknown): value is string | number | boolean | bigint =>
642+
typeof value === 'string' ||
643+
typeof value === 'number' ||
644+
typeof value === 'boolean' ||
645+
typeof value === 'bigint'
646+
641647
/**
642648
* Fans every accepted log line out through the OTel Logs API. Until an
643649
* application installs a global LoggerProvider (apps/sim does in
@@ -652,14 +658,28 @@ function emitOtelLogRecord(
652658
module: string,
653659
message: string,
654660
metadata: Record<string, unknown>,
655-
args: unknown[]
661+
args: unknown[],
662+
owned: Record<string, unknown>
656663
): void {
657664
try {
658665
const severity = OTEL_LOG_SEVERITY[level]
659666
const attributes: Record<string, string> = { 'log.module': module }
660667
for (const [key, value] of Object.entries(filterUndefined(metadata))) {
661668
attributes[key] = String(value)
662669
}
670+
// Scalar fields passed with the line become attributes, as they are top-level keys in the JSON
671+
// line, so `{ documentId }` filters the same way in both; nested values stay in `log.args`.
672+
for (const arg of args) {
673+
if (!isRecordLike(arg) || arg instanceof Error) continue
674+
try {
675+
for (const [key, value] of Object.entries(arg)) {
676+
if (isOtelScalar(value)) attributes[key] = String(value)
677+
}
678+
} catch {
679+
// A throwing getter loses only its own argument's fields; `log.args` still records it.
680+
}
681+
}
682+
for (const [key, value] of Object.entries(owned)) attributes[key] = String(value)
663683
const error = primaryError(args)
664684
if (error) {
665685
const logged = toLoggedError(error)

0 commit comments

Comments
 (0)