diff --git a/pkg/alerts/docker.go b/pkg/alerts/docker.go index d109d901..bb20c465 100644 --- a/pkg/alerts/docker.go +++ b/pkg/alerts/docker.go @@ -39,7 +39,8 @@ type DockerRun struct { Outcome string // ErrorCode is why a run failed: guard, download, install, daemon, start or no_result. ErrorCode string - // To is the version of the engine that runs after a run that succeeded. + // To is the engine version the status says: the one that runs after a run that succeeded, the + // plan's for a run that did not. Only a success tells it. To string // NotReturned are the containers that were running before the update and were not after, // already validated by whoever read the log. diff --git a/pkg/alerts/docker_test.go b/pkg/alerts/docker_test.go index e4575609..8069ebe5 100644 --- a/pkg/alerts/docker_test.go +++ b/pkg/alerts/docker_test.go @@ -191,6 +191,16 @@ func TestTheDockerUpdateEndsWithOneMessage(t *testing.T) { DockerRun{Outcome: "failed", ErrorCode: "daemon"}, "The Docker update failed: Docker did not come back after the update. Details are in the dashboard.", }, + // the status gives the version the plan goes to for a run that did not succeed: it is not told, + // and nor is a way back (there is none after a major jump) + "failed, with the version the plan went to": { + DockerRun{Outcome: "failed", ErrorCode: "daemon", To: "29.8.0"}, + "The Docker update failed: Docker did not come back after the update. Details are in the dashboard.", + }, + "restart pending, with the version the plan went to": { + DockerRun{Outcome: "restart_pending", To: "29.8.0"}, + "Docker's new version is installed, but the old one still runs: restart Docker to switch (sudo systemctl restart docker, which stops every container).", + }, "failed, start": { DockerRun{Outcome: "failed", ErrorCode: "start"}, "The Docker update failed: the update could not be started, nothing was changed. Details are in the dashboard.", diff --git a/pkg/dockerpkg/run.go b/pkg/dockerpkg/run.go index cc6589d7..5b8a0ffa 100644 --- a/pkg/dockerpkg/run.go +++ b/pkg/dockerpkg/run.go @@ -3,6 +3,7 @@ package dockerpkg import ( "crypto/rand" "encoding/hex" + "regexp" "strings" "time" ) @@ -84,6 +85,59 @@ func QueuedMarker(nonce string, at time.Time) string { return markerPrefix + "QUEUED " + nonce + " " + at.UTC().Format(time.RFC3339) + "\n" } +// PlanMarker is the second line of the log, which the core writes in the same write as the first: +// "CASAOS_DOCKER_UPDATE_PLAN <0|1>", the engine versions the plan goes from and +// to (digits and dots, "-" for one that is not known) and whether the plan changes the engine's +// major version. A version that is not digits and dots is written as unknown, so that the line +// holds nothing else. The unit never writes one: the core tells the page of a major jump from it. +func PlanMarker(nonce, from, to string, majorJump bool) string { + jump := "0" + if majorJump { + jump = "1" + } + return markerPrefix + "PLAN " + nonce + " " + planVersion(from) + " " + planVersion(to) + " " + jump + "\n" +} + +var planVersionPattern = regexp.MustCompile(`^[0-9]+(?:\.[0-9]+)*$`) + +func validPlanVersion(v string) bool { + return len(v) <= maxVersionLen && planVersionPattern.MatchString(v) +} + +// planVersion is how a version is written on the PLAN line. +func planVersion(v string) string { + if validPlanVersion(v) { + return v + } + return "-" +} + +// planFields reads the fields of a PLAN marker: two versions, each digits and dots or "-" (unknown, +// which is ""), and 0 or 1. +func planFields(fields []string) (from, to string, majorJump, ok bool) { + if len(fields) != 3 { + return "", "", false, false + } + versions := [2]string{} + for i, field := range fields[:2] { + switch { + case field == "-": + case validPlanVersion(field): + versions[i] = field + default: + return "", "", false, false + } + } + switch fields[2] { + case "0": + case "1": + majorJump = true + default: + return "", "", false, false + } + return versions[0], versions[1], majorJump, true +} + // NotReturned is a container that was running before the update and is not running after it. type NotReturned struct { Name string `json:"name"` @@ -114,6 +168,11 @@ type Run struct { DaemonVersion string // NotReturned are the containers that were running before and were not after. NotReturned []NotReturned + // From and To are the engine versions the plan goes from and to (digits and dots), "" when the + // plan did not know one or the log has no valid PLAN line; MajorJump is the plan's own word on + // whether it changes the major version, and is false with no PLAN line. + From, To string + MajorJump bool } // markerOf splits a line that is a marker of this run: "CASAOS_DOCKER_UPDATE_ " @@ -160,7 +219,8 @@ func validPin(pin string) bool { // is read only if it is "CASAOS_DOCKER_UPDATE_ " with the fields its KIND // takes; every field is validated again; and what is not a marker is ignored, whatever it // looks like: apt's output, a container named like a marker, a forged nonce. The last -// terminal marker wins, the first STARTED, INSTALLED and PREVIOUS, the last DAEMON. +// terminal marker wins, the first STARTED, INSTALLED, PREVIOUS and PLAN, the last DAEMON. A PLAN +// is the core's, written on line 2, so the first valid one is the plan and no later one changes it. // // A caller that reads only the end of a long log must put line 1 back in front of it. func ParseRun(log string) Run { @@ -174,6 +234,7 @@ func ParseRun(log string) Run { return Run{} } run := Run{Nonce: first[1], QueuedAt: queued} + planSeen := false for _, line := range strings.Split(tail, "\n") { kind, fields, ok := markerOf(strings.TrimRight(line, "\r"), run.Nonce) if !ok { @@ -197,6 +258,11 @@ func ParseRun(log string) Run { if run.Previous == nil { run.Previous = validPins(fields) } + case "PLAN": + if from, to, majorJump, ok := planFields(fields); ok && !planSeen { + planSeen = true + run.From, run.To, run.MajorJump = from, to, majorJump + } case "DAEMON": if len(fields) == 1 && validDaemonVersion(fields[0]) { run.DaemonVersion = fields[0] diff --git a/pkg/dockerpkg/run_test.go b/pkg/dockerpkg/run_test.go index ad9dc005..1e3b1cd2 100644 --- a/pkg/dockerpkg/run_test.go +++ b/pkg/dockerpkg/run_test.go @@ -497,3 +497,151 @@ func TestIsMarkerLineIsTheShapeParseRunLooksFor(t *testing.T) { t.Error("a marker the core writes is not a marker line") } } + +// The core writes the plan on the second line, in the same write as the first. What the page says of a +// major jump (and what it does not offer after one) rests on this line, so it is checked from both ends. +func TestPlanMarker(t *testing.T) { + line := func(fields string) string { return "CASAOS_DOCKER_UPDATE_PLAN " + testNonce + " " + fields + "\n" } + for _, c := range []struct { + from, to string + jump bool + want string + }{ + {"28.0.4", "29.8.0", true, line("28.0.4 29.8.0 1")}, + {"28.0.4", "28.1.0", false, line("28.0.4 28.1.0 0")}, + {"29.8.0", "29.8.0", false, line("29.8.0 29.8.0 0")}, + {"", "", false, line("- - 0")}, + {"", "29.8.0", false, line("- 29.8.0 0")}, + {"28.0.4", "", false, line("28.0.4 - 0")}, + // anything that is not digits and dots is written as unknown: the line holds no other text + {"5:28.0.4-1~debian.11~bullseye", "29.8.0;reboot", true, line("- - 1")}, + {"28.0.4\n", " 29.8.0", false, line("- - 0")}, + {"28 0", "$(id)", false, line("- - 0")}, + {"28.", ".29", false, line("- - 0")}, + {"28..0", "-", false, line("- - 0")}, + {"v28", "29.8.0-rc1", false, line("- - 0")}, + {strings.Repeat("1", 100), strings.Repeat("1", 101), false, line(strings.Repeat("1", 100) + " - 0")}, + } { + got := PlanMarker(testNonce, c.from, c.to, c.jump) + if got != c.want { + t.Errorf("PlanMarker(%q, %q, %v) = %q, want %q", c.from, c.to, c.jump, got, c.want) + } + if !strings.HasSuffix(got, "\n") || strings.Count(got, "\n") != 1 || !IsMarkerLine(strings.TrimSuffix(got, "\n")) { + t.Errorf("PlanMarker(%q, %q, %v) = %q, want one marker line", c.from, c.to, c.jump, got) + } + } +} + +func TestParseRunReadsThePlanTheCoreWrote(t *testing.T) { + for _, c := range []struct { + from, to string + jump bool + }{ + {"28.0.4", "29.8.0", true}, + {"28.0.4", "28.1.0", false}, + {"28.0.4", "28.0.4", false}, + {"", "", false}, + {"", "29.8.0", false}, + } { + got := ParseRun(QueuedMarker(testNonce, t0) + PlanMarker(testNonce, c.from, c.to, c.jump)) + want := Run{Nonce: testNonce, QueuedAt: t0, From: c.from, To: c.to, MajorJump: c.jump} + if !reflect.DeepEqual(got, want) { + t.Errorf("ParseRun(plan %q %q %v) =\n%#v\nwant\n%#v", c.from, c.to, c.jump, got, want) + } + } + // the plan is no step of the run: the phase and the rest are the unit's + got := ParseRun(QueuedMarker(testNonce, t0) + PlanMarker(testNonce, "28.0.4", "29.8.0", true) + marker("STARTED", ts(1)) + "\n") + if got.Phase() != PhasePreparing || got.Terminal != "" || !got.StartedAt.Equal(t0.Add(time.Second)) { + t.Errorf("a run with a plan = %#v", got) + } + // a log with no plan (an older core, or a forged one) is no major jump and knows no versions + got = ParseRun(QueuedMarker(testNonce, t0)) + if got.MajorJump || got.From != "" || got.To != "" { + t.Errorf("a run with no plan = %#v", got) + } +} + +func TestParseRunValidatesPlan(t *testing.T) { + first := strings.TrimSuffix(QueuedMarker(testNonce, t0), "\n") + for fields, want := range map[string]Run{ + "28.0.4 29.8.0 1": {From: "28.0.4", To: "29.8.0", MajorJump: true}, + "28.0.4 28.1.0 0": {From: "28.0.4", To: "28.1.0"}, + "29 30 1": {From: "29", To: "30", MajorJump: true}, + "- - 0": {}, + "- 29.8.0 0": {To: "29.8.0"}, + "28.0.4 - 0": {From: "28.0.4"}, + "28.0.4 29.8.0 1\r": {From: "28.0.4", To: "29.8.0", MajorJump: true}, + strings.Repeat("1", 100) + " - 0": {From: strings.Repeat("1", 100)}, + } { + want.Nonce, want.QueuedAt = testNonce, t0 + if got := ParseRun(logOf(first, marker("PLAN", fields))); !reflect.DeepEqual(got, want) { + t.Errorf("PLAN %q: ParseRun() =\n%#v\nwant\n%#v", fields, got, want) + } + } + for _, fields := range []string{ + "", "28.0.4", "28.0.4 29.8.0", "28.0.4 29.8.0 1 extra", "- - ", "-", + // the flag is 0 or 1 and nothing else + "28.0.4 29.8.0 2", "28.0.4 29.8.0 true", "28.0.4 29.8.0 yes", "28.0.4 29.8.0 -1", "28.0.4 29.8.0 01", "28.0.4 29.8.0 1;reboot", "28.0.4 29.8.0 \u0661", "28.0.4 29.8.0 -", + // a version is digits and dots, or "-" + "5:28.0.4-1 29.8.0 1", "28.0.4 29.8.0-1~debian.11~bullseye 1", "28.0.4;reboot 29.8.0 1", "28.0.4 `id` 1", "$(id) 29.8.0 1", + "28..4 29.8.0 1", ".4 29.8.0 1", "28. 29.8.0 1", "v28 29 1", "28.0.4-rc1 29.8.0 1", "\u0662\u0668 29.8.0 1", + strings.Repeat("1", 101) + " 29 1", "28 " + strings.Repeat("1", 101) + " 1", + } { + want := Run{Nonce: testNonce, QueuedAt: t0} + if got := ParseRun(logOf(first, marker("PLAN", fields))); !reflect.DeepEqual(got, want) { + t.Errorf("PLAN %q: ParseRun() =\n%#v\nwant no plan", fields, got) + } + } + // a PLAN line that has no nonce at all + for _, line := range []string{"CASAOS_DOCKER_UPDATE_PLAN", "CASAOS_DOCKER_UPDATE_PLAN 28.0.4 29.8.0 1", "CASAOS_DOCKER_UPDATE_PLAN " + testNonce} { + if got := ParseRun(logOf(first, line)); !reflect.DeepEqual(got, Run{Nonce: testNonce, QueuedAt: t0}) { + t.Errorf("%q gave %#v", line, got) + } + } +} + +func TestParseRunTakesThePlanOfTheCoreAndNoOther(t *testing.T) { + first := strings.TrimSuffix(QueuedMarker(testNonce, t0), "\n") + plan := strings.TrimSuffix(PlanMarker(testNonce, "28.0.4", "29.8.0", true), "\n") + forged := "CASAOS_DOCKER_UPDATE_PLAN " + otherNonce + " 28.0.4 28.1.0 0" + elsewhere := "28.0.4 28.1.0 0" + for name, c := range map[string]struct { + lines []string + want Run + }{ + "a wrong nonce is not the plan": {[]string{first, forged}, Run{}}, + "a wrong nonce leaves the plan": {[]string{first, plan, forged}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true}}, + "a wrong nonce first leaves it too": {[]string{first, forged, plan}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true}}, + "the first valid plan wins": {[]string{first, plan, marker("PLAN", elsewhere)}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true}}, + "the first, if it says no jump": {[]string{first, marker("PLAN", elsewhere), plan}, Run{From: "28.0.4", To: "28.1.0"}}, + "a malformed one is no plan, and the next one is": {[]string{first, marker("PLAN", "28.0.4 29.8.0 maybe"), marker("PLAN", "29.8.0;reboot 29.8.0 0"), plan}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true}}, + "a malformed one after does not undo": {[]string{first, plan, marker("PLAN", "- - 0"), marker("PLAN", "28.0.4 29.8.0 2")}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true}}, + // what apt, dpkg or Docker print is not a line that starts a marker, whatever it holds + "in the middle of apt output": {[]string{first, "Setting up docker-ce (5:29.8.0-1) ... " + marker("PLAN", elsewhere)}, Run{}}, + "after a prefix": {[]string{first, "container: " + marker("PLAN", elsewhere), "x" + marker("PLAN", elsewhere), " " + marker("PLAN", elsewhere), "\t" + marker("PLAN", elsewhere), "> " + marker("PLAN", elsewhere)}, Run{}}, + "in the log that apt wrote, after the real one": {[]string{first, plan, "Get:1 https://download.docker.com bullseye/stable docker-ce 5:29.8.0-1", marker("PLAN", elsewhere), marker("DAEMON", "29.8.0"), marker("SUCCESS", ts(9))}, Run{From: "28.0.4", To: "29.8.0", MajorJump: true, DaemonVersion: "29.8.0", Terminal: TerminalSuccess, CompletedAt: t0.Add(9 * time.Second)}}, + "the wrong case, kind or spacing": {[]string{first, strings.ToLower(marker("PLAN", elsewhere)), "CASAOS_DOCKER_UPDATE_PLANX " + testNonce + " " + elsewhere, "CASAOS_DOCKER_UPDATE_PLA " + testNonce + " " + elsewhere, "CASAOS_DOCKER_UPDATE_PLAN\t" + testNonce + " " + elsewhere, "CASAOS_DOCKER_UPDATE_PLAN" + testNonce + " " + elsewhere, "CASAOS_PACKAGE_UPDATE_PLAN " + testNonce + " " + elsewhere}, Run{}}, + } { + want := c.want + want.Nonce, want.QueuedAt = testNonce, t0 + if got := ParseRun(logOf(c.lines...)); !reflect.DeepEqual(got, want) { + t.Errorf("%s: ParseRun() =\n%#v\nwant\n%#v", name, got, want) + } + } +} + +// A plan that comes before the first line is not the run's: line 1 is the run, and the core writes it first. +func TestParseRunIgnoresAPlanBeforeTheFirstLine(t *testing.T) { + first := strings.TrimSuffix(QueuedMarker(testNonce, t0), "\n") + plan := marker("PLAN", "28.0.4 29.8.0 1") + for name, lines := range map[string][]string{ + "the plan alone": {plan}, + "the plan, then the first line": {plan, first, marker("SUCCESS", ts(5))}, + "apt output, the plan, the first": {"Reading package lists...", plan, first}, + "the plan with a first line that is not one": {plan, "CASAOS_DOCKER_UPDATE_QUEUED " + testNonce}, + } { + if got := ParseRun(logOf(lines...)); !reflect.DeepEqual(got, Run{}) { + t.Errorf("%s: ParseRun() = %#v, want the zero Run", name, got) + } + } +} diff --git a/route/v1/system_docker_update_test.go b/route/v1/system_docker_update_test.go index d0fffe0c..6512ea83 100644 --- a/route/v1/system_docker_update_test.go +++ b/route/v1/system_docker_update_test.go @@ -71,7 +71,7 @@ func TestStartDockerUpdatePassesThePlanIDAndAnswersWithTheStatus(t *testing.T) { if recorder.Code != http.StatusOK || len(fake.asked) != 1 || fake.asked[0] != planID { t.Fatalf("status = %d, asked = %v, body = %s", recorder.Code, fake.asked, recorder.Body) } - want := `{"success":200,"message":"ok","data":{"supported":true,"state":"running","phase":"downloading","outcome":"","error":"","error_code":"","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"","from":"","to":"","not_returned":[],"rollback_command":"","log":""}}` + want := `{"success":200,"message":"ok","data":{"supported":true,"state":"running","phase":"downloading","outcome":"","error":"","error_code":"","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"","from":"","to":"","major_jump":false,"not_returned":[],"rollback_command":"","log":""}}` if got := strings.TrimSpace(recorder.Body.String()); got != want { t.Errorf("body = %s\nwant %s", got, want) } @@ -193,8 +193,46 @@ func TestGetDockerUpdateStatusAnswersWithTheStatus(t *testing.T) { if err := GetDockerUpdateStatus(echo.New().NewContext(request, recorder)); err != nil { t.Fatal(err) } - want := `{"success":200,"message":"ok","data":{"supported":true,"state":"failed","phase":"","outcome":"failed","error":"Docker did not come back after the update.","error_code":"daemon","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"2026-10-09T10:07:00Z","from":"28.0.4","to":"","not_returned":[{"name":"job","restart_policy":"no"}],"rollback_command":"sudo apt-get install --allow-downgrades docker-ce=5:28.0.4-1","log":"CASAOS_DOCKER_UPDATE_QUEUED x\n"}}` + want := `{"success":200,"message":"ok","data":{"supported":true,"state":"failed","phase":"","outcome":"failed","error":"Docker did not come back after the update.","error_code":"daemon","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"2026-10-09T10:07:00Z","from":"28.0.4","to":"","major_jump":false,"not_returned":[{"name":"job","restart_policy":"no"}],"rollback_command":"sudo apt-get install --allow-downgrades docker-ce=5:28.0.4-1","log":"CASAOS_DOCKER_UPDATE_QUEUED x\n"}}` if got := strings.TrimSpace(recorder.Body.String()); recorder.Code != http.StatusOK || got != want { t.Errorf("status = %d\nbody = %s\nwant %s", recorder.Code, got, want) } } + +// After a major jump the status says so and gives no command to go back: the page reads major_jump, +// from and to, and an empty rollback_command, whatever the state. +func TestDockerUpdateStatusOfAMajorJumpCarriesTheJumpAndNoRollback(t *testing.T) { + failed := service.SystemDockerUpdateStatus{ + Supported: true, State: "failed", Outcome: "failed", Error: "Docker did not come back after the update.", ErrorCode: "daemon", + StartedAt: "2026-10-09T10:00:00Z", CompletedAt: "2026-10-09T10:07:00Z", From: "28.0.4", To: "29.8.0", MajorJump: true, + NotReturned: []dockerpkg.NotReturned{{Name: "job", RestartPolicy: "no"}}, + Log: "CASAOS_DOCKER_UPDATE_QUEUED x\n", + } + running := service.SystemDockerUpdateStatus{ + Supported: true, State: "running", Phase: "downloading", StartedAt: "2026-10-09T10:00:00Z", From: "28.0.4", To: "29.8.0", MajorJump: true, + NotReturned: []dockerpkg.NotReturned{}, + } + for name, c := range map[string]struct { + status service.SystemDockerUpdateStatus + want string + }{ + "failed": {failed, `{"success":200,"message":"ok","data":{"supported":true,"state":"failed","phase":"","outcome":"failed","error":"Docker did not come back after the update.","error_code":"daemon","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"2026-10-09T10:07:00Z","from":"28.0.4","to":"29.8.0","major_jump":true,"not_returned":[{"name":"job","restart_policy":"no"}],"rollback_command":"","log":"CASAOS_DOCKER_UPDATE_QUEUED x\n"}}`}, + "running": {running, `{"success":200,"message":"ok","data":{"supported":true,"state":"running","phase":"downloading","outcome":"","error":"","error_code":"","exit_code":null,"started_at":"2026-10-09T10:00:00Z","completed_at":"","from":"28.0.4","to":"29.8.0","major_jump":true,"not_returned":[],"rollback_command":"","log":""}}`}, + } { + withDockerUpdateService(t, &fakeDockerUpdateService{status: c.status}) + request := httptest.NewRequest(http.MethodGet, "/v1/sys/docker/update/status", nil) + recorder := httptest.NewRecorder() + if err := GetDockerUpdateStatus(echo.New().NewContext(request, recorder)); err != nil { + t.Fatal(err) + } + if got := strings.TrimSpace(recorder.Body.String()); recorder.Code != http.StatusOK || got != c.want { + t.Errorf("%s: status = %d\nbody = %s\nwant %s", name, recorder.Code, got, c.want) + } + // ... and the start of the update answers with the same object + fake := &fakeDockerUpdateService{status: c.status} + withDockerUpdateService(t, fake) + if got := strings.TrimSpace(postDockerUpdate(t, `{"plan_id":"`+planID+`"}`).Body.String()); got != c.want { + t.Errorf("%s: the start answered\n%s\nwant\n%s", name, got, c.want) + } + } +} diff --git a/service/system_package_docker_run.go b/service/system_package_docker_run.go index 4c64fdba..ba2c2e10 100644 --- a/service/system_package_docker_run.go +++ b/service/system_package_docker_run.go @@ -126,13 +126,19 @@ type SystemDockerUpdateStatus struct { ExitCode *int `json:"exit_code"` StartedAt string `json:"started_at"` CompletedAt string `json:"completed_at"` - // From and To are the engine's versions before and after, from the log. To is there when - // the new engine runs. + // From and To are the engine's versions before and after, from the log: the plan's until the + // unit says better (what it saw installed, which daemon runs), "" when none is known yet. From string `json:"from"` To string `json:"to"` + // MajorJump is the plan's own word that the update changes the engine's first number (28 to + // 29), from the PLAN line the core wrote; false for a log that has none. After one the + // packages can be put back and Docker starts, and the containers do not start again by + // themselves: no RollbackCommand is given. + MajorJump bool `json:"major_jump"` // NotReturned are the containers that were running before and were not after. NotReturned []dockerpkg.NotReturned `json:"not_returned"` - // RollbackCommand is what to type to put the packages back, for a run that failed. + // RollbackCommand is what to type to put the packages back, for a run that failed and was not + // a major jump; "" otherwise. RollbackCommand string `json:"rollback_command"` // Log is the end of the unit's log, at most 128 KiB. Log string `json:"log"` @@ -266,7 +272,10 @@ func (u *systemPackageUpdater) startDockerUpdate(planID string) (SystemDockerUpd return u.dockerFailedToStart(support, "", fmt.Sprintf("prepare Docker update log: %v", err), err) } queuedAt := u.now().UTC() - queued := dockerpkg.QueuedMarker(nonce, queuedAt) + // The first line is the run's, the second its plan: what the status says of the run before the + // unit has written a word, and after a failure that is the unit's own. Both in one write, before + // the unit starts. + queued := dockerpkg.QueuedMarker(nonce, queuedAt) + dockerpkg.PlanMarker(nonce, update.From, update.To, update.MajorJump) if err := u.writeFile(logPath, []byte(queued), 0o644); err != nil { return u.dockerFailedToStart(support, "", fmt.Sprintf("prepare Docker update log: %v", err), err) } @@ -286,6 +295,9 @@ func (u *systemPackageUpdater) startDockerUpdate(planID string) (SystemDockerUpd State: systemPackageUpdateStateRunning, Phase: dockerpkg.PhasePreparing, StartedAt: queuedAt.Format(time.RFC3339), + From: update.From, + To: update.To, + MajorJump: update.MajorJump, NotReturned: []dockerpkg.NotReturned{}, Log: queued, }, nil @@ -403,18 +415,21 @@ func (u *systemPackageUpdater) dockerRun() (SystemDockerUpdateStatus, string) { status.StartedAt = formatDockerTime(run.StartedAt, run.QueuedAt) status.NotReturned = append(status.NotReturned, run.NotReturned...) - from := "" + // The plan's versions, until the unit's own say otherwise: what it saw installed is where the + // engine came from, and the daemon that runs after a run that went well is where it is. + status.From, status.To, status.MajorJump = run.From, run.To, run.MajorJump for _, pin := range run.Previous { if name, version, _ := strings.Cut(pin, "="); name == "docker-ce" { - from = dockerpkg.EngineVersion(version) + status.From = dockerpkg.EngineVersion(version) } } - status.From = from switch run.Terminal { case dockerpkg.TerminalSuccess: status.State, status.Outcome = systemPackageUpdateStateSuccess, systemDockerOutcomeSuccess - status.To = dockerpkg.EngineVersion(run.DaemonVersion) + if running := dockerpkg.EngineVersion(run.DaemonVersion); running != "" { + status.To = running + } if status.From == "" { // docker-ce was not in the plan: the engine is the one that runs status.From = status.To @@ -448,6 +463,11 @@ func (u *systemPackageUpdater) dockerRun() (SystemDockerUpdateStatus, string) { status.RollbackCommand = dockerpkg.RollbackCommand(run.Previous) } } + if status.MajorJump { + // After a major jump the packages go back and Docker starts, and the containers do not: what + // is not known to work is not offered, whatever the state. + status.RollbackCommand = "" + } if !run.CompletedAt.IsZero() { status.CompletedAt = run.CompletedAt.Format(time.RFC3339) } diff --git a/service/system_package_docker_run_test.go b/service/system_package_docker_run_test.go index 8423839a..c28861e0 100644 --- a/service/system_package_docker_run_test.go +++ b/service/system_package_docker_run_test.go @@ -92,15 +92,19 @@ func TestStartDockerUpdateOwnersCase(t *testing.T) { t.Errorf("phase = %q", status.Phase) } - // the log's first line is the core's, with a nonce that only that line and the unit have + // the log's first line is the core's, with a nonce that only that line and the unit have; the + // second is the plan: Docker 28 to 29 is a major jump log, err := os.ReadFile(s.updater.dockerLogPath()) if err != nil { t.Fatal(err) } run := dockerpkg.ParseRun(string(log)) - if run.Nonce == "" || !dockerpkg.ValidNonce(run.Nonce) || string(log) != dockerpkg.QueuedMarker(run.Nonce, s.updater.now()) { + if run.Nonce == "" || !dockerpkg.ValidNonce(run.Nonce) || string(log) != dockerpkg.QueuedMarker(run.Nonce, s.updater.now())+dockerpkg.PlanMarker(run.Nonce, "28.0.4", "29.8.0", true) { t.Fatalf("log = %q", log) } + if status.Log != string(log) || !status.MajorJump || status.From != "28.0.4" || status.To != "29.8.0" || status.RollbackCommand != "" { + t.Errorf("the status of the start = %#v: want the log as it is, a major jump, 28.0.4 to 29.8.0", status) + } if info, err := os.Stat(s.updater.dockerLogPath()); err != nil || info.Mode().Perm() != 0o644 { t.Errorf("the log's mode = %v, %v: the System packages update's log has 0644", info, err) } @@ -572,9 +576,13 @@ func TestStartDockerUpdateWritesAWholeRunWhenSystemdRunFails(t *testing.T) { t.Fatalf("run = %#v, log = %q", run, log) } lines := strings.Split(strings.TrimSpace(string(log)), "\n") - if len(lines) != 3 || !strings.HasPrefix(lines[0], "CASAOS_DOCKER_UPDATE_QUEUED "+run.Nonce) || !strings.Contains(lines[1], "Access denied") || !strings.HasPrefix(lines[2], "CASAOS_DOCKER_UPDATE_FAILED "+run.Nonce+" 2026-08-13T01:02:03Z start") { + if len(lines) != 4 || !strings.HasPrefix(lines[0], "CASAOS_DOCKER_UPDATE_QUEUED "+run.Nonce) || lines[1] != "CASAOS_DOCKER_UPDATE_PLAN "+run.Nonce+" 28.0.4 29.8.0 1" || !strings.Contains(lines[2], "Access denied") || !strings.HasPrefix(lines[3], "CASAOS_DOCKER_UPDATE_FAILED "+run.Nonce+" 2026-08-13T01:02:03Z start") { t.Errorf("log = %q", log) } + // the plan is still the run's: the page is told what the update was to be, and no way back + if !status.MajorJump || status.From != "28.0.4" || status.To != "29.8.0" || status.RollbackCommand != "" { + t.Errorf("major_jump = %v, from %q, to %q, rollback %q", status.MajorJump, status.From, status.To, status.RollbackCommand) + } // a unit that systemd did not start is not a plan that changed: the code says so, and what // systemd said is the error if status.State != "failed" || status.Outcome != "failed" || status.ErrorCode != "start" || !strings.Contains(status.Error, "Access denied") || status.CompletedAt == "" || status.Phase != "" { @@ -896,3 +904,95 @@ func TestDockerUpdateArgsRefuseWhatIsNotValidated(t *testing.T) { } } } + +// The plan is the second line, and it is there before the unit is: the status of a unit that has +// not written a word yet already says where it goes, and a start that systemd then refuses leaves a +// log that still says it. +func TestStartDockerUpdateWritesTheQueuedLineAndThePlanInOneWrite(t *testing.T) { + s := newStartBox(t, nil) + var writes []string + write := s.updater.writeFile + s.updater.writeFile = func(path string, data []byte, mode os.FileMode) error { + if path == s.updater.dockerLogPath() { + writes = append(writes, string(data)) + } + return write(path, data, mode) + } + var seenByTheUnit string + start := s.updater.start + s.updater.start = func(path, unit string, args ...string) ([]byte, error) { + log, _ := os.ReadFile(s.updater.dockerLogPath()) + seenByTheUnit = string(log) + return start(path, unit, args...) + } + if _, err := s.updater.startDockerUpdate(s.planID); err != nil { + t.Fatalf("startDockerUpdate() error = %v", err) + } + if len(writes) != 1 || strings.Count(writes[0], "\n") != 2 || seenByTheUnit != writes[0] { + t.Fatalf("writes = %q, the log when the unit was started = %q: want the two lines in one write, before the start", writes, seenByTheUnit) + } + first, second, _ := strings.Cut(writes[0], "\n") + if !strings.HasPrefix(first, "CASAOS_DOCKER_UPDATE_QUEUED ") || !strings.HasPrefix(second, "CASAOS_DOCKER_UPDATE_PLAN ") { + t.Errorf("log = %q", writes[0]) + } +} + +func TestStartDockerUpdateWritesThePlanOfWhatItStarts(t *testing.T) { + patch := func(b *aptBox) { + const current, candidate = "5:29.8.1-1~debian.11~bullseye", "5:29.8.2-1~debian.11~bullseye" + engine, client := instEngine("docker-ce", current, candidate), instEngine("docker-ce-cli", current, candidate) + b.upgradeSimulation = engine + client + b.dockerCE = current + b.packages = map[string]string{"docker-ce-cli": current} + b.policy = strings.NewReplacer(debian28, current, debian29, candidate).Replace(ownerPolicy) + b.enginePlans = map[string]string{"docker-ce": engine, "docker-ce-cli": client} + } + pluginAlone := func(b *aptBox) { + const plugin, newer = "2.40.0-1~debian.11~bullseye", "2.40.1-1~debian.11~bullseye" + b.upgradeSimulation = instEngine("docker-compose-plugin", plugin, newer) + b.packages["docker-compose-plugin"] = plugin + b.policy = strings.NewReplacer(debian29, debian28).Replace(ownerPolicy) // the engine is current + b.enginePlans = map[string]string{"docker-compose-plugin": instEngine("docker-compose-plugin", plugin, newer)} + } + withDependencies := func(b *aptBox) { + b.upgradeSimulation = simLibc + b.enginePlans["containerd.io"] = ownerNewDependencies + ownerContaind + } + for _, c := range []struct { + name string + tweak func(*aptBox) + from, to string + jump bool + }{ + {"the owner's box", nil, "28.0.4", "29.8.0", true}, + {"the owner's box, with the packages Docker 29 needs", withDependencies, "28.0.4", "29.8.0", true}, + {"a patch of the same major", patch, "29.8.1", "29.8.2", false}, + {"a plugin alone, the engine does not move", pluginAlone, "28.0.4", "28.0.4", false}, + } { + s := newStartBox(t, c.tweak) + fresh := ownerBox(t) + if c.tweak != nil { + c.tweak(fresh) + } + s.planID = checkBox(t, fresh, nil).Docker.Update.PlanID + status, err := s.updater.startDockerUpdate(s.planID) + if err != nil { + t.Fatalf("%s: startDockerUpdate() error = %v", c.name, err) + } + log, _ := os.ReadFile(s.updater.dockerLogPath()) + run := dockerpkg.ParseRun(string(log)) + if want := dockerpkg.QueuedMarker(run.Nonce, s.updater.now()) + dockerpkg.PlanMarker(run.Nonce, c.from, c.to, c.jump); run.Nonce == "" || string(log) != want { + t.Errorf("%s: log = %q, want %q", c.name, log, want) + } + if run.From != c.from || run.To != c.to || run.MajorJump != c.jump { + t.Errorf("%s: the run says %q to %q, major jump %v", c.name, run.From, run.To, run.MajorJump) + } + // the status of the start and the status that follows say the same of it + again := s.updater.dockerStatus() + for _, got := range []SystemDockerUpdateStatus{status, again} { + if got.From != c.from || got.To != c.to || got.MajorJump != c.jump { + t.Errorf("%s: status = %#v, want %q to %q, major jump %v", c.name, got, c.from, c.to, c.jump) + } + } + } +} diff --git a/service/system_package_docker_script_test.go b/service/system_package_docker_script_test.go index 7edefe4a..a5d18176 100644 --- a/service/system_package_docker_script_test.go +++ b/service/system_package_docker_script_test.go @@ -893,3 +893,11 @@ func TestTheUnitsDefaultsAreTheWaitsOfTheSpec(t *testing.T) { t.Errorf("the unit waited %q virtual seconds, want two waits of 300 s (a poll of 2 s)", clock) } } + +// The plan line is the core's word, written before the unit exists: whether the update is a major +// jump is decided by the core and not by what the unit prints. +func TestTheScriptNeverWritesAPlanLine(t *testing.T) { + if strings.Contains(dockerUpdateScript, "PLAN") { + t.Error("the script mentions a PLAN marker, which only the core writes") + } +} diff --git a/service/system_package_docker_status_test.go b/service/system_package_docker_status_test.go index 44ef4bbf..0407c9c8 100644 --- a/service/system_package_docker_status_test.go +++ b/service/system_package_docker_status_test.go @@ -101,7 +101,7 @@ func TestDockerStatusWithoutARun(t *testing.T) { } // ... and what the page reads encoded, _ := json.Marshal(status) - if got := string(encoded); got != `{"supported":true,"state":"idle","phase":"","outcome":"","error":"","error_code":"","exit_code":null,"started_at":"","completed_at":"","from":"","to":"","not_returned":[],"rollback_command":"","log":""}` { + if got := string(encoded); got != `{"supported":true,"state":"idle","phase":"","outcome":"","error":"","error_code":"","exit_code":null,"started_at":"","completed_at":"","from":"","to":"","major_jump":false,"not_returned":[],"rollback_command":"","log":""}` { t.Errorf("JSON = %s", got) } } @@ -730,3 +730,208 @@ func TestReadDockerMarkersReadsWholeLinesOnly(t *testing.T) { t.Error("a log that is not there was read") } } + +// withPlan is a run's lines with the core's second line, the plan, put in after the first. +func withPlan(plan string, run []string) []string { + return append([]string{run[0], plan}, run[1:]...) +} + +var ( + planMajor = mark("PLAN", "28.0.4", "29.8.0", "1") + planMinor = mark("PLAN", "28.0.4", "28.1.0", "0") +) + +// After a major jump the packages go back and Docker starts, and the containers do not: no run of one +// is told of a command that does not bring the apps back. The plan the core wrote says it was one. +func TestDockerStatusOfAMajorJumpOffersNoRollbackAndSaysWhereItGoes(t *testing.T) { + failed := func(reason string) string { return mark("FAILED", "2026-08-13T01:03:00Z", reason) } + for _, c := range []struct { + name string + active bool + lines []string + state string + code string + to string + }{ + {"queued", true, []string{logQueued, planMajor}, "running", "", "29.8.0"}, + {"started, before the snapshot", true, []string{logQueued, planMajor, logStarted}, "running", "", "29.8.0"}, + {"running", true, withPlan(planMajor, ownersRun()), "running", "", "29.8.0"}, + {"failed in the guard", false, withPlan(planMajor, ownersRun(failed("guard"))), "failed", "guard", "29.8.0"}, + {"failed in the download", false, withPlan(planMajor, ownersRun(failed("download"))), "failed", "download", "29.8.0"}, + {"failed in the install", false, withPlan(planMajor, ownersRun(failed("install"))), "failed", "install", "29.8.0"}, + {"failed, Docker did not come back", false, withPlan(planMajor, ownersRun(failed("daemon"))), "failed", "daemon", "29.8.0"}, + {"failed to start", false, []string{logQueued, planMajor, "Failed to start transient service unit: Access denied", failed("start")}, "failed", "start", "29.8.0"}, + {"no result", false, withPlan(planMajor, ownersRun()), "failed", "no_result", "29.8.0"}, + {"restart pending", false, withPlan(planMajor, ownersRun(mark("DAEMON", "28.0.4"), mark("RESTART_PENDING", "2026-08-13T01:05:00Z"))), "succeeded", "", "29.8.0"}, + {"success", false, withPlan(planMajor, ownersRun(mark("DAEMON", "29.8.0"), mark("SUCCESS", "2026-08-13T01:05:00Z"))), "succeeded", "", "29.8.0"}, + } { + s := newStatusBox(t) + s.box.activeUnits[systemDockerUpdateUnit] = c.active + s.write(t, c.lines...) + status := s.status(t) + if status.State != c.state || status.ErrorCode != c.code { + t.Errorf("%s: status = %#v, want %s %q", c.name, status, c.state, c.code) + } + if !status.MajorJump || status.From != "28.0.4" || status.To != c.to || status.RollbackCommand != "" { + t.Errorf("%s: major_jump = %v, from %q, to %q, rollback %q: want true, 28.0.4, %s and none", c.name, status.MajorJump, status.From, status.To, status.RollbackCommand, c.to) + } + } +} + +// The command stays for a run that is not a major jump, and for a log that has no plan (an older +// core's run, which did not know it). +func TestDockerStatusOfAMinorUpdateStillOffersItsRollback(t *testing.T) { + want := "sudo apt-get install --allow-downgrades " + pinContainer + " docker-ce=" + debian28 + " docker-ce-cli=" + debian28 + for _, c := range []struct { + name string + lines []string + from string + to string + }{ + {"a plan that is not a jump, failed", withPlan(planMinor, ownersRun(mark("FAILED", "2026-08-13T01:03:00Z", "daemon"))), "28.0.4", "28.1.0"}, + {"a plan that is not a jump, no result", withPlan(planMinor, ownersRun()), "28.0.4", "28.1.0"}, + {"no plan, failed", ownersRun(mark("FAILED", "2026-08-13T01:03:00Z", "daemon")), "28.0.4", ""}, + {"no plan, no result", ownersRun(), "28.0.4", ""}, + {"a plan that knows no version, failed", withPlan(mark("PLAN", "-", "-", "0"), ownersRun(mark("FAILED", "2026-08-13T01:03:00Z", "install"))), "28.0.4", ""}, + } { + s := newStatusBox(t) + s.write(t, c.lines...) + status := s.status(t) + if status.State != "failed" || status.MajorJump || status.From != c.from || status.To != c.to || status.RollbackCommand != want { + t.Errorf("%s: status = %#v, want the rollback, no major jump, from %q to %q", c.name, status, c.from, c.to) + } + } +} + +// from and to are the plan's until a later marker of the unit has them: the snapshot of what was +// installed says where the engine came from, the daemon where it is once the run went well. +func TestDockerStatusTakesFromAndToFromThePlanAndThenFromTheUnit(t *testing.T) { + s := newStatusBox(t) + s.box.activeUnits[systemDockerUpdateUnit] = true + + s.write(t, logQueued, planMajor) + if status := s.status(t); status.From != "28.0.4" || status.To != "29.8.0" || !status.MajorJump || status.Phase != "preparing" { + t.Errorf("queued: status = %#v", status) + } + // the snapshot of the unit is what was installed, and is believed over the plan + s.write(t, logQueued, mark("PLAN", "27.0.0", "28.0.0", "1"), logStarted, logPrevious) + if status := s.status(t); status.From != "28.0.4" || status.To != "28.0.0" || !status.MajorJump { + t.Errorf("a snapshot: status = %#v, want from 28.0.4 (the snapshot) to 28.0.0 (the plan)", status) + } + // the daemon that runs once it went well is what the engine is now + s.box.activeUnits[systemDockerUpdateUnit] = false + s.write(t, withPlan(planMajor, ownersRun(mark("DAEMON", "29.8.1"), mark("SUCCESS", "2026-08-13T01:05:00Z")))...) + if status := s.status(t); status.State != "succeeded" || status.From != "28.0.4" || status.To != "29.8.1" || !status.MajorJump { + t.Errorf("a success: status = %#v, want to 29.8.1 (the daemon's)", status) + } + // ... but not when it still is the old one: the packages are the new ones + s.write(t, withPlan(planMajor, ownersRun(mark("DAEMON", "28.0.4"), mark("RESTART_PENDING", "2026-08-13T01:05:00Z")))...) + if status := s.status(t); status.Outcome != "restart_pending" || status.From != "28.0.4" || status.To != "29.8.0" || !status.MajorJump { + t.Errorf("a restart pending: status = %#v", status) + } + // a plan that does not know the versions leaves them to the unit, as an older core's run did + s.write(t, withPlan(mark("PLAN", "-", "-", "0"), ownersRun(mark("DAEMON", "29.8.0"), mark("SUCCESS", "2026-08-13T01:05:00Z")))...) + if status := s.status(t); status.From != "28.0.4" || status.To != "29.8.0" || status.MajorJump { + t.Errorf("an unknown plan: status = %#v", status) + } + // the engine did not move (only containerd.io did): the plan says the one that is installed + s.write(t, logQueued, mark("PLAN", "28.0.4", "28.0.4", "0"), logStarted, mark("PREVIOUS", pinContainer), mark("DAEMON", "28.0.4"), mark("SUCCESS", "2026-08-13T01:05:00Z")) + if status := s.status(t); status.From != "28.0.4" || status.To != "28.0.4" || status.MajorJump { + t.Errorf("a plan without docker-ce: status = %#v", status) + } +} + +// Only the core's line is the plan. What apt prints, a line with another run's nonce, a second line, a +// line that is not shaped like one, and a plan that comes before the first line are not. +func TestDockerStatusKeepsTheCoresPlanAgainstHostileLines(t *testing.T) { + failed := mark("FAILED", "2026-08-13T01:03:00Z", "daemon") + forgedNonce := "CASAOS_DOCKER_UPDATE_PLAN 0000000000000000000000000000000f 28.0.4 29.8.0 1" + rollback := "sudo apt-get install --allow-downgrades " + pinContainer + " docker-ce=" + debian28 + " docker-ce-cli=" + debian28 + for _, c := range []struct { + name string + lines []string + major bool + rollback string + to string + }{ + {"a plan of another nonce does not make a jump", withPlan(planMinor, ownersRun(forgedNonce, failed)), false, rollback, "28.1.0"}, + {"a plan of another nonce does not undo one", withPlan(planMajor, ownersRun(strings.Replace(forgedNonce, " 1", " 0", 1), failed)), true, "", "29.8.0"}, + {"a plan of another nonce alone is no plan", ownersRun(forgedNonce, failed), false, rollback, ""}, + {"a second plan does not undo the first", withPlan(planMajor, ownersRun(planMinor, failed)), true, "", "29.8.0"}, + {"a second plan does not make a jump", withPlan(planMinor, ownersRun(planMajor, failed)), false, rollback, "28.1.0"}, + {"a malformed plan is none", withPlan(mark("PLAN", "28.0.4", "29.8.0", "maybe"), ownersRun(failed)), false, rollback, ""}, + {"a plan with a version that is not one is none", withPlan(mark("PLAN", "28.0.4;reboot", "29.8.0", "1"), ownersRun(failed)), false, rollback, ""}, + {"a plan with a field too many is none", withPlan(mark("PLAN", "28.0.4", "29.8.0", "1", "x"), ownersRun(failed)), false, rollback, ""}, + {"a malformed plan leaves the next one", withPlan(mark("PLAN", "28.0.4", "29.8.0", "2"), withPlan(planMajor, ownersRun(failed))), true, "", "29.8.0"}, + {"a plan in apt's output does not make a jump", withPlan(planMinor, ownersRun("Setting up docker-ce (5:29.8.0-1) ... "+planMajor, " "+planMajor, "container: "+planMajor, failed)), false, rollback, "28.1.0"}, + {"a plan in apt's output is no plan", ownersRun("Setting up docker-ce (5:29.8.0-1) ... "+planMajor, "container: "+planMajor, failed), false, rollback, ""}, + {"a plan with a nonce and nothing else", withPlan(mark("PLAN"), ownersRun(failed)), false, rollback, ""}, + } { + s := newStatusBox(t) + s.write(t, c.lines...) + status := s.status(t) + if status.State != "failed" || status.MajorJump != c.major || status.RollbackCommand != c.rollback || status.To != c.to { + t.Errorf("%s: status = %#v, want major %v, to %q, rollback %q", c.name, status, c.major, c.to, c.rollback) + } + } + + // a plan before the core's first line: line 1 is the run, and there is none + s := newStatusBox(t) + s.write(t, append([]string{planMajor}, ownersRun(failed)...)...) + if status := s.status(t); status.State != "idle" || status.MajorJump || status.From != "" || status.To != "" { + t.Errorf("a plan before the first line: status = %#v", status) + } + s.write(t, append([]string{"Reading package lists...", planMajor}, ownersRun(failed)...)...) + if status := s.status(t); status.State != "idle" || status.MajorJump { + t.Errorf("a plan after something else: status = %#v", status) + } +} + +// The scan has a bound: the plan is on line 2, in the part that is read whatever comes after it. +func TestDockerStatusReadsThePlanOfAHugeLog(t *testing.T) { + s := newStatusBox(t) + noise := strings.Repeat(strings.Repeat("x", 1023)+"\n", 20<<10) // 20 MiB + log := lines(logQueued, planMajor, logStarted, logPrevious, "container: web always", mark("DOWNLOADED", "2026-08-13T01:00:30Z")) + noise + + lines(mark("INSTALLED", "2026-08-13T01:02:00Z"), mark("FAILED", "2026-08-13T01:03:00Z", "daemon")) + if int64(len(log)) <= systemDockerMarkerScanBytes { + t.Fatalf("the log is %d bytes, not beyond the bound of %d", len(log), systemDockerMarkerScanBytes) + } + s.writeRaw(t, log) + status := s.status(t) + if status.State != "failed" || status.ErrorCode != "daemon" || !status.MajorJump || status.From != "28.0.4" || status.To != "29.8.0" || status.RollbackCommand != "" { + t.Errorf("status = %#v", status) + } + // a plan that is a line of apt's, in the middle of what is not read, is not one + log = lines(logQueued, planMinor, logStarted, logPrevious) + noise + lines(planMajor, mark("FAILED", "2026-08-13T01:03:00Z", "daemon")) + s.writeRaw(t, log) + if status := s.status(t); status.MajorJump || status.To != "28.1.0" || status.RollbackCommand == "" { + t.Errorf("a second plan at the end of a huge log: status = %#v", status) + } +} + +// What readDockerMarkers keeps for ParseRun when the log is longer than the bound: the plan is a +// marker line, and is kept with the first line and the ones after it. +func TestReadDockerMarkersKeepsThePlanLine(t *testing.T) { + old := systemDockerMarkerScanBytes + systemDockerMarkerScanBytes = 2048 + t.Cleanup(func() { systemDockerMarkerScanBytes = old }) + + path := t.TempDir() + "/docker-update.log" + text := lines(logQueued, planMajor, logStarted) + strings.Repeat("noise noise noise\n", 400) + lines(mark("FAILED", "2026-08-13T01:03:00Z", "daemon")) + if int64(len(text)) <= systemDockerMarkerScanBytes { + t.Fatalf("the log is %d bytes", len(text)) + } + if err := os.WriteFile(path, []byte(text), 0o644); err != nil { + t.Fatal(err) + } + read, err := readDockerMarkers(path) + if err != nil { + t.Fatal(err) + } + if !strings.HasPrefix(read, logQueued+"\n"+planMajor+"\n") || strings.Contains(read, "noise") { + t.Errorf("read = %q", read) + } + if run := dockerpkg.ParseRun(read); !run.MajorJump || run.From != "28.0.4" || run.To != "29.8.0" || run.Terminal != dockerpkg.TerminalFailed { + t.Errorf("run = %#v", run) + } +}