How to Monitor with Logs

Sortie emits structured logs to stderr. The default format is key=value text; an optional json mode produces newline-delimited JSON for log aggregation systems. Logs are always on. No configuration is needed. They are the first place to look when something goes wrong.

Prerequisites

• Sortie installed and running

That’s it. Logs work with zero configuration.

Understand the log format

Sortie supports two log formats: text (default) and JSON.

Text format (default)

Sortie uses slog.TextHandler. Every line is a flat key=value record:

time=2026-03-26T14:30:01.305+00:00 level=INFO msg="tick completed" candidates=2 dispatched=2 ... running=2 retrying=0 ...

The tick completed line carries more fields than shown above and below throughout this guide. Dispatch-rule breakdown (dispatched_by_rule, dispatched_by_default, dispatched_by_fallback) and blocker-hold counters (held_by_blockers, blockers_unresolved, blockers_not_read, blockers_incomplete) also appear on every line. This guide calls out only the fields relevant to each example.

JSON format

When --log-format json is active (or logging.format: json in the workflow file), each line is a self-contained JSON object:

{"time":"2026-03-26T14:30:01.305+00:00","level":"INFO","msg":"tick completed","candidates":2,"dispatched":2,"dispatched_by_rule":0,"dispatched_by_default":2,"dispatched_by_fallback":0,"running":2,"retrying":0,"held_by_blockers":0,"blockers_unresolved":0,"blockers_not_read":0,"blockers_incomplete":0}

JSON format is designed for log aggregation systems (Loki, Datadog, CloudWatch, ELK) that ingest newline-delimited JSON. See switch to JSON format below.

Common fields

Three structural fields appear on every line in both formats:

• time: UTC timestamp
• level: INFO, WARN, ERROR, or DEBUG
• msg: human-readable message

Context fields appear on all issue-related lines, added automatically by the logging subsystem:

• issue_id: tracker-internal ID (e.g., abc123)
• issue_identifier: human-readable ticket key (e.g., MT-649)
• session_id: agent session identifier (present once a session starts)

The one rule you need to remember: WARN means Sortie is handling it. ERROR means you need to.

WARN lines indicate automatic recovery: a retry is scheduled, a transient failure is being worked around. ERROR lines mean Sortie gave up and needs operator attention. If you grep for nothing else, grep for level=ERROR.

Control log verbosity

By default Sortie logs at INFO level. Use the --log-level flag to change it:

# See debug-level detail: poll decisions, state transitions, adapter calls, tool calls
sortie --log-level debug ./WORKFLOW.md

# Reduce noise in production: only warnings and errors
sortie --log-level warn ./WORKFLOW.md

Accepted values: debug, info, warn, error. The flag applies before the workflow file is loaded, so startup messages reflect the requested level immediately.

Alternatively, set the level in the workflow file:

logging:
  level: debug

The CLI flag takes precedence when both are set. Changing logging.level in the workflow file requires a restart. It is not picked up by dynamic reload.

Key log messages to watch

Here are the log messages that matter most, grouped by lifecycle phase.

Poll cycle

time=2026-03-26T14:30:01.305+00:00 level=INFO msg="tick completed" candidates=2 dispatched=2 ... running=2 retrying=0 ...

This is the poll summary. It tells you how many issues were found (candidates), how many were dispatched this tick (dispatched), how many agents are active (running), and how many issues are awaiting retry (retrying). When candidates=0 dispatched=0, Sortie is idle.

Sortie logs the summary at INFO after the first completed tick following startup, and again whenever any of its counters differs from the previous summary. A tick that repeats the previous summary logs at DEBUG, so an idle Sortie is quiet at the default level. A tick that ends on a failed preflight or a failed tracker fetch logs an error instead and does not change what the next summary is compared with. Run with --log-level debug to see every tick, or watch sortie_poll_cycles_total in Prometheus metrics for a count of ticks that does not depend on the log level.

Dispatch and agent settings

time=2026-03-26T14:30:02.100+00:00 level=INFO msg="issue dispatched" issue_id=abc123 issue_identifier=MT-649 agent_kind=claude-code rule_name=bugfix model=claude-sonnet-4-5 effort=medium

This is the line to look for when you want to know which model an issue was given. agent_kind and rule_name are the selection Sortie made for the issue, and model and effort are the settings the session starts with: the agent kind’s top-level block with the matching dispatch rule’s block laid over it.

An empty rule_name means no rule routed the issue. An empty model or effort means nothing is configured, so the runtime uses its own default.

These are the configured values. The model the runtime reports running can differ, and is on the session view of the dashboard and in the state API.

A retry logs the same four fields, beside the attempt number:

time=2026-03-26T14:35:42.150+00:00 level=INFO msg="retried issue dispatched" issue_id=abc123 issue_identifier=MT-649 attempt=2 agent_kind=claude-code rule_name=bugfix model=claude-sonnet-4-5 effort=medium

Sortie resolves the settings again at the start of every attempt, so an edit to WORKFLOW.md reaches a retry. If model or effort differs from the first line, the workflow changed in between.

