From d55f025f16c183afe5c22855653c559852625ddb Mon Sep 17 00:00:00 2001 From: Sas Swart Date: Fri, 10 Jul 2026 09:29:47 +0000 Subject: [PATCH] feat: derive unit readiness intervals and add sync timeline CLI --- agent/agentsocket/client.go | 11 ++ agent/agentsocket/server.go | 7 +- agent/unit/timeline.go | 107 +++++++++++ agent/unit/timeline_test.go | 167 ++++++++++++++++++ cli/root_test.go | 4 + cli/sync.go | 1 + cli/sync_status.go | 49 ++++- cli/sync_test.go | 85 +++++++++ cli/sync_timeline.go | 88 +++++++++ cli/sync_timeline_internal_test.go | 84 +++++++++ cli/sync_timeline_render.go | 157 ++++++++++++++++ .../status_completed.golden | 6 + .../status_pending.golden | 5 + .../status_started.golden | 5 + .../status_with_dependencies.golden | 6 + .../timeline_json_format.golden | 40 +++++ .../timeline_no_events.golden | 1 + .../timeline_with_units.golden | 9 + cli/testdata/coder_exp_sync_--help.golden | 1 + .../coder_exp_sync_timeline_--help.golden | 18 ++ 20 files changed, 843 insertions(+), 8 deletions(-) create mode 100644 agent/unit/timeline.go create mode 100644 agent/unit/timeline_test.go create mode 100644 cli/sync_timeline.go create mode 100644 cli/sync_timeline_internal_test.go create mode 100644 cli/sync_timeline_render.go create mode 100644 cli/testdata/TestSyncCommands_Golden/timeline_json_format.golden create mode 100644 cli/testdata/TestSyncCommands_Golden/timeline_no_events.golden create mode 100644 cli/testdata/TestSyncCommands_Golden/timeline_with_units.golden create mode 100644 cli/testdata/coder_exp_sync_timeline_--help.golden diff --git a/agent/agentsocket/client.go b/agent/agentsocket/client.go index 975fdd5d5db..73fb997be78 100644 --- a/agent/agentsocket/client.go +++ b/agent/agentsocket/client.go @@ -19,6 +19,7 @@ type Option func(*options) type options struct { path string contextManager ContextManager + unitManager *unit.Manager } // WithPath sets the socket path. If not provided or empty, the client will @@ -40,6 +41,16 @@ func WithContextManager(cm ContextManager) Option { } } +// WithUnitManager supplies the unit Manager the server uses for sync +// coordination, letting tests inject a Manager with a mock clock for +// deterministic event timestamps. If not provided, the server constructs +// its own. Server-only; ignored by the client. +func WithUnitManager(um *unit.Manager) Option { + return func(opts *options) { + opts.unitManager = um + } +} + // Client provides a client for communicating with the workspace agentsocket API. type Client struct { client proto.DRPCAgentSocketClient diff --git a/agent/agentsocket/server.go b/agent/agentsocket/server.go index 605feeec05a..05033f7bf53 100644 --- a/agent/agentsocket/server.go +++ b/agent/agentsocket/server.go @@ -39,13 +39,18 @@ func NewServer(logger slog.Logger, opts ...Option) (*Server, error) { opt(options) } + unitManager := options.unitManager + if unitManager == nil { + unitManager = unit.NewManager() + } + logger = logger.Named("agentsocket-server") server := &Server{ logger: logger, path: options.path, service: &DRPCAgentSocketService{ logger: logger, - unitManager: unit.NewManager(), + unitManager: unitManager, contextManager: options.contextManager, }, } diff --git a/agent/unit/timeline.go b/agent/unit/timeline.go new file mode 100644 index 00000000000..66d728e4c23 --- /dev/null +++ b/agent/unit/timeline.go @@ -0,0 +1,107 @@ +package unit + +import "time" + +// Phase is a derived stage of a unit's lifecycle. Phases are not stored +// by the Manager; they are reconstructed from the event log. +type Phase string + +const ( + // PhaseBlocked means the unit is registered but at least one of its + // dependencies is not at its required status. + PhaseBlocked Phase = "blocked" + // PhaseReady means the unit is registered and every declared + // dependency is at its required status. + PhaseReady Phase = "ready" + // PhaseRunning means the unit has started. + PhaseRunning Phase = "running" + // PhaseDone means the unit has completed. + PhaseDone Phase = "done" +) + +// Interval is a derived span of a unit's lifecycle. +type Interval struct { + Unit ID + Phase Phase + Start time.Time + // End is the zero time if the interval is still open. + End time.Time +} + +// DeriveIntervals replays events in Seq order and returns per-unit +// lifecycle intervals. Readiness is reconstructed from status_change and +// dependency_added events, mirroring the Manager's readiness semantics +// (recalculateReadinessUnsafe): a pending unit is ready when every +// declared dependency's current status equals its required status. This +// captures blocked-to-ready flips caused by other units' status changes +// and ready-to-blocked flips caused by dependency edges added after +// registration. +func DeriveIntervals(events []Event) map[ID][]Interval { + type edge struct { + dependsOn ID + requiredStatus Status + } + statuses := make(map[ID]Status) + deps := make(map[ID][]edge) + // dependents holds reverse edges so a status change can be folded + // into the phase of every unit that depends on the changed unit. + dependents := make(map[ID][]ID) + intervals := make(map[ID][]Interval) + + // phaseOf derives the current phase of a registered unit from the + // replayed state. The second return is false for units that have + // not registered yet (for example, a dependency that only appears + // on the depends-on side of an edge). + phaseOf := func(u ID) (Phase, bool) { + switch statuses[u] { + case StatusNotRegistered: + return "", false + case StatusStarted: + return PhaseRunning, true + case StatusComplete: + return PhaseDone, true + } + for _, e := range deps[u] { + if statuses[e.dependsOn] != e.requiredStatus { + return PhaseBlocked, true + } + } + return PhaseReady, true + } + + // setPhase closes the unit's open interval and opens a new one if + // the phase changed. + setPhase := func(u ID, phase Phase, at time.Time) { + ivs := intervals[u] + if len(ivs) > 0 { + last := &ivs[len(ivs)-1] + if last.Phase == phase { + return + } + last.End = at + } + intervals[u] = append(ivs, Interval{Unit: u, Phase: phase, Start: at}) + } + + for _, ev := range events { + affected := []ID{ev.Unit} + switch ev.Kind { + case EventStatusChange: + statuses[ev.Unit] = ev.To + affected = append(affected, dependents[ev.Unit]...) + case EventDependencyAdded: + deps[ev.Unit] = append(deps[ev.Unit], edge{ + dependsOn: ev.DependsOn, + requiredStatus: ev.RequiredStatus, + }) + dependents[ev.DependsOn] = append(dependents[ev.DependsOn], ev.Unit) + } + for _, u := range affected { + if phase, ok := phaseOf(u); ok { + setPhase(u, phase, ev.Time) + } + } + } + + return intervals +} diff --git a/agent/unit/timeline_test.go b/agent/unit/timeline_test.go new file mode 100644 index 00000000000..32861fccdce --- /dev/null +++ b/agent/unit/timeline_test.go @@ -0,0 +1,167 @@ +package unit_test + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/coder/coder/v2/agent/unit" + "github.com/coder/quartz" +) + +func TestDeriveIntervals(t *testing.T) { + t.Parallel() + + t.Run("Empty", func(t *testing.T) { + t.Parallel() + + require.Empty(t, unit.DeriveIntervals(nil)) + }) + + t.Run("SingleUnitLifecycle", func(t *testing.T) { + t.Parallel() + + clock := quartz.NewMock(t) + manager := unit.NewManager(unit.WithClock(clock)) + start := clock.Now() + + require.NoError(t, manager.Register(unitA)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusStarted)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusComplete)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Equal(t, map[unit.ID][]unit.Interval{ + unitA: { + {Unit: unitA, Phase: unit.PhaseReady, Start: start, End: start.Add(time.Second)}, + {Unit: unitA, Phase: unit.PhaseRunning, Start: start.Add(time.Second), End: start.Add(2 * time.Second)}, + {Unit: unitA, Phase: unit.PhaseDone, Start: start.Add(2 * time.Second)}, + }, + }, intervals) + }) + + t.Run("BlockedUntilDependencySatisfied", func(t *testing.T) { + t.Parallel() + + clock := quartz.NewMock(t) + manager := unit.NewManager(unit.WithClock(clock)) + start := clock.Now() + + // unitB registers with an immediate dependency on unitA, which + // registers later and runs to completion. + require.NoError(t, manager.Register(unitB)) + require.NoError(t, manager.AddDependency(unitB, unitA, unit.StatusComplete)) + clock.Advance(time.Second) + require.NoError(t, manager.Register(unitA)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusStarted)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusComplete)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitB, unit.StatusStarted)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Equal(t, []unit.Interval{ + // Registration opens a ready interval that the immediately + // following dependency_added event closes at the same instant. + {Unit: unitB, Phase: unit.PhaseReady, Start: start, End: start}, + {Unit: unitB, Phase: unit.PhaseBlocked, Start: start, End: start.Add(3 * time.Second)}, + {Unit: unitB, Phase: unit.PhaseReady, Start: start.Add(3 * time.Second), End: start.Add(4 * time.Second)}, + {Unit: unitB, Phase: unit.PhaseRunning, Start: start.Add(4 * time.Second)}, + }, intervals[unitB]) + }) + + t.Run("LateDependencyFlipsReadyToBlocked", func(t *testing.T) { + t.Parallel() + + clock := quartz.NewMock(t) + manager := unit.NewManager(unit.WithClock(clock)) + start := clock.Now() + + // unitA registers with no dependencies, so it is immediately + // ready. A dependency added afterwards flips it back to blocked + // with no status change. This is the edge case that motivates + // recording dependency_added events. + require.NoError(t, manager.Register(unitA)) + clock.Advance(time.Second) + require.NoError(t, manager.AddDependency(unitA, unitB, unit.StatusComplete)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Equal(t, []unit.Interval{ + {Unit: unitA, Phase: unit.PhaseReady, Start: start, End: start.Add(time.Second)}, + {Unit: unitA, Phase: unit.PhaseBlocked, Start: start.Add(time.Second)}, + }, intervals[unitA]) + }) + + t.Run("MultipleDependencies", func(t *testing.T) { + t.Parallel() + + clock := quartz.NewMock(t) + manager := unit.NewManager(unit.WithClock(clock)) + start := clock.Now() + + // unitC depends on both unitA and unitB completing. It only + // becomes ready when the last dependency is satisfied. + require.NoError(t, manager.Register(unitC)) + require.NoError(t, manager.AddDependency(unitC, unitA, unit.StatusComplete)) + require.NoError(t, manager.AddDependency(unitC, unitB, unit.StatusComplete)) + require.NoError(t, manager.Register(unitA)) + require.NoError(t, manager.Register(unitB)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusStarted)) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusComplete)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitB, unit.StatusStarted)) + require.NoError(t, manager.UpdateStatus(unitB, unit.StatusComplete)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Equal(t, []unit.Interval{ + {Unit: unitC, Phase: unit.PhaseReady, Start: start, End: start}, + {Unit: unitC, Phase: unit.PhaseBlocked, Start: start, End: start.Add(2 * time.Second)}, + {Unit: unitC, Phase: unit.PhaseReady, Start: start.Add(2 * time.Second)}, + }, intervals[unitC]) + }) + + t.Run("DependencyOnRunningStatus", func(t *testing.T) { + t.Parallel() + + clock := quartz.NewMock(t) + manager := unit.NewManager(unit.WithClock(clock)) + start := clock.Now() + + // A dependency requiring StatusStarted is satisfied while the + // dependency runs and unsatisfied again once it completes. + require.NoError(t, manager.Register(unitB)) + require.NoError(t, manager.AddDependency(unitB, unitA, unit.StatusStarted)) + require.NoError(t, manager.Register(unitA)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusStarted)) + clock.Advance(time.Second) + require.NoError(t, manager.UpdateStatus(unitA, unit.StatusComplete)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Equal(t, []unit.Interval{ + {Unit: unitB, Phase: unit.PhaseReady, Start: start, End: start}, + {Unit: unitB, Phase: unit.PhaseBlocked, Start: start, End: start.Add(time.Second)}, + {Unit: unitB, Phase: unit.PhaseReady, Start: start.Add(time.Second), End: start.Add(2 * time.Second)}, + {Unit: unitB, Phase: unit.PhaseBlocked, Start: start.Add(2 * time.Second)}, + }, intervals[unitB]) + }) + + t.Run("UnregisteredDependencyHasNoIntervals", func(t *testing.T) { + t.Parallel() + + manager := unit.NewManager(unit.WithClock(quartz.NewMock(t))) + + // unitB never registers; it only appears on the depends-on side + // of an edge, so it must not get intervals of its own. + require.NoError(t, manager.Register(unitA)) + require.NoError(t, manager.AddDependency(unitA, unitB, unit.StatusComplete)) + + intervals := unit.DeriveIntervals(manager.Events()) + require.Contains(t, intervals, unitA) + require.NotContains(t, intervals, unitB) + }) +} diff --git a/cli/root_test.go b/cli/root_test.go index 534bf9b9cf2..b0da45df789 100644 --- a/cli/root_test.go +++ b/cli/root_test.go @@ -103,6 +103,10 @@ func TestCommandHelp(t *testing.T) { Name: "coder exp sync list --help", Cmd: []string{"exp", "sync", "list", "--help"}, }, + clitest.CommandHelpCase{ + Name: "coder exp sync timeline --help", + Cmd: []string{"exp", "sync", "timeline", "--help"}, + }, )) } diff --git a/cli/sync.go b/cli/sync.go index 01046cbeac6..08e68a599fe 100644 --- a/cli/sync.go +++ b/cli/sync.go @@ -21,6 +21,7 @@ func (r *RootCmd) syncCommand() *serpent.Command { r.syncComplete(&socketPath), r.syncStatus(&socketPath), r.syncList(&socketPath), + r.syncTimeline(&socketPath), }, Options: serpent.OptionSet{ { diff --git a/cli/sync_status.go b/cli/sync_status.go index e394a0e6c84..549c6cc3489 100644 --- a/cli/sync_status.go +++ b/cli/sync_status.go @@ -2,6 +2,7 @@ package cli import ( "fmt" + "strings" "golang.org/x/xerrors" @@ -62,18 +63,30 @@ func (*RootCmd) syncStatus(socketPath *string) *serpent.Command { } var out string - header := fmt.Sprintf("Unit: %s\nStatus: %s\nReady: %t\n\nDependencies:\n", unit, statusResp.Status, statusResp.IsReady) - if formatter.FormatID() == "table" && len(statusResp.Dependencies) == 0 { - out = header + "No dependencies found" + if formatter.FormatID() == "table" { + header := fmt.Sprintf("Unit: %s\nStatus: %s\nReady: %t\n\nDependencies:\n", unit, statusResp.Status, statusResp.IsReady) + dependencies := "No dependencies found" + if len(statusResp.Dependencies) > 0 { + dependencies, err = formatter.Format(ctx, statusResp) + if err != nil { + return xerrors.Errorf("format status: %w", err) + } + dependencies = strings.TrimRight(dependencies, "\n") + } + history := "No history found" + if len(statusResp.History) > 0 { + history, err = cliui.DisplayTable(syncHistoryRows(statusResp.History), "", nil) + if err != nil { + return xerrors.Errorf("format history: %w", err) + } + history = strings.TrimRight(history, "\n") + } + out = header + dependencies + "\n\nHistory:\n" + history } else { out, err = formatter.Format(ctx, statusResp) if err != nil { return xerrors.Errorf("format status: %w", err) } - - if formatter.FormatID() == "table" { - out = header + out - } } _, _ = fmt.Fprintln(i.Stdout, out) @@ -85,3 +98,25 @@ func (*RootCmd) syncStatus(socketPath *string) *serpent.Command { formatter.AttachOptions(&cmd.Options) return cmd } + +// syncHistoryRow is one rendered line of a unit's event history. +type syncHistoryRow struct { + Time string `table:"time,nosort"` + Elapsed string `table:"elapsed"` + Event string `table:"event"` +} + +// syncHistoryRows renders unit events as history table rows. Times are +// shown in UTC; elapsed offsets are relative to the first event. +func syncHistoryRows(history []agentsocket.UnitEvent) []syncHistoryRow { + rows := make([]syncHistoryRow, 0, len(history)) + base := history[0].Time + for _, ev := range unitEventsFromSocket(history) { + rows = append(rows, syncHistoryRow{ + Time: ev.Time.UTC().Format("15:04:05.000"), + Elapsed: syncElapsed(base, ev.Time), + Event: syncEventDescription(ev), + }) + } + return rows +} diff --git a/cli/sync_test.go b/cli/sync_test.go index 6af7b10b011..974fdd05f26 100644 --- a/cli/sync_test.go +++ b/cli/sync_test.go @@ -12,8 +12,10 @@ import ( "cdr.dev/slog/v3" "github.com/coder/coder/v2/agent/agentsocket" + "github.com/coder/coder/v2/agent/unit" "github.com/coder/coder/v2/cli/clitest" "github.com/coder/coder/v2/testutil" + "github.com/coder/quartz" ) // setupSocketServer creates an agentsocket server at a temporary path for testing. @@ -36,6 +38,9 @@ func setupSocketServer(t *testing.T) (path string, cleanup func()) { server, err := agentsocket.NewServer( slog.Make().Leveled(slog.LevelDebug), agentsocket.WithPath(socketPath), + // A mock clock keeps event timestamps deterministic so golden + // files that include unit event history are stable. + agentsocket.WithUnitManager(unit.NewManager(unit.WithClock(quartz.NewMock(t)))), ) require.NoError(t, err, "create socket server") @@ -428,6 +433,86 @@ func TestSyncCommands_Golden(t *testing.T) { clitest.TestGoldenFile(t, "TestSyncCommands_Golden/list_no_units", outBuf.Bytes(), nil) }) + t.Run("timeline_no_events", func(t *testing.T) { + t.Parallel() + path, cleanup := setupSocketServer(t) + defer cleanup() + + ctx := testutil.Context(t, testutil.WaitShort) + + var outBuf bytes.Buffer + inv, _ := clitest.New(t, "exp", "sync", "timeline", "--socket-path", path) + inv.Stdout = &outBuf + inv.Stderr = &outBuf + + err := inv.WithContext(ctx).Run() + require.NoError(t, err) + + clitest.TestGoldenFile(t, "TestSyncCommands_Golden/timeline_no_events", outBuf.Bytes(), nil) + }) + + t.Run("timeline_with_units", func(t *testing.T) { + t.Parallel() + path, cleanup := setupSocketServer(t) + defer cleanup() + + ctx := testutil.Context(t, testutil.WaitShort) + + // dep-unit runs to completion, unblocking test-unit which then + // runs to completion itself. + client, err := agentsocket.NewClient(ctx, agentsocket.WithPath(path)) + require.NoError(t, err) + err = client.SyncWant(ctx, "test-unit", "dep-unit") + require.NoError(t, err) + err = client.SyncStart(ctx, "dep-unit") + require.NoError(t, err) + err = client.SyncComplete(ctx, "dep-unit") + require.NoError(t, err) + err = client.SyncStart(ctx, "test-unit") + require.NoError(t, err) + err = client.SyncComplete(ctx, "test-unit") + require.NoError(t, err) + client.Close() + + var outBuf bytes.Buffer + inv, _ := clitest.New(t, "exp", "sync", "timeline", "--socket-path", path) + inv.Stdout = &outBuf + inv.Stderr = &outBuf + + err = inv.WithContext(ctx).Run() + require.NoError(t, err) + + clitest.TestGoldenFile(t, "TestSyncCommands_Golden/timeline_with_units", outBuf.Bytes(), nil) + }) + + t.Run("timeline_json_format", func(t *testing.T) { + t.Parallel() + path, cleanup := setupSocketServer(t) + defer cleanup() + + ctx := testutil.Context(t, testutil.WaitShort) + + client, err := agentsocket.NewClient(ctx, agentsocket.WithPath(path)) + require.NoError(t, err) + err = client.SyncWant(ctx, "test-unit", "dep-unit") + require.NoError(t, err) + err = client.SyncStart(ctx, "dep-unit") + require.NoError(t, err) + err = client.SyncComplete(ctx, "dep-unit") + require.NoError(t, err) + client.Close() + + var outBuf bytes.Buffer + inv, _ := clitest.New(t, "exp", "sync", "timeline", "--output", "json", "--socket-path", path) + inv.Stdout = &outBuf + inv.Stderr = &outBuf + + err = inv.WithContext(ctx).Run() + require.NoError(t, err) + + clitest.TestGoldenFile(t, "TestSyncCommands_Golden/timeline_json_format", outBuf.Bytes(), nil) + }) + t.Run("list_with_units", func(t *testing.T) { t.Parallel() path, cleanup := setupSocketServer(t) diff --git a/cli/sync_timeline.go b/cli/sync_timeline.go new file mode 100644 index 00000000000..704a83e18d8 --- /dev/null +++ b/cli/sync_timeline.go @@ -0,0 +1,88 @@ +package cli + +import ( + "fmt" + "strings" + + "golang.org/x/xerrors" + + "github.com/coder/coder/v2/agent/agentsocket" + "github.com/coder/coder/v2/agent/unit" + "github.com/coder/coder/v2/cli/cliui" + "github.com/coder/serpent" +) + +func (*RootCmd) syncTimeline(socketPath *string) *serpent.Command { + formatter := cliui.NewOutputFormatter( + cliui.ChangeFormatterData( + cliui.TextFormat(), + func(data any) (any, error) { + events, ok := data.([]agentsocket.UnitEvent) + if !ok { + return nil, xerrors.Errorf("expected []agentsocket.UnitEvent, got %T", data) + } + return renderTimeline(unitEventsFromSocket(events)), nil + }), + cliui.JSONFormat(), + ) + + cmd := &serpent.Command{ + Use: "timeline", + Short: "Show a timeline of unit state changes", + Long: "Show every recorded unit state transition and dependency declaration across all units, in the order they occurred. The default output is an ASCII graph of the dependency DAG in event-time order; use --output json for the raw event list.", + Handler: func(i *serpent.Invocation) error { + ctx := i.Context() + + opts := []agentsocket.Option{} + if *socketPath != "" { + opts = append(opts, agentsocket.WithPath(*socketPath)) + } + + client, err := agentsocket.NewClient(ctx, opts...) + if err != nil { + return xerrors.Errorf("connect to agent socket: %w", err) + } + defer client.Close() + + events, err := client.SyncTimeline(ctx) + if err != nil { + // Older agents do not implement the SyncTimeline RPC. + if strings.Contains(err.Error(), "unknown rpc") { + return xerrors.New("agent does not support timeline") + } + return xerrors.Errorf("get timeline failed: %w", err) + } + + out, err := formatter.Format(ctx, events) + if err != nil { + return xerrors.Errorf("format timeline: %w", err) + } + + _, _ = fmt.Fprintln(i.Stdout, out) + + return nil + }, + } + + formatter.AttachOptions(&cmd.Options) + return cmd +} + +// unitEventsFromSocket converts socket client event wrappers back to +// unit.Event values for rendering and derivation. +func unitEventsFromSocket(events []agentsocket.UnitEvent) []unit.Event { + out := make([]unit.Event, 0, len(events)) + for _, ev := range events { + out = append(out, unit.Event{ + Seq: ev.Seq, + Time: ev.Time, + Kind: ev.Kind, + Unit: ev.Unit, + From: ev.From, + To: ev.To, + DependsOn: ev.DependsOn, + RequiredStatus: ev.RequiredStatus, + }) + } + return out +} diff --git a/cli/sync_timeline_internal_test.go b/cli/sync_timeline_internal_test.go new file mode 100644 index 00000000000..650d9aeb12a --- /dev/null +++ b/cli/sync_timeline_internal_test.go @@ -0,0 +1,84 @@ +package cli + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/coder/coder/v2/agent/unit" +) + +func TestRenderTimeline(t *testing.T) { + t.Parallel() + + base := time.Date(2024, 1, 1, 14, 2, 1, 0, time.UTC) + at := base.Add + + t.Run("Empty", func(t *testing.T) { + t.Parallel() + + require.Equal(t, "No events found", renderTimeline(nil)) + }) + + t.Run("SingleUnit", func(t *testing.T) { + t.Parallel() + + events := []unit.Event{ + {Seq: 1, Time: at(0), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusNotRegistered, To: unit.StatusPending}, + {Seq: 2, Time: at(100 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusPending, To: unit.StatusStarted}, + {Seq: 3, Time: at(2300 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusStarted, To: unit.StatusComplete}, + } + require.Equal(t, `* [+0.0s] db-migrate registered (pending) +* [+0.1s] db-migrate pending → started +* [+2.3s] db-migrate started → completed`, renderTimeline(events)) + }) + + t.Run("DependencySatisfaction", func(t *testing.T) { + t.Parallel() + + // dev-server registers with a dependency on db-migrate. When + // db-migrate completes, dev-server becomes ready: a connector + // row and a derived ready row are drawn. db-migrate's lane + // disappears after completion. + events := []unit.Event{ + {Seq: 1, Time: at(0), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusNotRegistered, To: unit.StatusPending}, + {Seq: 2, Time: at(100 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusPending, To: unit.StatusStarted}, + {Seq: 3, Time: at(100 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "dev-server", From: unit.StatusNotRegistered, To: unit.StatusPending}, + {Seq: 4, Time: at(100 * time.Millisecond), Kind: unit.EventDependencyAdded, Unit: "dev-server", DependsOn: "db-migrate", RequiredStatus: unit.StatusComplete}, + {Seq: 5, Time: at(2300 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "db-migrate", From: unit.StatusStarted, To: unit.StatusComplete}, + {Seq: 6, Time: at(2400 * time.Millisecond), Kind: unit.EventStatusChange, Unit: "dev-server", From: unit.StatusPending, To: unit.StatusStarted}, + {Seq: 7, Time: at(8 * time.Second), Kind: unit.EventStatusChange, Unit: "dev-server", From: unit.StatusStarted, To: unit.StatusComplete}, + } + require.Equal(t, `* [+0.0s] db-migrate registered (pending) +* [+0.1s] db-migrate pending → started +| * [+0.1s] dev-server registered (pending) +| * [+0.1s] dev-server depends on db-migrate (completed) +* | [+2.3s] db-migrate started → completed +\ | + * [+2.3s] dev-server ready (dependency satisfied) + * [+2.4s] dev-server pending → started + * [+8.0s] dev-server started → completed`, renderTimeline(events)) + }) + + t.Run("ReadyFlipNotDrawnWhenStillBlocked", func(t *testing.T) { + t.Parallel() + + // unit-c depends on both unit-a and unit-b. Completing unit-a + // alone must not produce a derived ready row. + events := []unit.Event{ + {Seq: 1, Time: at(0), Kind: unit.EventStatusChange, Unit: "unit-c", From: unit.StatusNotRegistered, To: unit.StatusPending}, + {Seq: 2, Time: at(0), Kind: unit.EventDependencyAdded, Unit: "unit-c", DependsOn: "unit-a", RequiredStatus: unit.StatusComplete}, + {Seq: 3, Time: at(0), Kind: unit.EventDependencyAdded, Unit: "unit-c", DependsOn: "unit-b", RequiredStatus: unit.StatusComplete}, + {Seq: 4, Time: at(0), Kind: unit.EventStatusChange, Unit: "unit-a", From: unit.StatusNotRegistered, To: unit.StatusPending}, + {Seq: 5, Time: at(time.Second), Kind: unit.EventStatusChange, Unit: "unit-a", From: unit.StatusPending, To: unit.StatusStarted}, + {Seq: 6, Time: at(2 * time.Second), Kind: unit.EventStatusChange, Unit: "unit-a", From: unit.StatusStarted, To: unit.StatusComplete}, + } + require.Equal(t, `* [+0.0s] unit-c registered (pending) +* [+0.0s] unit-c depends on unit-a (completed) +* [+0.0s] unit-c depends on unit-b (completed) +| * [+0.0s] unit-a registered (pending) +| * [+1.0s] unit-a pending → started +| * [+2.0s] unit-a started → completed`, renderTimeline(events)) + }) +} diff --git a/cli/sync_timeline_render.go b/cli/sync_timeline_render.go new file mode 100644 index 00000000000..9560bbd4c38 --- /dev/null +++ b/cli/sync_timeline_render.go @@ -0,0 +1,157 @@ +package cli + +import ( + "fmt" + "strings" + "time" + + "github.com/coder/coder/v2/agent/unit" +) + +// syncEventDescription renders a unit event as a short human-readable +// phrase, shared by the sync status history and sync timeline views. +func syncEventDescription(ev unit.Event) string { + switch ev.Kind { + case unit.EventStatusChange: + if ev.From == unit.StatusNotRegistered { + return fmt.Sprintf("registered (%s)", ev.To) + } + return fmt.Sprintf("%s → %s", ev.From, ev.To) + case unit.EventDependencyAdded: + return fmt.Sprintf("depends on %s (%s)", ev.DependsOn, ev.RequiredStatus) + } + return string(ev.Kind) +} + +// syncElapsed formats the offset of t from base as a compact elapsed +// label, for example "+2.3s". +func syncElapsed(base, t time.Time) string { + return fmt.Sprintf("+%.1fs", t.Sub(base).Seconds()) +} + +// renderTimeline renders the unit event log as a git-log-style ASCII +// graph. Each unit gets a lane in order of first appearance; every event +// prints a "*" row in its unit's lane with an elapsed-time label. When a +// status change satisfies another unit's dependencies, a connector row is +// drawn from the satisfying lane to the dependent lane, followed by a +// derived "ready" row. Lanes disappear once a unit completes. +func renderTimeline(events []unit.Event) string { + if len(events) == 0 { + return "No events found" + } + + type edge struct { + dependsOn unit.ID + requiredStatus unit.Status + } + var ( + lanes []unit.ID + laneOf = make(map[unit.ID]int) + active = make(map[unit.ID]bool) + statuses = make(map[unit.ID]unit.Status) + deps = make(map[unit.ID][]edge) + dependents = make(map[unit.ID][]unit.ID) + ) + + ensureLane := func(u unit.ID) { + if _, ok := laneOf[u]; ok { + return + } + laneOf[u] = len(lanes) + lanes = append(lanes, u) + active[u] = true + } + + // isReady mirrors the Manager's readiness semantics: a pending unit + // is ready when every dependency's current status equals its + // required status. + isReady := func(u unit.ID) bool { + if statuses[u] != unit.StatusPending { + return false + } + for _, e := range deps[u] { + if statuses[e.dependsOn] != e.requiredStatus { + return false + } + } + return true + } + + // glyphRow renders one graph row: mark in the target unit's lane, + // "|" in other active lanes, and spaces elsewhere. + glyphRow := func(target unit.ID, mark string) string { + glyphs := make([]string, len(lanes)) + for i, u := range lanes { + switch { + case u == target: + glyphs[i] = mark + case active[u]: + glyphs[i] = "|" + default: + glyphs[i] = " " + } + } + return strings.TrimRight(strings.Join(glyphs, " "), " ") + } + + // connectorRow draws the dependency-satisfaction edge from lane + // "from" toward lane "to". + connectorRow := func(from, to unit.ID) string { + glyphs := make([]string, len(lanes)) + for i, u := range lanes { + switch { + case u == from && laneOf[from] < laneOf[to]: + glyphs[i] = `\` + case u == from: + glyphs[i] = "/" + case active[u]: + glyphs[i] = "|" + default: + glyphs[i] = " " + } + } + return strings.TrimRight(strings.Join(glyphs, " "), " ") + } + + base := events[0].Time + var sb strings.Builder + writeRow := func(graph string, at time.Time, u unit.ID, description string) { + _, _ = sb.WriteString(fmt.Sprintf("%s [%s] %s %s\n", graph, syncElapsed(base, at), u, description)) + } + + for _, ev := range events { + ensureLane(ev.Unit) + + switch ev.Kind { + case unit.EventStatusChange: + // Snapshot dependent readiness before applying the status + // change so blocked-to-ready flips can be detected. + wasReady := make(map[unit.ID]bool, len(dependents[ev.Unit])) + for _, dep := range dependents[ev.Unit] { + wasReady[dep] = isReady(dep) + } + + statuses[ev.Unit] = ev.To + writeRow(glyphRow(ev.Unit, "*"), ev.Time, ev.Unit, syncEventDescription(ev)) + if ev.To == unit.StatusComplete { + active[ev.Unit] = false + } + + for _, dep := range dependents[ev.Unit] { + if !wasReady[dep] && isReady(dep) { + _, _ = sb.WriteString(connectorRow(ev.Unit, dep) + "\n") + writeRow(glyphRow(dep, "*"), ev.Time, dep, "ready (dependency satisfied)") + } + } + case unit.EventDependencyAdded: + deps[ev.Unit] = append(deps[ev.Unit], edge{ + dependsOn: ev.DependsOn, + requiredStatus: ev.RequiredStatus, + }) + dependents[ev.DependsOn] = append(dependents[ev.DependsOn], ev.Unit) + writeRow(glyphRow(ev.Unit, "*"), ev.Time, ev.Unit, syncEventDescription(ev)) + } + } + + return strings.TrimRight(sb.String(), "\n") +} diff --git a/cli/testdata/TestSyncCommands_Golden/status_completed.golden b/cli/testdata/TestSyncCommands_Golden/status_completed.golden index 3fee6f914a9..3e0974c7384 100644 --- a/cli/testdata/TestSyncCommands_Golden/status_completed.golden +++ b/cli/testdata/TestSyncCommands_Golden/status_completed.golden @@ -4,3 +4,9 @@ Ready: true Dependencies: No dependencies found + +History: +TIME ELAPSED EVENT +00:00:00.000 +0.0s registered (pending) +00:00:00.000 +0.0s pending → started +00:00:00.000 +0.0s started → completed diff --git a/cli/testdata/TestSyncCommands_Golden/status_pending.golden b/cli/testdata/TestSyncCommands_Golden/status_pending.golden index 5c7e3272631..b1d49e8d918 100644 --- a/cli/testdata/TestSyncCommands_Golden/status_pending.golden +++ b/cli/testdata/TestSyncCommands_Golden/status_pending.golden @@ -5,3 +5,8 @@ Ready: false Dependencies: DEPENDS ON REQUIRED STATUS CURRENT STATUS SATISFIED dep-unit completed not registered false + +History: +TIME ELAPSED EVENT +00:00:00.000 +0.0s registered (pending) +00:00:00.000 +0.0s depends on dep-unit (completed) diff --git a/cli/testdata/TestSyncCommands_Golden/status_started.golden b/cli/testdata/TestSyncCommands_Golden/status_started.golden index 0f9fc841fbb..aacfaac47c7 100644 --- a/cli/testdata/TestSyncCommands_Golden/status_started.golden +++ b/cli/testdata/TestSyncCommands_Golden/status_started.golden @@ -4,3 +4,8 @@ Ready: true Dependencies: No dependencies found + +History: +TIME ELAPSED EVENT +00:00:00.000 +0.0s registered (pending) +00:00:00.000 +0.0s pending → started diff --git a/cli/testdata/TestSyncCommands_Golden/status_with_dependencies.golden b/cli/testdata/TestSyncCommands_Golden/status_with_dependencies.golden index 50d86f50518..4f7a075a70f 100644 --- a/cli/testdata/TestSyncCommands_Golden/status_with_dependencies.golden +++ b/cli/testdata/TestSyncCommands_Golden/status_with_dependencies.golden @@ -6,3 +6,9 @@ Dependencies: DEPENDS ON REQUIRED STATUS CURRENT STATUS SATISFIED dep-1 completed completed true dep-2 completed not registered false + +History: +TIME ELAPSED EVENT +00:00:00.000 +0.0s registered (pending) +00:00:00.000 +0.0s depends on dep-1 (completed) +00:00:00.000 +0.0s depends on dep-2 (completed) diff --git a/cli/testdata/TestSyncCommands_Golden/timeline_json_format.golden b/cli/testdata/TestSyncCommands_Golden/timeline_json_format.golden new file mode 100644 index 00000000000..26760b177c4 --- /dev/null +++ b/cli/testdata/TestSyncCommands_Golden/timeline_json_format.golden @@ -0,0 +1,40 @@ +[ + { + "seq": 1, + "time": "====[timestamp]=====", + "kind": "status_change", + "unit": "test-unit", + "to": "pending" + }, + { + "seq": 2, + "time": "====[timestamp]=====", + "kind": "dependency_added", + "unit": "test-unit", + "depends_on": "dep-unit", + "required_status": "completed" + }, + { + "seq": 3, + "time": "====[timestamp]=====", + "kind": "status_change", + "unit": "dep-unit", + "to": "pending" + }, + { + "seq": 4, + "time": "====[timestamp]=====", + "kind": "status_change", + "unit": "dep-unit", + "from": "pending", + "to": "started" + }, + { + "seq": 5, + "time": "====[timestamp]=====", + "kind": "status_change", + "unit": "dep-unit", + "from": "started", + "to": "completed" + } +] diff --git a/cli/testdata/TestSyncCommands_Golden/timeline_no_events.golden b/cli/testdata/TestSyncCommands_Golden/timeline_no_events.golden new file mode 100644 index 00000000000..3e42c8e64fb --- /dev/null +++ b/cli/testdata/TestSyncCommands_Golden/timeline_no_events.golden @@ -0,0 +1 @@ +No events found diff --git a/cli/testdata/TestSyncCommands_Golden/timeline_with_units.golden b/cli/testdata/TestSyncCommands_Golden/timeline_with_units.golden new file mode 100644 index 00000000000..09fff87c5da --- /dev/null +++ b/cli/testdata/TestSyncCommands_Golden/timeline_with_units.golden @@ -0,0 +1,9 @@ +* [+0.0s] test-unit registered (pending) +* [+0.0s] test-unit depends on dep-unit (completed) +| * [+0.0s] dep-unit registered (pending) +| * [+0.0s] dep-unit pending → started +| * [+0.0s] dep-unit started → completed +| / +* [+0.0s] test-unit ready (dependency satisfied) +* [+0.0s] test-unit pending → started +* [+0.0s] test-unit started → completed diff --git a/cli/testdata/coder_exp_sync_--help.golden b/cli/testdata/coder_exp_sync_--help.golden index 7ac85c9dba9..dec70b52983 100644 --- a/cli/testdata/coder_exp_sync_--help.golden +++ b/cli/testdata/coder_exp_sync_--help.golden @@ -17,6 +17,7 @@ SUBCOMMANDS: ping Test agent socket connectivity and health start Wait until all unit dependencies are satisfied status Show unit status and dependency state + timeline Show a timeline of unit state changes want Declare that a unit depends on other units completing before it can start diff --git a/cli/testdata/coder_exp_sync_timeline_--help.golden b/cli/testdata/coder_exp_sync_timeline_--help.golden new file mode 100644 index 00000000000..de88089932e --- /dev/null +++ b/cli/testdata/coder_exp_sync_timeline_--help.golden @@ -0,0 +1,18 @@ +coder v0.0.0-devel + +USAGE: + coder exp sync timeline [flags] + + Show a timeline of unit state changes + + Show every recorded unit state transition and dependency declaration across + all units, in the order they occurred. The default output is an ASCII graph of + the dependency DAG in event-time order; use --output json for the raw event + list. + +OPTIONS: + -o, --output text|json (default: text) + Output format. + +——— +Run `coder --help` for a list of global options.