| 1 | package host |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "reflect" |
| 6 | "strings" |
| 7 | "sync" |
| 8 | "testing" |
| 9 | "time" |
| 10 | |
| 11 | "github.com/carlosframework/platform/internal/activator" |
| 12 | "github.com/carlosframework/platform/internal/applog" |
| 13 | "github.com/carlosframework/platform/internal/provision" |
| 14 | "github.com/carlosframework/platform/internal/release" |
| 15 | "github.com/carlosframework/platform/internal/runs" |
| 16 | ) |
| 17 | |
| 18 | // eventLog records what a worker hands its EventSink. |
| 19 | type eventLog struct { |
| 20 | mu sync.Mutex |
| 21 | events []loggedEvent |
| 22 | } |
| 23 | |
| 24 | type loggedEvent struct{ acct, app, host, level, msg string } |
| 25 | |
| 26 | func (l *eventLog) App(acct, app, host, line string) {} |
| 27 | |
| 28 | func (l *eventLog) Event(acct, app, host, level, msg string) { |
| 29 | l.mu.Lock() |
| 30 | defer l.mu.Unlock() |
| 31 | l.events = append(l.events, loggedEvent{acct, app, host, level, msg}) |
| 32 | } |
| 33 | |
| 34 | func (l *eventLog) all() []loggedEvent { |
| 35 | l.mu.Lock() |
| 36 | defer l.mu.Unlock() |
| 37 | return append([]loggedEvent(nil), l.events...) |
| 38 | } |
| 39 | |
| 40 | func TestRunEndedLineSaysHowTheRunEnded(t *testing.T) { |
| 41 | start := time.Date(2026, 10, 20, 12, 0, 0, 0, time.UTC) |
| 42 | end := start.Add(90*time.Second + 400*time.Millisecond) |
| 43 | ran := func(r runs.Result) runs.Result { r.Started, r.Ended = start, end; return r } |
| 44 | cases := []struct { |
| 45 | res runs.Result |
| 46 | started bool |
| 47 | want string |
| 48 | }{ |
| 49 | {ran(runs.Result{}), true, "run r1 ended with exit 0 after 1m30s"}, |
| 50 | {ran(runs.Result{Exit: 3}), true, "run r1 ended with exit 3 after 1m30s"}, |
| 51 | {ran(runs.Result{Signal: "9"}), true, "run r1 was ended by signal 9 after 1m30s"}, |
| 52 | {ran(runs.Result{TimedOut: true}), true, "run r1 timed out after 1m30s"}, |
| 53 | {runs.Result{TimedOut: true, Ended: end}, false, "run r1 timed out before it started"}, |
| 54 | {ran(runs.Result{Cancelled: true, Exit: 143}), true, "run r1 was cancelled after 1m30s"}, |
| 55 | {runs.Result{Cancelled: true, Ended: end}, false, "run r1 was cancelled before it started"}, |
| 56 | {ran(runs.Result{Interrupted: activator.StopRestart}), true, |
| 57 | "run r1 was interrupted: the instance was restarted. it may have done part of its work"}, |
| 58 | {runs.Result{Interrupted: runs.InterruptedAgentRestart, Ended: end}, true, |
| 59 | "run r1 was interrupted: the box's agent restarted. it may have done part of its work"}, |
| 60 | {runs.Result{Interrupted: activator.StopRestart, Ended: end}, false, |
| 61 | "run r1 did not start: the instance was restarted"}, |
| 62 | {runs.Result{Interrupted: runs.InterruptedStartFailed, Ended: end}, false, |
| 63 | "run r1 was interrupted: the box could not start the command. it may have done part of its work"}, |
| 64 | {runs.Result{Refused: runs.RefusedFlat}, false, "run r1 did not start: the box is not on the nested layout yet"}, |
| 65 | {runs.Result{Refused: runs.RefusedClaim}, false, "run r1 did not start: the box has host claims armed"}, |
| 66 | {runs.Result{Refused: runs.RefusedWake, Detail: "wake failed: restore"}, false, |
| 67 | "run r1 did not start: the instance did not wake. wake failed: restore"}, |
| 68 | {runs.Result{Refused: runs.RefusedIncarnation}, false, |
| 69 | "run r1 did not start: the instance was deleted and created again after the run was requested"}, |
| 70 | {runs.Result{Refused: runs.RefusedImport}, false, "run r1 did not start: the instance is an import that is not committed yet"}, |
| 71 | {runs.Result{Refused: "something-new"}, false, "run r1 did not start: something-new"}, |
| 72 | } |
| 73 | for _, c := range cases { |
| 74 | if got := runEndedLine("r1", c.res, c.started); got != c.want { |
| 75 | t.Errorf("%+v (started %v):\n got %q\nwant %q", c.res, c.started, got, c.want) |
| 76 | } |
| 77 | } |
| 78 | } |
| 79 | |
| 80 | // The start line names the run and who asked for it, and never the |
| 81 | // command's arguments: they can carry what a log reader should not see. |
| 82 | func TestRunStartedLineCarriesNoArguments(t *testing.T) { |
| 83 | req := runs.Request{ID: "r1", By: "member@example.com", Argv: []string{"import", "--token", "s3cret"}} |
| 84 | got := runStartedLine(req) |
| 85 | if got != "run r1 started by member@example.com" { |
| 86 | t.Fatalf("got %q", got) |
| 87 | } |
| 88 | for _, a := range req.Argv { |
| 89 | if strings.Contains(got, a) { |
| 90 | t.Fatalf("%q carries the argument %q", got, a) |
| 91 | } |
| 92 | } |
| 93 | } |
| 94 | |
| 95 | // A run closed out after an agent restart is logged as interrupted once, |
| 96 | // however many passes still read it as picked. |
| 97 | func TestRunClosedOutAfterAnAgentRestartIsLoggedOnce(t *testing.T) { |
| 98 | s := release.NewDirStore(t.TempDir()) |
| 99 | _, id := queueRun(t, s, time.Now().Add(time.Minute)) |
| 100 | got, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| 101 | if err != nil { |
| 102 | t.Fatal(err) |
| 103 | } |
| 104 | var l execLog |
| 105 | var events eventLog |
| 106 | w := testWorker(s, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| 107 | w.events = &events |
| 108 | // got is the stale read a second pass would also have noted. |
| 109 | w.consider(context.Background(), *got) |
| 110 | w.consider(context.Background(), *got) |
| 111 | want := []loggedEvent{{"bab", "shop", runHost, applog.LevelInfo, |
| 112 | "run " + id + " was interrupted: the box's agent restarted. it may have done part of its work"}} |
| 113 | if ev := events.all(); !reflect.DeepEqual(ev, want) { |
| 114 | t.Fatalf("events %+v, want %+v", ev, want) |
| 115 | } |
| 116 | } |
| 117 | |
| 118 | // A restart after the command's own result landed, but before its done |
| 119 | // CAS did, closes the run out without a second ending: the boot that ran |
| 120 | // the command logged it (Astra review, finding 2). |
| 121 | func TestRunClosedOutAfterItsOwnResultLogsNothing(t *testing.T) { |
| 122 | s := release.NewDirStore(t.TempDir()) |
| 123 | _, id := queueRun(t, s, time.Now().Add(time.Minute)) |
| 124 | got, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| 125 | if err != nil { |
| 126 | t.Fatal(err) |
| 127 | } |
| 128 | if err := runs.WriteResult(context.Background(), s, "bab", "shop", id, runs.Result{Exit: 0, Box: "box-1", Ended: time.Now().UTC()}); err != nil { |
| 129 | t.Fatal(err) |
| 130 | } |
| 131 | var l execLog |
| 132 | var events eventLog |
| 133 | w := testWorker(s, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| 134 | w.events = &events |
| 135 | w.consider(context.Background(), *got) |
| 136 | if ev := events.all(); len(ev) != 0 { |
| 137 | t.Fatalf("events %+v, want none", ev) |
| 138 | } |
| 139 | if r := currentRun(t, s); r.State != provision.RunDone { |
| 140 | t.Fatalf("run %+v, want done", r) |
| 141 | } |
| 142 | if res, _ := runs.ReadResult(context.Background(), s, "bab", "shop", id); res == nil || res.Interrupted != "" { |
| 143 | t.Fatalf("result %+v, want the command's own", res) |
| 144 | } |
| 145 | } |
| 146 | |
| 147 | // A stale pass after the run was acknowledged (its result deleted, the |
| 148 | // record cleared) recreates a result, but its done CAS fails, so it logs |
| 149 | // no second ending (Astra round 2, finding 2). |
| 150 | func TestRunClosedOutByAStalePassAfterTheAckLogsNothing(t *testing.T) { |
| 151 | s := release.NewDirStore(t.TempDir()) |
| 152 | _, id := queueRun(t, s, time.Now().Add(time.Minute)) |
| 153 | got, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| 154 | if err != nil { |
| 155 | t.Fatal(err) |
| 156 | } |
| 157 | var l execLog |
| 158 | var events eventLog |
| 159 | w := testWorker(s, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| 160 | w.events = &events |
| 161 | w.consider(context.Background(), *got) |
| 162 | // The CLI acknowledges the run: the record is cleared and the result |
| 163 | // deleted, as handleAPIRunAck does. |
| 164 | if _, err := provision.SetRecordRun(context.Background(), s, "bab", "shop", runHost, provision.RunClear(id)); err != nil { |
| 165 | t.Fatal(err) |
| 166 | } |
| 167 | if err := runs.DeleteRun(context.Background(), s, "bab", "shop", id); err != nil { |
| 168 | t.Fatal(err) |
| 169 | } |
| 170 | w.consider(context.Background(), *got) |
| 171 | if ev := events.all(); len(ev) != 1 { |
| 172 | t.Fatalf("events %+v, want the first pass's ending only", ev) |
| 173 | } |
| 174 | } |
| 175 | |
| 176 | // A done CAS whose answer was lost loses the line rather than risk a |
| 177 | // second one: run lines are at most once, and result.json is the record. |
| 178 | func TestRunClosedOutWithALostDoneAnswerIsNotLoggedTwice(t *testing.T) { |
| 179 | dir := release.NewDirStore(t.TempDir()) |
| 180 | _, id := queueRun(t, dir, time.Now().Add(time.Minute)) |
| 181 | got, err := provision.SetRecordRun(context.Background(), dir, "bab", "shop", runHost, provision.RunPick(id, "box-1", "boot-old", time.Now().Add(time.Hour))) |
| 182 | if err != nil { |
| 183 | t.Fatal(err) |
| 184 | } |
| 185 | var l execLog |
| 186 | var events eventLog |
| 187 | w := testWorker(&lostAnswer{Store: dir, land: true}, runOwnedRoute(runHost), "box-1", "boot-new", &l) |
| 188 | w.events = &events |
| 189 | w.consider(context.Background(), *got) |
| 190 | w.consider(context.Background(), *got) |
| 191 | if r := currentRun(t, dir); r.State != provision.RunDone { |
| 192 | t.Fatalf("run %+v, want done (the CAS landed)", r) |
| 193 | } |
| 194 | if ev := events.all(); len(ev) != 0 { |
| 195 | t.Fatalf("events %+v, want none: the done answer was lost", ev) |
| 196 | } |
| 197 | if res, _ := runs.ReadResult(context.Background(), dir, "bab", "shop", id); res == nil || res.Interrupted != runs.InterruptedAgentRestart { |
| 198 | t.Fatalf("result %+v, want the interrupted result", res) |
| 199 | } |
| 200 | } |
| 201 | |
| 202 | // A worker with no sink, as on a box with no log store, still runs. |
| 203 | func TestRunEventWithoutASinkIsANoop(t *testing.T) { |
| 204 | w := &runsWorker{} |
| 205 | w.runEvent(provision.Record{Account: "bab", App: "shop", Host: runHost}, "run r1 started by member@example.com") |
| 206 | } |
| 207 | |
amadan