A retry keeps the dispatch rule its issue was first routed to. If that rule is gone, or no longer carries a settings block for the agent kind, the retry still runs and says so once:

time=2026-03-26T14:35:42.140+00:00 level=INFO msg="rule settings no longer present, attempt runs on the kind's top-level settings" issue_id=abc123 issue_identifier=MT-649 rule_name=bugfix agent_kind=claude-code

Nothing is failing. The attempt runs on the top-level block, so the retried issue dispatched line that follows may show a different model than the first attempt. If you removed the block on purpose, there is nothing to do. If not, restore it; the next attempt picks it up.

When the settings an attempt resolves fail a check that is an error, the attempt starts no session. A retry is rescheduled with backoff and keeps its claim and its session:

time=2026-03-26T14:35:42.160+00:00 level=ERROR msg="retry agent settings refused" issue_id=abc123 issue_identifier=MT-649 error="dispatch preflight failed: claude-code.permission_mode is set to a value that lets the agent stop and ask for approval, and an unattended run has no one to answer; only \"bypassPermissions\" is supported" rule_name=bugfix agent_kind=claude-code check=claude-code.permission_mode.interactive diagnostic="claude-code.permission_mode is set to a value that lets the agent stop and ask for approval, and an unattended run has no one to answer; only \"bypassPermissions\" is supported" attempt=3 delay_ms=40000

check names the first check that failed and diagnostic is its message; error lists every failed check. sortie validate and the per-tick preflight apply the same checks, but a retry never passes through that preflight, so a reload that introduced the bad block surfaces here first. Fix the agent_kind settings the check names, in the rule rule_name or in the top-level block. The next retry resolves the corrected settings; attempt and delay_ms say which try that is and how long Sortie waits for it.

A first dispatch gets the same check under the message agent settings refused, without attempt, delay_ms, or the issue fields. The per-tick preflight runs immediately before and normally stops a bad block first, so you will mostly see it as dispatch preflight failed. When it does fire, Sortie skips that issue for the tick, counts the dispatch as an error in sortie_dispatches_total, and tries again on the next poll.

Workspace preparation

time=2026-03-26T14:30:02.150+00:00 level=INFO msg="workspace prepared" issue_id=abc123 issue_identifier=MT-649 workspace=/tmp/sortie_workspaces/MT-649

Sortie created (or reused) a workspace directory and ran any configured hooks. The workspace field shows the absolute path.

MCP configuration

time=2026-03-26T14:30:02.310+00:00 level=INFO msg="mcp config written" issue_id=abc123 issue_identifier=MT-649 mcp_config_path=/tmp/sortie_workspaces/MT-649/.sortie/mcp.json agent_kind=codex operator_mcp_config_path=/srv/sortie/mcp-servers.json

Sortie wrote the session’s MCP configuration into the workspace. agent_kind is the agent kind this session was dispatched with, and operator_mcp_config_path is the mcp_config value resolved from that kind’s own block, empty when the block sets none. Read the two together when a session reaches servers you did not expect: they name the block the servers came from.

The file is written for every kind, but not every session can reach it.

Agent session

time=2026-03-26T14:30:03.150+00:00 level=INFO msg="agent credential verified" issue_id=abc123 issue_identifier=MT-649 duration_ms=270
time=2026-03-26T14:30:03.420+00:00 level=INFO msg="agent session started" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001
time=2026-03-26T14:30:03.500+00:00 level=INFO msg="turn started" issue_id=abc123 issue_identifier=MT-649 turn_number=1 max_turns=5
time=2026-03-26T14:31:45.800+00:00 level=INFO msg="turn completed" issue_id=abc123 issue_identifier=MT-649 turn_number=1 max_turns=5

agent credential verified is credential verification, a short-lived session Sortie opens for itself before a worker attempt, on every agent kind, to prove the credential actually works before spending a real turn on it; duration_ms is how long that check took. When Sortie already proved the same agent setup within the last 15 minutes, the attempt logs agent credential verification skipped with a proven_at time instead, and starts its working session without the check. A WARN line credential verification did not reach the model, retrying with the full agent context means the runtime rejected a switch that drops its instructions and tools; the check repeats once with the full context and its result stands. Each issue then gets a working session with one or more turns. turn_number and max_turns show where the agent is in its work budget.

When the session’s kind delivers no tool channel, one more line lands between agent session started and turn started. Sortie says so once, on the first turn, and leaves the tool advertisement out of the prompt:

time=2026-03-26T14:30:03.420+00:00 level=INFO msg="agent session started" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001
time=2026-03-26T14:30:03.425+00:00 level=INFO msg="no tool execution channel for this session, withholding tool advertisement" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 agent_kind=mock
time=2026-03-26T14:30:03.500+00:00 level=INFO msg="turn started" issue_id=abc123 issue_identifier=MT-649 turn_number=1 max_turns=5

