From 3bd4f1bdfe790037c6bfd0c6edf383e487c4434d Mon Sep 17 00:00:00 2001 From: Zoltan Csizmadia Date: Mon, 12 Oct 2026 08:19:59 -0500 Subject: [PATCH] fix(supervise): the scheduled prune talks to the engine API, so it no longer resets the idle clock (#496) The prune ran docker through Skrog's own pipe, which stamped LastActivity; a prune.every at or below idle-timeout kept the engine from ever idling. prune.RunAPI executes the same plan against /containers, /images, /volumes and /build prune over the bridge's own transport (shared with the busy probe as engineClient). skrog prune by hand still uses the CLI. The doctor check for the combination is removed: it is no longer a problem. --- CHANGELOG.md | 8 ++ cmd/skrog/idle.go | 36 +++--- cmd/skrog/prune.go | 5 +- cmd/skrog/supervise.go | 2 +- docs/housekeeping.md | 14 +-- internal/doctor/check_prune_idle.go | 85 -------------- internal/doctor/check_prune_idle_test.go | 142 ----------------------- internal/doctor/doctor.go | 1 - internal/doctor/host.go | 10 -- internal/prune/api.go | 111 ++++++++++++++++++ internal/prune/api_test.go | 74 ++++++++++++ 11 files changed, 223 insertions(+), 265 deletions(-) delete mode 100644 internal/doctor/check_prune_idle.go delete mode 100644 internal/doctor/check_prune_idle_test.go create mode 100644 internal/prune/api.go create mode 100644 internal/prune/api_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index c64ec1e..1c65277 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,14 @@ useful than saying where the real one is. ### Fixed +- **A short `prune.every` no longer stops the engine idling** + ([#496](https://github.com/wslkit/skrog/issues/496)). The scheduled prune ran + `docker` through Skrog's own pipe, so every sweep counted as client activity + and reset the idle clock; with `prune.every` at or below `idle-timeout` the + engine never idle-stopped. The supervisor now talks to the engine API + directly, which the idle clock does not see. `skrog doctor` no longer warns + about the combination, because it is no longer a problem. `skrog prune` run + by hand is unchanged. - **`skrog start` right after `wsl --shutdown` could time out.** Since 0.9.0 a `wsl --shutdown` is left alone until the next docker command. If `skrog start` ran before the supervisor's next health check, it wrote nothing the diff --git a/cmd/skrog/idle.go b/cmd/skrog/idle.go index 957fa7d..3135e11 100644 --- a/cmd/skrog/idle.go +++ b/cmd/skrog/idle.go @@ -79,20 +79,7 @@ func (rwcConn) SetWriteDeadline(time.Time) error { return nil } // transport the bridge uses. The idle stop needs a definite "no": any error // here vetoes it (supervise.Supervisor.Busy's contract). func busyProbe(dialer pipeproxy.Dialer, busyLog *slog.Logger) func(ctx context.Context) (bool, error) { - client := &http.Client{ - Transport: &http.Transport{ - DialContext: func(ctx context.Context, _, _ string) (net.Conn, error) { - rwc, err := dialer.Dial(ctx) - if err != nil { - return nil, err - } - return rwcConn{rwc}, nil - }, - // One probe, one connection: the engine socket is not a place to - // pool idle keep-alives that would themselves look like activity. - DisableKeepAlives: true, - }, - } + client := engineClient(dialer) return func(ctx context.Context) (bool, error) { ctx, cancel := context.WithTimeout(ctx, 10*time.Second) defer cancel() @@ -158,3 +145,24 @@ func engineBusy(dialer pipeproxy.Dialer, p *provision.Provisioner, opts provisio return p.SocketBusy(ctx, opts) } } + +// engineClient is an http.Client that reaches the engine over the bridge's own +// transport rather than through the pipe server, so what it sends is never +// client activity. The busy probe and the scheduled prune (#496) both need +// exactly that. +func engineClient(dialer pipeproxy.Dialer) *http.Client { + return &http.Client{ + Transport: &http.Transport{ + DialContext: func(ctx context.Context, _, _ string) (net.Conn, error) { + rwc, err := dialer.Dial(ctx) + if err != nil { + return nil, err + } + return rwcConn{rwc}, nil + }, + // One request, one connection: the engine socket is not a place to + // pool idle keep-alives that would themselves look like activity. + DisableKeepAlives: true, + }, + } +} diff --git a/cmd/skrog/prune.go b/cmd/skrog/prune.go index 7184c26..e6d0317 100644 --- a/cmd/skrog/prune.go +++ b/cmd/skrog/prune.go @@ -9,6 +9,7 @@ import ( "os" "github.com/wslkit/skrog/internal/dockerctx" + "github.com/wslkit/skrog/internal/pipeproxy" "github.com/wslkit/skrog/internal/prune" "github.com/wslkit/skrog/internal/supervise" ) @@ -105,9 +106,9 @@ flags: // All is on: an automatic sweep that only removed dangling layers would leave // the tagged images that actually fill a disk, and the age guard is what keeps // that honest rather than the dangling-only filter. -func autoPrune(log *slog.Logger) func(context.Context, supervise.PrunePolicy) (uint64, error) { +func autoPrune(dialer pipeproxy.Dialer, log *slog.Logger) func(context.Context, supervise.PrunePolicy) (uint64, error) { return func(ctx context.Context, p supervise.PrunePolicy) (uint64, error) { - res := prune.Run(ctx, prune.DockerRunner{}, prune.Options{ + res := prune.RunAPI(ctx, engineClient(dialer), prune.Options{ All: true, Until: p.KeepSince, BuildCache: p.BuildCache, diff --git a/cmd/skrog/supervise.go b/cmd/skrog/supervise.go index e12e945..f65cd94 100644 --- a/cmd/skrog/supervise.go +++ b/cmd/skrog/supervise.go @@ -412,7 +412,7 @@ flags: BuildCache: c.PruneBuildCache, } }, - Prune: autoPrune(log), + Prune: autoPrune(dialer, log), } srv.Dialer = &demandDialer{sup: sup, inner: dialer} go sup.Run(ctx) diff --git a/docs/housekeeping.md b/docs/housekeeping.md index d6ec611..10d6270 100644 --- a/docs/housekeeping.md +++ b/docs/housekeeping.md @@ -71,16 +71,10 @@ slow pull later. An idle stop will also wait while a prune is running, rather than stopping the engine out from under it. -> **A short `prune.every` can suppress idle-stop entirely** -> ([#496](https://github.com/wslkit/skrog/issues/496), open). The prune talks -> to the engine, and that traffic stamps the same "last activity" clock the -> idle timeout reads — so a `prune.every` shorter than your `idle-timeout` -> keeps resetting it and the engine never goes idle. Two features that are -> each working as described, quietly cancelling each other. Until that is -> settled, keep `prune.every` comfortably longer than `idle-timeout` -- and -> `skrog doctor` warns when they are set the other way round, because the -> symptom ("my engine never releases its RAM") is not one anyone would connect -> to a housekeeping setting on their own. +The prune talks to the engine API directly rather than running `docker`, so +it does not count as client activity: a `prune.every` shorter than your +`idle-timeout` no longer keeps the engine awake +([#496](https://github.com/wslkit/skrog/issues/496)). Before 0.10.0 it did. ### Finding out what it did diff --git a/internal/doctor/check_prune_idle.go b/internal/doctor/check_prune_idle.go deleted file mode 100644 index e81a124..0000000 --- a/internal/doctor/check_prune_idle.go +++ /dev/null @@ -1,85 +0,0 @@ -package doctor - -import ( - "fmt" - "strconv" - "time" -) - -// checkPruneIdle reports a `prune.every` short enough to stop the engine ever -// idling (#496). -// -// The automatic prune drives docker back through Skrog's own pipe, so every -// sweep stamps the same "last activity" clock the idle timeout reads. With -// `prune.every` at or below `idle-timeout`, the window is reset before it can -// ever expire and the engine never idle-stops: the supervisor keeps waking it -// up to tidy it. -// -// Both settings are off by default, so nothing ships in this state -- it takes -// turning both on and setting the prune interval shorter, which is the -// opposite of how either is normally tuned. But the symptom when it happens is -// "my engine never releases its RAM", which is a thing people notice, cannot -// explain, and would have no reason to connect to a housekeeping setting. -// -// Judged from the CONFIGURATION, not from the idle-stop counters. Counters -// look like the obvious evidence and are the weaker signal: a machine that has -// simply been busy, or started five minutes ago, also shows zero idle stops. -// Two durations and a comparison is a verdict; a counter at zero is a guess. -func checkPruneIdle() Check { - c := Check{Name: "prune-idle", Title: "idle-stop versus automatic prune"} - c.Run = func(f Facts) Result { - if f.IdleTimeout <= 0 { - return result(c, Skip, "idle-timeout is off, so there is no idle stop to prevent") - } - if f.PruneEvery <= 0 { - return result(c, Skip, "prune.every is off, so nothing resets the idle clock") - } - if f.PruneEvery > f.IdleTimeout { - return result(c, OK, fmt.Sprintf( - "prune.every %s is longer than idle-timeout %s, so the engine can still idle", - short(f.PruneEvery), short(f.IdleTimeout))) - } - - r := result(c, Warn, fmt.Sprintf( - "prune.every %s is not longer than idle-timeout %s, so the engine will never idle-stop", - short(f.PruneEvery), short(f.IdleTimeout))) - r.Detail = []string{ - "The automatic prune talks to the engine through Skrog's own pipe, and that", - "traffic restarts the idle window -- so the timeout is reset before it can", - "expire and the RAM is never returned.", - } - r.Remedy = fmt.Sprintf( - "set prune.every longer than idle-timeout: `skrog config set prune.every %s` "+ - "(or lower idle-timeout). Tracked as #496.", suggest(f.IdleTimeout)) - return r - } - return c -} - -// short renders a duration the way the setting is written, not the way Go -// prints it: `10m`, not `10m0s`. The remedy is meant to be pasted. -// -// By division rather than by trimming the string. Trimming looks simpler and -// is wrong: `strings.TrimSuffix("1m30s", "0s")` is `"1m3"`, because the suffix -// matches the end of "30s" too. -func short(d time.Duration) string { - switch { - case d >= time.Hour && d%time.Hour == 0: - return strconv.FormatInt(int64(d/time.Hour), 10) + "h" - case d >= time.Minute && d%time.Minute == 0: - return strconv.FormatInt(int64(d/time.Minute), 10) + "m" - default: - return d.String() - } -} - -// suggest is a prune interval comfortably clear of the idle timeout rather -// than one second past it: a value that only just clears the comparison would -// still race a sweep that runs long. -func suggest(idle time.Duration) string { - d := idle * 4 - if d < time.Hour { - d = time.Hour - } - return short(d.Round(time.Minute)) -} diff --git a/internal/doctor/check_prune_idle_test.go b/internal/doctor/check_prune_idle_test.go deleted file mode 100644 index ddfbc6f..0000000 --- a/internal/doctor/check_prune_idle_test.go +++ /dev/null @@ -1,142 +0,0 @@ -package doctor - -import ( - "context" - "strings" - "testing" - "time" - - "github.com/wslkit/skrog/internal/config" -) - -func pruneIdleResult(t *testing.T, idle, every time.Duration) Result { - t.Helper() - return checkPruneIdle().Run(Facts{IdleTimeout: idle, PruneEvery: every}) -} - -// The case the check exists for: a prune interval that resets the idle window -// before it can expire, so the engine never returns its RAM (#496). -func TestPruneShorterThanIdleWarns(t *testing.T) { - r := pruneIdleResult(t, 30*time.Minute, 10*time.Minute) - if r.Status != Warn { - t.Fatalf("status = %v, want Warn", r.Status) - } - // The message has to name both numbers, or the reader cannot tell which - // of their two settings to change. - for _, want := range []string{"10m", "30m", "never idle-stop"} { - if !strings.Contains(r.Summary, want) { - t.Errorf("summary should mention %q: %q", want, r.Summary) - } - } - if r.Remedy == "" { - t.Error("a warning with no remedy is the kind doctor output people learn to skim") - } -} - -// Equal is the same failure: the window is reset exactly as it would expire. -func TestPruneEqualToIdleWarns(t *testing.T) { - if r := pruneIdleResult(t, 20*time.Minute, 20*time.Minute); r.Status != Warn { - t.Errorf("status = %v for equal durations, want Warn", r.Status) - } -} - -func TestPruneLongerThanIdleIsOK(t *testing.T) { - if r := pruneIdleResult(t, 20*time.Minute, 24*time.Hour); r.Status != OK { - t.Errorf("status = %v, want OK", r.Status) - } -} - -// Both are off by default, and a check that warned on a default machine is a -// check people stop reading. -func TestPruneIdleSkipsWhenEitherIsOff(t *testing.T) { - if r := pruneIdleResult(t, 0, 10*time.Minute); r.Status != Skip { - t.Errorf("idle-timeout off: status = %v, want Skip", r.Status) - } - if r := pruneIdleResult(t, 30*time.Minute, 0); r.Status != Skip { - t.Errorf("prune.every off: status = %v, want Skip", r.Status) - } - if r := pruneIdleResult(t, 0, 0); r.Status != Skip { - t.Errorf("both off: status = %v, want Skip", r.Status) - } -} - -// The remedy must clear the timeout by a margin, not by a second: a value that -// only just wins the comparison still races a sweep that runs long. -func TestTheSuggestedIntervalClearsTheTimeoutByAMargin(t *testing.T) { - idle := 30 * time.Minute - got, err := time.ParseDuration(suggest(idle)) - if err != nil { - t.Fatalf("the suggested interval does not parse as a duration: %v", err) - } - if got <= idle { - t.Errorf("suggested %s for an idle timeout of %s", got, idle) - } - // And it must be a value `skrog config set prune.every` accepts, which is - // what makes the remedy copy-pasteable rather than decorative. - if strings.Contains(suggest(idle), "µ") || strings.Contains(suggest(idle), "ns") { - t.Errorf("suggested %q is not a value anyone would type", suggest(idle)) - } -} - -// Registered, not merely written. -// -// This is the failure checkEmulation had: the check, its helper and its tests -// were all correct and nothing called it from Registry, so `skrog doctor` was -// silent about the thing the check existed to report. -func TestPruneIdleCheckIsRegistered(t *testing.T) { - for _, c := range Registry() { - if c.Name == "prune-idle" { - return - } - } - t.Fatal("checkPruneIdle is not in Registry(), so `skrog doctor` never runs it") -} - -// ...and the settings must actually REACH Facts from the config file. -// -// Every test above builds Facts by hand, which proves the check and proves -// nothing about whether `skrog doctor` ever sees a real value. That gap is how -// a correct check with correct tests reports nothing on a real machine -- the -// same shape as checkEmulation, which was registered nowhere while its own -// tests passed. -func TestIdleAndPruneSettingsReachFactsFromConfig(t *testing.T) { - dir := t.TempDir() - if err := config.Set(dir, config.KeyIdleTimeout, "30m"); err != nil { - t.Fatal(err) - } - if err := config.Set(dir, config.KeyPruneEvery, "10m"); err != nil { - t.Fatal(err) - } - - f := Gather(context.Background(), GatherOptions{StateDir: dir}) - if f.IdleTimeout != 30*time.Minute { - t.Errorf("IdleTimeout = %v, want 30m; the setting never reached doctor", f.IdleTimeout) - } - if f.PruneEvery != 10*time.Minute { - t.Errorf("PruneEvery = %v, want 10m; the setting never reached doctor", f.PruneEvery) - } - // And the check therefore fires on this machine. - if r := checkPruneIdle().Run(f); r.Status != Warn { - t.Errorf("status = %v on a machine configured to never idle-stop, want Warn", r.Status) - } -} - -// Durations read the way the settings are written, and the obvious -// implementation is wrong: TrimSuffix("1m30s", "0s") is "1m3". -func TestShortRendersDurationsTheWayPeopleWriteThem(t *testing.T) { - for _, tc := range []struct { - in time.Duration - want string - }{ - {10 * time.Minute, "10m"}, - {2 * time.Hour, "2h"}, - {25 * time.Hour, "25h"}, - {30 * time.Minute, "30m"}, - {90 * time.Second, "1m30s"}, - {45 * time.Second, "45s"}, - } { - if got := short(tc.in); got != tc.want { - t.Errorf("short(%v) = %q, want %q", tc.in, got, tc.want) - } - } -} diff --git a/internal/doctor/doctor.go b/internal/doctor/doctor.go index 6628c64..e3a6ad4 100644 --- a/internal/doctor/doctor.go +++ b/internal/doctor/doctor.go @@ -92,7 +92,6 @@ func Registry() []Check { checkGPU(), checkMultiArch(), checkEmulation(), - checkPruneIdle(), checkPublishedPorts(), checkContainerListeners(), checkDisk(), diff --git a/internal/doctor/host.go b/internal/doctor/host.go index e6cfa70..871790e 100644 --- a/internal/doctor/host.go +++ b/internal/doctor/host.go @@ -8,7 +8,6 @@ import ( "os/exec" "path/filepath" "strings" - "time" "github.com/wslkit/skrog/internal/config" "github.com/wslkit/skrog/internal/dockercli" @@ -98,13 +97,6 @@ type Facts struct { // only the second question catches that. EmulationPlatforms string - // IdleTimeout and PruneEvery are the two settings that can cancel each - // other out (#496): a prune interval at or below the idle timeout resets - // the idle window before it can expire. Zero means off, which is the - // default for both. - IdleTimeout time.Duration - PruneEvery time.Duration - // PublishedPorts is what running containers publish on the host side, and // WSLNetworkingMode is the `networkingMode` from ~/.wslconfig ("" means the // default, NAT). PublishScopeLAN is `network.publish-scope`. Together they @@ -347,8 +339,6 @@ func Gather(ctx context.Context, opts GatherOptions) Facts { pOpts.GPUVendor = c.GPUVendor f.DiskWarnBelow = c.DiskWarnBelow f.EmulationPlatforms = c.EmulationPlatforms - f.IdleTimeout = c.IdleTimeout - f.PruneEvery = c.PruneEvery f.PublishScopeLAN = c.PublishScope == config.PublishScopeLAN } diff --git a/internal/prune/api.go b/internal/prune/api.go new file mode 100644 index 0000000..47306c6 --- /dev/null +++ b/internal/prune/api.go @@ -0,0 +1,111 @@ +package prune + +import ( + "context" + "encoding/json" + "fmt" + "io" + "net/http" + "net/url" + "strings" +) + +// Doer is the slice of http.Client RunAPI needs. The supervisor hands it a +// client that dials the engine over the bridge's own transport, so the prune +// never crosses the pipe server and never counts as client activity (#496). +type Doer interface { + Do(*http.Request) (*http.Response, error) +} + +// apiVersion pins the engine API like busyProbe does, for the same reason: a +// bare unversioned path is ambiguous. +const apiVersion = "v1.44" + +// apiResult is the part of every prune response RunAPI reads. The four +// endpoints differ only in the name of the list of things they deleted. +type apiResult struct { + SpaceReclaimed int64 `json:"SpaceReclaimed"` +} + +// RunAPI is Run for the supervisor: the same plan, executed against the engine +// API instead of the docker CLI. The CLI connects over the named pipe like any +// other client, so a scheduled prune stamped LastActivity and a short +// prune.every kept the engine from ever idling (#496). A failed step never +// stops the others, as in Run. +func RunAPI(ctx context.Context, c Doer, o Options) Result { + var res Result + for _, st := range Plan(o) { + n, err := apiStep(ctx, c, st.Name, o) + if err != nil { + st.Err = err.Error() + res.Failed++ + } else { + st.ReclaimedBytes = n + res.ReclaimedBytes += n + } + res.Steps = append(res.Steps, st) + } + return res +} + +func apiStep(ctx context.Context, c Doer, name string, o Options) (int64, error) { + filters := map[string][]string{} + // volume prune has no until filter, as in Plan. + if o.Until > 0 && name != "volumes" { + filters["until"] = []string{durationArg(o.Until)} + } + q := url.Values{} + var path string + switch name { + case "containers": + path = "/containers/prune" + case "images": + path = "/images/prune" + // The API prunes dangling images by default; -a is dangling=false. + if o.All { + filters["dangling"] = []string{"false"} + } + case "volumes": + path = "/volumes/prune" + case "build-cache": + path = "/build/prune" + default: + return 0, fmt.Errorf("unknown prune step %q", name) + } + if len(filters) > 0 { + b, err := json.Marshal(filters) + if err != nil { + return 0, err + } + q.Set("filters", string(b)) + } + u := "http://engine/" + apiVersion + path + if len(q) > 0 { + u += "?" + q.Encode() + } + req, err := http.NewRequestWithContext(ctx, http.MethodPost, u, nil) + if err != nil { + return 0, err + } + resp, err := c.Do(req) + if err != nil { + return 0, err + } + defer resp.Body.Close() + body, err := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) + if err != nil { + return 0, err + } + if resp.StatusCode != http.StatusOK { + msg := strings.TrimSpace(string(body)) + if msg == "" { + msg = resp.Status + } + return 0, fmt.Errorf("engine returned %s: %s", resp.Status, msg) + } + var r apiResult + if err := json.Unmarshal(body, &r); err != nil { + return 0, fmt.Errorf("decoding %s response: %w", name, err) + } + return r.SpaceReclaimed, nil +} diff --git a/internal/prune/api_test.go b/internal/prune/api_test.go new file mode 100644 index 0000000..3592801 --- /dev/null +++ b/internal/prune/api_test.go @@ -0,0 +1,74 @@ +package prune + +import ( + "io" + "net/http" + "net/url" + "strings" + "testing" + "time" +) + +type fakeDoer struct { + reqs []*http.Request + status map[string]int + body map[string]string +} + +func (f *fakeDoer) Do(r *http.Request) (*http.Response, error) { + f.reqs = append(f.reqs, r) + code, ok := f.status[r.URL.Path] + if !ok { + code = 200 + } + b, ok := f.body[r.URL.Path] + if !ok { + b = `{"SpaceReclaimed":100}` + } + return &http.Response{StatusCode: code, Status: http.StatusText(code), Body: io.NopCloser(strings.NewReader(b))}, nil +} + +func TestRunAPIMirrorsThePlan(t *testing.T) { + f := &fakeDoer{} + res := RunAPI(t.Context(), f, Options{All: true, Until: 168 * time.Hour, BuildCache: true, Volumes: true}) + var paths []string + for _, r := range f.reqs { + if r.Method != http.MethodPost { + t.Errorf("%s used %s, want POST", r.URL.Path, r.Method) + } + paths = append(paths, r.URL.Path) + } + want := "/v1.44/containers/prune /v1.44/images/prune /v1.44/volumes/prune /v1.44/build/prune" + if strings.Join(paths, " ") != want { + t.Errorf("paths = %v", paths) + } + if res.ReclaimedBytes != 400 || res.Failed != 0 { + t.Errorf("result = %+v", res) + } + imgs, _ := url.QueryUnescape(f.reqs[1].URL.RawQuery) + if !strings.Contains(imgs, `"dangling":["false"]`) || !strings.Contains(imgs, `"until":["168h"]`) { + t.Errorf("image filters = %s", imgs) + } + if strings.Contains(f.reqs[2].URL.RawQuery, "until") { + t.Errorf("volume prune has no until filter: %s", f.reqs[2].URL.RawQuery) + } +} + +func TestRunAPIDefaultImagesAreDanglingOnly(t *testing.T) { + f := &fakeDoer{} + RunAPI(t.Context(), f, Options{}) + if len(f.reqs) != 2 || f.reqs[1].URL.RawQuery != "" { + t.Fatalf("want 2 unfiltered requests, got %d, query %q", len(f.reqs), f.reqs[len(f.reqs)-1].URL.RawQuery) + } +} + +func TestRunAPIFailedStepDoesNotStopTheRest(t *testing.T) { + f := &fakeDoer{status: map[string]int{"/v1.44/containers/prune": 500}, body: map[string]string{"/v1.44/containers/prune": "boom"}} + res := RunAPI(t.Context(), f, Options{}) + if res.Failed != 1 || len(res.Steps) != 2 || res.ReclaimedBytes != 100 { + t.Fatalf("result = %+v", res) + } + if !strings.Contains(res.Steps[0].Err, "boom") { + t.Errorf("error should carry the engine's message: %q", res.Steps[0].Err) + } +}