diff --git a/slack-mcp/server/router.ts b/slack-mcp/server/router.ts index a936a74a..dd40e473 100644 --- a/slack-mcp/server/router.ts +++ b/slack-mcp/server/router.ts @@ -90,6 +90,7 @@ app.get("/temp-files/:id", async (c) => { // ============================================================================ app.post("/slack/events/:connectionId", async (c) => { + const receivedAt = Date.now(); const connectionId = c.req.param("connectionId"); const traceId = HyperDXLogger.generateTraceId(); const rawBody = await c.req.text(); @@ -149,7 +150,7 @@ app.post("/slack/events/:connectionId", async (c) => { ); } - const { verified, payload } = await logger.measure( + const verified = await logger.measure( () => verifySlackRequest( rawBody, @@ -161,7 +162,7 @@ app.post("/slack/events/:connectionId", async (c) => { { connectionId, trace_id: traceId }, ); - if (!verified || !payload) { + if (!verified) { logger.error("Invalid signature", { connectionId, trace_id: traceId, @@ -173,19 +174,22 @@ app.post("/slack/events/:connectionId", async (c) => { const botUserId = connectionConfig.botUserId ?? botUserIdCache.get(connectionId); - if (shouldIgnoreEvent(payload, botUserId)) { + if (shouldIgnoreEvent(parsedPayload, botUserId)) { return c.json({ ok: true }); } - processConnectionEventAsync(payload, connectionConfig, traceId).catch( - (error) => { - logger.error("Event processing failed", { - connectionId, - trace_id: traceId, - error: String(error), - }); - }, - ); + processConnectionEventAsync( + parsedPayload, + connectionConfig, + traceId, + receivedAt, + ).catch((error) => { + logger.error("Event processing failed", { + connectionId, + trace_id: traceId, + error: String(error), + }); + }); return c.json({ ok: true }); }); @@ -258,6 +262,7 @@ async function processConnectionEventAsync( payload: SlackWebhookPayload, connectionConfig: SlackConnectionConfig, traceId: string, + receivedAt: number, ): Promise { if (!payload.event) { return; @@ -314,6 +319,8 @@ async function processConnectionEventAsync( }, teamId: payload.team_id, apiAppId: payload.api_app_id, + traceId, + receivedAt, }, teamConfig, connectionId, diff --git a/slack-mcp/server/slack/handlers/eventHandler.ts b/slack-mcp/server/slack/handlers/eventHandler.ts index d37e9531..96606926 100644 --- a/slack-mcp/server/slack/handlers/eventHandler.ts +++ b/slack-mcp/server/slack/handlers/eventHandler.ts @@ -328,6 +328,37 @@ async function processAttachedFiles( }; } +/** + * Per-handler timing metadata threaded in from the webhook router. + * + * `receivedAt` is the wall-clock ms the webhook hit the pod; `traceId` + * matches the router-side log entries. Used only for perf-debug logs + * — see `logPerfStep`. Optional so unit tests don't have to fake it. + */ +interface HandlerMeta { + traceId?: string; + receivedAt?: number; +} + +/** + * Emit a debug-level perf marker tagged with the cumulative pod time + * since the webhook was received. Only flows to HyperDX when LOG_LEVEL=debug + * (`logger.debug` is dropped below the configured min level — see logger.ts). + */ +function logPerfStep( + step: string, + meta: HandlerMeta, + extras: Record = {}, +): void { + if (!meta.receivedAt) return; + logger.debug(`perf:${step}`, { + step, + trace_id: meta.traceId, + duration_ms: Date.now() - meta.receivedAt, + ...extras, + }); +} + /** * Append transcribed audio + text-file contents to the user's original text * so they flow through the trigger payload's `text` field. The lazy import of @@ -370,7 +401,8 @@ export async function handleSlackEvent( teamConfig: SlackTeamConfig, connectionId: string, ): Promise { - const { type, payload } = context; + const { type, payload, traceId, receivedAt } = context; + const meta: HandlerMeta = { traceId, receivedAt }; const triggerOnly = teamConfig.responseConfig?.triggerOnly ?? false; @@ -383,22 +415,32 @@ export async function handleSlackEvent( // answered twice (once by the LLM, once by the trigger subscriber). if (triggerOnly) { await publishAppMention(connectionId, payload); + logPerfStep("trigger_published", meta, { + mode: "triggerOnly", + event_type: type, + }); } else { await handleAppMention( payload as SlackAppMentionEvent, teamConfig, connectionId, + meta, ); } break; case "message": if (triggerOnly) { await publishMessageReceived(connectionId, payload); + logPerfStep("trigger_published", meta, { + mode: "triggerOnly", + event_type: type, + }); } else { await handleMessage( payload as SlackMessageEvent, teamConfig, connectionId, + meta, ); } break; @@ -429,6 +471,7 @@ async function handleAppMention( event: SlackAppMentionEvent, teamConfig: SlackTeamConfig, connectionId: string, + meta: HandlerMeta = {}, ): Promise { const { channel, text, ts, thread_ts, files } = event; @@ -442,6 +485,11 @@ async function handleAppMention( const thinkingMsg = showThinking ? await sendThinkingMessage(channel, replyTo) : null; + logPerfStep("thinking_sent", meta, { + channel, + has_thinking: Boolean(thinkingMsg?.ts), + event_type: "app_mention", + }); const { textFiles, transcriptions, audioWithoutWhisper } = await processAttachedFiles(files); @@ -463,6 +511,10 @@ async function handleAppMention( { ...event, text: fullText }, { thinking_message_ts: thinkingMsg?.ts }, ); + logPerfStep("trigger_published", meta, { + channel, + event_type: "app_mention", + }); } /** @@ -477,6 +529,7 @@ async function handleMessage( event: SlackMessageEvent, teamConfig: SlackTeamConfig, connectionId: string, + meta: HandlerMeta = {}, ): Promise { const { channel, text, thread_ts, channel_type } = event; const isDM = channel_type === "im" || channel?.startsWith("D"); @@ -504,11 +557,11 @@ async function handleMessage( // (see handleDirectMessage). Channel messages only reach this branch when // thread_ts is set AND the bot has participated in that thread. if (isDM && thread_ts) { - await handleThreadReply(event, thread_ts, teamConfig, connectionId); + await handleThreadReply(event, thread_ts, teamConfig, connectionId, meta); } else if (isDM) { - await handleDirectMessage(event, teamConfig, connectionId); + await handleDirectMessage(event, teamConfig, connectionId, meta); } else if (thread_ts) { - await handleThreadReply(event, thread_ts, teamConfig, connectionId); + await handleThreadReply(event, thread_ts, teamConfig, connectionId, meta); } } @@ -523,6 +576,7 @@ async function handleDirectMessage( event: SlackMessageEvent, teamConfig: SlackTeamConfig, connectionId: string, + meta: HandlerMeta = {}, ): Promise { const { channel, text, ts, files } = event; @@ -536,6 +590,11 @@ async function handleDirectMessage( const thinkingMsg = showThinking ? await sendThinkingMessage(channel, replyTo) : null; + logPerfStep("thinking_sent", meta, { + channel, + has_thinking: Boolean(thinkingMsg?.ts), + event_type: "direct_message", + }); const { textFiles, transcriptions, audioWithoutWhisper } = await processAttachedFiles(files); @@ -557,6 +616,10 @@ async function handleDirectMessage( { ...event, text: fullText }, { thinking_message_ts: thinkingMsg?.ts }, ); + logPerfStep("trigger_published", meta, { + channel, + event_type: "direct_message", + }); } /** @@ -567,6 +630,7 @@ async function handleThreadReply( threadTs: string, teamConfig: SlackTeamConfig, connectionId: string, + meta: HandlerMeta = {}, ): Promise { const { channel, text, files } = event; @@ -579,6 +643,11 @@ async function handleThreadReply( const thinkingMsg = showThinking ? await sendThinkingMessage(channel, threadTs) : null; + logPerfStep("thinking_sent", meta, { + channel, + has_thinking: Boolean(thinkingMsg?.ts), + event_type: "thread_reply", + }); const { textFiles, transcriptions, audioWithoutWhisper } = await processAttachedFiles(files); @@ -600,6 +669,10 @@ async function handleThreadReply( { ...event, text: fullText }, { thinking_message_ts: thinkingMsg?.ts }, ); + logPerfStep("trigger_published", meta, { + channel, + event_type: "thread_reply", + }); } // ============================================================================ diff --git a/slack-mcp/server/slack/handlers/types.ts b/slack-mcp/server/slack/handlers/types.ts index 0b0e015d..5c1d9cc1 100644 --- a/slack-mcp/server/slack/handlers/types.ts +++ b/slack-mcp/server/slack/handlers/types.ts @@ -27,13 +27,20 @@ export const SLACK_EVENT_TYPES = { } as const; /** - * Context for a Slack event + * Context for a Slack event. + * + * `traceId` and `receivedAt` are populated by the webhook router and used + * by handlers to emit perf-timing logs (`logger.debug("perf:…")`) so we + * can measure pod overhead from webhook receipt to "Pensando..." being + * sent and to the trigger being published. */ export interface SlackEventContext { type: string; payload: SlackEvent & { original_text?: string }; teamId?: string; apiAppId?: string; + traceId?: string; + receivedAt?: number; } /** diff --git a/slack-mcp/server/webhook.ts b/slack-mcp/server/webhook.ts index d6a1b029..562368e5 100644 --- a/slack-mcp/server/webhook.ts +++ b/slack-mcp/server/webhook.ts @@ -8,17 +8,22 @@ import type { SlackWebhookPayload } from "./lib/types.ts"; /** - * Verify a Slack webhook request using the signing secret + * Verify a Slack webhook request using the signing secret. + * + * Returns only a boolean — the caller is responsible for parsing the body + * once (typically before calling this) and reusing that parsed payload. + * We deliberately do NOT JSON.parse the rawBody here: it was already + * parsed in the router, and parsing twice on every webhook is wasteful. */ export async function verifySlackRequest( rawBody: string, signature: string | null, timestamp: string | null, signingSecret: string, -): Promise<{ verified: boolean; payload: SlackWebhookPayload | null }> { +): Promise { if (!signature || !timestamp) { console.error("[Slack Webhook] Missing signature or timestamp"); - return { verified: false, payload: null }; + return false; } // Check timestamp to prevent replay attacks (5 minutes tolerance) @@ -26,7 +31,7 @@ export async function verifySlackRequest( const now = Math.floor(Date.now() / 1000); if (Math.abs(now - requestTimestamp) > 300) { console.error("[Slack Webhook] Request timestamp too old"); - return { verified: false, payload: null }; + return false; } // Construct the signature base string @@ -60,7 +65,7 @@ export async function verifySlackRequest( // Constant-time comparison if (computedSignature.length !== signature.length) { - return { verified: false, payload: null }; + return false; } let result = 0; @@ -72,16 +77,9 @@ export async function verifySlackRequest( if (!verified) { console.error("[Slack Webhook] Signature verification failed"); - return { verified: false, payload: null }; } - try { - const payload = JSON.parse(rawBody) as SlackWebhookPayload; - return { verified: true, payload }; - } catch { - console.error("[Slack Webhook] Failed to parse payload as JSON"); - return { verified: false, payload: null }; - } + return verified; } /**