This is the line to look for when an agent never mentions Sortie’s tools. Nothing is failing: the agent was deliberately not told about tools it could not call. The built-in mock kind and a custom adapter that declares no tool channel produce it, and so does a session whose gap was already known when the session started; for that, look for the declared tool server gap for session line below. See delivery by agent kind.

A session on an SSH host reaches Sortie’s tools through a reverse forward, and the tool server logs its own outcome with component=tool-relay. These records carry no issue fields, so match them to a session by time:

time=2026-03-26T14:30:03.380+00:00 level=INFO msg="delivered tool server to session" component=tool-relay
time=2026-03-26T14:30:03.380+00:00 level=WARN msg="declared tool server gap for session" component=tool-relay reason=forward_refused

delivered tool server to session means the runtime connected to the tool server. declared tool server gap for session means it did not, and reason says why: the host refused the forward, the runtime accepts no HTTP server, or no runtime connected in time. The session continues without Sortie’s tools and emits a notification, this session started with a declared capability gap in: tool servers. The no tool execution channel line above follows only when the gap was known before the first prompt: a tool server that did not start or a refused forward on any kind, and for codex and agent-client-protocol also a runtime without HTTP support or one that never connected, since their session start waits for the connection. A kind that starts one process per turn learns no_connection only when its first turn completes, after the prompt went out with the tool advertisement, so that case logs the gap and emits the notification but no no tool execution channel line. The reasons are listed in when a session runs without the tools; the fix for a refused forward is in let remote agents use Sortie’s tools.

Further WARN lines belong to tool delivery. withheld tool servers from remote session lists, in servers, the mcp_config servers an SSH session left out because they run as a local program. tool server env value left on the command line names a server and a variable whose value Codex could not receive through its environment; the value is never logged.

An agent runtime can also change its own session id after the session has already started. Sortie logs it the moment it happens:

time=2026-03-26T14:31:46.010+00:00 level=INFO msg="agent session id accepted" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 previous_session_id=session-abc-001 accepted_session_id=session-abc-001b

The session_id field on this line, like on every other line for the run, still names the id from agent session started: it identifies the run in the logs and never changes, so the recipes below keep working against it. accepted_session_id is the new value, and it is what the run’s tracker comment, its operator notifications, and a continuation retry’s resume attempt carry from this point on.

Copilot CLI’s adapter is one example: it captures the session id from each turn’s own result and reports it back as that turn’s session id, so a runtime-side change can reach Sortie this way.

On the agent-client-protocol kind, the runtime’s handshake decides how the session’s token usage is read. Sortie logs the name and version the runtime reported once the session id is known:

time=2026-03-26T14:30:03.430+00:00 level=INFO msg="agent implementation" component=clientprotocol-adapter session_id=session-abc-001 name=gemini-cli version=0.12.0

When agent.command names one runtime and the handshake reports another, Sortie measures the session as the runtime that answered and warns, on the credential check and on the working session alike:

time=2026-03-26T14:30:03.300+00:00 level=WARN msg="agent runtime differs from its configured command" component=clientprotocol-adapter configured_runtime=gemini-cli handshake_runtime=acme-agent usage_declaration=default

configured_runtime is the runtime the command line names, handshake_runtime the name the runtime gave, and usage_declaration the measurement source the session runs under: the handshake’s runtime when Sortie ships a source for it, default otherwise. A session under default reads the protocol’s standard usage fields, and its figure is a lower bound. A command that names no runtime, such as a wrapper script, logs no warning: the handshake alone picks the source. See token accounting on that kind.

An agent kind that attaches no source that counts tokens has the usage arrival none. When its runtime sends a usage figure anyway, Sortie discards the figure and logs it once per run, on the first occurrence:

time=2026-03-26T14:32:10.100+00:00 level=WARN msg="token usage discarded: agent kind attaches no source that counts tokens" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-003 agent_kind=acme

Every built-in agent kind attaches a source that counts tokens, so none of them produces this line. Seeing it means a custom adapter is running that sends usage figures without attaching a source that counts them.

What happens to the figure is covered under usage reporting by agent kind: nothing changes for this session’s numbers, because they already read as a kind that reports nothing.

The action is on the adapter, not on your workflow configuration: stop it sending figures, or attach a source that counts tokens if it genuinely can report usage.

Tool calls

Each finished tool call logs at DEBUG, so these lines appear only under --log-level debug. At the default level a session’s output stays out of the log; use the sortie_tool_calls_total counter in Prometheus metrics to count calls and failures at any level.

time=2026-03-26T14:31:12.300+00:00 level=DEBUG msg="tool call completed" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 tool=tracker_api duration_ms=145 outcome=success
time=2026-03-26T14:31:13.100+00:00 level=DEBUG msg="tool call completed" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 tool=tracker_api duration_ms=89 outcome=error tool_error="tracker_auth_error: invalid API key"

Every tool invocation gets a line with the tool name, wall-clock duration, and outcome. The tool_error field appears only when outcome=error. It holds the first line of the tool’s error, cut to 200 characters, because a tool’s output can run to thousands of lines.

