Skip to content

DEBUGGING_PLAYBOOK.md

Latest commit

 

History

History
495 lines (362 loc) · 36.4 KB

DEBUGGING_PLAYBOOK.md

File metadata and controls

495 lines (362 loc) · 36.4 KB
Raw

Debugging Playbook

Reference for querying structured logs across all Open-Inspect services.

All services emit flat JSON lines with a common envelope. Use the msg field (stable event identifier) for filtering, and correlation fields (trace_id, session_id, message_id) for joining across service boundaries.

Common Envelope

Every log line includes:

Field Type Description
level string debug | info | warn | error
service string web | control-plane | modal-infra | slack-bot
component string Sub-area (e.g. router, session-do, bridge)
msg string Stable event identifier for querying
ts number Epoch milliseconds

Correlation Fields

Include whichever are available at the call site:

Field Scope Generated by
trace_id Cross-service Router / slack-bot edge
request_id Single HTTP hop Router
session_id Session lifetime Control-plane on create
message_id Single prompt run Control-plane on enqueue
sandbox_id Sandbox lifetime Sandbox backend on create/restore
opencode_session_id OpenCode process Supervisor on ensure

Canonical Naming + Boundary Conversion

Canonical correlation keys are snake_case everywhere outside local in-memory variables:

  • Logs: trace_id, request_id, session_id, sandbox_id
  • HTTP headers: x-trace-id, x-request-id, x-session-id, x-sandbox-id
  • Provider/client correlation objects: correlation.trace_id, correlation.request_id, etc.

If a module uses camelCase internally, convert once at the boundary and keep the rest of the path canonical. Do not mix traceId/requestId and trace_id/request_id within the same boundary.

Joining across services

A prompt run flows through the client, control plane, selected sandbox backend, and sandbox runtime. For Slack with Modal, the path is: slack-bot -> control-plane -> modal-infra -> sandbox.

  1. Slack-bot generates trace_id and sends it as x-trace-id header.
  2. Control-plane router propagates trace_id into Durable Object and provider calls.
  3. Provider-specific clients or endpoints bind the same trace to sandbox startup logs where supported.

Web API correlation

The Next.js API layer accepts a valid inbound x-trace-id or generates one at the /api edge. It also generates a fresh hop-local x-request-id for the web response and logs. When the web service calls the control-plane, it forwards only x-trace-id; the control-plane still generates its own per-hop request_id.

To trace a full request: filter by trace_id across all three services, or narrow by session_id + message_id for a specific prompt run.

Error Shape

All services use the same error fields:

Field Description
error_type Error class name (e.g. TimeoutError)
error_message Human-readable message
error_stack Stack trace (error level only, truncated)
error_code Application error code (when applicable)

Outcome Convention

Wide events use outcome to indicate result:

  • success — completed normally
  • error — failed with an error
  • rejected — denied before processing (auth, validation)
  • timeout — timed out
  • cancelled — cancelled by caller

Event Catalog

Control Plane (service: "control-plane")

Router (component: "router")

Event Level Key Fields Description
http.request info, error http_method, http_path, http_status, duration_ms, outcome One per incoming HTTP request

Image Builds (component: "image-builds:*" / "router:image-builds")

One image_build.* vocabulary covers both scope kinds; events carry scope_kind (repo | environment) and scope_id (lowercase owner/name or an environment id).

