Improve Copilot error handling and logging

Author: Sg312

apps/sim/app/workspace/[workspaceId]/home/hooks/use-chat.ts

@@ -228,6 +228,7 @@ const RECONNECT_TAIL_ERROR =
 const MAX_RECONNECT_ATTEMPTS = 10
 const RECONNECT_BASE_DELAY_MS = 1000
 const RECONNECT_MAX_DELAY_MS = 30_000
+const RECONNECT_EXHAUSTED_RECHECK_MS = 30_000
 const STREAM_BATCH_FETCH_TIMEOUT_MS = 10_000
 const STREAM_CHAT_ID_RESOLVE_TIMEOUT_MS = 10_000
 const CHAT_HISTORY_RECOVERY_TIMEOUT_MS = 10_000
@@ -1470,6 +1471,10 @@ export function useChat(
     () => {}
   )
   const recoveringQueuedSendHandoffRef = useRef<ActiveQueuedSendHandoffRecovery | null>(null)
+  const recoverActiveStreamRef = useRef<
+    (reason: 'pageshow' | 'visible' | 'online' | 'exhausted_recheck') => Promise<void>
+  >(async () => {})
+  const reconnectExhaustedRecheckTimerRef = useRef<ReturnType<typeof setTimeout> | null>(null)
 
   const abortControllerRef = useRef<AbortController | null>(null)
   const detachedChatResolutionControllersRef = useRef<Set<AbortController>>(new Set())
@@ -3242,7 +3247,29 @@ export function useChat(
         maxAttempts: MAX_RECONNECT_ATTEMPTS,
       })
       if (streamGenRef.current === gen) {
+        /**
+         * Never give up silently: surface the failure so the pane shows why
+         * the live stream stopped instead of a torn-down transcript. Callers
+         * own the finalize on a false return (every call site finalizes with
+         * error: true), which refetches the persisted transcript; if the
+         * server turn is still running, the visibility/online recovery path
+         * re-attaches on the next pageshow/visible/online event.
+         */
         setIsReconnecting(false)
+        setError(RECONNECT_TAIL_ERROR)
+        /**
+         * The tab may stay visible (no pageshow/visible/online event will ever
+         * fire) while the server turn keeps running detached. One bounded
+         * recheck re-enters recovery once the transient network condition has
+         * had time to clear; recovery itself no-ops when nothing is active.
+         */
+        if (reconnectExhaustedRecheckTimerRef.current) {
+          clearTimeout(reconnectExhaustedRecheckTimerRef.current)
+        }
+        reconnectExhaustedRecheckTimerRef.current = setTimeout(() => {
+          reconnectExhaustedRecheckTimerRef.current = null
+          void recoverActiveStreamRef.current('exhausted_recheck')
+        }, RECONNECT_EXHAUSTED_RECHECK_MS)
       }
       return false
     },