Worker exit

time=2026-03-26T14:35:20.100+00:00 level=INFO msg="worker exiting" issue_id=abc123 issue_identifier=MT-649 exit_kind=normal turns_completed=5

The worker finished its loop. exit_kind=normal means the agent completed its turns without error.

Workspace sweep

time=2026-03-26T14:30:02.100+00:00 level=INFO msg="sweep: removed expired workspace" workspace_key=MT-512 last_activity=2026-02-14T09:12:44Z age_days=40
time=2026-03-26T14:30:02.140+00:00 level=INFO msg="sweep: pass complete" candidates=7 excluded_running=1 excluded_retry=0 excluded_reaction=1 removed_terminal=2 removed_age=1 retained_in_window=1 retained_no_activity=1 retained_not_evaluated=0 failed=0 retention_days=30 age_pass=on tracker_read=ok

sweep: pass complete is emitted once per sweep pass, whether or not anything was removed. That is the point of it: a bound that removes nothing looks identical to a bound that is switched off, so the record reports why every candidate survived rather than only what it deleted.

Read it as three questions.

Is the age bound on at all? age_pass and retention_days answer that. age_pass=on means the window shown in retention_days was evaluated. age_pass=off means retention_days is unset or below the floor of 30, so no age evaluation ran. age_pass=unavailable means the pass could not run: the persistence store was absent, or the run-history query failed.

Did the tracker answer this pass? tracker_read=ok or tracker_read=failed. On a failed read nothing is removed as terminal, but the age pass still evaluates, because it reads no tracker state.

Why did each candidate survive? The excluded_* and retained_* counters, one reason each:

• excluded_running: a worker is processing that issue. Not a fault.
• excluded_retry: a retry is scheduled for that issue. Not a fault.
• excluded_reaction: a pending reaction whose kind carries an expiry pins the workspace. It resolves itself when the watch window ends, 30 minutes by default and 24 hours for ci_failure. A reaction with a standing escalation has no window and pins the workspace until the escalation ends, so a workspace of an issue that waits on a person stays. Not a fault.
• retained_in_window: the workspace’s latest recorded activity is newer than retention_days. Not a fault; the bound is working as configured.
• retained_no_activity: no run completion and no recorded push exist for that key, so there is no anchor to measure age from and the workspace is kept. This is the reason operators are least likely to guess. It covers a run that never completed and any directory Sortie did not create.
• retained_not_evaluated: the age pass did not evaluate these candidates. Read age_pass for the reason.
• failed: a removal or a path resolution failed, under either mechanism. Look for the adjacent WARN line naming the key.

The nine counters after candidates partition the candidate set, so they always sum to candidates. In the pass above, 1 + 0 + 1 + 2 + 1 + 1 + 1 + 0 + 0 = 7. removed_terminal counts the other mechanism, workspaces removed because the tracker reported their issues in a terminal state; it runs first on the same pass, so removed_age never counts a workspace the terminal check would have taken.

Each age removal also emits sweep: removed expired workspace, carrying the workspace_key that was removed, last_activity (the RFC3339 anchor that was measured), and age_days. Configure the window itself through workspace.retention_days.

Handoff transition

time=2026-03-26T14:35:21.500+00:00 level=INFO msg="handoff transition succeeded, releasing claim" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 handoff_state="In Review"

Sortie transitioned the issue to the configured handoff_state in the tracker and released its claim. Sortie is done with the issue; the issue itself is now waiting on a person.

If the issue had already reached a terminal state by the time the worker exited, you get this instead and no transition happens:

time=2026-03-26T14:35:21.480+00:00 level=INFO msg="handoff suppressed for terminal issue" issue_id=abc123 issue_identifier=MT-649 state=Done state_source=verified handoff_state="In Review"

This is the line to look for when an issue you closed mid-run did not get overwritten, and the line to look for when you expected a handoff and did not get one.

state is the state Sortie saw, and state_source tells you where it saw it: reconcile from a reconciliation pass, worker from the worker’s own per-turn refresh, snapshot from the state last recorded for the run (the dispatch read, or a later one), or verified from an extra read Sortie takes before acting, either immediately before the write or immediately before recording a withheld handoff.

The claim is released and no retry is scheduled. Each of these also increments sortie_handoff_transitions_total with result="skipped".

That extra read can fail on its own, and Sortie proceeds with the handoff rather than assuming the issue is closed:

time=2026-03-26T14:35:21.470+00:00 level=WARN msg="handoff verification read failed, proceeding with handoff" issue_id=abc123 issue_identifier=MT-649 error="tracker request timeout" state_source=worker

The handoff-evidence policy takes a read of its own before recording a withheld handoff. When that read finds the issue terminal, the withheld outcome is discarded and you get this line, followed by the handoff suppressed for terminal issue line above carrying state_source=verified:

time=2026-03-26T14:35:21.475+00:00 level=INFO msg="withheld handoff suppressed for terminal issue" issue_id=abc123 issue_identifier=MT-649 state=Done state_source=verified handoff_state="In Review" policy=observed verdict="absence of work observed" reason="workspace commit and working tree match the run baseline" turns_completed=2

