| 1 | package host |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "errors" |
| 6 | "reflect" |
| 7 | "strings" |
| 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/instancectl" |
| 14 | "github.com/carlosframework/platform/internal/provision" |
| 15 | "github.com/carlosframework/platform/internal/release" |
| 16 | ) |
| 17 | |
| 18 | // A run that starts logs its start, then its end, against the record's |
| 19 | // instance, at info, through the worker's sink. |
| 20 | func TestRunLogsItsStartAndItsEnd(t *testing.T) { |
| 21 | s := release.NewDirStore(t.TempDir()) |
| 22 | rec, req := pickedRun(t, s, 60) |
| 23 | req.By = "member@example.com" |
| 24 | h := &fakeHandle{polls: make(chan instancectl.CmdStatus, 1)} |
| 25 | h.polls <- instancectl.CmdStatus{State: instancectl.CmdDone, InvocationID: "inv1", Result: "exit-code", Status: "3", Code: "1"} |
| 26 | var events eventLog |
| 27 | w := execWorker(t, s, &fakeLauncher{handle: h, out: "the output\n"}, "boot-1") |
| 28 | w.events = &events |
| 29 | runOn(t, w, s, rec, req, newRunHandle()) |
| 30 | ev := events.all() |
| 31 | if len(ev) != 2 { |
| 32 | t.Fatalf("events %+v, want a start and an end", ev) |
| 33 | } |
| 34 | want := loggedEvent{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " started by member@example.com"} |
| 35 | if ev[0] != want { |
| 36 | t.Errorf("start %+v, want %+v", ev[0], want) |
| 37 | } |
| 38 | end := ev[1] |
| 39 | if end.acct != rec.Account || end.app != rec.App || end.host != rec.Host || end.level != applog.LevelInfo || |
| 40 | !strings.HasPrefix(end.msg, "run "+req.ID+" ended with exit 3 after ") { |
| 41 | t.Errorf("end %+v", end) |
| 42 | } |
| 43 | for _, e := range ev { |
| 44 | if strings.Contains(e.msg, "the output") || strings.Contains(e.msg, "import") { |
| 45 | t.Errorf("%q carries the run's output or its arguments", e.msg) |
| 46 | } |
| 47 | } |
| 48 | } |
| 49 | |
| 50 | // A run the box does not start logs only that it did not start, and why. |
| 51 | func TestRunNotStartedLogsOnlyItsEnd(t *testing.T) { |
| 52 | cases := []struct { |
| 53 | err error |
| 54 | want string |
| 55 | }{ |
| 56 | {activator.ErrCmdClaim, "did not start: the box has host claims armed"}, |
| 57 | {activator.ErrCmdNotNested, "did not start: the box is not on the nested layout yet"}, |
| 58 | {&activator.CmdStoppedError{Reason: activator.StopRestart}, "did not start: the instance was restarted"}, |
| 59 | // A failed start may have started the unit (a lost response): the |
| 60 | // line hedges rather than say it never ran. |
| 61 | {errors.New("start cmd unit: 502"), "was interrupted: the box could not start the command. it may have done part of its work"}, |
| 62 | } |
| 63 | for _, c := range cases { |
| 64 | s := release.NewDirStore(t.TempDir()) |
| 65 | rec, req := pickedRun(t, s, 60) |
| 66 | var events eventLog |
| 67 | w := execWorker(t, s, &fakeLauncher{err: c.err}, "boot-1") |
| 68 | w.events = &events |
| 69 | runOn(t, w, s, rec, req, newRunHandle()) |
| 70 | want := []loggedEvent{{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " " + c.want}} |
| 71 | if ev := events.all(); !reflect.DeepEqual(ev, want) { |
| 72 | t.Errorf("%v: events %+v, want %+v", c.err, ev, want) |
| 73 | } |
| 74 | } |
| 75 | } |
| 76 | |
| 77 | // A run whose result never landed logs no ending of its own: the run stays |
| 78 | // picked, and the next agent's close-out writes and logs the one ending, |
| 79 | // so the log never holds two that contradict each other (Astra round 3). |
| 80 | func TestRunWhoseResultNeverLandedLeavesTheEndingToTheCloseOut(t *testing.T) { |
| 81 | defer func(d time.Duration) { runFinishBound = d }(runFinishBound) |
| 82 | runFinishBound = 300 * time.Millisecond |
| 83 | dir := release.NewDirStore(t.TempDir()) |
| 84 | rec, req := pickedRun(t, dir, 60) |
| 85 | req.By = "member@example.com" |
| 86 | h := &fakeHandle{polls: make(chan instancectl.CmdStatus, 1)} |
| 87 | h.polls <- instancectl.CmdStatus{State: instancectl.CmdDone, InvocationID: "inv1", Result: "exit-code", Status: "0", Code: "1"} |
| 88 | var events eventLog |
| 89 | w := execWorker(t, &failingPuts{Store: dir, part: "/result.json"}, &fakeLauncher{handle: h}, "boot-1") |
| 90 | w.events = &events |
| 91 | rt, _ := runOwnedRoute(runHost)(runHost) |
| 92 | w.execute(context.Background(), rec, req, *rt, newRunHandle()) |
| 93 | if r := currentRun(t, dir); r.State != provision.RunPicked { |
| 94 | t.Fatalf("run %+v, want still picked", r) |
| 95 | } |
| 96 | // The agent restarts once storage has recovered. |
| 97 | cur, err := provision.GetRecord(context.Background(), dir, rec.Account, rec.App, rec.Host) |
| 98 | if err != nil { |
| 99 | t.Fatal(err) |
| 100 | } |
| 101 | var l execLog |
| 102 | next := testWorker(dir, runOwnedRoute(runHost), "box-1", "boot-2", &l) |
| 103 | next.events = &events |
| 104 | next.consider(context.Background(), *cur) |
| 105 | var endings []string |
| 106 | for _, e := range events.all() { |
| 107 | if !strings.Contains(e.msg, " started by ") { |
| 108 | endings = append(endings, e.msg) |
| 109 | } |
| 110 | } |
| 111 | if len(endings) != 1 || !strings.Contains(endings[0], "the box's agent restarted") { |
| 112 | t.Fatalf("endings %q, want only the close-out's", endings) |
| 113 | } |
| 114 | } |
| 115 | |
amadan