runner/.opencode/plans/dap-debug-logging.md

DAP Debug Logging Feature

Status: Implemented
Date: January 2026
Related: dap-debugging.md, dap-step-backwards.md

Overview

Add comprehensive debug logging to the DAP debugging infrastructure that can be toggled from the DAP client. This helps diagnose issues like step conclusions not updating correctly after step-back operations.

Features

1. Debug Log Levels

Level	Value	What Gets Logged
Off	0	Nothing
Minimal	1	Errors, critical state changes
Normal	2	Step lifecycle, checkpoint operations
Verbose	3	Everything including outputs, expressions

2. Enabling Debug Logging

Via Attach Arguments (nvim-dap config)

{
  type = "runner",
  request = "attach",
  debugLogging = true,           -- Enable debug logging (defaults to "normal" level)
  debugLogLevel = "verbose",     -- Optional: "off", "minimal", "normal", "verbose"
}

Via REPL Commands (runtime toggle)

Command	Description
!debug on	Enable debug logging (level: normal)
!debug off	Disable debug logging
!debug minimal	Set level to minimal
!debug normal	Set level to normal
!debug verbose	Set level to verbose
!debug status	Show current debug settings

3. Log Output Format

All debug logs are sent to the DAP console with the format:

[DEBUG] [Category] Message

Categories include:

• [Step] - Step lifecycle events
• [Checkpoint] - Checkpoint creation/restoration
• [StepsContext] - Steps context mutations (SetOutcome, SetConclusion, SetOutput, ClearScope)

4. Example Output

With !debug verbose enabled:

[DEBUG] [Step] Starting: 'cat doesnotexist' (index=2)
[DEBUG] [Step] Checkpoints available: 2
[DEBUG] [StepsContext] SetOutcome: step='thecat', outcome=failure
[DEBUG] [StepsContext] SetConclusion: step='thecat', conclusion=failure
[DEBUG] [Step] Completed: 'cat doesnotexist', result=Failed
[DEBUG] [Step] Context state: outcome=failure, conclusion=failure

# After step-back:
[DEBUG] [Checkpoint] Restoring checkpoint [1] for step 'cat doesnotexist'
[DEBUG] [StepsContext] ClearScope: scope='(root)'
[DEBUG] [StepsContext] Restoring: clearing scope '(root)', restoring 2 step(s)
[DEBUG] [StepsContext] Restored: step='thefoo', outcome=success, conclusion=success

# After re-running with file created:
[DEBUG] [Step] Starting: 'cat doesnotexist' (index=2)
[DEBUG] [StepsContext] SetOutcome: step='thecat', outcome=success
[DEBUG] [StepsContext] SetConclusion: step='thecat', conclusion=success
[DEBUG] [Step] Completed: 'cat doesnotexist', result=Succeeded
[DEBUG] [Step] Context state: outcome=success, conclusion=success

Implementation

Progress Checklist

• Phase 1: Add debug logging infrastructure to DapDebugSession
• Phase 2: Add REPL !debug command handling
• Phase 3: Add OnDebugLog callback to StepsContext
• Phase 4: Add debug logging calls throughout DapDebugSession
• Phase 5: Hook up StepsContext logging to DapDebugSession
• Phase 6: Testing

---

Phase 1: Debug Logging Infrastructure

File: src/Runner.Worker/Dap/DapDebugSession.cs

Add enum and helper method:

// Add enum for debug log levels (near top of file with other enums)
public enum DebugLogLevel
{
    Off = 0,
    Minimal = 1,    // Errors, critical state changes
    Normal = 2,     // Step lifecycle, checkpoints
    Verbose = 3     // Everything including outputs, expressions
}

// Add field (with other private fields)
private DebugLogLevel _debugLogLevel = DebugLogLevel.Off;

// Add helper method (in a #region Debug Logging)
private void DebugLog(string message, DebugLogLevel minLevel = DebugLogLevel.Normal)
{
    if (_debugLogLevel >= minLevel)
    {
        _server?.SendEvent(new Event
        {
            EventType = "output",
            Body = new OutputEventBody
            {
                Category = "console",
                Output = $"[DEBUG] {message}\n"
            }
        });
    }
}