This is the line to look for when a run that produced nothing on an issue somebody finished mid-run left no failure behind: no failed run is recorded, no failure comment is posted, no retry is scheduled, and the consecutive-absence count does not move. When that read fails instead, Sortie records the withheld handoff as it otherwise would:

time=2026-03-26T14:35:21.472+00:00 level=WARN msg="withheld handoff verification read failed, recording withheld handoff" issue_id=abc123 issue_identifier=MT-649 error="tracker request timeout" state_source=worker

Tracker comments

time=2026-03-26T14:32:00.200+00:00 level=INFO msg="dispatch comment posted" issue_id=abc123 issue_identifier=MT-649
time=2026-03-26T14:35:21.600+00:00 level=INFO msg="tracker comment posted" issue_id=abc123 issue_identifier=MT-649 lifecycle=completion

When a tracker_comment entry lists the session events, Sortie posts audit comments on the tracker issue at dispatch, completion, or failure. INFO means the comment was delivered. If the comment API call fails:

time=2026-03-26T14:35:21.600+00:00 level=WARN msg="tracker comment failed" issue_id=abc123 issue_identifier=MT-649 lifecycle=completion error="tracker: tracker_auth_error: POST /rest/api/3/issue/abc123/comment: 403"

The WARN means the comment failed but the session lifecycle is unaffected. Check API token permissions if persistent.

A send to a webhook, slack, telegram, or discord entry that fails logs a separate WARN, which names the event, the entry, and its kind:

time=2026-03-26T14:35:21.600+00:00 level=WARN msg="notification delivery failed" event_type=session.failed destination=notifications[1] notifier_kind=slack error="..."

The delivery does not affect the session lifecycle and is not retried. Successful sends log at DEBUG as notification delivered.

Errors and retries

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="worker run failed, scheduling retry" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 error="agent turn 4: agent: turn_timeout: turn exceeded the configured 1800000 ms bound; the adapter's own report follows: context deadline exceeded" next_attempt=2 delay_ms=20000

The WARN with scheduling retry means Sortie is recovering automatically. The next_attempt and delay_ms fields tell you when the retry fires.

time=2026-03-26T14:35:22.500+00:00 level=ERROR msg="worker run failed, non-retryable, releasing claim" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-001 error="agent: agent_not_found: agent command \"claude\" not found: exec: \"claude\": executable file not found in $PATH"

The ERROR means Sortie gave up. This issue won’t be retried. Fix the underlying problem (in this case, install the agent binary) and Sortie will pick the issue up on the next poll.

Token budget exhaustion

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="token budget exhausted, blocking re-dispatch" issue_id=abc123 issue_identifier=MT-649 reason=token_budget used_tokens=52000 budget_tokens=50000 used_sessions=3 budget_sessions=5

This fires when agent.max_tokens is set and an issue’s cumulative tokens across every completed session reach the configured ceiling. It is the pre-dispatch lane: it runs before a scheduled retry fires and blocks that dispatch. A session already running is stopped by a separate record, below. used_tokens is the issue’s running total without prompt-cache reads, the count agent.max_tokens is compared with; budget_tokens is the ceiling it hit. used_sessions and budget_sessions report the same comparison for the session-count budget, in case the issue is close to both ceilings at once.

A session whose coding agent reported no token usage at all is recorded as unmeasured and contributes nothing to used_tokens. When an issue is still under the ceiling but its total is known to fall short of what the issue really spent, Sortie says so and dispatches anyway:

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="token budget cannot be fully evaluated, allowing dispatch" issue_id=abc123 issue_identifier=MT-649 used_tokens=31000 budget_tokens=50000 unmeasured_sessions=2 unaccounted_turns=0

Two counts say what the sum leaves out, and the record carries both every time. unmeasured_sessions is how many of the issue’s recorded sessions carry no token figure. unaccounted_turns is how many turns reached the model without a figure that covered them, which a session can accumulate even when every one of its figures arrived.

Either count above 0 makes used_tokens a lower bound rather than the whole story. The ceiling message above takes precedence: an issue whose measured total already reaches the ceiling is blocked and logs that instead.

If Sortie can’t read the token total at all, it fails open rather than blocking a retry on a persistence error:

time=2026-03-26T14:35:21.900+00:00 level=WARN msg="token budget check failed, proceeding with dispatch" issue_id=abc123 issue_identifier=MT-649 error="database is locked"

WARN in all three cases, but the outcome differs: dispatch proceeds for the latter two, where the ceiling message blocks it.

Token ceiling stops a run in flight

time=2026-03-26T14:41:07.000+00:00 level=WARN msg="run stopped by token ceiling" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-002 reason=token_budget used_tokens=50240 budget_tokens=50000 issue_tokens_completed=31000 session_tokens=19240 sum_source=confirmed_read ceiling_setting=agent.max_tokens unmeasured_sessions=0 unaccounted_turns=0

