Debugging with ASH_VERBOSE

Audience and purpose

This page is for a developer troubleshooting a problem with an ash install — a failed tool call, an unexpected assistant reply, a stuck scratch script, or a provider request that behaved oddly. It explains how to turn on ASH_VERBOSE, exactly what it changes, how to read every field in a log entry (including the EID and request_id fields), where the execution dashboard report comes from, and where logs live when ASH_VERBOSE is not set.

Quick start: turning it on

export ASH_VERBOSE=1
ash "list the files in this directory"

Accepted values (case-insensitive), checked by verboseLoggingEnabled in support.go: 1, true, yes, y, on, debug. Anything else (including unset) leaves verbose logging off.

Two optional companions:

export ASH_LOG_FILE=/tmp/ash-debug.log   # write debug JSON to a file instead of stderr
export ASH_LOG_MAX_BYTES=1048576         # rotate ASH_LOG_FILE at this size (default 1 MiB)

Both are read in configureDebugLogging in support.go. If ASH_LOG_FILE is set, logs go to a self-rotating file (newRotatingSchedulerLogWriter, same file) instead of your terminal's stderr — useful when you want a clean terminal but a full trace to inspect afterward.

Turn it off again with unset ASH_VERBOSE (or export ASH_VERBOSE=0).

What ASH_VERBOSE actually changes

Two independent things happen when it's enabled, both wired up once per invocation in run() (ash.go):

1. Log level rises from Info to Debug. Without ASH_VERBOSE, only slog.Info/slog.Warn/slog.Error calls are emitted. With it, slog.Debug calls also print — this is where almost all of the useful step-by-step detail lives (AI request/response metadata, tool invocation names and results, tool-loop iteration counts, sub-agent completions). See the level switch in configureDebugLogging (support.go).
2. An execution dashboard prints before the process exits. This is a plain-text (or ANSI-colored, if stdout is a terminal) report written to stdout, produced by a defer in run() so it prints even when the invocation fails or exits early. The same defer also emits a structured JSON "execution summary" log line via logExecutionSummary (see below) before rendering the dashboard:

defer func() {
    metrics.finish(timeNow())
    if verboseLoggingEnabled() {
        logExecutionSummary(summaryRequestID, metrics)
        _, _ = io.WriteString(stdout, renderExecutionDashboard(metrics, writerIsTerminal(stdout)))
    }
}()

See ash.go.

Where logs go when ASH_VERBOSE is not set

This is the "always available" baseline a developer can rely on even without reproducing with verbose logging turned on:

• slog.Info/slog.Warn/slog.Error calls are always emitted, regardless of ASH_VERBOSE — they are not gated behind it, only slog.Debug calls are. So install recommendations, top-level failures, and warnings are always visible.
• The default destination is stderr, as structured JSON (newStructuredLogger, support.go) — there is no persistent log file unless you set ASH_LOG_FILE yourself.
• Every one of those log lines still carries an EID field (see below), so even a plain non-verbose failure can be traced back to its exact source line.
• Scheduled invocations are the one exception: a one-off schedule_future_prompt run automatically enables verbose logging and writes JSON debug logs to ~/.ash/logs/task_$SESSION_ID.log, rotating at 1 MiB, regardless of whether you set ASH_VERBOSE yourself. This is the file to check first when a scheduled job misbehaves.

Anatomy of a log entry

A representative line (pretty-printed here; actual output is single-line JSON):

{
  "time": "2026-08-30T11:16:17.6259633-04:00",
  "level": "debug",
  "message": "Tool invocation requested",
  "request_id": "3f1a9c2b7e0d4488",
  "name": "run_unix_command",
  "arg_count": 1,
  "EID": "iYWCHf8N"
}

Field	Meaning
time	RFC3339-nano timestamp, from Go's standard slog JSON handler.
level	debug, info, warn, or error, lowercased by the ReplaceAttr hook in newStructuredLogger (support.go).
message	Human-readable event name (msg is renamed to message by the same hook).
request_id	Identifies which single ash invocation this line belongs to — see below.
EID	Identifies which exact source line emitted this log call — see below.
everything else	Call-specific fields — e.g. name/arg_count for a tool invocation, bytes/sha256/status for an AI request/response, parent_session_id/child_session_id for a sub-agent completion. These are always bounded metadata (sizes, hashes, statuses, names) — never raw prompts, credentials, tool arguments, or tool output (see the Logging hygiene section of Security-Model-and-Environment-Variables).

