diff --git a/frontend/src/backend/wails.test.ts b/frontend/src/backend/wails.test.ts index 9c878e70..ec3be91c 100644 --- a/frontend/src/backend/wails.test.ts +++ b/frontend/src/backend/wails.test.ts @@ -144,7 +144,8 @@ describe("Wails backend adapter", () => { expect(bridge.probe).toHaveBeenCalledWith({ provider: "custom", api_base_url: "https://proxy.test/v1", api_key: "secret", model: "m", agents: null }); expect(bridge.getProvider).toHaveBeenCalledWith({ id: "acme" }); expect(bridge.deleteProvider).toHaveBeenCalledWith({ id: "acme" }); - expect(bridge.install).toHaveBeenCalledWith(expect.objectContaining({ agents: ["codex"], timeout: 180, agent_version: "" })); + // 0 means "use the Go default" rather than a duplicated number here. + expect(bridge.install).toHaveBeenCalledWith(expect.objectContaining({ agents: ["codex"], timeout: 0, agent_version: "" })); expect(bridge.register).toHaveBeenCalledWith({ provider: "ppio", agents: null }); expect(bridge.activate).toHaveBeenCalledWith(expect.objectContaining({ agent_id: "codex", profile_id: "", small_fast_model: "" })); expect(bridge.launch).toHaveBeenCalledWith({ agent_id: "codex" }); diff --git a/frontend/src/backend/wails.ts b/frontend/src/backend/wails.ts index bfa83931..9df6fe52 100644 --- a/frontend/src/backend/wails.ts +++ b/frontend/src/backend/wails.ts @@ -147,7 +147,9 @@ export const wailsApi = { agent_version: input.agent_version ?? "", skip_test: input.skip_test, registry: input.registry ?? "", - timeout: input.timeout ?? 180, + // 0 asks Go for its own default. Repeating a number here made this a second + // source of truth that silently disagreed when the Go side changed. + timeout: input.timeout ?? 0, })) as CancellableRequest, openRegister: (provider: ProviderId, agents: string[]): Promise => call(() => ProviderService.OpenRegistration({ provider, agents: agents.length ? agents : null })) as Promise, diff --git a/frontend/src/styles/app.css b/frontend/src/styles/app.css index 5c255b62..2f8373a8 100644 --- a/frontend/src/styles/app.css +++ b/frontend/src/styles/app.css @@ -728,6 +728,8 @@ padding: 0 10px; border: 1px solid var(--border-strong); border-radius: var(--radius-control); + color: var(--text-primary); + background: var(--window-bg); display: grid; grid-template-columns: 20px minmax(0, 1fr) 30px; align-items: center; @@ -742,11 +744,19 @@ .secure-field > svg { color: var(--text-tertiary); } +/* The background belongs to .secure-field, which draws the border and the focus + ring; this input is only the text surface inside it. Both declarations are + required rather than inherited: an takes neither its parent's colour + nor a transparent background from the UA sheet, so without them the field + rendered white-on-white in dark mode. .field-stack > input does not reach here + because .secure-field sits between them. */ .secure-field input { min-width: 0; height: 40px; border: 0; outline: none; + color: inherit; + background: transparent; } .secure-field button { @@ -794,6 +804,8 @@ padding: 0 11px; border: 1px solid var(--border-strong); border-radius: var(--radius-control); + color: var(--text-primary); + background: var(--window-bg); display: grid; grid-template-columns: 20px minmax(0, 1fr); align-items: center; @@ -801,7 +813,10 @@ } .search-field svg { color: var(--text-tertiary); } -.search-field input { height: 36px; border: 0; outline: 0; } +/* Same wrapper pattern as .secure-field: the box owns the border and background, + the input is only the text surface, so it needs both declarations to stop the + UA sheet painting it white. */ +.search-field input { height: 36px; border: 0; outline: 0; color: inherit; background: transparent; } .model-list { max-height: 270px; diff --git a/frontend/src/styles/input-surface.test.ts b/frontend/src/styles/input-surface.test.ts new file mode 100644 index 00000000..749f38ad --- /dev/null +++ b/frontend/src/styles/input-surface.test.ts @@ -0,0 +1,90 @@ +/** + * Guards the text inputs that sit inside a styled wrapper. + * + * .secure-field (the API Key row) and .search-field draw their own border, focus + * ring and background, and hold the as a bare text surface. That shape is + * what makes them fragile: `.field-stack > input` -- the rule that gives every + * other field its themed colours -- is a child selector, so the wrapper in + * between stops it from applying. Nothing else colours these inputs, and the UA + * sheet's default is white-on-black, so a missing declaration renders the field + * white in dark mode while the box around it goes dark. + * + * Two things therefore have to hold, and neither is covered elsewhere: + * + * - the wrapper carries themed color/background, and its input inherits them + * rather than falling back to the UA sheet, and + * - color-scheme tracks the forced palette, which is what colours the parts of + * a password field the stylesheet cannot reach: the masking dots, the caret + * and the autofill background. + * + * jsdom does not resolve var(), so getComputedStyle sees none of this; the + * assertions read the stylesheets as text, as agent-mark.test.ts does. + */ +import { readFileSync } from "node:fs"; +import { fileURLToPath } from "node:url"; + +import { describe, expect, it } from "vitest"; + +/** Comments carry `--token` names and `:` in prose, so they must go first. */ +function sheet(name: string): string { + const css = readFileSync(fileURLToPath(new URL(name, import.meta.url)), "utf8"); + return css.replace(/\/\*[\s\S]*?\*\//g, " "); +} + +/** + * The declarations of the last block whose prelude, with whitespace collapsed, + * is exactly `selector`. Last rather than first because a later block at equal + * specificity is what actually applies. + */ +function declarations(css: string, selector: string): Map { + const want = selector.replace(/\s+/g, " ").trim(); + const found = new Map(); + let seen = false; + for (const block of css.matchAll(/([^{}]+)\{([^{}]*)\}/g)) { + if (block[1].replace(/\s+/g, " ").trim() !== want) continue; + seen = true; + found.clear(); + for (const part of block[2].split(";")) { + const split = part.indexOf(":"); + if (split < 0) continue; + found.set(part.slice(0, split).trim(), part.slice(split + 1).trim().replace(/\s+/g, " ")); + } + } + expect(seen, `${selector} should exist`).toBe(true); + return found; +} + +const WRAPPED_FIELDS = ["secure-field", "search-field"]; + +describe("inputs inside a styled wrapper", () => { + it("themes the wrapper rather than leaving it on the UA default", () => { + const app = sheet("app.css"); + for (const field of WRAPPED_FIELDS) { + const rules = declarations(app, `.${field}`); + expect(rules.get("color"), field).toBe("var(--text-primary)"); + expect(rules.get("background"), field).toBe("var(--window-bg)"); + } + }); + + it("hands the wrapper's colours to the input", () => { + // inherit/transparent rather than repeating the tokens: the wrapper is what + // draws the field, and a second copy of the values would be one more place to + // miss on a palette change. + const app = sheet("app.css"); + for (const field of WRAPPED_FIELDS) { + const rules = declarations(app, `.${field} input`); + expect(rules.get("color"), field).toBe("inherit"); + expect(rules.get("background"), field).toBe("transparent"); + } + }); + + it("moves color-scheme with an explicitly forced palette", () => { + // Without these two, forcing a theme leaves color-scheme following the + // desktop, so the password dots, caret and autofill background come from the + // opposite palette -- the API Key field reading white on a dark form. + const tokens = sheet("tokens.css"); + expect(declarations(tokens, ":root").get("color-scheme")).toBe("light dark"); + expect(declarations(tokens, ":root.theme-dark").get("color-scheme")).toBe("dark"); + expect(declarations(tokens, ":root.theme-light").get("color-scheme")).toBe("light"); + }); +}); diff --git a/frontend/src/styles/tokens.css b/frontend/src/styles/tokens.css index 4eefeb13..87673ce8 100644 --- a/frontend/src/styles/tokens.css +++ b/frontend/src/styles/tokens.css @@ -60,6 +60,13 @@ --footer-height) live in :root above and must stay there: duplicating them would mean every future change had to be made twice, and forcing light mode would drop whichever copy was missed. */ +/* The mirror of .theme-dark below: forcing light on a dark desktop otherwise + leaves color-scheme at `light dark`, so the engine keeps painting controls + dark against the light palette. */ +:root.theme-light { + color-scheme: light; +} + @media (prefers-color-scheme: dark) { /* Skipped when the user forced light: the class wins over the desktop. */ :root:not(.theme-light) { @@ -95,7 +102,14 @@ } /* An explicit choice, independent of the desktop setting. */ +/* An explicit choice has to move color-scheme too, not just the custom + properties. color-scheme is what tells the engine how to paint the parts of a + control we do not draw ourselves: the dots in a password field, the caret, and + the autofill background. Left at the :root default of `light dark` it follows + the desktop, so forcing dark on a light desktop produced a dark field with a + light caret and light autofill -- the API Key row still reading as white. */ :root.theme-dark { + color-scheme: dark; --page-bg: #151517; --window-bg: #1e1e20; --sidebar-bg: rgba(24, 24, 26, 0.94); diff --git a/internal/binding/services.go b/internal/binding/services.go index 77c087ac..5444305d 100644 --- a/internal/binding/services.go +++ b/internal/binding/services.go @@ -4,16 +4,23 @@ package binding import ( "context" + "fmt" "net/url" "strings" "time" "github.com/MaimoryLab/OneAgent/internal/app" oneerrors "github.com/MaimoryLab/OneAgent/internal/errors" + "github.com/MaimoryLab/OneAgent/internal/install" "github.com/MaimoryLab/OneAgent/internal/process" "github.com/MaimoryLab/OneAgent/internal/provider" ) +// maxInstallTimeoutSeconds caps an explicitly requested timeout. It sits above +// DefaultCommandTimeout on purpose: a ceiling equal to the default would mean a +// caller could not ask for the default explicitly. +const maxInstallTimeoutSeconds = 6 * 60 * 60 + type Services struct { Status *StatusService Provider *ProviderService @@ -306,9 +313,12 @@ func (s *AgentService) Install(ctx context.Context, request InstallRequest) (Ins if s == nil || s.core == nil { return InstallResponse{}, notReady("Agent installation is not configured") } - timeout := 180 * time.Second - if request.Timeout < 0 || request.Timeout > 3600 { - return InstallResponse{}, oneerrors.New(oneerrors.InvalidRequest, "timeout must be an integer between 1 and 3600") + // The default lives in internal/install so Go owns it alone. The frontend used + // to send a hardcoded 180, which made this a second source of truth that could + // disagree silently. + timeout := install.DefaultCommandTimeout + if request.Timeout < 0 || request.Timeout > maxInstallTimeoutSeconds { + return InstallResponse{}, oneerrors.New(oneerrors.InvalidRequest, fmt.Sprintf("timeout must be an integer between 0 and %d, where 0 selects the default", maxInstallTimeoutSeconds)) } if request.Timeout > 0 { timeout = time.Duration(request.Timeout) * time.Second diff --git a/internal/binding/services_test.go b/internal/binding/services_test.go index bea35ac7..54c7f9e3 100644 --- a/internal/binding/services_test.go +++ b/internal/binding/services_test.go @@ -12,10 +12,12 @@ import ( "strings" "sync" "testing" + "time" "github.com/MaimoryLab/OneAgent/internal/app" "github.com/MaimoryLab/OneAgent/internal/catalog" oneerrors "github.com/MaimoryLab/OneAgent/internal/errors" + "github.com/MaimoryLab/OneAgent/internal/install" "github.com/MaimoryLab/OneAgent/internal/platform" "github.com/MaimoryLab/OneAgent/internal/provider" ) @@ -325,6 +327,52 @@ func TestAgentServiceInstallsThroughGoUseCase(t *testing.T) { } } +// Timeout 0 has to mean "use the Go default", because that is what the frontend +// now sends. Previously the frontend sent a hardcoded 180 and this branch was +// never exercised, so the two sides could disagree without any test noticing. +func TestAgentServiceTreatsZeroTimeoutAsTheGoDefault(t *testing.T) { + home := t.TempDir() + core := app.NewUseCases(app.StatusOptions{ + Home: home, + Platform: platform.For("linux", "amd64"), + Lookup: func(string) (string, bool) { return "", false }, + }) + service := &AgentService{core: core} + response, err := service.Install(context.Background(), InstallRequest{ + Agents: []string{"codex"}, Provider: "ppio", APIKey: "secret", Model: "model-a", + Configure: true, SkipTest: true, Timeout: 0, + }) + if err != nil { + t.Fatalf("zero timeout was rejected instead of taking the default: %v", err) + } + if !response.OK { + t.Fatalf("zero timeout install response = %#v", response) + } +} + +// The ceiling must exceed the default, or a caller could not request the default +// value explicitly. Both rejections return InvalidRequest rather than silently +// clamping, because a clamped timeout would be a surprise, not a fix. +func TestAgentServiceRejectsOutOfRangeTimeouts(t *testing.T) { + service := &AgentService{core: app.NewUseCases(app.StatusOptions{ + Home: t.TempDir(), + Platform: platform.For("linux", "amd64"), + Lookup: func(string) (string, bool) { return "", false }, + })} + for _, timeout := range []int{-1, maxInstallTimeoutSeconds + 1} { + _, err := service.Install(context.Background(), InstallRequest{ + Agents: []string{"codex"}, Provider: "ppio", APIKey: "secret", Model: "m", Timeout: timeout, + }) + if err == nil { + t.Fatalf("timeout %d was accepted", timeout) + } + } + if int(install.DefaultCommandTimeout/time.Second) > maxInstallTimeoutSeconds { + t.Fatalf("the ceiling %d is below the default %v, so the default cannot be requested explicitly", + maxInstallTimeoutSeconds, install.DefaultCommandTimeout) + } +} + func TestInstallResultBindingPreservesFieldPresence(t *testing.T) { tests := []struct { name string diff --git a/internal/desktopapp/desktopapp.go b/internal/desktopapp/desktopapp.go index 9613687c..1ea51aa3 100644 --- a/internal/desktopapp/desktopapp.go +++ b/internal/desktopapp/desktopapp.go @@ -79,7 +79,17 @@ type Options struct { const ( inspectTimeout = 10 * time.Second + // installTimeout bounds local work: hdiutil, ditto, codesign, spctl. These are + // disk and CPU bound, so elapsed time is a fair limit for them. installTimeout = 20 * time.Minute + // downloadTimeout is the backstop for fetching an installer, where elapsed + // time is not a fair limit — a 200 MB DMG on a slow link is healthy, and + // downloadStallTimeout is what distinguishes that from a dead transfer. + downloadTimeout = 60 * time.Minute + // Matches install.DownloadStallTimeout. Not imported from there because this + // package does not otherwise depend on internal/install, and a desktop + // installer download has the same characteristics as a runtime archive. + downloadStallTimeout = 120 * time.Second ) var packageVersionPattern = regexp.MustCompile(`^[0-9]+(?:\.[0-9]+){1,3}$`) @@ -654,7 +664,7 @@ func installChatGPTWindowsInstaller(ctx context.Context, options Options, status } func downloadFile(ctx context.Context, options Options, url, destination, target string) error { - downloadCtx, cancel := context.WithTimeout(ctx, installTimeout) + downloadCtx, cancel := context.WithTimeout(ctx, downloadTimeout) defer cancel() request, err := http.NewRequestWithContext(downloadCtx, http.MethodGet, url, nil) if err != nil { @@ -662,6 +672,8 @@ func downloadFile(ctx context.Context, options Options, url, destination, target } client := options.Downloader if client == nil { + // http.DefaultClient sets no Timeout, which is what we want here: the + // stall check below is the limit on the body transfer. client = http.DefaultClient } response, err := client.Do(request) @@ -676,7 +688,7 @@ func downloadFile(ctx context.Context, options Options, url, destination, target if err != nil { return err } - written, copyErr := process.CopyWithProgress(file, response.Body, response.ContentLength, target, options.Output) + written, copyErr := process.CopyWithStallTimeout(downloadCtx, file, response.Body, response.ContentLength, target, options.Output, downloadStallTimeout) closeErr := file.Close() contextErr := downloadCtx.Err() if copyErr != nil || closeErr != nil || contextErr != nil || written == 0 { diff --git a/internal/install/bootstrap.go b/internal/install/bootstrap.go index 87485e9c..78922a50 100644 --- a/internal/install/bootstrap.go +++ b/internal/install/bootstrap.go @@ -6,6 +6,7 @@ import ( "encoding/hex" "fmt" "io" + "net" "net/http" "os" "path/filepath" @@ -18,9 +19,39 @@ import ( "github.com/MaimoryLab/OneAgent/internal/process" ) -// RuntimeDownloadTimeout bounds one runtime archive download. Node is roughly -// 50 MB, so this is generous enough for a slow link but still terminates. -const RuntimeDownloadTimeout = 10 * time.Minute +// RuntimeDownloadTimeout is a backstop for one runtime archive download, not the +// working limit. DownloadStallTimeout is what ends a dead transfer; this only +// has to exceed any legitimate download. At 10 minutes it was cutting off Node's +// ~50 MB archive on genuinely slow links, and as an http.Client.Timeout it +// bounded the whole request including the body, so a transfer that was still +// making progress died anyway. +const RuntimeDownloadTimeout = 60 * time.Minute + +// DownloadStallTimeout is how long a download may receive nothing before it is +// abandoned. Shorter than the command stall window because a stalled socket is +// unambiguous: unlike npm, an HTTP body has no reason to go quiet for a minute +// and then recover. +const DownloadStallTimeout = 120 * time.Second + +// dialTimeout and responseHeaderTimeout bound the phases that should be fast +// even on a slow link. Only the body transfer is unbounded, and stall detection +// covers that. +const ( + dialTimeout = 30 * time.Second + responseHeaderTimeout = 60 * time.Second +) + +// defaultDownloadClient deliberately sets no Client.Timeout. That field bounds +// the entire request including reading the body, which is exactly the wall-clock +// limit this change removes; the phase timeouts above plus stall detection +// replace it. +func defaultDownloadClient() *http.Client { + transport := http.DefaultTransport.(*http.Transport).Clone() + transport.DialContext = (&net.Dialer{Timeout: dialTimeout}).DialContext + transport.TLSHandshakeTimeout = dialTimeout + transport.ResponseHeaderTimeout = responseHeaderTimeout + return &http.Client{Transport: transport} +} // Doer is the narrow HTTP boundary so runtime downloads are testable without a // network. It matches internal/provider's client boundary on purpose. @@ -152,6 +183,17 @@ type RuntimeOptions struct { // PreferMirror tries the locked mirror before the official source. The // checksum gate is identical either way, so this only chooses a host. PreferMirror bool + // StallTimeout overrides DownloadStallTimeout for one request. Zero takes the + // default and negative disables the check, matching OSRunner.StallTimeout. + // Tests set it so they need not wait out the real window. + StallTimeout time.Duration +} + +func (o RuntimeOptions) stallTimeout() time.Duration { + if o.StallTimeout != 0 { + return o.StallTimeout + } + return DownloadStallTimeout } // EnsureRuntime installs a locked runtime when its command is not already @@ -296,14 +338,14 @@ func installRuntime(ctx context.Context, runtime Runtime, client Doer, runtimeID func downloadArtifact(ctx context.Context, client Doer, entry catalog.Runtime, artifact catalog.RuntimeArtifact, directory string, options RuntimeOptions, listener process.OutputListener, target string) (string, error) { if client == nil { - client = &http.Client{Timeout: RuntimeDownloadTimeout} + client = defaultDownloadClient() } downloadCtx, cancel := context.WithTimeout(ctx, RuntimeDownloadTimeout) defer cancel() var lastErr error for _, source := range downloadSources(artifact, options.PreferMirror) { - path, err := fetchTo(downloadCtx, client, source, artifact.SHA256, directory, listener, target) + path, err := fetchTo(downloadCtx, client, source, artifact.SHA256, directory, listener, target, options.stallTimeout()) if err == nil { return path, nil } @@ -329,7 +371,7 @@ func downloadSources(artifact catalog.RuntimeArtifact, preferMirror bool) []stri return []string{artifact.URL, artifact.MirrorURL} } -func fetchTo(ctx context.Context, client Doer, source, expected, directory string, listener process.OutputListener, target string) (string, error) { +func fetchTo(ctx context.Context, client Doer, source, expected, directory string, listener process.OutputListener, target string, stallTimeout time.Duration) (string, error) { request, err := http.NewRequestWithContext(ctx, http.MethodGet, source, nil) if err != nil { return "", err @@ -350,7 +392,7 @@ func fetchTo(ctx context.Context, client Doer, source, expected, directory strin digest := sha256.New() // A retry against the fallback host starts the bar over rather than // resuming: the mirror's byte count says nothing about the official source's. - _, copyErr := process.CopyWithProgress(io.MultiWriter(file, digest), response.Body, response.ContentLength, target, listener) + _, copyErr := process.CopyWithStallTimeout(ctx, io.MultiWriter(file, digest), response.Body, response.ContentLength, target, listener, stallTimeout) closeErr := file.Close() if copyErr != nil || closeErr != nil { os.Remove(path) diff --git a/internal/install/bootstrap_test.go b/internal/install/bootstrap_test.go index 2a49466e..a58fad79 100644 --- a/internal/install/bootstrap_test.go +++ b/internal/install/bootstrap_test.go @@ -8,12 +8,15 @@ import ( "context" "crypto/sha256" "encoding/hex" + "errors" "io" "net/http" "os" "path/filepath" "strings" + "sync" "testing" + "time" "github.com/MaimoryLab/OneAgent/internal/catalog" oneerrors "github.com/MaimoryLab/OneAgent/internal/errors" @@ -27,6 +30,94 @@ type fakeDownloader struct { hits []string } +// drippingBody hands back one chunk per Read with a pause between them, which is +// what a slow-but-alive CDN looks like. Close is recorded so a test can prove the +// stall watchdog is what unblocked the read. +type drippingBody struct { + content []byte + chunk int + pause time.Duration + mu sync.Mutex + closed bool +} + +func (b *drippingBody) Read(buffer []byte) (int, error) { + if b.isClosed() { + return 0, errors.New("body closed") + } + if len(b.content) == 0 { + return 0, io.EOF + } + time.Sleep(b.pause) + if b.isClosed() { + return 0, errors.New("body closed") + } + size := min(min(b.chunk, len(buffer)), len(b.content)) + written := copy(buffer, b.content[:size]) + b.content = b.content[written:] + return written, nil +} + +func (b *drippingBody) isClosed() bool { + b.mu.Lock() + defer b.mu.Unlock() + return b.closed +} + +func (b *drippingBody) Close() error { + b.mu.Lock() + b.closed = true + b.mu.Unlock() + return nil +} + +// stalledBody blocks in Read until it is closed, standing in for a TCP socket +// that stops delivering. Nothing but closing the body can end this read, which is +// precisely why stall detection has to close it rather than only set a flag. +type stalledBody struct { + release chan struct{} + once sync.Once +} + +func (b *stalledBody) Read([]byte) (int, error) { + <-b.release + return 0, errors.New("body closed") +} + +func (b *stalledBody) Close() error { + b.once.Do(func() { close(b.release) }) + return nil +} + +type bodyDownloader struct { + body io.ReadCloser + // total is what the server claims in Content-Length, which may exceed what the + // body will actually deliver. + total int64 +} + +// sequencedDownloader answers each request with the next prepared response, so a +// test can make the first host stall and the second succeed. +type sequencedDownloader struct { + responses []*http.Response + hits []string +} + +func (d *sequencedDownloader) Do(request *http.Request) (*http.Response, error) { + d.hits = append(d.hits, request.URL.String()) + if len(d.responses) == 0 { + return &http.Response{StatusCode: http.StatusNotFound, Body: io.NopCloser(strings.NewReader("")), Request: request}, nil + } + response := d.responses[0] + d.responses = d.responses[1:] + response.Request = request + return response, nil +} + +func (d bodyDownloader) Do(request *http.Request) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusOK, Body: d.body, ContentLength: d.total, Request: request}, nil +} + type cancelAtEOFBody struct { cancel context.CancelFunc content []byte @@ -252,7 +343,9 @@ func TestFetchToDeletesTheFileWhenCancellationWinsAtEOF(t *testing.T) { directory := t.TempDir() ctx, cancel := context.WithCancel(context.Background()) content := []byte("partial runtime archive") - _, err := fetchTo(ctx, cancellingDownloader{cancel: cancel, content: content}, "https://example.test/runtime", digestOf(content), directory, nil, "node") + // Stall detection off: this case is about cancellation losing a race with EOF, + // and a watchdog would only add a second way for it to end. + _, err := fetchTo(ctx, cancellingDownloader{cancel: cancel, content: content}, "https://example.test/runtime", digestOf(content), directory, nil, "node", -1) if err != context.Canceled { t.Fatalf("cancelled download error = %v", err) } @@ -262,6 +355,72 @@ func TestFetchToDeletesTheFileWhenCancellationWinsAtEOF(t *testing.T) { } } +// The reason this change exists: a download that keeps arriving slowly must run +// to completion. Under the old whole-request http.Client.Timeout this was the +// case that failed, because elapsed time alone decided the outcome. +func TestFetchToAllowsASlowButProgressingDownload(t *testing.T) { + directory := t.TempDir() + content := []byte("a runtime archive delivered in small slow pieces") + body := &drippingBody{content: append([]byte(nil), content...), chunk: 4, pause: 40 * time.Millisecond} + // Each pause is well inside the window; the transfer as a whole takes several + // times longer than it. + path, err := fetchTo(context.Background(), bodyDownloader{body: body, total: int64(len(content))}, + "https://example.test/runtime", digestOf(content), directory, nil, "node", 300*time.Millisecond) + if err != nil { + t.Fatalf("slow download error = %v", err) + } + written, readErr := os.ReadFile(path) + if readErr != nil || string(written) != string(content) { + t.Fatalf("slow download wrote %q, err=%v", written, readErr) + } +} + +// The other half of the contract: a transfer that stops delivering ends on its +// own instead of hanging until the hour-long backstop. +func TestFetchToAbandonsAStalledDownloadAndLeavesNoFile(t *testing.T) { + directory := t.TempDir() + body := &stalledBody{release: make(chan struct{})} + started := time.Now() + _, err := fetchTo(context.Background(), bodyDownloader{body: body, total: 1024}, + "https://example.test/runtime", "unused-digest", directory, nil, "node", 250*time.Millisecond) + if !errors.Is(err, process.ErrStalled) { + t.Fatalf("stalled download error = %v, want ErrStalled", err) + } + if elapsed := time.Since(started); elapsed > 10*time.Second { + t.Fatalf("stall detection took %v", elapsed) + } + // A half-written temp file would be picked up as a valid archive by nothing, + // but it would accumulate on every failed attempt. + entries, readErr := os.ReadDir(directory) + if readErr != nil || len(entries) != 0 { + t.Fatalf("stalled download left files behind: %v, %v", entries, readErr) + } +} + +// A stalled first host must not consume the retry: the mirror is the whole point +// of having two sources, and both are checked against the same locked digest. +func TestDownloadArtifactFallsBackAfterAStalledHost(t *testing.T) { + directory := t.TempDir() + content := []byte("mirror copy of the archive") + stalled := &stalledBody{release: make(chan struct{})} + client := &sequencedDownloader{responses: []*http.Response{ + {StatusCode: http.StatusOK, Body: stalled, ContentLength: 1024}, + {StatusCode: http.StatusOK, Body: io.NopCloser(bytes.NewReader(content)), ContentLength: int64(len(content))}, + }} + artifact := catalog.RuntimeArtifact{URL: "https://example.test/official.tar.gz", MirrorURL: "https://mirror.test/official.tar.gz", SHA256: digestOf(content)} + path, err := downloadArtifact(context.Background(), client, catalog.Runtime{Name: "Node.js", Version: "1"}, artifact, directory, RuntimeOptions{StallTimeout: 250 * time.Millisecond}, nil, "node") + if err != nil { + t.Fatalf("fallback after stall error = %v", err) + } + written, readErr := os.ReadFile(path) + if readErr != nil || string(written) != string(content) { + t.Fatalf("fallback wrote %q, err=%v", written, readErr) + } + if len(client.hits) != 2 { + t.Fatalf("expected both hosts to be tried, got %d", len(client.hits)) + } +} + func TestEnsureRuntimeSupportsFlatZipAndSkipsExistingCommand(t *testing.T) { home := t.TempDir() archive := zipball(t, "uv.exe", "uvx.exe") diff --git a/internal/install/runtime.go b/internal/install/runtime.go index 34320b57..22f820b3 100644 --- a/internal/install/runtime.go +++ b/internal/install/runtime.go @@ -14,7 +14,12 @@ import ( ) const ( - DefaultCommandTimeout = 180 * time.Second + // DefaultCommandTimeout is a backstop, not the working limit. Stall detection + // in internal/process is what actually ends a hung install, so this only has + // to be larger than any legitimate install: at 180s it was cutting off + // perfectly healthy `npm install -g` runs on slow links, and the user saw + // "timed out" rather than anything pointing at the registry. + DefaultCommandTimeout = 60 * time.Minute VersionCommandTimeout = 30 * time.Second ) diff --git a/internal/process/process.go b/internal/process/process.go index 5db12bff..11a3a8c6 100644 --- a/internal/process/process.go +++ b/internal/process/process.go @@ -6,6 +6,7 @@ package process import ( "bytes" "context" + "errors" "fmt" "io" "maps" @@ -21,6 +22,17 @@ import ( const MaxOutputBytes = 1 << 20 +// DefaultStallTimeout bounds how long a command may produce nothing before it is +// treated as hung. It replaces a wall-clock budget as the primary limit: an app +// store does not give up on a slow download, it gives up on a stopped one, and a +// fixed budget only ever punished users on slow links. +// +// Deliberately generous. `npm install -g` runs without --no-progress, and npm +// says very little on a non-TTY, so a healthy install can be quiet for tens of +// seconds while it fetches a large tarball. Tightening this to something like +// 30s would start failing exactly the installs this change exists to rescue. +const DefaultStallTimeout = 180 * time.Second + type Result struct { Args []string ExitCode int @@ -67,6 +79,138 @@ func CopyWithProgress(destination io.Writer, source io.Reader, total int64, targ return io.Copy(io.MultiWriter(destination, counter), source) } +// CopyWithStallTimeout copies a download and fails if no bytes arrive for +// stallTimeout, reporting progress like CopyWithProgress does. +// +// io.Copy cannot be interrupted, so a body that blocks forever in Read would +// otherwise hang until the caller's wall-clock deadline. Rather than bound the +// total, this bounds the gap between reads: a slow-but-moving transfer runs as +// long as it needs, and a dead one ends at the first idle window. +// +// stallTimeout <= 0 disables the check and copies straight through, so callers +// with their own bound keep the previous behaviour. listener may be nil. +func CopyWithStallTimeout(ctx context.Context, destination io.Writer, source io.Reader, total int64, target string, listener OutputListener, stallTimeout time.Duration) (int64, error) { + if stallTimeout <= 0 { + return CopyWithProgress(destination, source, total, target, listener) + } + tracked := &stallReader{ctx: ctx, source: source, timeout: stallTimeout} + tracked.touch() + stop := tracked.watch() + defer stop() + written, err := CopyWithProgress(destination, tracked, total, target, listener) + // The reader records why it was interrupted, which is more specific than the + // generic "read failed" io.Copy surfaces. + if reason := tracked.reason(); reason != nil { + return written, reason + } + return written, err +} + +// ErrStalled reports a transfer or command that stopped producing bytes. It is +// distinct from context.DeadlineExceeded so a caller can tell "the network went +// quiet" from "the overall budget ran out". +var ErrStalled = errors.New("transfer stalled: no data received within the stall timeout") + +// stallReader wraps a body so a watchdog can observe whether reads are still +// arriving. It does not interrupt Read itself -- that is impossible for an +// arbitrary io.Reader -- it closes the underlying body when one is available, +// which is what unblocks a stalled HTTP read. +type stallReader struct { + ctx context.Context + source io.Reader + timeout time.Duration + + mu sync.Mutex + last time.Time + stalled bool + canceled bool +} + +func (r *stallReader) Read(buffer []byte) (int, error) { + // Checked before the read so an already-tripped watchdog stops the copy even + // if the body happens to return buffered bytes. + if reason := r.reason(); reason != nil { + return 0, reason + } + n, err := r.source.Read(buffer) + if n > 0 { + r.touch() + } + if reason := r.reason(); reason != nil { + return n, reason + } + return n, err +} + +func (r *stallReader) touch() { + r.mu.Lock() + r.last = time.Now() + r.mu.Unlock() +} + +func (r *stallReader) reason() error { + r.mu.Lock() + defer r.mu.Unlock() + if r.stalled { + return ErrStalled + } + if r.canceled { + return r.ctx.Err() + } + return nil +} + +// watch polls instead of arming a timer per read: a 50 MB download is hundreds +// of thousands of reads, and resetting a timer on each one costs more than +// checking a timestamp a few times a second. +func (r *stallReader) watch() func() { + done := make(chan struct{}) + // Checking several times per stall window keeps the overshoot small without + // making the poll itself noticeable. + interval := r.timeout / 4 + if interval < 50*time.Millisecond { + interval = 50 * time.Millisecond + } + go func() { + ticker := time.NewTicker(interval) + defer ticker.Stop() + for { + select { + case <-done: + return + case <-r.ctx.Done(): + r.mu.Lock() + r.canceled = true + r.mu.Unlock() + r.interrupt() + return + case <-ticker.C: + r.mu.Lock() + idle := time.Since(r.last) + r.mu.Unlock() + if idle < r.timeout { + continue + } + r.mu.Lock() + r.stalled = true + r.mu.Unlock() + r.interrupt() + return + } + } + }() + return func() { close(done) } +} + +// interrupt unblocks a Read that is parked in the network stack. Closing the +// body is the only thing that does that; a flag alone would not be seen until +// the read returned on its own, which is the case we are trying to escape. +func (r *stallReader) interrupt() { + if closer, ok := r.source.(io.Closer); ok { + _ = closer.Close() + } +} + // Reporting each 32 KB io.Copy chunk would push thousands of events through // the Wails bridge for one desktop image. const progressInterval = 200 * time.Millisecond @@ -117,6 +261,10 @@ type Launcher interface { type OSRunner struct { Env map[string]string Lookup func(string) (string, bool) + // StallTimeout overrides DefaultStallTimeout. Zero means the default; a + // negative value disables stall detection. Tests set it so they can assert + // the behaviour without waiting minutes. + StallTimeout time.Duration } func Current() OSRunner { @@ -281,20 +429,37 @@ func (r OSRunner) RunWithOutput(ctx context.Context, argv []string, overrides ma runContext, cancel = context.WithTimeout(ctx, timeout) defer cancel() } + // A separate cancel for the watchdog, so a stall ends the command without + // waiting for the wall-clock budget the deadline above still enforces. + runContext, stopForStall := context.WithCancel(runContext) + defer stopForStall() command := exec.CommandContext(runContext, argv[0], argv[1:]...) HideWindow(command) command.Env = mergeEnvironment(r.Env, overrides) stdout := &boundedBuffer{limit: MaxOutputBytes} stderr := &boundedBuffer{limit: MaxOutputBytes} var streamLock sync.Mutex - command.Stdout = &streamWriter{stream: "stdout", buffer: stdout, listener: listener, mu: &streamLock} - command.Stderr = &streamWriter{stream: "stderr", buffer: stderr, listener: listener, mu: &streamLock} + activity := &activityClock{} + activity.touch() + command.Stdout = &streamWriter{stream: "stdout", buffer: stdout, listener: listener, mu: &streamLock, activity: activity} + command.Stderr = &streamWriter{stream: "stderr", buffer: stderr, listener: listener, mu: &streamLock, activity: activity} + stalled := watchForStall(runContext, activity, r.stallTimeout(), stopForStall) err := command.Run() + stalled.stop() result.Stdout = stdout.String() result.Stderr = stderr.String() if command.ProcessState != nil { result.ExitCode = command.ProcessState.ExitCode() } + // Reported ahead of the generic "killed" error, because the caller cannot + // otherwise distinguish a stall from a user cancellation: both arrive as a + // cancelled context on the same ctx. The captured output goes back with it -- + // whatever the command said before going quiet is the only clue to where it + // got stuck, and a bare error would strip exactly the diagnostic this change + // exists to provide. + if stalled.tripped() { + return result, ErrStalled + } if runErr := runContext.Err(); runErr != nil { return result, runErr } @@ -311,6 +476,83 @@ func (r OSRunner) RunWithOutput(ctx context.Context, argv []string, overrides ma return result, nil } +// activityClock records when a command last produced output. Separate from +// streamWriter because stdout and stderr each have their own writer but share +// one liveness signal: output on either stream means the command is alive. +type activityClock struct { + mu sync.Mutex + last time.Time +} + +func (c *activityClock) touch() { + c.mu.Lock() + c.last = time.Now() + c.mu.Unlock() +} + +func (c *activityClock) idle() time.Duration { + c.mu.Lock() + defer c.mu.Unlock() + return time.Since(c.last) +} + +type stallWatch struct { + done chan struct{} + fired chan struct{} + stopped sync.Once +} + +func (w *stallWatch) stop() { w.stopped.Do(func() { close(w.done) }) } + +func (w *stallWatch) tripped() bool { + select { + case <-w.fired: + return true + default: + return false + } +} + +// watchForStall cancels a command that has produced nothing for timeout. A +// zero or negative timeout disables the watchdog. +func watchForStall(ctx context.Context, activity *activityClock, timeout time.Duration, cancel context.CancelFunc) *stallWatch { + watch := &stallWatch{done: make(chan struct{}), fired: make(chan struct{})} + if timeout <= 0 { + return watch + } + interval := timeout / 4 + if interval < 50*time.Millisecond { + interval = 50 * time.Millisecond + } + go func() { + ticker := time.NewTicker(interval) + defer ticker.Stop() + for { + select { + case <-watch.done: + return + case <-ctx.Done(): + return + case <-ticker.C: + if activity.idle() < timeout { + continue + } + close(watch.fired) + cancel() + return + } + } + }() + return watch +} + +func (r OSRunner) stallTimeout() time.Duration { + if r.StallTimeout != 0 { + return r.StallTimeout + } + return DefaultStallTimeout +} + type streamWriter struct { stream string buffer *boundedBuffer @@ -319,10 +561,18 @@ type streamWriter struct { // one chunk at a time. Each writer has its own buffer, but a lock per writer // would not serialise anything — the two goroutines would take different // locks and still enter the listener together. - mu *sync.Mutex + mu *sync.Mutex + activity *activityClock } func (w *streamWriter) Write(data []byte) (int, error) { + // Recorded before anything can discard the data, and unconditionally. Once + // boundedBuffer hits MaxOutputBytes it accepts nothing and the listener stops + // being called, so keying liveness off either of those would report a + // chatty-but-healthy command as stalled the moment it passed 1 MB. + if w.activity != nil { + w.activity.touch() + } w.mu.Lock() defer w.mu.Unlock() before := w.buffer.buffer.Len() diff --git a/internal/process/process_test.go b/internal/process/process_test.go index f98ea8db..41134e20 100644 --- a/internal/process/process_test.go +++ b/internal/process/process_test.go @@ -2,6 +2,7 @@ package process import ( "context" + "errors" "os" "os/exec" "path/filepath" @@ -27,6 +28,38 @@ func TestProcessHelper(_ *testing.T) { // kills this process, so the sleep never runs to completion. <-time.After(10 * time.Second) } + // Keeps talking for longer than the caller's stall timeout while never going + // quiet for as long as it. A healthy slow install looks like this, and it must + // not be killed. + if os.Getenv("ONEAGENT_PROCESS_DRIP") == "1" { + // Total runtime (~3s) must exceed the caller's stall window while each + // individual gap (300ms) stays well inside it. Otherwise the case would + // pass simply by finishing before the watchdog first looked. + for range 10 { + os.Stdout.WriteString("tick ") + <-time.After(300 * time.Millisecond) + } + os.Exit(0) + } + // Writes past MaxOutputBytes so boundedBuffer starts discarding and the + // listener stops being called, then keeps writing. Liveness must still be + // observed, or a chatty install dies once it crosses 1 MB. + if os.Getenv("ONEAGENT_PROCESS_FLOOD") == "1" { + chunk := strings.Repeat("x", 64*1024) + // 1.5 MB up front to push boundedBuffer past MaxOutputBytes, so everything + // after this point is written while the buffer accepts nothing and the + // listener is no longer called. + for range 24 { + os.Stdout.WriteString(chunk) + } + // Then keep writing past the caller's stall window. Only an activity + // signal taken before the buffer decides what to keep can see these. + for range 10 { + os.Stdout.WriteString(chunk) + <-time.After(300 * time.Millisecond) + } + os.Exit(0) + } // Interleaves both streams so the runner's stdout and stderr copiers are // active at the same time. Real installs look like this — npm reports progress // on stderr while printing results on stdout. @@ -240,3 +273,157 @@ func TestOSRunnerUsesExecutableWithoutShell(t *testing.T) { t.Fatalf("direct executable result = %#v, err=%v", result, err) } } + +// The point of stall detection: a command that keeps producing output runs to +// completion even though it takes far longer than the stall window, because the +// limit is on silence, not on elapsed time. +func TestOSRunnerLetsASlowButTalkingCommandFinish(t *testing.T) { + runner := helperRunner(t) + // Has to absorb process start-up, not just the gaps between writes: a + // race-instrumented helper needs a few hundred ms before it prints anything, + // and that silence counts against the stall window like any other. + runner.StallTimeout = 2 * time.Second + result, err := runner.RunWithOutput(context.Background(), []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_DRIP": "1", + }, helperTimeout, nil) + if err != nil { + t.Fatalf("slow but talking command error = %v", err) + } + if result.ExitCode != 0 { + t.Fatalf("slow but talking command result = %#v", result) + } + // 12 ticks at 50ms is ~600ms, comfortably past the 200ms stall window, so a + // pass here cannot be explained by the command finishing before the watchdog + // ever looked. + if count := strings.Count(result.Stdout, "tick"); count != 10 { + t.Fatalf("drip output had %d ticks, want all 10: %q", count, result.Stdout) + } +} + +// Guards the trap this change is most likely to introduce: boundedBuffer stops +// accepting at MaxOutputBytes and streamWriter then stops calling the listener, +// so keying liveness off accepted bytes or off listener calls would kill a +// healthy command the moment its output passed 1 MB. +func TestOSRunnerDoesNotMistakeAFloodedBufferForASilentCommand(t *testing.T) { + runner := helperRunner(t) + // Same start-up allowance as the drip case above. + runner.StallTimeout = 2 * time.Second + events := 0 + result, err := runner.RunWithOutput(context.Background(), []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_FLOOD": "1", + }, helperTimeout, func(Output) { events++ }) + if err != nil { + t.Fatalf("flooding command error = %v", err) + } + if result.ExitCode != 0 { + t.Fatalf("flooding command result exit = %d", result.ExitCode) + } + // Confirms the command really did exceed the buffer, so this test would in + // fact catch a liveness signal that depends on accepted bytes. + if !strings.Contains(result.Stdout, "[output truncated]") { + t.Fatal("helper did not exceed MaxOutputBytes, so the case proves nothing") + } + if events == 0 { + t.Fatal("listener never fired") + } +} + +// A genuinely hung command still ends, and reports ErrStalled rather than the +// bare context error, so callers can tell a stall from a user cancellation. +func TestOSRunnerStopsACommandThatGoesSilent(t *testing.T) { + runner := helperRunner(t) + runner.StallTimeout = 300 * time.Millisecond + started := time.Now() + _, err := runner.RunWithOutput(context.Background(), []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_WAIT": "1", + "ONEAGENT_PROCESS_READY": "1", + }, helperTimeout, nil) + if !errors.Is(err, ErrStalled) { + t.Fatalf("stalled command error = %v, want ErrStalled", err) + } + // The helper sleeps 10s and helperTimeout is 60s, so finishing quickly is the + // evidence that the stall watchdog ended it rather than either deadline. + if elapsed := time.Since(started); elapsed > 5*time.Second { + t.Fatalf("stall detection took %v, so a deadline ended this instead", elapsed) + } +} + +// Stall detection must not change what cancellation looks like. The Task Center's +// stop button is the only way out of a long install now that the wall-clock +// budget is an hour, so this staying context.Canceled is load-bearing. +func TestOSRunnerStillReportsCancellationDistinctlyFromAStall(t *testing.T) { + runner := helperRunner(t) + runner.StallTimeout = 30 * time.Second + ctx, cancel := context.WithCancel(context.Background()) + ready := make(chan struct{}, 1) + done := make(chan error, 1) + go func() { + _, err := runner.RunWithOutput(ctx, []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_WAIT": "1", + "ONEAGENT_PROCESS_READY": "1", + }, helperTimeout, func(output Output) { + if strings.Contains(output.Text, "ready") { + select { + case ready <- struct{}{}: + default: + } + } + }) + done <- err + }() + select { + case <-ready: + cancel() + case <-time.After(10 * time.Second): + cancel() + t.Fatal("helper process did not start") + } + err := <-done + if !errors.Is(err, context.Canceled) { + t.Fatalf("cancelled command error = %v, want context.Canceled", err) + } + if errors.Is(err, ErrStalled) { + t.Fatal("a user cancellation was reported as a stall") + } +} + +// stallTimeout's contract: zero takes the default, negative disables. Disabling +// matters for the version probes, which have their own short deadline and would +// be pointless to also watch for silence. +func TestStallTimeoutZeroTakesTheDefaultAndNegativeDisables(t *testing.T) { + if got := (OSRunner{}).stallTimeout(); got != DefaultStallTimeout { + t.Fatalf("zero stallTimeout = %v, want %v", got, DefaultStallTimeout) + } + if got := (OSRunner{StallTimeout: -1}).stallTimeout(); got >= 0 { + t.Fatalf("negative stallTimeout = %v, want it preserved as negative", got) + } + runner := helperRunner(t) + runner.StallTimeout = -1 + // With the watchdog off, a silent command is bounded only by the deadline. + _, err := runner.Run(context.Background(), []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_WAIT": "1", + }, 300*time.Millisecond) + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("disabled watchdog error = %v, want DeadlineExceeded", err) + } +} + +// A stall must still hand back what the command managed to say. The whole point +// of distinguishing a stall from a timeout is that the user gets a diagnosable +// failure, and the last few lines before a command went quiet are the only +// evidence of where it got stuck -- an npm registry URL, a partial download, a +// permissions warning. Returning a bare error throws that away. +func TestOSRunnerKeepsOutputProducedBeforeAStall(t *testing.T) { + runner := helperRunner(t) + runner.StallTimeout = 300 * time.Millisecond + result, err := runner.RunWithOutput(context.Background(), []string{os.Args[0], "-test.run=TestProcessHelper"}, map[string]string{ + "ONEAGENT_PROCESS_WAIT": "1", + "ONEAGENT_PROCESS_READY": "1", + }, helperTimeout, nil) + if !errors.Is(err, ErrStalled) { + t.Fatalf("stalled command error = %v, want ErrStalled", err) + } + if !strings.Contains(result.Stdout, "ready") { + t.Fatalf("stdout before the stall was dropped: Stdout = %q", result.Stdout) + } +}