Update HandleAttach to parse debug logging arguments:

private Response HandleAttach(Request request)
{
    Trace.Info("Attach request handled");

    // Parse debug logging from attach args
    if (request.Arguments is JsonElement args)
    {
        if (args.TryGetProperty("debugLogging", out var debugLogging))
        {
            if (debugLogging.ValueKind == JsonValueKind.True)
            {
                _debugLogLevel = DebugLogLevel.Normal;
                Trace.Info("Debug logging enabled via attach args (level: normal)");
            }
        }
        if (args.TryGetProperty("debugLogLevel", out var level) && level.ValueKind == JsonValueKind.String)
        {
            _debugLogLevel = level.GetString()?.ToLower() switch
            {
                "minimal" => DebugLogLevel.Minimal,
                "normal" => DebugLogLevel.Normal,
                "verbose" => DebugLogLevel.Verbose,
                "off" => DebugLogLevel.Off,
                _ => _debugLogLevel
            };
            Trace.Info($"Debug log level set via attach args: {_debugLogLevel}");
        }
    }

    return CreateSuccessResponse(null);
}

---

Phase 2: REPL !debug Command

File: src/Runner.Worker/Dap/DapDebugSession.cs

In HandleEvaluateAsync, add handling for !debug command before other shell command handling:

// Near the start of HandleEvaluateAsync, after getting the expression:

// Check for debug command
if (expression.StartsWith("!debug", StringComparison.OrdinalIgnoreCase))
{
    return HandleDebugCommand(expression);
}

// ... rest of existing HandleEvaluateAsync code

Add the handler method:

private Response HandleDebugCommand(string command)
{
    var parts = command.Split(' ', StringSplitOptions.RemoveEmptyEntries);
    var arg = parts.Length > 1 ? parts[1].ToLower() : "status";
    
    string result;
    switch (arg)
    {
        case "on":
            _debugLogLevel = DebugLogLevel.Normal;
            result = "Debug logging enabled (level: normal)";
            break;
        case "off":
            _debugLogLevel = DebugLogLevel.Off;
            result = "Debug logging disabled";
            break;
        case "minimal":
            _debugLogLevel = DebugLogLevel.Minimal;
            result = "Debug logging set to minimal";
            break;
        case "normal":
            _debugLogLevel = DebugLogLevel.Normal;
            result = "Debug logging set to normal";
            break;
        case "verbose":
            _debugLogLevel = DebugLogLevel.Verbose;
            result = "Debug logging set to verbose";
            break;
        case "status":
        default:
            result = $"Debug logging: {_debugLogLevel}";
            break;
    }

    return CreateSuccessResponse(new EvaluateResponseBody
    {
        Result = result,
        VariablesReference = 0
    });
}

---

Phase 3: StepsContext OnDebugLog Callback

File: src/Runner.Worker/StepsContext.cs

Add callback property and helper:

public sealed class StepsContext
{
    private static readonly Regex _propertyRegex = new("^[a-zA-Z_][a-zA-Z0-9_]*$", RegexOptions.Compiled);
    private readonly DictionaryContextData _contextData = new();

    /// <summary>
    /// Optional callback for debug logging. When set, will be called with debug messages
    /// for all StepsContext mutations.
    /// </summary>
    public Action<string> OnDebugLog { get; set; }

    private void DebugLog(string message)
    {
        OnDebugLog?.Invoke(message);
    }

    // ... rest of class
}

Update ClearScope:

public void ClearScope(string scopeName)
{
    DebugLog($"[StepsContext] ClearScope: scope='{scopeName ?? "(root)"}'");
    if (_contextData.TryGetValue(scopeName, out _))
    {
        _contextData[scopeName] = new DictionaryContextData();
    }
}

Update SetOutput:

