Skip to content

Commit 2f51561

Browse files
committed
fix(logs): log the webhook poll id and emitted event id under their own names
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 d22623b commit 2f51561

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)