@@ -3251,7 +3278,7 @@ export function useChat(
   retryReconnectRef.current = retryReconnect
 
   const recoverActiveStreamFromRedis = useCallback(
-    async (reason: 'pageshow' | 'visible' | 'online'): Promise<void> => {
+    async (reason: 'pageshow' | 'visible' | 'online' | 'exhausted_recheck'): Promise<void> => {
       const startingChatId = chatIdRef.current
       const startingSelectedChatId = selectedChatIdRef.current
       const chatId = startingChatId ?? startingSelectedChatId
@@ -3386,6 +3413,7 @@ export function useChat(
     },
     [getActiveStreamIdForChat, queryClient, resumeOrFinalize, setTransportReconnecting]
   )
+  recoverActiveStreamRef.current = recoverActiveStreamFromRedis
 
   useEffect(() => {
     if (typeof window === 'undefined' || typeof document === 'undefined') return
@@ -3417,6 +3445,10 @@ export function useChat(
       document.removeEventListener('visibilitychange', handleVisibilityChange)
       window.removeEventListener('pageshow', handlePageShow)
       window.removeEventListener('online', handleOnline)
+      if (reconnectExhaustedRecheckTimerRef.current) {
+        clearTimeout(reconnectExhaustedRecheckTimerRef.current)
+        reconnectExhaustedRecheckTimerRef.current = null
+      }
     }
   }, [recoverActiveStreamFromRedis])
 

apps/sim/instrumentation-node.ts

@@ -83,6 +83,23 @@ function normalizeOtlpMetricsUrl(url: string): string {
   }
 }
 
+// Logs counterpart to `normalizeOtlpMetricsUrl` — same parsed-pathname
+// handling, targeting the /v1/logs signal path.
+function normalizeOtlpLogsUrl(url: string): string {
+  if (!url) return url
+  try {
+    const u = new URL(url)
+    const path = u.pathname.replace(/\/$/, '')
+    if (path.endsWith('/v1/logs')) return url
+    u.pathname = path.endsWith('/v1/traces')
+      ? path.replace(/\/v1\/traces$/, '/v1/logs')
+      : `${path}/v1/logs`
+    return u.toString()
+  } catch {
+    return url
+  }
+}
+
 // deployment.environment in the GO value space (dev | staging | prod) without
 // any new infra env var. Every deployed Sim tier already gets
 // APPCONFIG_ENVIRONMENT = the infra env name (dev | staging | production), so we
@@ -177,6 +194,8 @@ async function initializeOpenTelemetry() {
     const { OTLPTraceExporter } = await import('@opentelemetry/exporter-trace-otlp-http')
     const { OTLPMetricExporter } = await import('@opentelemetry/exporter-metrics-otlp-http')
     const { PeriodicExportingMetricReader } = await import('@opentelemetry/sdk-metrics')
+    const { OTLPLogExporter } = await import('@opentelemetry/exporter-logs-otlp-http')
+    const { BatchLogRecordProcessor } = await import('@opentelemetry/sdk-logs')
     const { BatchSpanProcessor } = await import('@opentelemetry/sdk-trace-node')
     const { TraceIdRatioBasedSampler, SamplingDecision } = await import(
       '@opentelemetry/sdk-trace-base'
@@ -271,6 +290,19 @@ async function initializeOpenTelemetry() {
       exportIntervalMillis: 60000,
     })
 
+    // Logs share the trace endpoint and headers as well (signal path
+    // /v1/logs). Every @sim/logger line fans out through the global Logs API
+    // (see packages/logger), which the NodeSDK wires to this processor — the
+    // stdout JSON lines continue to CloudWatch unchanged.
+    const logRecordProcessor = new BatchLogRecordProcessor(
+      new OTLPLogExporter({
+        url: normalizeOtlpLogsUrl(telemetryConfig.endpoint),
+        headers: otlpHeaders,
+        timeoutMillis: Math.min(telemetryConfig.batchSettings.exportTimeoutMillis, 10000),
+        keepAlive: false,
+      })
+    )
+
     // Must be unique per process: replicas sharing one instance id collapse
     // into a single Prometheus series, so their independent cumulative
     // counters interleave and corrupt rate()/increase(). The slug keeps Sim
@@ -320,6 +352,7 @@ async function initializeOpenTelemetry() {
       spanProcessors,
       sampler,
       metricReader,
+      logRecordProcessors: [logRecordProcessor],
     })
 
     sdk.start()

apps/sim/lib/copilot/application/error.ts

@@ -1,13 +1,25 @@
+import { trace } from '@opentelemetry/api'
+import { toError } from '@sim/utils/errors'
 import { asOrchestrationError } from '@/lib/core/orchestration/types'
 
 export const COPILOT_APPLICATION_SYSTEM_ERROR_MESSAGE =
   'The operation failed due to a system error. Please retry.'
 
-/** Projects only caller-actionable application failures into Copilot-visible content. */
+/**
+ * Projects only caller-actionable application failures into Copilot-visible
+ * content. Whenever the real cause is swallowed by the generic fallback, it is
+ * recorded on the active span first — otherwise these failures are
+ * undiagnosable from telemetry (the cause otherwise lives only in stdout logs
+ * that do not ship anywhere queryable).
+ */
 export function messageForCopilotApplicationError(
   error: unknown,
   fallback = COPILOT_APPLICATION_SYSTEM_ERROR_MESSAGE
 ): string {
   const classified = asOrchestrationError(error)
-  return classified && classified.code !== 'internal' ? classified.message : fallback
+  if (classified && classified.code !== 'internal') {
+    return classified.message
+  }
+  trace.getActiveSpan()?.recordException(toError(error))
+  return fallback
 }

apps/sim/lib/copilot/tools/client/browser-tool-execution.test.ts

@@ -436,3 +436,38 @@ describe('executeBrowserToolOnClient', () => {
     })
   })
 })
+
+describe('pre-dispatch drops still resolve the waiter', () => {
+  beforeEach(() => {
+    vi.clearAllMocks()
+    mockReportCompletion.mockResolvedValue(undefined)
+  })
+
+  it('reports an error confirmation for a stale event instead of hanging the turn', async () => {
+    const staleTs = new Date(Date.now() - 10 * 60 * 1000).toISOString()
+    executeBrowserToolOnClient('stale-call-1', 'browser_list_sessions', {}, 'chat-scope-1', staleTs)
+    await sleep(0)
+
+    expect(mockExecuteBrowserTool).not.toHaveBeenCalled()
+    expect(mockReportCompletion).toHaveBeenCalledWith(
+      'stale-call-1',
+      'error',
+      expect.stringContaining('too late'),
+      expect.objectContaining({ staleEvent: true })
+    )
+  })
+
+  it('reports an error confirmation when no chat scope exists', async () => {
+    useBrowserSessionStore.setState({ activeScopeId: null })
+    executeBrowserToolOnClient('no-scope-1', 'browser_list_sessions', {}, undefined)
+    await sleep(0)
+
+    expect(mockExecuteBrowserTool).not.toHaveBeenCalled()
+    expect(mockReportCompletion).toHaveBeenCalledWith(
+      'no-scope-1',
+      'error',
+      expect.stringContaining('no active browser session'),
+      expect.anything()
+    )
+  })
+})