request_id: what it is and how it's generated

request_id ties together every debug log line that belongs to one ash invocation — one AI request/response cycle, every tool call it made, every tool-loop iteration, and any sub-agent it spawned — so you can filter a busy log file down to just the run you care about.

• It is generated once per invocation, near the top of run(), by requestIDGenerator() — a package-level function variable initialized in init() to newRandomRequestID, which fills 8 random bytes via crypto/rand.Read and hex-encodes them into a 16-character string. See support.go#L263-L275.
• That single ID is then threaded through the rest of the call chain via context.Context, using withRequestID/requestIDFromContext (metrics.go#L76-L91) — the same pattern used to carry the execution-metrics object (withExecutionMetrics/executionMetricsFromContext) through chat(), runToolLoop(), and the tool shim.
• Practically: every debug line for a single ash "..." command shares the same request_id; the next invocation (a new process) gets an independent, unrelated one. There's no ordering guarantee across invocations — treat it purely as a correlation key, not a sequence number.

If you're staring at a log file with many interleaved invocations (for example a rotated scheduler log), the fastest way to isolate one run is:

jq -r 'select(.request_id == "3f1a9c2b7e0d4488")' /tmp/ash-debug.log

EID: what it is, how it's generated, and how to use it during debugging

Every slog.Debug/Info/Warn/Error call in the codebase — and every error-carrying toolCommandResult literal in tools.go — carries a static EID field: an 8-character random alphanumeric string, generated once, at commit time, and then frozen into the source forever.

• Generation happens in scripts/eid-injector, specifically mustRandAlphaNum(8) drawing from crypto/rand (main.go#L816-L824).
• It runs automatically as a git pre-commit hook (githooks/pre-commit) that scans staged .go files and injects a canonical "EID", "<8-char-code>" pair into any logging call that's missing one — see scripts/eid-injector/README.md for the standalone usage (go run ./scripts/eid-injector --all rescans the whole tree).
• make lint test enforces that every logging call has one (AST-validated), so you should never see a log line without an EID in a build that passed CI.

Why it matters for debugging: log messages are free text and can be non-unique (the same message string might appear in more than one place, or be rephrased later). The EID is a stable, unique pointer to the exact source line that produced a given entry — much faster than searching for message text, and it survives message wording changes. Once you have an EID from a log line or an error message, jump straight to its source:

grep -rn '"iYWCHf8N"' --include='*.go' .

This will land you on the exact slog.Debug(...)/slog.Error(...) call (or toolCommandResult{...} literal) that produced the line you're looking at — no need to guess which of several similarly-worded log statements fired.

logExecutionSummary: the dashboard as structured JSON

Alongside the printed dashboard, logExecutionSummary (metrics.go) emits a single slog.Info("execution summary", ...) line carrying the same statistics as the dashboard, but as machine-parseable JSON fields instead of formatted text. It is gated by the same verboseLoggingEnabled() check as the dashboard — it only appears when ASH_VERBOSE is on — and is logged at Info level (not Debug), so it is easy to filter for on its own.

Fields: request_id, version (from executionDashboardVersion()), defaults_ms, connect_ms, connection_reused, ai_processing_ms, tool_calls, tool_duration_ms, tool_call_counts (per-tool-name map), sub_agent_calls, sub_agent_duration_ms, sub_agent_canceled, sub_agent_timed_out, sub_agent_failed, input_tokens, input_tokens_available, output_tokens, output_tokens_available, scratch_files_written, scratch_files_executed.

Use it when you want to aggregate or alert on execution stats across many invocations (for example scanning a rotated scheduler log for runs where tool_calls spiked or sub_agent_failed is non-zero) instead of parsing the printed dashboard text:

jq -r 'select(.message == "execution summary") | "\(.request_id) tool_calls=\(.tool_calls) sub_agent_failed=\(.sub_agent_failed)"' /tmp/ash-debug.log

The execution dashboard (the report)

Printed to stdout at process exit whenever ASH_VERBOSE is enabled, built by renderExecutionDashboard in metrics.go from the executionMetrics struct (metrics.go) that accumulates counters throughout the run. The header includes the running ash version via executionDashboardVersion(). Example:

ASH v0.14.0 EXECUTION SUMMARY
Loading defaults     12 ms
Connecting to AI server 45 ms
Connection reused    yes
AI processing        820 ms
Tool calls           3 tools (140 ms)
  by tool
  ash_write_scratch_file      1
  run_unix_command            2
Sub-agents           0 (0 ms), canceled 0, timed out 0, failed 0
Input tokens         512
Output tokens        128
Scratch files written
  plan/notes.txt               1
Scratch files executed
  plan/run.sh                  1
Total realtime        1.10 s

Field-by-field:

Line	Source of truth
Loading defaults / Connecting to AI server / AI processing	Per-stage timers (metricsStageDefaults/metricsStageConnect/metricsStageAIProcessing), recorded via addStageDuration (metrics.go).
Connection reused	Whether the Connection-Sharing broker (or direct HTTP client) reused an existing TLS connection for this request. Connect timing (connect_ms/"Connecting to AI server") is measured precisely via an httptrace.ClientTrace hook in httpClientDoWithReuse (chat.go), and the "AI processing" stage timer starts from the end of that measured connect duration rather than a second independent clock read — so the two stages never double-count the same time window.
Tool calls + by tool breakdown	Total tool invocations and per-name counts, recorded by addToolCall(name, duration) (metrics.go#L121-L133), called from the tool loop in runner.go. The by tool section is omitted entirely when no tools were called.
Sub-agents	Count/duration/outcome of any run_sub_agent delegations for this invocation.
Input tokens / Output tokens	Token usage reported by the AI provider, when available.
Scratch files written	Distinct scratch-file paths written via ash_write_scratch_file/ash_append_scratch_file/ash_edit_scratch_file, with per-path counts, recorded by addScratchWrite(relPath) (metrics.go#L139-L146). Omitted when nothing was written.
Scratch files executed	Distinct scratch-file paths passed as an argument to run_unix_command (for example bash /path/to/scratch/run.sh), recorded by addScratchExec(relPath) (metrics.go) via recordScratchExecArgs in tools.go. A scratch file's absolute path can never be the executable name itself (normalizeToolName rejects any value containing / or a leading .), so this only fires for interpreter arguments, not the allowlisted command name. Omitted when nothing scratch-related was executed.
Total realtime	Wall-clock time from the start of run() to this defer firing.

The dashboard is plain text with no ANSI escapes when stdout isn't a terminal (writerIsTerminal, metrics.go) — safe to pipe or redirect for later inspection.

Practical debugging workflow

1. Reproduce with ASH_VERBOSE=1 (add ASH_LOG_FILE=/tmp/ash-debug.log if you want a clean terminal and a file to grep afterward).
2. Find the failing or suspicious log line; note its message and EID.
3. grep -rn '"<EID>"' --include='*.go' . in a checkout of ash to jump to the exact call site that produced it.
4. Use request_id to pull every line belonging to that same invocation out of a busy or rotated log file (see the jq example above) and read the whole sequence in order.
5. Check the dashboard at the end of the run for aggregate confirmation — for example, "did run_unix_command actually get called twice?" or "was the scratch script I wrote actually executed?" — before digging further into individual log lines.

Related reading

• Security-Model-and-Environment-Variables — the full environment variable reference, including logging hygiene guarantees (bounded metadata only, never raw payloads).
• Connection-Sharing — what "Connection reused" in the dashboard means and how the broker works.
• README.md — the condensed ASH_VERBOSE/ASH_LOG_FILE/ASH_LOG_MAX_BYTES reference and full environment variable list.
• docs/ash.1 — the man page entry for these variables.
• AGENTS.md — repository-level note that the EID is a unique ID for every logging call, used to find the source of the log message.