From 356346122a7933f1ec1dcf19fb59b62193a8c335 Mon Sep 17 00:00:00 2001 From: Gary Date: Sat, 10 Oct 2026 20:16:56 +0200 Subject: [PATCH 1/2] feat(packages): the Docker update's log records the plan, and whether it is a major jump The core writes a PLAN line right after the QUEUED line: the engine versions the plan goes from and to, and the plan's own major_jump. ParseRun reads it with the same discipline as the other markers: the first valid one wins, a malformed one or one with another nonce is ignored. --- pkg/dockerpkg/run.go | 68 +++++++++++++++++- pkg/dockerpkg/run_test.go | 148 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 215 insertions(+), 1 deletion(-) 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) + } + } +} From 70a623bebc0e0d659dfccfbd51842a5cda9e372e Mon Sep 17 00:00:00 2001 From: Gary Date: Sat, 10 Oct 2026 20:25:47 +0200 Subject: [PATCH 2/2] fix(packages): offer no way back after a Docker major jump A first real proof showed that after Docker 28 to 29 the packages go back and Docker starts, and the containers stay stopped. The rollback command the status printed is then no way back. The start writes the QUEUED and PLAN lines in one write; the status carries major_jump, and from/to from the PLAN line until the unit's own markers say better (the snapshot of what was installed for from, the daemon at success for to). rollback_command is empty whenever major_jump is true, in the failed and the no_result states alike. A log with no PLAN line (an older core's run) reads as no major jump and keeps today's behaviour. --- pkg/alerts/docker.go | 3 +- pkg/alerts/docker_test.go | 10 + route/v1/system_docker_update_test.go | 42 +++- service/system_package_docker_run.go | 36 +++- service/system_package_docker_run_test.go | 106 +++++++++- service/system_package_docker_script_test.go | 8 + service/system_package_docker_status_test.go | 207 ++++++++++++++++++- 7 files changed, 397 insertions(+), 15 deletions(-) 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/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) + } +}