Skip to content

Commit 743daea

Browse files
authored
fix(logs): log the webhook poll id and emitted event id under their own names (#9747)
Webhook polls and Sim events logged their own generated ids as requestId, which the poll route's request context overwrites, so the ids never reached a log line. The orchestrator now binds each poll's id on the handler logger as pollId, handlers drop their per-line requestId fields, and the event emitter logs its per-event id as dispatchId. The ids passed downstream as each execution's request id are unchanged.
1 parent 4f89a61 commit 743daea

13 files changed

Lines changed: 159 additions & 305 deletions

File tree

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -423,6 +423,7 @@ export const {service}PollingHandler: PollingProviderHandler = {
423423
- First poll seeds state and emits nothing (avoids flooding with existing data)
424424
- Use `pollingIdempotency.executeWithIdempotency(provider, key, callback)` for dedup
425425
- Use `processPolledWebhookEvent(webhookData, workflowData, payload, requestId)` to fire the workflow
426+
- Log through `ctx.logger` (already bound with `webhookId` and `pollId`, which equals `ctx.requestId`). Never add `{ requestId }` to a log line; the poll route's request context owns that field and overwrites it
426427
- Use `updateWebhookProviderConfig(webhookId, partialConfig, logger)` for read-merge-write on state
427428
- Use the latest server-side timestamp from API responses (not wall clock) to avoid clock skew
428429

‎apps/sim/lib/webhooks/polling/gmail.ts‎

Lines changed: 30 additions & 61 deletions
Original file line numberDiff line numberDiff line change
@@ -77,12 +77,7 @@ export const gmailPollingHandler: PollingProviderHandler = {
7777
const config = getProviderConfig<GmailWebhookConfig>(webhookData.providerConfig)
7878
const now = new Date()
7979

80-
const { emails, latestHistoryId } = await fetchNewEmails(
81-
accessToken,
82-
config,
83-
requestId,
84-
logger
85-
)
80+
const { emails, latestHistoryId } = await fetchNewEmails(accessToken, config, logger)
8681
const pollState = {
8782
lastCheckedTimestamp: now.toISOString(),
8883
// Omit unless this poll held a cursor, so it can't clear one an overlapping poll stored.
@@ -92,11 +87,11 @@ export const gmailPollingHandler: PollingProviderHandler = {
9287
if (!emails || !emails.length) {
9388
await updateWebhookProviderConfig(webhookId, pollState, logger)
9489
await markWebhookSuccess(webhookId, logger)
95-
logger.info(`No new emails found for webhook ${webhookId}`, { requestId })
90+
logger.info(`No new emails found for webhook ${webhookId}`)
9691
return 'success'
9792
}
9893

99-
logger.info(`Found ${emails.length} new emails for webhook ${webhookId}`, { requestId })
94+
logger.info(`Found ${emails.length} new emails for webhook ${webhookId}`)
10095

10196
const { processedCount, failedCount } = await processEmails(
10297
emails,
@@ -112,35 +107,27 @@ export const gmailPollingHandler: PollingProviderHandler = {
112107

113108
if (failedCount > 0 && processedCount === 0) {
114109
await markWebhookFailed(webhookId, logger)
115-
logger.warn(`All ${failedCount} emails failed to process for webhook ${webhookId}`, {
116-
requestId,
117-
})
110+
logger.warn(`All ${failedCount} emails failed to process for webhook ${webhookId}`)
118111
return 'failure'
119112
}
120113

121114
await markWebhookSuccess(webhookId, logger)
122115
logger.info(
123-
`Successfully processed ${processedCount} emails for webhook ${webhookId}${failedCount > 0 ? ` (${failedCount} failed)` : ''}`,
124-
{ requestId }
116+
`Successfully processed ${processedCount} emails for webhook ${webhookId}${failedCount > 0 ? ` (${failedCount} failed)` : ''}`
125117
)
126118
return 'success'
127119
} catch (error) {
128120
if (error instanceof PollAdmissionRefusedError) {
129-
return skipAdmissionRefusedPoll(logger, requestId, webhookId)
121+
return skipAdmissionRefusedPoll(logger, webhookId)
130122
}
131-
logger.error(`Error processing Gmail webhook ${webhookId}:`, error, { requestId })
123+
logger.error(`Error processing Gmail webhook ${webhookId}:`, error)
132124
await markWebhookFailed(webhookId, logger)
133125
return 'failure'
134126
}
135127
},
136128
}
137129

138-
async function fetchNewEmails(
139-
accessToken: string,
140-
config: GmailWebhookConfig,
141-
requestId: string,
142-
logger: Logger
143-
) {
130+
async function fetchNewEmails(accessToken: string, config: GmailWebhookConfig, logger: Logger) {
144131
try {
145132
const useHistoryApi = !!config.historyId
146133
let emails: GmailEmail[] = []
@@ -166,15 +153,13 @@ async function fetchNewEmails(
166153
if (status === 404 || status === 400) {
167154
await historyResponse.body?.cancel().catch(() => {})
168155
logger.info(
169-
`Gmail rejected history cursor ${config.historyId} (${status}); resyncing through search`,
170-
{ requestId }
156+
`Gmail rejected history cursor ${config.historyId} (${status}); resyncing through search`
171157
)
172-
return resyncAfterExpiredHistory(accessToken, config, requestId, logger)
158+
return resyncAfterExpiredHistory(accessToken, config, logger)
173159
}
174160

175161
const errorData = await historyResponse.json().catch(() => ({}))
176162
logger.warn('Gmail history API error:', {
177-
requestId,
178163
status,
179164
statusText: historyResponse.statusText,
180165
error: errorData,
@@ -186,8 +171,8 @@ async function fetchNewEmails(
186171
)
187172
}
188173

189-
logger.info(`Falling back to search API after history API error ${status}`, { requestId })
190-
return searchEmails(accessToken, config, requestId, logger)
174+
logger.info(`Falling back to search API after history API error ${status}`)
175+
return searchEmails(accessToken, config, logger)
191176
}
192177

193178
const historyData = await historyResponse.json()
@@ -215,14 +200,14 @@ async function fetchNewEmails(
215200

216201
const sortedIds = [...messageIds].sort().reverse()
217202
const idsToFetch = sortedIds.slice(0, config.maxEmailsPerPoll || 25)
218-
logger.info(`Processing ${idsToFetch.length} emails from history API`, { requestId })
203+
logger.info(`Processing ${idsToFetch.length} emails from history API`)
219204

220205
const emailResults = await Promise.allSettled(
221206
idsToFetch.map((messageId) => getEmailDetails(accessToken, messageId))
222207
)
223208
const rejected = emailResults.filter((r) => r.status === 'rejected')
224209
if (rejected.length > 0) {
225-
logger.warn(`Failed to fetch ${rejected.length} email details`, { requestId })
210+
logger.warn(`Failed to fetch ${rejected.length} email details`)
226211
}
227212
emails = emailResults
228213
.filter(
@@ -232,13 +217,13 @@ async function fetchNewEmails(
232217

233218
emails = filterEmailsByLabels(emails, config)
234219
} else {
235-
return searchEmails(accessToken, config, requestId, logger)
220+
return searchEmails(accessToken, config, logger)
236221
}
237222

238223
return { emails, latestHistoryId }
239224
} catch (error) {
240225
const errorMessage = getErrorMessage(error, 'Unknown error')
241-
logger.error('Error fetching new emails:', errorMessage, { requestId })
226+
logger.error('Error fetching new emails:', errorMessage)
242227
throw error
243228
}
244229
}
@@ -283,12 +268,7 @@ function buildGmailSearchQuery(config: {
283268
return baseQuery
284269
}
285270

286-
async function searchEmails(
287-
accessToken: string,
288-
config: GmailWebhookConfig,
289-
requestId: string,
290-
logger: Logger
291-
) {
271+
async function searchEmails(accessToken: string, config: GmailWebhookConfig, logger: Logger) {
292272
try {
293273
const baseQuery = buildGmailSearchQuery(config)
294274
let timeConstraint = ''
@@ -324,7 +304,6 @@ async function searchEmails(
324304
if (!searchResponse.ok) {
325305
const errorData = await searchResponse.json()
326306
logger.error('Gmail search API error:', {
327-
requestId,
328307
status: searchResponse.status,
329308
statusText: searchResponse.statusText,
330309
query,
@@ -338,24 +317,23 @@ async function searchEmails(
338317
const searchData = await searchResponse.json()
339318

340319
if (!searchData.messages || !searchData.messages.length) {
341-
logger.info(`No emails found matching query: ${query}`, { requestId })
320+
logger.info(`No emails found matching query: ${query}`)
342321
return { emails: [], latestHistoryId: config.historyId }
343322
}
344323

345324
const idsToFetch = searchData.messages.slice(0, config.maxEmailsPerPoll || 25)
346325
let latestHistoryId = config.historyId
347326

348327
logger.info(
349-
`Processing ${idsToFetch.length} emails from search API (total matches: ${searchData.messages.length})`,
350-
{ requestId }
328+
`Processing ${idsToFetch.length} emails from search API (total matches: ${searchData.messages.length})`
351329
)
352330

353331
const emailResults = await Promise.allSettled(
354332
idsToFetch.map((message: { id: string }) => getEmailDetails(accessToken, message.id))
355333
)
356334
const rejected = emailResults.filter((r) => r.status === 'rejected')
357335
if (rejected.length > 0) {
358-
logger.warn(`Failed to fetch ${rejected.length} email details`, { requestId })
336+
logger.warn(`Failed to fetch ${rejected.length} email details`)
359337
}
360338
const emails = emailResults
361339
.filter(
@@ -370,7 +348,7 @@ async function searchEmails(
370348
return { emails, latestHistoryId }
371349
} catch (error) {
372350
const errorMessage = getErrorMessage(error, 'Unknown error')
373-
logger.error('Error searching emails:', errorMessage, { requestId })
351+
logger.error('Error searching emails:', errorMessage)
374352
throw error
375353
}
376354
}
@@ -383,40 +361,36 @@ async function searchEmails(
383361
async function resyncAfterExpiredHistory(
384362
accessToken: string,
385363
config: GmailWebhookConfig,
386-
requestId: string,
387364
logger: Logger
388365
) {
389-
const searchResult = await searchEmails(accessToken, config, requestId, logger)
366+
const searchResult = await searchEmails(accessToken, config, logger)
390367
const candidate =
391368
searchResult.latestHistoryId !== config.historyId
392369
? searchResult.latestHistoryId
393-
: await getGmailProfileHistoryId(accessToken, requestId, logger)
370+
: await getGmailProfileHistoryId(accessToken, logger)
394371
const latestHistoryId = candidate && candidate !== config.historyId ? candidate : undefined
395372
if (!latestHistoryId) {
396-
logger.info('No replacement Gmail history cursor yet; polling through search', { requestId })
373+
logger.info('No replacement Gmail history cursor yet; polling through search')
397374
}
398375
return { emails: searchResult.emails, latestHistoryId }
399376
}
400377

401378
async function getGmailProfileHistoryId(
402379
accessToken: string,
403-
requestId: string,
404380
logger: Logger
405381
): Promise<string | null> {
406382
try {
407383
const response = await fetch('https://gmail.googleapis.com/gmail/v1/users/me/profile', {
408384
headers: { Authorization: `Bearer ${accessToken}` },
409385
})
410386
if (!response.ok) {
411-
logger.warn(`Failed to fetch Gmail profile for fresh historyId: ${response.status}`, {
412-
requestId,
413-
})
387+
logger.warn(`Failed to fetch Gmail profile for fresh historyId: ${response.status}`)
414388
return null
415389
}
416390
const profile = await response.json()
417391
return (profile.historyId as string | undefined) ?? null
418392
} catch (error) {
419-
logger.warn('Error fetching Gmail profile:', error, { requestId })
393+
logger.warn('Error fetching Gmail profile:', error)
420394
return null
421395
}
422396
}
@@ -524,9 +498,7 @@ async function processEmails(
524498
const attachmentInfo = extractAttachmentInfo(payload)
525499
attachments = await downloadAttachments(email.id, attachmentInfo, accessToken)
526500
} catch (error) {
527-
logger.error(`Error downloading attachments for email ${email.id}:`, error, {
528-
requestId,
529-
})
501+
logger.error(`Error downloading attachments for email ${email.id}:`, error)
530502
}
531503
}
532504

@@ -563,8 +535,7 @@ async function processEmails(
563535
logger.error(
564536
`Failed to process webhook for email ${email.id}:`,
565537
result.statusCode,
566-
result.error,
567-
{ requestId }
538+
result.error
568539
)
569540
throw new Error(`Webhook processing failed (${result.statusCode}): ${result.error}`)
570541
}
@@ -577,14 +548,12 @@ async function processEmails(
577548
}
578549
)
579550

580-
logger.info(`Successfully processed email ${email.id} for webhook ${webhookData.id}`, {
581-
requestId,
582-
})
551+
logger.info(`Successfully processed email ${email.id} for webhook ${webhookData.id}`)
583552
processedCount++
584553
} catch (error) {
585554
if (error instanceof PollAdmissionRefusedError && processedCount === 0) throw error
586555
const errorMessage = getErrorMessage(error, 'Unknown error')
587-
logger.error(`Error processing email ${email.id}:`, errorMessage, { requestId })
556+
logger.error(`Error processing email ${email.id}:`, errorMessage)
588557
failedCount++
589558
}
590559
}

‎apps/sim/lib/webhooks/polling/google-calendar.ts‎

Lines changed: 10 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -119,7 +119,7 @@ export const googleCalendarPollingHandler: PollingProviderHandler = {
119119
logger
120120
)
121121
await markWebhookSuccess(webhookId, logger)
122-
logger.info(`First poll for webhook ${webhookId}, seeded timestamp`, { requestId })
122+
logger.info(`First poll for webhook ${webhookId}, seeded timestamp`)
123123
return 'success'
124124
}
125125

@@ -128,11 +128,11 @@ export const googleCalendarPollingHandler: PollingProviderHandler = {
128128

129129
if (!events.length) {
130130
await markWebhookSuccess(webhookId, logger)
131-
logger.info(`No changed events for webhook ${webhookId}`, { requestId })
131+
logger.info(`No changed events for webhook ${webhookId}`)
132132
return 'success'
133133
}
134134

135-
logger.info(`Found ${events.length} changed events for webhook ${webhookId}`, { requestId })
135+
logger.info(`Found ${events.length} changed events for webhook ${webhookId}`)
136136

137137
const { processedCount, failedCount, latestUpdated } = await processEvents(
138138
events,
@@ -162,23 +162,20 @@ export const googleCalendarPollingHandler: PollingProviderHandler = {
162162

163163
if (failedCount > 0 && processedCount === 0) {
164164
await markWebhookFailed(webhookId, logger)
165-
logger.warn(`All ${failedCount} events failed to process for webhook ${webhookId}`, {
166-
requestId,
167-
})
165+
logger.warn(`All ${failedCount} events failed to process for webhook ${webhookId}`)
168166
return 'failure'
169167
}
170168

171169
await markWebhookSuccess(webhookId, logger)
172170
logger.info(
173-
`Successfully processed ${processedCount} events for webhook ${webhookId}${failedCount > 0 ? ` (${failedCount} failed)` : ''}`,
174-
{ requestId }
171+
`Successfully processed ${processedCount} events for webhook ${webhookId}${failedCount > 0 ? ` (${failedCount} failed)` : ''}`
175172
)
176173
return 'success'
177174
} catch (error) {
178175
if (error instanceof PollAdmissionRefusedError) {
179-
return skipAdmissionRefusedPoll(logger, requestId, webhookId)
176+
return skipAdmissionRefusedPoll(logger, webhookId)
180177
}
181-
logger.error(`Error processing Google Calendar webhook ${webhookId}:`, error, { requestId })
178+
logger.error(`Error processing Google Calendar webhook ${webhookId}:`, error)
182179
await markWebhookFailed(webhookId, logger)
183180
return 'failure'
184181
}
@@ -341,8 +338,7 @@ async function processEvents(
341338
logger.error(
342339
`Failed to process webhook for event ${event.id}:`,
343340
result.statusCode,
344-
result.error,
345-
{ requestId }
341+
result.error
346342
)
347343
throw new Error(`Webhook processing failed (${result.statusCode}): ${result.error}`)
348344
}
@@ -351,14 +347,12 @@ async function processEvents(
351347
}
352348
)
353349

354-
logger.info(`Successfully processed event ${event.id} for webhook ${webhookData.id}`, {
355-
requestId,
356-
})
350+
logger.info(`Successfully processed event ${event.id} for webhook ${webhookData.id}`)
357351
processedCount++
358352
} catch (error) {
359353
if (error instanceof PollAdmissionRefusedError && processedCount === 0) throw error
360354
const errorMessage = getErrorMessage(error, 'Unknown error')
361-
logger.error(`Error processing event ${event.id}:`, errorMessage, { requestId })
355+
logger.error(`Error processing event ${event.id}:`, errorMessage)
362356
failedCount++
363357
}
364358
}

0 commit comments

Comments
 (0)