Event Level Key Fields Description
image_build.build_triggered info build_id, scope_kind, scope_id, repositories_fingerprint, trace_id, request_id Build registered and accepted by the active provider
image_build.build_complete_received info build_id, scope_kind, scope_id, provider, provider_session_id, runtime_version, trace_id, request_id Runtime success was accepted for Queue finalization
image_build.build_failed info build_id, scope_kind, scope_id, provider, error_message, provider_session_id, trace_id, request_id Runtime reported a failed build
image_build.callback_auth_failed warn build_id, provider, provider_session_id, trace_id, request_id Build callback had invalid auth or session binding
image_build.finalization_job_invalid error queue_message_id, attempts Malformed Queue command was rejected
image_build.finalization_error error build_id, queue_message_id, attempts, error Queue finalization threw; retries exhaust to the DLQ
image_build.scheduler_tick info phase counters, provider, trace_id, request_id One provider-neutral maintenance scan completed
image_build.scheduler_finalization_republish_failed warn error Finalization-recovery scan was skipped
image_build.scheduler_finalization_republish_row_failed warn build_id, error One recovery command could not be published; the scan continued
image_build.scheduler_stale_failed warn error Stale-build marking phase was skipped
image_build.scheduler_session_cleanup_phase_failed warn error Provider-session cleanup scan was skipped
image_build.scheduler_session_cleanup_failed warn build_id, provider, provider_session_id, error One terminal build-session cleanup failed; the scan continued
image_build.scheduler_reconciliation_phase_failed warn error Scope-reconciliation phase was skipped
image_build.scheduler_scope_failed warn scope_kind, scope_id, error One scope could not be reconciled; the scan continued
image_build.scheduler_artifact_cleanup_failed warn error Provider-artifact/history cleanup phase was skipped
image_build.scheduler_source_control_unavailable warn error Rebuild reconciliation was disabled because source control was unavailable
image_build.trigger_mark_failed_error warn build_id, error, trace_id, request_id Build trigger failed and the workflow could not mark the build failed
image_build.build_failed_error error build_id, error, trace_id, request_id Failure callback could not mark the build failed
image_build.trigger_error error scope_kind, scope_id, error, trace_id, request_id Manual or scheduled build trigger failed
image_build.late_artifact_recorded info build_id, provider, provider_image_id, trace_id, request_id Artifact reported after the row left building; recorded for the reaper
image_build.save_hook_trigger info scope_kind, scope_id, result, build_id, trace_id, request_id Entity save (env save, repo toggle-on) kicked a prebuild
image_build.save_hook_trigger_failed warn scope_kind, scope_id, error, trace_id, request_id Save-hook prebuild kick failed (the entity save itself succeeded)
image_build.secrets_change_superseded info scope_kind, scope_id, superseded, trace_id, request_id Secret change retired the scope's live images before the rebuild
image_build.toggle info scope_kind, scope_id, enabled, trace_id, request_id Repo prebuild toggle written
image_build.cleanup / image_build.stale_marked info deleted, reaped_superseded / count, trace_id, request_id Scheduler-driven maintenance results

Session Durable Object (component: "session-do")

Event Level Key Fields Description
do.request info http_method, http_path, http_status, duration_ms, outcome One per DO internal route call
ws.connect info, warn ws_type (sandbox|client), outcome, reject_reason, sandbox_id, participant_id, duration_ms WebSocket lifecycle
prompt.enqueue info message_id, source, author_id, user_id, model, content_length, has_attachments, queue_position Message queued
prompt.dispatch info message_id, outcome, reason, model, has_sandbox_ws, queue_wait_ms Message sent to sandbox
prompt.complete info, warn message_id, outcome, total_duration_ms, processing_duration_ms, queue_duration_ms Prompt run finished
callback.complete_delivery info, error session_id, message_id, source, outcome, duration_ms, attempts, retries, http_status, reject_reason Completion callback delivery result
callback.started_delivery info, error session_id, message_id, outcome, duration_ms, attempts, retries, http_status, reject_reason Linear start-callback delivery result

Lifecycle Manager (component: "lifecycle-manager")

Dashboards and alerts must migrate sandbox.spawned and sandbox.spawn_failed to sandbox.spawn outcomes, and sandbox.restored to sandbox.restore outcomes.

Event Level Key Fields Description
sandbox.spawn info, error outcome, duration_ms, sandbox_id, expected_sandbox_id, provider_object_id, repo_owner, repo_name, error Spawn completed
sandbox.restore info, error outcome, duration_ms, snapshot_image_id, sandbox_id, provider_object_id, repo_owner, repo_name, error Restore completed
sandbox.snapshot info reason, provider_object_id Snapshot attempt started
sandbox.snapshot_saved info image_id, reason Snapshot saved
sandbox.heartbeat_stale warn last_heartbeat_ms, threshold_ms Heartbeat missed
sandbox.timeout info last_activity, timeout_ms Inactivity timeout reached

Provider Clients