The same ceiling, reached during a session rather than between two. The moment a usage figure carries the sum to the ceiling, Sortie decides to stop the run. This record is logged later, at the run’s exit, once that decision is confirmed to be what ended the run, so its timestamp can trail the crossing by however long teardown takes.

Not every decision produces this line. Only a run the ceiling’s cancellation actually ends gets one; a run that finishes on its own, or that a different cancellation ends first, gets none. See how to control agent costs for which runs that is. A stop that lands during self-review, or keeps it from starting, is recorded here too, with no handoff transition performed. Later usage events on a session already stopped log nothing.

used_tokens and the other counts on this line are a snapshot from the decision, not the exit. The run-history error field for the same run computes its own “used N of M tokens” figure fresh at exit, after any usage the session reported in between, so the two can differ: read this line’s figures as what triggered the stop, and the run-history figure as the session’s final tally.

Read session_tokens against issue_tokens_completed to see who spent the budget. session_tokens is what the cancelled session had spent on its own, issue_tokens_completed is what the issue’s earlier sessions had already banked, and used_tokens is their sum, the figure compared against budget_tokens.

sum_source says how that sum was established. confirmed_read means a database read settled the completed total, and the record then carries unmeasured_sessions and unaccounted_turns, the two counts that report what the total leaves out. session_spend_alone means the read failed and the running session had spent the whole budget by itself, which needs no read to prove; neither count appears in that case, and used_tokens is a lower bound.

Four more records surround the check, all WARN, all gated on agent.max_tokens being set. Two fire at dispatch and describe what the ceiling can bound for the session about to start:

time=2026-03-26T14:38:02.000+00:00 level=WARN msg="token ceiling cannot bound this run" issue_id=abc123 issue_identifier=MT-649 agent_kind=acme usage_arrival=none budget_tokens=50000
time=2026-03-26T14:39:14.000+00:00 level=WARN msg="prior token spend unknown, token ceiling bounds this session only" issue_id=def456 issue_identifier=MT-702 error="database is locked" budget_tokens=50000

The first means the agent kind attaches no source that counts tokens, so nothing will ever reach the ceiling; agent.turn_timeout_ms is the remaining cap. Every built-in kind attaches one, so only a custom adapter draws it. The second means the read of the issue’s completed spend failed, so that session starts from a baseline of zero: it still stops at the full budget, but earlier sessions are not counted against it. One dispatch emits at most one of the two, which is why the two lines above are two different issues.

The third fires later, when the read that would confirm a stop fails:

time=2026-03-26T14:40:55.000+00:00 level=WARN msg="in-flight token ceiling check failed, run continues" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-002 error="database is locked" budget_tokens=50000

The run keeps going and can pass the ceiling until a later read succeeds or the session ends. It logs once per run, no matter how many later reads fail, so read one of these as an interval during which the ceiling was not enforced rather than as a single moment.

The fourth fires once, at the end of a run that reported nothing although its agent kind said figures would arrive:

time=2026-03-26T14:52:18.000+00:00 level=WARN msg="run reported no token usage, token ceiling could not bound it" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-004 agent_kind=agent-client-protocol usage_arrival=turn_end budget_tokens=50000

This is the after-the-fact counterpart of the first record. Nothing warned at dispatch, because the kind attaches a source that counts tokens; the runtime behind it then produced no figure, and the ceiling bounded nothing. agent-client-protocol is where you are most likely to meet it: a runtime Sortie ships no source for is read from the protocol’s standard usage fields, and a runtime that fills none of them leaves the run unmeasured. See token accounting on that kind for which way a given session went.

Token warning threshold

time=2026-03-26T14:40:10.000+00:00 level=WARN msg="token warning threshold reached" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-002 used_tokens=1350000 warning_tokens=1350000 budget_tokens=1500000 issue_tokens_completed=1180000 session_tokens=170000 ceiling_setting=agent.max_tokens warning_setting=agent.token_warning_percent

This fires when agent.token_warning_percent is set and the issue’s live token sum, the same sum agent.max_tokens enforces against, reaches the configured threshold. used_tokens and warning_tokens are the sum and the threshold it crossed; budget_tokens is the ceiling the threshold sits below. issue_tokens_completed and session_tokens split that sum the same way the ceiling’s own stop record does: what earlier sessions had already banked, and what the running session has spent on its own.

Sortie logs this once per run: a run that crosses the threshold again on a later usage figure does not log a second time, and a run that never crosses it does not log at all. See how to control agent costs for choosing a percentage, and the cost_budget tool for how the agent reads the same condition mid-session.

Money budget

When agent.max_cost_usd is set, the money ceiling logs beside the token ceiling, in the same three places. Before a dispatch, a scheduled retry that finds the issue at the ceiling logs:

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="money budget exhausted, blocking re-dispatch" issue_id=abc123 issue_identifier=MT-649 reason=money_budget used_usd=25.31 budget_usd=25 used_sessions=3 budget_sessions=5