public void SetOutput(
    string scopeName,
    string stepName,
    string outputName,
    string value,
    out string reference)
{
    var step = GetStep(scopeName, stepName);
    var outputs = step["outputs"].AssertDictionary("outputs");
    outputs[outputName] = new StringContextData(value);
    if (_propertyRegex.IsMatch(outputName))
    {
        reference = $"steps.{stepName}.outputs.{outputName}";
    }
    else
    {
        reference = $"steps['{stepName}']['outputs']['{outputName}']";
    }
    DebugLog($"[StepsContext] SetOutput: step='{stepName}', output='{outputName}', value='{TruncateValue(value)}'");
}

private static string TruncateValue(string value, int maxLength = 50)
{
    if (string.IsNullOrEmpty(value)) return "(empty)";
    if (value.Length <= maxLength) return value;
    return value.Substring(0, maxLength) + "...";
}

Update SetConclusion:

public void SetConclusion(
    string scopeName,
    string stepName,
    ActionResult conclusion)
{
    var step = GetStep(scopeName, stepName);
    var conclusionStr = conclusion.ToString().ToLowerInvariant();
    step["conclusion"] = new StringContextData(conclusionStr);
    DebugLog($"[StepsContext] SetConclusion: step='{stepName}', conclusion={conclusionStr}");
}

Update SetOutcome:

public void SetOutcome(
    string scopeName,
    string stepName,
    ActionResult outcome)
{
    var step = GetStep(scopeName, stepName);
    var outcomeStr = outcome.ToString().ToLowerInvariant();
    step["outcome"] = new StringContextData(outcomeStr);
    DebugLog($"[StepsContext] SetOutcome: step='{stepName}', outcome={outcomeStr}");
}

---

Phase 4: DapDebugSession Logging Calls

File: src/Runner.Worker/Dap/DapDebugSession.cs

In OnStepStartingAsync (after setting _currentStep and _jobContext):

DebugLog($"[Step] Starting: '{step.DisplayName}' (index={stepIndex})");
DebugLog($"[Step] Checkpoints available: {_checkpoints.Count}");

In OnStepCompleted (after logging to Trace):

DebugLog($"[Step] Completed: '{step.DisplayName}', result={result}");

// Log current steps context state for this step
if (_debugLogLevel >= DebugLogLevel.Normal)
{
    var stepsScope = step.ExecutionContext?.Global?.StepsContext?.GetScope(step.ExecutionContext.ScopeName);
    if (stepsScope != null && !string.IsNullOrEmpty(step.ExecutionContext?.ContextName))
    {
        if (stepsScope.TryGetValue(step.ExecutionContext.ContextName, out var stepData) && stepData is DictionaryContextData sd)
        {
            var outcome = sd.TryGetValue("outcome", out var o) && o is StringContextData os ? os.Value : "null";
            var conclusion = sd.TryGetValue("conclusion", out var c) && c is StringContextData cs ? cs.Value : "null";
            DebugLog($"[Step] Context state: outcome={outcome}, conclusion={conclusion}");
        }
    }
}

In CreateCheckpointForPendingStep (after creating checkpoint):

DebugLog($"[Checkpoint] Created [{_checkpoints.Count - 1}] for step '{_pendingStep.DisplayName}'");
if (_debugLogLevel >= DebugLogLevel.Verbose)
{
    DebugLog($"[Checkpoint] Snapshot contains {checkpoint.StepsSnapshot.Count} step(s)", DebugLogLevel.Verbose);
    foreach (var entry in checkpoint.StepsSnapshot)
    {
        DebugLog($"[Checkpoint]   {entry.Key}: outcome={entry.Value.Outcome}, conclusion={entry.Value.Conclusion}", DebugLogLevel.Verbose);
    }
}

In RestoreCheckpoint (at start of method):

DebugLog($"[Checkpoint] Restoring [{checkpointIndex}] for step '{checkpoint.StepDisplayName}'");
if (_debugLogLevel >= DebugLogLevel.Verbose)
{
    DebugLog($"[Checkpoint] Snapshot has {checkpoint.StepsSnapshot.Count} step(s)", DebugLogLevel.Verbose);
}