Event Level Key Fields Description
modal.request info endpoint, session_id, sandbox_id, http_status, duration_ms, outcome One per control-plane -> Modal call
vercel_sandbox.request info endpoint, session_id, http_status, duration_ms, outcome One per control-plane -> Vercel API call
daytona.create_sandbox info sandbox_id, target, duration_ms, outcome Daytona sandbox create/restore API result

Modal Infra (service: "modal-infra")

API (component: "api")

Event Level Key Fields Description
modal.http_request info http_method, http_path, http_status, duration_ms, outcome, endpoint_name, trace_id, request_id One per Modal endpoint call

Sandbox Manager (component: "sandbox")

Event Level Key Fields Description
sandbox.create info sandbox_id, modal_object_id, repo_owner, repo_name, duration_ms, outcome Sandbox creation
sandbox.snapshot info sandbox_id, snapshot_id, image_id, duration_ms, outcome Snapshot taken
sandbox.restore info sandbox_id, modal_object_id, snapshot_image_id, duration_ms, outcome Sandbox restored

Supervisor (component: "supervisor")

Event Level Key Fields Description
sandbox.startup info repo_owner, repo_name, restored_from_snapshot, git_sync_success, opencode_ready, duration_ms One per sandbox boot
supervisor.start info repo_owner, repo_name Supervisor process started
supervisor.error error exc Unhandled supervisor error
supervisor.fatal error message Fatal error, sandbox will exit

Bridge (component: "bridge")

Event Level Key Fields Description
bridge.connect info outcome WebSocket connected to control-plane
bridge.disconnect info, warn reason, ws_close_code, connection_duration_seconds, total_connected_duration_seconds, connection_count, reconnect_count, reconnect_attempt_count WebSocket disconnected with lifetime aggregates
bridge.reconnect info attempt, reconnect_attempt_count, delay_s Reconnection attempt
bridge.run_complete info outcome, connection_count, reconnect_count, reconnect_attempt_count, total_connected_duration_seconds Bridge process exited with aggregate connection stats
prompt.start info message_id, model Prompt processing started
prompt.run info message_id, model, outcome, duration_ms Prompt processing completed (wide)
prompt.error error message_id, exc Prompt processing failed

Git Operations (component: "bridge" / "supervisor")

Event Level Key Fields Description
git.clone_start info repo_owner, repo_name, authenticated Clone started
git.clone_complete info repo_path Clone succeeded
git.clone_error error stderr, exit_code Clone failed
git.sync_complete info head_sha Repo sync complete
git.push_start info branch_name, repo_owner, repo_name, token_source Push started
git.push_complete info branch_name Push succeeded
git.push_error warn, error reason or exc, branch_name Push failed

OpenCode (component: "bridge")

Event Level Key Fields Description
opencode.session.ensure info opencode_session_id, action Session created or loaded
opencode.start info — OpenCode process started
opencode.ready info — OpenCode health check OK
opencode.crash error exit_code, restart_count OpenCode process died

Slack Bot (service: "slack-bot")

Handler (component: "handler")

Event Level Key Fields Description
http.request info, warn trace_id, http_method, http_path, http_status, event_type, outcome, duration_ms One per /events or /interactions
slack.dm.received info trace_id, user, channel Direct message received
slack.event.duplicate debug trace_id, event_id Deduplicated Slack event
thread_session.stale warn trace_id, session_id, channel, thread_ts Stale session in thread
control_plane.create_session info, error trace_id, repo_owner, repo_name, model, session_id, http_status, duration_ms Session creation call
control_plane.send_prompt info, error trace_id, session_id, message_id, http_status, duration_ms, outcome Prompt submission call
slack.app_home error user_id, outcome, slack_error App Home publish failed
kv.get / kv.put / kv.delete error, warn key_prefix, contextual IDs KV storage operation failed

Attachments (component: "attachments")

Event Level Key Fields Description
slack.attachment.untrusted_url warn trace_id, file_id, file_mode Non-Slack or remote file rejected
slack.attachment.download_failed warn trace_id, file_id, http_status Slack file download returned an error
slack.attachment.download_error warn trace_id, file_id, error Slack file download threw or timed out
slack.attachment.size_rejected warn trace_id, file_id, size_bytes Download response failed the byte cap
slack.attachment.too_large warn trace_id, file_id, size_bytes Slack metadata exceeded the byte cap
slack.attachment.upload_failed warn trace_id, session_id, file_id, http_status or error Session attachment upload was rejected
slack.attachment.upload_error warn trace_id, session_id, file_id, error Session attachment upload threw
slack.attachment.notify_failed warn trace_id, channel, slack_error Could not post the dropped-image warning