used_usd is the issue’s estimated cost in US dollars and budget_usd the ceiling. The poll tick’s rebuild records the same hold once, as candidate held by budget ceiling with reason=money_budget, used_usd, budget_usd, and ceiling_setting=agent.max_cost_usd. A run in progress is stopped by a separate record, logged at the run’s exit:

time=2026-03-26T14:41:07.000+00:00 level=WARN msg="run stopped by money ceiling" issue_id=abc123 issue_identifier=MT-649 session_id=session-abc-002 reason=money_budget used_usd=25.31 budget_usd=25 issue_cost_completed=19.8 session_cost_usd=5.51 cost_complete=true sum_source=confirmed_read ceiling_setting=agent.max_cost_usd unmeasured_sessions=0 unaccounted_turns=0

Read session_cost_usd against issue_cost_completed to see who spent the budget: the session’s own estimate and what the issue’s earlier runs had already recorded add up to used_usd. cost_complete is false when the figure is a lower bound. sum_source reads as it does for the token record, and the two counts at the end appear only with confirmed_read.

An issue below the ceiling whose figure is only a lower bound dispatches, and Sortie says so:

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="money budget cannot be fully evaluated, allowing dispatch" issue_id=abc123 issue_identifier=MT-649 used_usd=11.2 budget_usd=25 unmeasured_sessions=0 unaccounted_turns=0 partial_sessions=1 unpriced_sessions=1

partial_sessions counts the issue’s runs recorded with only part of their spend priced, and unpriced_sessions counts the runs recorded with no price at all. The other two counts are the ones the token record carries.

Three more records mirror the token ceiling’s failure cases and leave the work going: money budget check failed, proceeding with dispatch when the read before a retry fails, prior spend unknown, money ceiling bounds this session only when the read at dispatch fails, and in-flight money ceiling check failed, run continues, once per run, when the read that would confirm a stop fails.

Instance spend ceiling

When agent.max_daily_cost_usd, agent.max_weekly_cost_usd or agent.max_monthly_cost_usd is set, Sortie evaluates each window on every poll tick and every retry check. None of these records carries issue fields, because a window belongs to no issue. When a window first reaches its ceiling, Sortie logs:

time=2026-03-26T17:02:44.000+00:00 level=WARN msg="spend ceiling reached, holding dispatch" window=daily used_usd=100.4 used_usd_complete=true budget_usd=100 ceiling_setting=agent.max_daily_cost_usd resets_at=2026-03-27T00:00:00.000Z

window is daily, weekly or monthly, and resets_at is when that window next resets: the next 00:00 UTC for daily, the next Monday 00:00 UTC for weekly, and the first of the next month at 00:00 UTC for monthly. used_usd_complete is false when the figure is a lower bound. A weekly hold reached on a Thursday looks like this:

time=2026-03-26T09:15:31.000+00:00 level=WARN msg="spend ceiling reached, holding dispatch" window=weekly used_usd=500.8 used_usd_complete=true budget_usd=500 ceiling_setting=agent.max_weekly_cost_usd resets_at=2026-03-30T00:00:00.000Z

The record appears once per hold, not once per tick. While the hold lasts, a retry that comes due logs a debug record naming the reason and when Sortie checks it again:

time=2026-03-26T17:03:44.000+00:00 level=DEBUG msg="retry held by spend ceiling, rechecking" issue_id=abc123 issue_identifier=MT-649 reason=daily_spend_ceiling attempt=2 delay_ms=30000

attempt is the retry’s own attempt number, which the hold leaves unchanged. When a window stops holding, because it reset or you raised or removed the ceiling, Sortie logs:

time=2026-03-27T00:00:11.000+00:00 level=INFO msg="spend ceiling hold ended" window=daily budget_usd=100 used_usd=0 ceiling_setting=agent.max_daily_cost_usd dispatch_held=false

dispatch_held is true when any other window still holds, because dispatch resumes only once every window that reached its ceiling has cleared. After you remove the ceiling, budget_usd reads 0 and used_usd is absent.

A window below its ceiling whose figure is only a lower bound dispatches, and Sortie says so once for the window:

time=2026-03-26T14:35:22.000+00:00 level=WARN msg="spend ceiling cannot be fully evaluated, allowing dispatch" window=daily used_usd=61.2 budget_usd=100 unmeasured_sessions=0 unaccounted_turns=0 partial_sessions=1 unpriced_sessions=2

unmeasured_sessions counts the runs and running sessions that report no token usage, unaccounted_turns the turns whose usage was not accounted, partial_sessions the runs priced in part, and unpriced_sessions the runs with no price. When the read of run history fails, Sortie keeps the last result, or treats the window as not holding when it has none, and logs spend ceiling check failed, keeping the last result with window and error.

A held candidate logs no per-issue record; sortie_candidate_holds_total counts it under reason daily_spend_ceiling, weekly_spend_ceiling or monthly_spend_ceiling. When several windows hold at once, the count carries the reason of the one that resets latest, the longer window on a tie. See Cap what the whole instance spends for what the hold stops and when it ends.

