diff --git a/.opencode/plans/dap-debug-logging.md b/.opencode/plans/dap-debug-logging.md new file mode 100644 index 000000000..aba77f8f9 --- /dev/null +++ b/.opencode/plans/dap-debug-logging.md @@ -0,0 +1,511 @@ +# DAP Debug Logging Feature + +**Status:** Implemented +**Date:** January 2026 +**Related:** [dap-debugging.md](./dap-debugging.md), [dap-step-backwards.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) + +```lua +{ + 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 + +- [x] **Phase 1:** Add debug logging infrastructure to DapDebugSession +- [x] **Phase 2:** Add REPL `!debug` command handling +- [x] **Phase 3:** Add OnDebugLog callback to StepsContext +- [x] **Phase 4:** Add debug logging calls throughout DapDebugSession +- [x] **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: + +```csharp +// 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: + +```csharp +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: + +```csharp +// 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: + +```csharp +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: + +```csharp +public sealed class StepsContext +{ + private static readonly Regex _propertyRegex = new("^[a-zA-Z_][a-zA-Z0-9_]*$", RegexOptions.Compiled); + private readonly DictionaryContextData _contextData = new(); + + /// + /// Optional callback for debug logging. When set, will be called with debug messages + /// for all StepsContext mutations. + /// + public Action OnDebugLog { get; set; } + + private void DebugLog(string message) + { + OnDebugLog?.Invoke(message); + } + + // ... rest of class +} +``` + +Update `ClearScope`: + +```csharp +public void ClearScope(string scopeName) +{ + DebugLog($"[StepsContext] ClearScope: scope='{scopeName ?? "(root)"}'"); + if (_contextData.TryGetValue(scopeName, out _)) + { + _contextData[scopeName] = new DictionaryContextData(); + } +} +``` + +Update `SetOutput`: + +```csharp +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`: + +```csharp +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`: + +```csharp +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`): + +```csharp +DebugLog($"[Step] Starting: '{step.DisplayName}' (index={stepIndex})"); +DebugLog($"[Step] Checkpoints available: {_checkpoints.Count}"); +``` + +#### In `OnStepCompleted` (after logging to Trace): + +```csharp +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): + +```csharp +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): + +```csharp +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): + +```csharp +private void RestoreStepsContext(StepsContext stepsContext, Dictionary 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): + +```csharp +// 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 diff --git a/src/Runner.Worker/Dap/DapDebugSession.cs b/src/Runner.Worker/Dap/DapDebugSession.cs index 5bffbec5a..99ad8b6fa 100644 --- a/src/Runner.Worker/Dap/DapDebugSession.cs +++ b/src/Runner.Worker/Dap/DapDebugSession.cs @@ -89,6 +89,32 @@ namespace GitHub.Runner.Worker.Dap ReverseContinue } + /// + /// Debug log levels for controlling verbosity of debug output. + /// + public enum DebugLogLevel + { + /// + /// No debug logging. + /// + Off = 0, + + /// + /// Errors and critical state changes only. + /// + Minimal = 1, + + /// + /// Step lifecycle and checkpoint operations. + /// + Normal = 2, + + /// + /// Everything including outputs, expressions, and StepsContext mutations. + /// + Verbose = 3 + } + /// /// Reasons for stopping/pausing execution. /// @@ -268,6 +294,9 @@ namespace GitHub.Runner.Worker.Dap private int? _pendingRestoreCheckpoint = null; private StepCheckpoint _restoredCheckpoint = null; + // Debug logging level (controlled via attach args or REPL command) + private DebugLogLevel _debugLogLevel = DebugLogLevel.Off; + public bool IsActive => _state == DapSessionState.Ready || _state == DapSessionState.Paused || _state == DapSessionState.Running; public DapSessionState State => _state; @@ -383,6 +412,34 @@ namespace GitHub.Runner.Worker.Dap private Response HandleAttach(Request request) { Trace.Info("Attach request handled"); + + // Parse debug logging from attach args + if (request.Arguments != null) + { + // Check for debugLogging (boolean) + var debugLogging = request.Arguments["debugLogging"]; + if (debugLogging != null && debugLogging.Type == Newtonsoft.Json.Linq.JTokenType.Boolean && (bool)debugLogging) + { + _debugLogLevel = DebugLogLevel.Normal; + Trace.Info("Debug logging enabled via attach args (level: normal)"); + } + + // Check for debugLogLevel (string) + var debugLogLevel = request.Arguments["debugLogLevel"]; + if (debugLogLevel != null && debugLogLevel.Type == Newtonsoft.Json.Linq.JTokenType.String) + { + _debugLogLevel = ((string)debugLogLevel)?.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); } @@ -588,6 +645,12 @@ namespace GitHub.Runner.Worker.Dap Trace.Info($"Evaluate: '{expression}' (context: {evalContext})"); + // Check for !debug command (works in any context) + if (expression.StartsWith("!debug", StringComparison.OrdinalIgnoreCase)) + { + return HandleDebugCommand(expression); + } + // Get the current execution context var executionContext = _currentStep?.ExecutionContext ?? _jobContext; if (executionContext == null) @@ -963,6 +1026,56 @@ namespace GitHub.Runner.Worker.Dap #endif } + /// + /// Handles the !debug REPL command for controlling debug logging. + /// + 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)"; + Trace.Info("Debug logging enabled via REPL command"); + break; + case "off": + _debugLogLevel = DebugLogLevel.Off; + result = "Debug logging disabled"; + Trace.Info("Debug logging disabled via REPL command"); + break; + case "minimal": + _debugLogLevel = DebugLogLevel.Minimal; + result = "Debug logging set to minimal"; + Trace.Info("Debug log level set to minimal via REPL command"); + break; + case "normal": + _debugLogLevel = DebugLogLevel.Normal; + result = "Debug logging set to normal"; + Trace.Info("Debug log level set to normal via REPL command"); + break; + case "verbose": + _debugLogLevel = DebugLogLevel.Verbose; + result = "Debug logging set to verbose"; + Trace.Info("Debug log level set to verbose via REPL command"); + break; + case "status": + default: + result = $"Debug logging: {_debugLogLevel}\n" + + $"Commands: !debug [on|off|minimal|normal|verbose|status]"; + break; + } + + return CreateSuccessResponse(new EvaluateResponseBody + { + Result = result, + VariablesReference = 0 + }); + } + private Response HandleSetBreakpoints(Request request) { // Stub - breakpoints not implemented in demo @@ -1053,9 +1166,19 @@ namespace GitHub.Runner.Worker.Dap _currentStep = step; _jobContext = jobContext; + // 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); + } + // Reset variable provider state for new step context _variableProvider.Reset(); + // Log step starting + DebugLog($"[Step] Starting: '{step.DisplayName}' (index={_pendingStepIndex})"); + DebugLog($"[Step] Checkpoints available: {_checkpoints.Count}"); + // Determine if we should pause bool shouldPause = isFirstStep || _pauseOnNextStep; @@ -1099,6 +1222,24 @@ namespace GitHub.Runner.Worker.Dap var result = step.ExecutionContext?.Result; Trace.Info($"Step completed: {step.DisplayName}, result: {result}"); + // Log step completion + DebugLog($"[Step] Completed: '{step.DisplayName}', result={result}"); + + // Log current steps context state for this step at Normal level + 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}"); + } + } + } + // Add to completed steps list _completedSteps.Add(new CompletedStepInfo { @@ -1285,6 +1426,17 @@ namespace GitHub.Runner.Worker.Dap $"(env vars: {checkpoint.EnvironmentVariables.Count}, " + $"prepend paths: {checkpoint.PrependPath.Count})"); + // Debug logging for checkpoint creation + 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); + } + } + // Send notification to debugger _server?.SendEvent(new Event { @@ -1342,6 +1494,13 @@ namespace GitHub.Runner.Worker.Dap var checkpoint = _checkpoints[checkpointIndex]; Trace.Info($"Restoring checkpoint [{checkpointIndex}] for step '{checkpoint.StepDisplayName}'"); + // Debug logging for checkpoint restoration + DebugLog($"[Checkpoint] Restoring [{checkpointIndex}] for step '{checkpoint.StepDisplayName}'"); + if (_debugLogLevel >= DebugLogLevel.Verbose) + { + DebugLog($"[Checkpoint] Snapshot has {checkpoint.StepsSnapshot.Count} step(s)", DebugLogLevel.Verbose); + } + // Restore environment variables jobContext.Global.EnvironmentVariables.Clear(); foreach (var kvp in checkpoint.EnvironmentVariables) @@ -1360,9 +1519,8 @@ namespace GitHub.Runner.Worker.Dap jobContext.Result = checkpoint.JobResult; jobContext.JobContext.Status = checkpoint.JobStatus; - // Note: StepsContext restoration is complex and requires internal access - // For now, we just log this limitation - Trace.Info($"Steps context restoration: {checkpoint.StepsSnapshot.Count} steps in snapshot (partial restoration)"); + // Restore steps context - clear scope and restore from snapshot + RestoreStepsContext(jobContext.Global.StepsContext, checkpoint.StepsSnapshot, jobContext.ScopeName); // Clear checkpoints after this one (they're now invalid) if (checkpointIndex + 1 < _checkpoints.Count) @@ -1444,6 +1602,59 @@ namespace GitHub.Runner.Worker.Dap context.ExpressionValues["env"] = newEnvContext; } + private void RestoreStepsContext(StepsContext stepsContext, Dictionary snapshot, string scopeName) + { + // Normalize scope name (null -> empty string) + scopeName = scopeName ?? string.Empty; + + DebugLog($"[StepsContext] Restoring: clearing scope '{(string.IsNullOrEmpty(scopeName) ? "(root)" : scopeName)}', will restore {snapshot.Count} step(s)"); + + // Clear the entire scope - removes all step data that shouldn't exist yet in this timeline + stepsContext.ClearScope(scopeName); + + // Restore each step's state from the snapshot + foreach (var entry in snapshot) + { + // Key format is "{scopeName}/{stepName}" - e.g., "/thefoo" for root-level steps (empty scope) + 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); + + // Only restore steps for the current scope + 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); + } + + // Restore outputs + 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"); + } + private Dictionary SnapshotStepsContext(StepsContext stepsContext, string scopeName) { var result = new Dictionary(); @@ -1507,6 +1718,31 @@ namespace GitHub.Runner.Worker.Dap #endregion + #region Debug Logging + + /// + /// Sends a debug log message to the DAP console if the current log level permits. + /// + /// The message to log (will be prefixed with [DEBUG]) + /// Minimum level required for this message to be logged + 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" + } + }); + } + } + + #endregion + #region Response Helpers private Response CreateSuccessResponse(object body) diff --git a/src/Runner.Worker/StepsContext.cs b/src/Runner.Worker/StepsContext.cs index 6f16956e5..c2e0e32ee 100644 --- a/src/Runner.Worker/StepsContext.cs +++ b/src/Runner.Worker/StepsContext.cs @@ -1,4 +1,4 @@ -using GitHub.DistributedTask.Pipelines.ContextData; +using GitHub.DistributedTask.Pipelines.ContextData; using GitHub.DistributedTask.WebApi; using GitHub.Runner.Common.Util; using System; @@ -19,12 +19,31 @@ namespace GitHub.Runner.Worker private static readonly Regex _propertyRegex = new("^[a-zA-Z_][a-zA-Z0-9_]*$", RegexOptions.Compiled); private readonly DictionaryContextData _contextData = new(); + /// + /// Optional callback for debug logging. When set, will be called with debug messages + /// for all StepsContext mutations. + /// + public Action OnDebugLog { get; set; } + + private void DebugLog(string message) + { + OnDebugLog?.Invoke(message); + } + + 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) + "..."; + } + /// /// Clears memory for a composite action's isolated "steps" context, after the action /// is finished executing. /// public void ClearScope(string scopeName) { + DebugLog($"[StepsContext] ClearScope: scope='{scopeName ?? "(root)"}'"); if (_contextData.TryGetValue(scopeName, out _)) { _contextData[scopeName] = new DictionaryContextData(); @@ -78,6 +97,7 @@ namespace GitHub.Runner.Worker { reference = $"steps['{stepName}']['outputs']['{outputName}']"; } + DebugLog($"[StepsContext] SetOutput: step='{stepName}', output='{outputName}', value='{TruncateValue(value)}'"); } public void SetConclusion( @@ -86,7 +106,9 @@ namespace GitHub.Runner.Worker ActionResult conclusion) { var step = GetStep(scopeName, stepName); - step["conclusion"] = new StringContextData(conclusion.ToString().ToLowerInvariant()); + var conclusionStr = conclusion.ToString().ToLowerInvariant(); + step["conclusion"] = new StringContextData(conclusionStr); + DebugLog($"[StepsContext] SetConclusion: step='{stepName}', conclusion={conclusionStr}"); } public void SetOutcome( @@ -95,7 +117,9 @@ namespace GitHub.Runner.Worker ActionResult outcome) { var step = GetStep(scopeName, stepName); - step["outcome"] = new StringContextData(outcome.ToString().ToLowerInvariant()); + var outcomeStr = outcome.ToString().ToLowerInvariant(); + step["outcome"] = new StringContextData(outcomeStr); + DebugLog($"[StepsContext] SetOutcome: step='{stepName}', outcome={outcomeStr}"); } private DictionaryContextData GetStep(string scopeName, string stepName)