Callback (component: "callback")

Event Level Key Fields Description
http.request info, warn trace_id, http_method, http_path, http_status, session_id, message_id, delivery_id, outcome, duration_ms Completion callback validated/enqueued
slack.completion.enqueue error trace_id, session_id, message_id, delivery_id, error Queue send failed
slack.completion.job_invalid error queue_message_id, issues Invalid queued payload discarded
slack.completion.unhandled error delivery_id, session_id, message_id, error Unexpected consumer error
callback.complete info, error trace_id, session_id, message_id, channel, agent_success, tool_call_count, artifact_count, media_artifact_count, duration_ms Queued completion delivery processed

Completion Media (component: "completion-media")

Event Level Key Fields Description
slack.media.fetch warn trace_id, session_id, message_id, artifact_id, artifact_type, http_status, outcome Protected media retrieval failed
slack.media.get_upload_url warn trace_id, session_id, message_id, artifact_id, slack_error, outcome Slack upload ticket request failed
slack.media.upload_bytes warn trace_id, session_id, message_id, artifact_id, slack_error, outcome Byte upload failed
slack.media.complete_upload warn trace_id, session_id, message_id, slack_file_ids, slack_error, outcome Batch file sharing failed
slack.media.delivery info trace_id, session_id, message_id, artifact_id, size_bytes, uploaded, failed, omitted, outcome Media attached or skipped

Extractor (component: "extractor")

Event Level Key Fields Description
control_plane.fetch_events info, error trace_id, session_id, message_id, event_count, tool_call_count, duration_ms Fetch events for a message

Repos (component: "repos")

Event Level Key Fields Description
control_plane.fetch_repos info, warn, error trace_id, repo_count, source, duration_ms Fetch available repositories

Classifier (component: "classifier")

Event Level Key Fields Description
classifier.classify error trace_id, method, channel_id, outcome LLM classification failed

Debugging Scenarios

"Why did an attached Slack image not reach the agent?"

Follow the request by trace_id through file discovery, download, session upload, and prompt submission.

# 1. Could the bot recover and trust the Slack file metadata?
service="slack-bot" trace_id="<TRACE_ID>" msg="slack.attachment.file_lookup_failed"
service="slack-bot" trace_id="<TRACE_ID>" msg="slack.attachment.untrusted_url"

# 2. Did the Slack-hosted download fail or exceed 10 MiB?
service="slack-bot" component="attachments" trace_id="<TRACE_ID>" msg="slack.attachment.*"

# 3. Did the control plane accept the session attachment before the prompt?
service="slack-bot" component="attachments" trace_id="<TRACE_ID>" msg="slack.attachment.upload*"
service="slack-bot" component="handler" trace_id="<TRACE_ID>" msg="control_plane.send_prompt"

slack.attachment.file_lookup_failed is emitted by handler or target-selection, depending on whether lookup failed during initial handling or after repository clarification. An HTTP failure while downloading often means the bot lacks files:read or was not reinstalled after the scope was added. Size events enforce 10 MiB per image; the bot forwards at most six images per message. If a text-plus-image request loses images, the text still runs and the bot attempts an in-thread warning.

"What happened to message X?"

Trace a prompt from submission to completion across all services.

# 1. Find the prompt in control-plane
service="control-plane" msg="prompt.enqueue" message_id="<MSG_ID>"

# 2. Was it dispatched to a sandbox?
service="control-plane" msg="prompt.dispatch" message_id="<MSG_ID>"

# 3. Did the sandbox process it?
service="modal-infra" msg="prompt.run" message_id="<MSG_ID>"

# 4. Did it complete?
service="control-plane" msg="prompt.complete" message_id="<MSG_ID>"

