mirror of
https://github.com/actions/runner.git
synced 2026-01-17 01:03:38 +08:00
logging
This commit is contained in:
Francesco Renzi
511
.opencode/plans/dap-debug-logging.md
Normal file
511
.opencode/plans/dap-debug-logging.md
Normal file
@@ -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();
|
||||
|
||||
/// <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`:
|
||||
|
||||
```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<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):
|
||||
|
||||
```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
|
||||
Reference in New Issue
Block a user