Skip to content

Commit 570cc81

Browse files
committed
feat(12-01): add structured state transition logging with Stopwatch timing in GsdStateMachine
1 parent af9b38d commit 570cc81

1 file changed

Lines changed: 19 additions & 7 deletions

File tree

src/GsdOrchestrator/Workflows/GsdStateMachine.cs

Lines changed: 19 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -49,13 +49,15 @@ public async Task<GsdWorkflowContext> ResumeAsync(string workflowId, Cancellatio
4949
var ctx = await _checkpoints.LoadAsync(workflowId, ct)
5050
?? throw new InvalidOperationException($"No checkpoint found for workflow '{workflowId}'");
5151

52-
_logger.LogInformation("Resuming workflow {Id} from state {State}", workflowId, ctx.CurrentState);
52+
_logger.LogInformation("Resuming workflow {WorkflowId} from state {StateName}", workflowId, ctx.CurrentState);
5353
return await ExecuteLoopAsync(ctx, ct);
5454
}
5555

5656
private async Task<GsdWorkflowContext> ExecuteLoopAsync(GsdWorkflowContext ctx, CancellationToken ct)
5757
{
58-
_logger.LogInformation("Workflow {Id} starting at state {State}", ctx.WorkflowId, ctx.CurrentState);
58+
_logger.LogInformation(
59+
"Workflow {WorkflowId} starting at state {StateName}. IssueNumber={IssueNumber}",
60+
ctx.WorkflowId, ctx.CurrentState, ctx.Issue?.Number);
5961

6062
while (ctx.CurrentState is not WorkflowState.Done and not WorkflowState.Failed)
6163
{
@@ -64,24 +66,35 @@ private async Task<GsdWorkflowContext> ExecuteLoopAsync(GsdWorkflowContext ctx,
6466
if (!_states.TryGetValue(ctx.CurrentState, out var stateHandler))
6567
throw new InvalidOperationException($"No handler registered for state {ctx.CurrentState}");
6668

69+
var previousState = ctx.CurrentState;
70+
var sw = System.Diagnostics.Stopwatch.StartNew();
6771
try
6872
{
6973
// Checkpoint BEFORE executing (so we can resume from this state)
7074
await _checkpoints.SaveAsync(ctx, ct);
7175

7276
ctx = await stateHandler.ExecuteAsync(ctx, ct);
77+
sw.Stop();
7378

74-
_logger.LogInformation("[{Id}] → {State}", ctx.WorkflowId, ctx.CurrentState);
79+
_logger.LogInformation(
80+
"State {StateName} completed in {DurationMs}ms — WorkflowId={WorkflowId} IssueNumber={IssueNumber} NextState={NextState}",
81+
previousState, sw.ElapsedMilliseconds, ctx.WorkflowId, ctx.Issue?.Number, ctx.CurrentState);
7582
}
7683
catch (OperationCanceledException)
7784
{
78-
_logger.LogWarning("Workflow {Id} cancelled at state {State}", ctx.WorkflowId, ctx.CurrentState);
85+
sw.Stop();
86+
_logger.LogWarning(
87+
"Workflow {WorkflowId} cancelled at state {StateName} after {DurationMs}ms. IssueNumber={IssueNumber}",
88+
ctx.WorkflowId, previousState, sw.ElapsedMilliseconds, ctx.Issue?.Number);
7989
await _checkpoints.SaveAsync(ctx, ct);
8090
throw;
8191
}
8292
catch (Exception ex)
8393
{
84-
_logger.LogError(ex, "Workflow {Id} failed at state {State}", ctx.WorkflowId, ctx.CurrentState);
94+
sw.Stop();
95+
_logger.LogError(ex,
96+
"Workflow {WorkflowId} failed at state {StateName} after {DurationMs}ms. IssueNumber={IssueNumber}",
97+
ctx.WorkflowId, previousState, sw.ElapsedMilliseconds, ctx.Issue?.Number);
8598
ctx = (ctx with { FailureReason = ex.Message }).Transition(WorkflowState.Failed);
8699
}
87100
}
@@ -106,8 +119,7 @@ private async Task PostFailureCommentAsync(GsdWorkflowContext ctx, CancellationT
106119
if (ctx.Issue is null) return;
107120
try
108121
{
109-
var body = $"""
110-
🤖 **GSD Orchestrator failed**
122+
var body = $""" 🤖 **GSD Orchestrator failed**
111123
112124
Last state: `{ctx.History.LastOrDefault()?.From}`
113125
Reason: {ctx.FailureReason ?? "Unknown error"}

0 commit comments

Comments
 (0)