Key fields to check:

  • prompt.dispatch → outcome and reason (was a sandbox connected?)
  • prompt.run → outcome and duration_ms (did it succeed? how long?)
  • prompt.complete → total_duration_ms (end-to-end time)

"Why is the sandbox not connecting?"

# 1. Did the sandbox spawn?
service="control-plane" msg="sandbox.spawn" session_id="<SESSION_ID>"
service="control-plane" msg="sandbox.spawned" session_id="<SESSION_ID>"

# 2. Did the provider create it? Modal example:
service="modal-infra" msg="sandbox.create" sandbox_id="<SANDBOX_ID>"

# 3. Did startup succeed?
service="modal-infra" msg="sandbox.startup" sandbox_id="<SANDBOX_ID>"

# 4. Did the bridge connect?
service="modal-infra" msg="bridge.connect" sandbox_id="<SANDBOX_ID>"

# 5. Did the control-plane accept the WebSocket?
service="control-plane" msg="ws.connect" ws_type="sandbox" session_id="<SESSION_ID>"

Check outcome and reject_reason on ws.connect. Common reasons:

  • sandbox_id_mismatch — sandbox was replaced (stale sandbox reconnecting)
  • token_mismatch — auth token doesn't match
  • sandbox_stopped — session already terminated

"Why did a sandbox spawn fail?"

service="control-plane" msg="sandbox.spawn_failed" session_id="<SESSION_ID>"

Check the error_type and error_message. Then look at the selected provider side. Modal example:

service="modal-infra" msg="sandbox.create" outcome="error"

If the circuit breaker opened:

service="control-plane" component="lifecycle-manager" msg="Circuit breaker open"

"Why did snapshot restore fail?"

# Control-plane side
service="control-plane" msg="sandbox.restore" session_id="<SESSION_ID>"

# Provider side. Modal example:
service="modal-infra" msg="sandbox.restore" outcome="error"

"Slack message isn't getting a response"

Trace from the Slack bot edge inward:

# 1. Did the slack-bot receive the event?
service="slack-bot" msg="http.request" http_path="/events"

# 2. Was it a duplicate?
service="slack-bot" msg="slack.event.duplicate"

# 3. Did classification succeed?
service="slack-bot" msg="classifier.classify"

# 4. Was a session created?
service="slack-bot" msg="control_plane.create_session" trace_id="<TRACE_ID>"

# 5. Was the prompt sent?
service="slack-bot" msg="control_plane.send_prompt" trace_id="<TRACE_ID>"

# 6. Did the callback arrive?
service="slack-bot" msg="callback.complete" trace_id="<TRACE_ID>"

Use the trace_id from step 1 to follow the request into the control-plane and sandbox backend logs.

"Errors by type across all services"

level="error" | group by error_type, service, msg | count

"Slow sandbox spawns"

service="control-plane" msg="sandbox.spawned" | where duration_ms > 30000

Or on the provider side. Modal example:

service="modal-infra" msg="sandbox.create" | where duration_ms > 30000

"Prompt failures by model"

service="control-plane" msg="prompt.complete" outcome!="success"
  | group by model, outcome | count

"Slack bot → control-plane latency"

service="slack-bot" msg="control_plane.create_session"
  | stats avg(duration_ms), p95(duration_ms), max(duration_ms)

service="slack-bot" msg="control_plane.send_prompt"
  | stats avg(duration_ms), p95(duration_ms), max(duration_ms)

"OpenCode crashes"

service="modal-infra" msg="opencode.crash"
  | group by exit_code, restart_count | count

Redaction Rules

The following must never appear in logs:

  • Authorization headers
  • HMAC tokens derived from MODAL_API_SECRET (control plane → Modal), and sig1 service signatures derived from the per-service SERVICE_AUTH_SECRETs
  • GitHub App private keys or installation tokens
  • GitHub OAuth access/refresh tokens
  • Sandbox auth tokens

Body content is omitted unless explicitly whitelisted and truncated.

Log Level Guidelines

Level Use for
debug High-frequency internals (heartbeats, per-token events, cache)
info Wide events for normal operations
warn Degraded but recoverable (stale sessions, fallbacks, retries)
error Failures requiring investigation

Set LOG_LEVEL environment variable per service to control verbosity. Default is info. Use debug in staging, info or warn in production.