apps/sim/lib/copilot/tools/client/browser-tool-execution.ts

@@ -175,15 +175,45 @@ export function executeBrowserToolOnClient(
 ): void {
   if (!scopeId) {
     logger.error('Cannot execute browser tool without a chat scope', { toolCallId, toolName })
+    // Tell the waiter, or the turn hangs forever on a tool that never ran.
+    const message = 'This browser action could not run: no active browser session for this chat.'
+    void reportClientToolCompletion(toolCallId, ASYNC_TOOL_CONFIRMATION_STATUS.error, message, {
+      error: message,
+    }).catch((reportErr) => {
+      logger.error('Failed to report missing-scope browser tool error', {
+        toolCallId,
+        error: toError(reportErr).message,
+      })
+    })
     return
   }
   if (hasAlreadyExecuted(toolCallId)) {
+    // Same-page re-delivery: the original dispatch is in flight (or done) and
+    // owns the result. Reporting here would race it — the server claims each
+    // resume exactly once, so an error now would discard the genuine result.
     logger.info('Skipping already-executed browser tool (replay)', { toolCallId, toolName })
     return
   }
   const age = eventAgeMs(eventTs)
   if (age !== null && age > MAX_EVENT_AGE_MS) {
     logger.info('Skipping stale browser tool event', { toolCallId, toolName, age })
+    // Usually a replay of an action that already ran and resumed in a previous
+    // page lifetime — the server claims each resume exactly once, so this
+    // duplicate confirmation is simply discarded. When it is NOT a replay
+    // (the event was delivered late, e.g. a backgrounded tab with throttled
+    // timers), this error unblocks the turn instead of leaving it hanging
+    // forever on a tool that will never execute.
+    const message =
+      'This browser action was delivered too late to run safely. Ask again to retry it.'
+    void reportClientToolCompletion(toolCallId, ASYNC_TOOL_CONFIRMATION_STATUS.error, message, {
+      error: message,
+      staleEvent: true,
+    }).catch((reportErr) => {
+      logger.error('Failed to report stale browser tool error', {
+        toolCallId,
+        error: toError(reportErr).message,
+      })
+    })
     return
   }
   markExecuted(toolCallId)

apps/sim/lib/copilot/tools/client/completion.ts

@@ -2,6 +2,7 @@ import { createLogger } from '@sim/logger'
 import { toError } from '@sim/utils/errors'
 import { sleep } from '@sim/utils/helpers'
 import { isRecordLike } from '@sim/utils/object'
+import { backoffWithJitter } from '@sim/utils/retry'
 import type {
   AsyncCompletionData,
   AsyncConfirmationStatus,
@@ -48,7 +49,13 @@ export async function reportClientToolCompletion(
   const bodySize = new Blob([body]).size
   let lastError: Error | null = null
 
-  for (let attempt = 1; attempt <= 2; attempt++) {
+  // A lost confirmation strands the server-side waiter forever (the turn shows
+  // the tool as running indefinitely), so ride out multi-second network blips:
+  // 5 attempts with jittered exponential backoff (~15s total) instead of a
+  // sub-second give-up. The confirm endpoint claims each resume exactly once,
+  // so duplicate deliveries from retries are discarded server-side.
+  const maxAttempts = 5
+  for (let attempt = 1; attempt <= maxAttempts; attempt++) {
     try {
       const response = await send(body)
       if (response.ok) return
@@ -78,8 +85,8 @@ export async function reportClientToolCompletion(
       lastError = toError(error)
     }
 
-    if (attempt < 2) {
-      await sleep(250)
+    if (attempt < maxAttempts) {
+      await sleep(backoffWithJitter(attempt, null))
     }
   }
 

apps/sim/lib/copilot/tools/client/run-tool-execution.test.ts

@@ -57,6 +57,11 @@ const setCurrentExecutionId = vi.fn()
 const getCurrentExecutionId = vi.fn()
 const getWorkflowExecution = vi.fn(() => ({ isExecuting: false }))
 
+// Neutralize the confirm-retry backoff so exhaustion tests stay fast.
+vi.mock('@sim/utils/retry', () => ({
+  backoffWithJitter: () => 0,
+}))
+
 vi.mock('@/app/workspace/[workspaceId]/w/[workflowId]/utils/workflow-execution-utils', () => ({
   executeWorkflowWithFullLogging,
 }))
@@ -265,6 +270,9 @@ describe('run tool execution cancellation', () => {
       })
       .mockResolvedValueOnce({ ok: false, status: 503 })
       .mockResolvedValueOnce({ ok: false, status: 503 })
+      .mockResolvedValueOnce({ ok: false, status: 503 })
+      .mockResolvedValueOnce({ ok: false, status: 503 })
+      .mockResolvedValueOnce({ ok: false, status: 503 })
       .mockResolvedValue({ ok: true })
     vi.stubGlobal('fetch', fetchMock)
 
@@ -273,7 +281,7 @@ describe('run tool execution cancellation', () => {
       async: true,
     })
 
-    await vi.waitFor(() => expect(fetchMock).toHaveBeenCalledTimes(3))
+    await vi.waitFor(() => expect(fetchMock).toHaveBeenCalledTimes(6))
     await vi.waitFor(() => expect(isRunToolActiveForId('tool-recover-async')).toBe(false))
     loadExecutionPointer.mockResolvedValueOnce({
       workflowId: 'wf-1',
@@ -283,10 +291,10 @@ describe('run tool execution cancellation', () => {
 
     await expect(bindRunToolToExecution('tool-recover-async', 'wf-1')).resolves.toBe(true)
 
-    expect(fetchMock).toHaveBeenCalledTimes(4)
-    expect(fetchMock.mock.calls[3][0]).toBe('/api/copilot/confirm')
-    expect(fetchMock.mock.calls[3][1]?.body).toContain('"status":"background"')
-    expect(fetchMock.mock.calls[3][1]?.body).toContain('"executionId":"exec-recover-async"')
+    expect(fetchMock).toHaveBeenCalledTimes(7)
+    expect(fetchMock.mock.calls[6][0]).toBe('/api/copilot/confirm')
+    expect(fetchMock.mock.calls[6][1]?.body).toContain('"status":"background"')
+    expect(fetchMock.mock.calls[6][1]?.body).toContain('"executionId":"exec-recover-async"')
     expect(
       fetchMock.mock.calls.filter(([url]) => url === '/api/workflows/wf-1/execute')
     ).toHaveLength(1)

apps/sim/lib/copilot/tools/handlers/function-execute.test.ts

@@ -247,7 +247,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
     )
 
     expect(mockExecuteTool).toHaveBeenCalledWith(
-      'run_function',
+      'function_execute',
       expect.objectContaining({
         envVars: { API_KEY: 'secret-value' },
         secretScope: 'selected',
@@ -272,7 +272,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
 
     expect(mockMaterializeCopilotCodeSecrets).not.toHaveBeenCalled()
     expect(mockExecuteTool).toHaveBeenCalledWith(
-      'run_function',
+      'function_execute',
       expect.objectContaining({ envVars: {}, secretScope: 'selected', mountedSecrets: [] }),
       { resolvedSecretTraceRegistry: expect.any(ResolvedSecretTraceRegistry) }
     )
@@ -305,7 +305,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
         requestedNames: names,
       })
       expect(mockExecuteTool).toHaveBeenCalledWith(
-        'run_function',
+        'function_execute',
         expect.objectContaining({ code, language, mountedSecrets: names }),
         { resolvedSecretTraceRegistry: expect.any(ResolvedSecretTraceRegistry) }
       )
@@ -332,7 +332,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
       requestedNames: ['CLI_TOKEN'],
     })
     expect(mockExecuteTool).toHaveBeenCalledWith(
-      'run_function',
+      'function_execute',
       expect.objectContaining({ code, language: 'shell', mountedSecrets: ['CLI_TOKEN'] }),
       {
         resolvedSecretTraceRegistry: expect.any(ResolvedSecretTraceRegistry),
@@ -353,7 +353,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
     )
 
     expect(mockExecuteTool).toHaveBeenCalledWith(
-      'run_function',
+      'function_execute',
       expect.objectContaining({
         _context: expect.not.objectContaining({ sandboxProfile: expect.anything() }),
       }),
@@ -373,7 +373,7 @@ describe('executeFunctionExecute trace-secret provenance', () => {
 
     expect(mockHasWorkspaceSandboxAccess).toHaveBeenCalledWith('ws_1')
     expect(mockExecuteTool).toHaveBeenCalledWith(
-      'run_function',
+      'function_execute',
       expect.objectContaining({ sandboxId: 'sandbox-1' }),
       expect.objectContaining({ internalSandboxProfile: 'mothership' })
     )