Dispatch preflight failures

time=2026-03-26T14:30:01.300+00:00 level=ERROR msg="dispatch preflight failed" error="dispatch preflight failed: unknown tracker adapter kind \"jra\"; registered: [file, gitea, github, gitlab, jira, linear]"

This fires before any work is dispatched. It means your workflow configuration is invalid. Sortie can’t dispatch anything until you fix the config and restart. Here a typo in tracker.kind is the cause, and the bracketed list is every kind the binary actually has registered, so it names the correction. Your own list grows as adapters are added.

Common grep patterns

These commands work against the text log format. For JSON logs, see JSON log filtering with jq below.

Follow a specific issue across its entire lifecycle:

grep 'issue_identifier=MT-649' sortie.log

Find all errors that need your attention:

grep 'level=ERROR' sortie.log

Find retries (to see which issues are struggling):

grep 'scheduling retry' sortie.log

Find issues blocked by a token budget:

grep 'token budget exhausted' sortie.log

Find sessions the token ceiling stopped in flight:

grep 'run stopped by token ceiling' sortie.log

Find issues blocked by the money budget, and sessions the money ceiling stopped in flight:

grep -e 'money budget exhausted' -e 'run stopped by money ceiling' sortie.log

Find when an instance spend ceiling began and ended holding dispatch:

grep -e 'spend ceiling reached' -e 'spend ceiling hold ended' sortie.log

Find runs that crossed the token warning threshold:

grep 'token warning threshold reached' sortie.log

Find dispatches allowed on a spend figure that is only a lower bound, and runs whose usage the ceiling never saw:

grep -e 'cannot be fully evaluated' -e 'token ceiling could not bound it' -e 'token ceiling cannot bound this run' sortie.log

Watch changes in the poll summary in real time:

tail -f sortie.log | grep 'tick completed'

See which model and effort each dispatch started with, first attempts and retries together:

grep 'issue dispatched' sortie.log

Find attempts refused over their agent settings:

grep 'agent settings refused' sortie.log

Find tool call failures (needs --log-level debug):

grep 'tool call completed.*outcome=error' sortie.log

Follow a specific agent session across turns and tool calls:

grep 'session_id=session-abc-001' sortie.log

Review every workspace sweep pass, including the ones that removed nothing:

grep 'sweep: pass complete' sortie.log

Find workspaces removed by the age bound:

grep 'sweep: removed expired workspace' sortie.log

Switch to JSON format

For deployments that route logs to an aggregation system, switch to JSON output:

sortie --log-format json ./WORKFLOW.md

Or set it in the workflow file and leave the CLI unchanged:

logging:
  format: json

The CLI flag takes precedence when both are set. Both formats carry the same structured fields. Only the serialization differs.

JSON log filtering with jq

When running with --log-format json, use jq instead of grep for precise field-level filtering.

Follow a specific issue:

jq 'select(.issue_identifier == "MT-649")' sortie.log

Find all errors:

jq 'select(.level == "ERROR")' sortie.log

Find retries with their delay:

jq 'select(.msg | contains("scheduling retry")) | {issue: .issue_identifier, next_attempt, delay_ms}' sortie.log

Find issues blocked by a token budget:

jq 'select(.msg | contains("token budget exhausted")) | {issue: .issue_identifier, used_tokens, budget_tokens}' sortie.log

Watch changes in the poll summary in real time:

tail -f sortie.log | jq 'select(.msg == "tick completed")'

List the model and effort each dispatch started with:

jq 'select(.msg | endswith("issue dispatched")) | {issue: .issue_identifier, attempt, rule_name, model, effort}' sortie.log

Find tool call failures with duration (needs --log-level debug):

jq 'select(.msg == "tool call completed" and .outcome == "error") | {tool, tool_error, duration_ms}' sortie.log

Extract a timeline for a specific session:

jq 'select(.session_id == "session-abc-001") | {time, msg, level}' sortie.log

Find sweep passes that removed at least one workspace on age:

jq 'select(.msg == "sweep: pass complete" and .removed_age > 0)' sortie.log

Redirect logs to a file

Sortie logs to stderr by default. Redirect to a file with shell redirection:

sortie ./WORKFLOW.md 2>sortie.log

Or use tee to keep both console and file output:

sortie ./WORKFLOW.md 2>&1 | tee sortie.log

For systemd services, logs go to journald automatically. Watch them in real time with:

journalctl -u sortie -f

Or filter for errors only:

journalctl -u sortie -p err

What we covered

You now know how to read Sortie’s structured logs in both text and JSON formats, follow specific issues through the dispatch lifecycle, distinguish between warnings (automatic recovery) and errors (needs your attention), switch to JSON for log aggregation, filter JSON logs with jq, find tool call failures, and persist logs to a file.

For the complete error catalog, see the error reference. For metric-based monitoring with Prometheus and Grafana, see Monitor with Prometheus. For real-time visual monitoring, see the dashboard reference.