In RestoreStepsContext (update existing method):

private void RestoreStepsContext(StepsContext stepsContext, Dictionary<string, StepStateSnapshot> snapshot, string scopeName)
{
    scopeName = scopeName ?? string.Empty;

    DebugLog($"[StepsContext] Restoring: clearing scope '{(string.IsNullOrEmpty(scopeName) ? "(root)" : scopeName)}', will restore {snapshot.Count} step(s)");

    stepsContext.ClearScope(scopeName);

    foreach (var entry in snapshot)
    {
        var key = entry.Key;
        var slashIndex = key.IndexOf('/');

        if (slashIndex >= 0)
        {
            var snapshotScopeName = slashIndex > 0 ? key.Substring(0, slashIndex) : string.Empty;
            var stepName = key.Substring(slashIndex + 1);

            if (snapshotScopeName == scopeName)
            {
                var state = entry.Value;

                if (state.Outcome.HasValue)
                {
                    stepsContext.SetOutcome(scopeName, stepName, state.Outcome.Value);
                }
                if (state.Conclusion.HasValue)
                {
                    stepsContext.SetConclusion(scopeName, stepName, state.Conclusion.Value);
                }

                if (state.Outputs != null)
                {
                    foreach (var output in state.Outputs)
                    {
                        stepsContext.SetOutput(scopeName, stepName, output.Key, output.Value, out _);
                    }
                }

                DebugLog($"[StepsContext] Restored: step='{stepName}', outcome={state.Outcome}, conclusion={state.Conclusion}", DebugLogLevel.Verbose);
            }
        }
    }

    Trace.Info($"Steps context restored: cleared scope '{scopeName}' and restored {snapshot.Count} step(s) from snapshot");
}

---

Phase 5: Hook Up StepsContext Logging

File: src/Runner.Worker/Dap/DapDebugSession.cs

In OnStepStartingAsync, after setting _jobContext, hook up the callback (only once):

// Hook up StepsContext debug logging (do this once when we first get jobContext)
if (jobContext.Global.StepsContext.OnDebugLog == null)
{
    jobContext.Global.StepsContext.OnDebugLog = (msg) => DebugLog(msg, DebugLogLevel.Verbose);
}

Note: StepsContext logging is set to Verbose level since SetOutput can be noisy. SetConclusion and SetOutcome will still appear at Verbose level, but all the important state changes are also logged directly in OnStepCompleted at Normal level.

---

Phase 6: Testing

Manual Testing Checklist

• !debug status shows "Off" by default
• !debug on enables logging, shows step lifecycle
• !debug verbose shows StepsContext mutations
• !debug off disables logging
• Attach with debugLogging: true enables logging on connect
• Attach with debugLogLevel: "verbose" sets correct level
• Step-back scenario shows restoration logs
• Logs help identify why conclusion might not update

Test Workflow

Use the test workflow with thecat step:

1. Run workflow, let thecat fail
2. Enable !debug verbose
3. Step back
4. Create the missing file
5. Step forward
6. Observe logs to see if SetConclusion is called with success

---

Files Summary

Modified Files

File	Changes
src/Runner.Worker/Dap/DapDebugSession.cs	Add DebugLogLevel enum, _debugLogLevel field, DebugLog() helper, HandleDebugCommand(), update HandleAttach, add logging calls throughout, hook up StepsContext callback
src/Runner.Worker/StepsContext.cs	Add OnDebugLog callback, DebugLog() helper, TruncateValue() helper, add logging to ClearScope, SetOutput, SetConclusion, SetOutcome

---

Future Enhancements (Out of Scope)

• Additional debug commands (!debug checkpoints, !debug steps, !debug env)
• Log to file option
• Structured logging with timestamps
• Category-based filtering (e.g., only show [StepsContext] logs)
• Integration with nvim-dap's virtual text for inline debug info