package host import ( "context" "errors" "reflect" "strings" "testing" "time" "github.com/carlosframework/platform/internal/activator" "github.com/carlosframework/platform/internal/applog" "github.com/carlosframework/platform/internal/instancectl" "github.com/carlosframework/platform/internal/provision" "github.com/carlosframework/platform/internal/release" ) // A run that starts logs its start, then its end, against the record's // instance, at info, through the worker's sink. func TestRunLogsItsStartAndItsEnd(t *testing.T) { s := release.NewDirStore(t.TempDir()) rec, req := pickedRun(t, s, 60) req.By = "member@example.com" h := &fakeHandle{polls: make(chan instancectl.CmdStatus, 1)} h.polls <- instancectl.CmdStatus{State: instancectl.CmdDone, InvocationID: "inv1", Result: "exit-code", Status: "3", Code: "1"} var events eventLog w := execWorker(t, s, &fakeLauncher{handle: h, out: "the output\n"}, "boot-1") w.events = &events runOn(t, w, s, rec, req, newRunHandle()) ev := events.all() if len(ev) != 2 { t.Fatalf("events %+v, want a start and an end", ev) } want := loggedEvent{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " started by member@example.com"} if ev[0] != want { t.Errorf("start %+v, want %+v", ev[0], want) } end := ev[1] if end.acct != rec.Account || end.app != rec.App || end.host != rec.Host || end.level != applog.LevelInfo || !strings.HasPrefix(end.msg, "run "+req.ID+" ended with exit 3 after ") { t.Errorf("end %+v", end) } for _, e := range ev { if strings.Contains(e.msg, "the output") || strings.Contains(e.msg, "import") { t.Errorf("%q carries the run's output or its arguments", e.msg) } } } // A run the box does not start logs only that it did not start, and why. func TestRunNotStartedLogsOnlyItsEnd(t *testing.T) { cases := []struct { err error want string }{ {activator.ErrCmdClaim, "did not start: the box has host claims armed"}, {activator.ErrCmdNotNested, "did not start: the box is not on the nested layout yet"}, {&activator.CmdStoppedError{Reason: activator.StopRestart}, "did not start: the instance was restarted"}, // A failed start may have started the unit (a lost response): the // line hedges rather than say it never ran. {errors.New("start cmd unit: 502"), "was interrupted: the box could not start the command. it may have done part of its work"}, } for _, c := range cases { s := release.NewDirStore(t.TempDir()) rec, req := pickedRun(t, s, 60) var events eventLog w := execWorker(t, s, &fakeLauncher{err: c.err}, "boot-1") w.events = &events runOn(t, w, s, rec, req, newRunHandle()) want := []loggedEvent{{rec.Account, rec.App, rec.Host, applog.LevelInfo, "run " + req.ID + " " + c.want}} if ev := events.all(); !reflect.DeepEqual(ev, want) { t.Errorf("%v: events %+v, want %+v", c.err, ev, want) } } } // A run whose result never landed logs no ending of its own: the run stays // picked, and the next agent's close-out writes and logs the one ending, // so the log never holds two that contradict each other (Astra round 3). func TestRunWhoseResultNeverLandedLeavesTheEndingToTheCloseOut(t *testing.T) { defer func(d time.Duration) { runFinishBound = d }(runFinishBound) runFinishBound = 300 * time.Millisecond dir := release.NewDirStore(t.TempDir()) rec, req := pickedRun(t, dir, 60) req.By = "member@example.com" h := &fakeHandle{polls: make(chan instancectl.CmdStatus, 1)} h.polls <- instancectl.CmdStatus{State: instancectl.CmdDone, InvocationID: "inv1", Result: "exit-code", Status: "0", Code: "1"} var events eventLog w := execWorker(t, &failingPuts{Store: dir, part: "/result.json"}, &fakeLauncher{handle: h}, "boot-1") w.events = &events rt, _ := runOwnedRoute(runHost)(runHost) w.execute(context.Background(), rec, req, *rt, newRunHandle()) if r := currentRun(t, dir); r.State != provision.RunPicked { t.Fatalf("run %+v, want still picked", r) } // The agent restarts once storage has recovered. cur, err := provision.GetRecord(context.Background(), dir, rec.Account, rec.App, rec.Host) if err != nil { t.Fatal(err) } var l execLog next := testWorker(dir, runOwnedRoute(runHost), "box-1", "boot-2", &l) next.events = &events next.consider(context.Background(), *cur) var endings []string for _, e := range events.all() { if !strings.Contains(e.msg, " started by ") { endings = append(endings, e.msg) } } if len(endings) != 1 || !strings.Contains(endings[0], "the box's agent restarted") { t.Fatalf("endings %q, want only the close-out's", endings) } }