From ce125db99d02ae9214248a0cc3e0fcc0ba766ad0 Mon Sep 17 00:00:00 2001 From: Peter Amiri Date: Mon, 3 Aug 2026 23:27:06 -0700 Subject: [PATCH] fix(cli): give wheels test its own timeout budget instead of the bridge default MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `wheels test` failed with `Read timed out` and NO result document on a suite of roughly 500 specs taking about 2.5 minutes — not a failure report, a crashed runner. Indistinguishable from a hung app to anyone who has not seen it before, and it scales IN: a suite works, then silently stops working as it grows. The cause is one line. `makeHttpRequestWithStatus()` hardcodes `conn.setReadTimeout(120000)` for every caller, which matches the reported ~140s threshold. That budget is correct for the short request/response bridge commands, but a test run is the one command here whose duration is expected to scale with the project, so it now gets its own. - `--timeout=`, else WHEELS_TEST_TIMEOUT, else 900. - Non-numeric or non-positive input falls back to the default rather than throwing: a mistyped timeout should not be the thing that stops a test run. - The browser-test runner at the second call site makes the same long-running request over the same helper, so it gets the same budget. Fixing only one would have left the identical bug in a sibling. - On a timeout the message now says which side gave up, that the specs may well have passed, and how to give it longer or scope the run. The old output was the raw engine message. The shared helper keeps its 120s default, so no other command's behaviour changes. Two harness defects in the same family, both of which bit me while verifying tonight's other PRs, and both matching this issue's theme of a runner that reports something other than what happened: - tools/test-local.sh wrote results to a single fixed /tmp path shared by every checkout on the machine. Two working copies running the suite overwrite each other — which silently turned my first develop-vs-branch comparison into two copies of the same run, with identical totals that looked like a legitimate no-op result. Now keyed on the project root, overridable with WHEELS_TEST_RESULT_FILE. - When the request failed outright (HTTP 000, typically a server not yet up) the previous run's results were left in place and even printed. I read one of those as a current result before noticing the numbers were implausible. The file is now cleared before the request, so a crashed run leaves no result rather than a stale one. 3 specs on $resolveTestTimeout covering the default, an explicit value, and the junk-input fallback. Verification, CLI suite via /wheels/cli/tests: develop ab901cff7 1143 pass / 0 fail / 0 error / 1203 specs this branch 1146 pass / 0 fail / 0 error / 1206 specs Exactly +3, the new specs. Core suite unaffected and unchanged at 4732. Note: tools/test-cli-local.sh could not be used — it invokes a `lucli` binary that does not exist on a normal install (cli/CLAUDE.md: `wheels` IS the binary). Both runs above went through the /wheels/cli/tests endpoint against a server started with `wheels server run`. Closes #3352 Signed-off-by: Peter Amiri --- changelog.d/3352-test-timeout.fixed.md | 2 + cli/lucli/Module.cfc | 80 ++++++++++++++++--- .../tests/specs/commands/TestCommandSpec.cfc | 27 +++++++ tools/test-local.sh | 10 ++- 4 files changed, 108 insertions(+), 11 deletions(-) create mode 100644 changelog.d/3352-test-timeout.fixed.md diff --git a/changelog.d/3352-test-timeout.fixed.md b/changelog.d/3352-test-timeout.fixed.md new file mode 100644 index 0000000000..4528d08396 --- /dev/null +++ b/changelog.d/3352-test-timeout.fixed.md @@ -0,0 +1,2 @@ +- `wheels test` no longer dies with `Read timed out` on a suite that takes more than about two minutes. The CLI's HTTP client applied a hardcoded 120-second read timeout to every request, which is right for the short request/response bridge commands but is a hard ceiling on how big a suite the test command can run — and it produced **no result at all**, not a failure report, so a passing suite was indistinguishable from a hung app. The budget is now 900 seconds by default and configurable with `--timeout=` or `WHEELS_TEST_TIMEOUT`. When it is still exceeded, the message says which side gave up, that the specs may well have passed, and how to give it longer or scope the run. The browser-test runner, which makes the same long-running call, got the same budget (#3352) +- `tools/test-local.sh` writes its results to a per-checkout file instead of a single fixed `/tmp` path, so two working copies running the suite no longer overwrite each other — which silently turned a develop-vs-branch comparison into two copies of the same run. It also clears the file before the request, so a run that fails outright (`HTTP 000`, typically a server that is not up yet) can no longer leave the previous run's results behind to be read as if they were current. Override with `WHEELS_TEST_RESULT_FILE` (#3352) diff --git a/cli/lucli/Module.cfc b/cli/lucli/Module.cfc index fb7a84543f..cf822aa32f 100644 --- a/cli/lucli/Module.cfc +++ b/cli/lucli/Module.cfc @@ -276,6 +276,7 @@ component extends="modules.BaseModule" { .option(name = "reporter", default = "simple", description = "Output format: simple, json, or tap") .option(name = "db", default = "sqlite", description = "Database the suite runs against") .option(name = "base-path", default = "", description = "URL prefix the app is mounted under (e.g. /myapp). Auto-derived from WHEELS_SUBPATH or set(subpath=...) when omitted.") + .option(name = "timeout", default = "", description = "Seconds to wait for the suite to finish (default 900). Also settable with WHEELS_TEST_TIMEOUT.") .flag(name = "verbose", default = false, description = "Print per-spec detail instead of the summary rollup") .flag(name = "ci", default = false, description = "CI mode output") .flag(name = "core", default = false, description = "Run the framework core suite (vendor/wheels/tests) instead of the app suite") @@ -738,10 +739,46 @@ component extends="modules.BaseModule" { db = parsed.db, dbExplicit = structKeyExists(arguments.coll, "db"), useTestDB = parsed["test-db"], - basePath = parsed["base-path"] + basePath = parsed["base-path"], + timeout = $resolveTestTimeout(parsed.timeout) }; } + /** + * Seconds to wait for the test-runner response. `--timeout` wins, then + * WHEELS_TEST_TIMEOUT, then 900. + * + * The shared HTTP helper reads for 120 seconds, which is right for the + * request/response bridge commands but is a hard ceiling on how big a suite + * `wheels test` can run: a suite that grows past roughly 140 seconds starts + * failing with `Read timed out` and NO result document at all — not a failure + * report, a crashed runner (issue #3352). The threshold moves with machine + * speed, so a suite can pass locally and fail in CI. A test run is the one + * command here whose duration is expected to scale with the project, so it + * gets its own budget rather than inheriting the bridge default. + * + * Non-numeric or non-positive input falls back to the default rather than + * throwing: a mistyped timeout should not be the thing that stops a test run. + */ + public numeric function $resolveTestTimeout(string parsedTimeout = "") { + if ( + len(trim(arguments.parsedTimeout)) + && isNumeric(trim(arguments.parsedTimeout)) + && val(arguments.parsedTimeout) > 0 + ) { + return val(arguments.parsedTimeout); + } + // mirrors how $resolveTestBasePath() reads WHEELS_SUBPATH + try { + var envValue = createObject("java", "java.lang.System").getenv("WHEELS_TEST_TIMEOUT"); + if (!isNull(envValue) && len(trim(envValue)) && isNumeric(trim(envValue)) && val(envValue) > 0) { + return val(envValue); + } + } catch (any e) { + } + return 900; + } + /** * hint: Run test suite with optional filter and reporter */ @@ -757,6 +794,7 @@ component extends="modules.BaseModule" { var dbExplicit = opts.dbExplicit; var useTestDB = opts.useTestDB; var basePath = opts.basePath; + var timeoutSeconds = opts.timeout; // Default to APP mode unless --core is set explicitly. The previous // auto-detection ("if vendor/wheels/tests/ exists, default to core") @@ -775,7 +813,10 @@ component extends="modules.BaseModule" { // expects. Onboarding finding #2. filter = $normalizeTestFilter(filter, coreTests); - return runTests(filter, reporter, format, verboseOutput, coreTests, db, ciMode, useTestDB, dbExplicit, basePath); + return runTests( + filter, reporter, format, verboseOutput, coreTests, + db, ciMode, useTestDB, dbExplicit, basePath, timeoutSeconds + ); } /** @@ -5709,7 +5750,8 @@ component extends="modules.BaseModule" { boolean ciMode = false, boolean useTestDB = true, boolean dbExplicit = false, - string basePath = "" + string basePath = "", + numeric timeoutSeconds = 900 ) { var serverPort = $requireRunningServer([ "Start one with: wheels start", @@ -5778,7 +5820,7 @@ component extends="modules.BaseModule" { testUrl &= "&directory=#filter#"; } - var httpResult = makeHttpRequest(testUrl); + var httpResult = makeHttpRequest(testUrl, arguments.timeoutSeconds * 1000); // Try to parse JSON result if (isJSON(httpResult)) { @@ -5821,7 +5863,18 @@ component extends="modules.BaseModule" { } } catch (any e) { runState.crashed = true; - out("Test execution failed: #e.message#", "red"); + // A read timeout here is indistinguishable from a hung app to anyone who has not + // seen it before, because the runner produced no document at all — the suite may + // well have passed (issue #3352). Say which side gave up, and how to give it longer. + if (reFindNoCase("(read timed out|SocketTimeout)", e.message)) { + out("Test run timed out after #arguments.timeoutSeconds#s waiting for the suite to finish.", "red"); + out("The specs may have passed — the CLI stopped waiting, the runner did not stop running.", "yellow"); + out("Give it longer: wheels test --timeout=#arguments.timeoutSeconds * 2#", "yellow"); + out("Or set WHEELS_TEST_TIMEOUT= for the whole environment.", "yellow"); + out("Or scope the run: wheels test --filter=", "yellow"); + } else { + out("Test execution failed: #e.message#", "red"); + } } // Exit non-zero when specs failed/errored so CI and shells can detect it. @@ -7584,8 +7637,13 @@ component extends="modules.BaseModule" { return result; } - private string function makeHttpRequest(required string requestUrl) { - return makeHttpRequestWithStatus(arguments.requestUrl).body; + /** + * @readTimeout Milliseconds to wait for the response. Defaults to the + * request/response bridge budget; long-running callers such as + * `wheels test` pass their own (issue #3352). + */ + private string function makeHttpRequest(required string requestUrl, numeric readTimeout = 120000) { + return makeHttpRequestWithStatus(requestUrl = arguments.requestUrl, readTimeout = arguments.readTimeout).body; } /** @@ -7601,14 +7659,15 @@ component extends="modules.BaseModule" { */ private struct function makeHttpRequestWithStatus( required string requestUrl, - boolean followRedirects = true + boolean followRedirects = true, + numeric readTimeout = 120000 ) { var javaUrl = createObject("java", "java.net.URL").init(arguments.requestUrl); var conn = javaUrl.openConnection(); conn.setRequestMethod("GET"); conn.setInstanceFollowRedirects(javacast("boolean", arguments.followRedirects)); conn.setConnectTimeout(5000); - conn.setReadTimeout(120000); + conn.setReadTimeout(javacast("int", arguments.readTimeout)); var responseCode = conn.getResponseCode(); var inputStream = responseCode >= 400 ? conn.getErrorStream() : conn.getInputStream(); @@ -8023,7 +8082,8 @@ component extends="modules.BaseModule" { var testUrl = "http://localhost:#serverPort##runnerPath#?db=sqlite&format=json&directory=#directory#"; try { - var httpResult = makeHttpRequest(testUrl); + // same long-running suite over the same 120s-default helper (issue #3352) + var httpResult = makeHttpRequest(testUrl, $resolveTestTimeout() * 1000); } catch (any e) { out("Failed to reach test runner at: #testUrl#", "red"); out("Is the server running? Try: wheels start", "yellow"); diff --git a/cli/lucli/tests/specs/commands/TestCommandSpec.cfc b/cli/lucli/tests/specs/commands/TestCommandSpec.cfc index 809dd78e70..5ba3107a05 100644 --- a/cli/lucli/tests/specs/commands/TestCommandSpec.cfc +++ b/cli/lucli/tests/specs/commands/TestCommandSpec.cfc @@ -110,6 +110,33 @@ component extends="wheels.wheelstest.system.BaseSpec" { }); + // Issue #3352: the shared HTTP helper reads for 120 seconds, which is right for the + // request/response bridge commands but is a hard ceiling on how big a suite `wheels + // test` can run. Past roughly 140 seconds the run fails with `Read timed out` and NO + // result document — not a failure report, a crashed runner — and the threshold moves + // with machine speed, so a suite can pass locally and fail in CI. + describe("$resolveTestTimeout", () => { + + it("defaults to 900 seconds when nothing is supplied", () => { + // generous enough that a multi-minute suite completes, which is the ask + expect(mod.$resolveTestTimeout()).toBe(900); + expect(mod.$resolveTestTimeout("")).toBe(900); + expect(mod.$resolveTestTimeout(" ")).toBe(900); + }); + + it("honours an explicit --timeout", () => { + expect(mod.$resolveTestTimeout("1800")).toBe(1800); + expect(mod.$resolveTestTimeout(" 45 ")).toBe(45); + }); + + it("falls back to the default rather than throwing on junk input", () => { + // a mistyped timeout must not be the thing that stops a test run + expect(mod.$resolveTestTimeout("soon")).toBe(900); + expect(mod.$resolveTestTimeout("0")).toBe(900); + expect(mod.$resolveTestTimeout("-30")).toBe(900); + }); + }); + describe("$normalizeTestFilter (app mode)", () => { it("returns empty string for empty input", () => { diff --git a/tools/test-local.sh b/tools/test-local.sh index 17815c7f0b..8552041a54 100755 --- a/tools/test-local.sh +++ b/tools/test-local.sh @@ -32,7 +32,11 @@ DB="${DB:-sqlite}" # Must match set(reloadPassword=...) in config/settings.cfm — a mismatch never # reloads and, since #3062, counts against the per-IP reload rate limit. PASSWORD="wheels-dev" -RESULT_FILE="/tmp/wheels-local-test-results.json" +# Per-checkout results file. A single fixed /tmp path is shared by every checkout on +# the machine, so two working copies running the suite overwrite each other's results — +# and a develop-vs-branch comparison silently becomes two copies of the same run +# (issue #3352). Keyed on the project root so concurrent checkouts stay separate. +RESULT_FILE="${WHEELS_TEST_RESULT_FILE:-/tmp/wheels-local-test-results-$(echo "$PROJECT_ROOT" | shasum | cut -c1-12).json}" # Browser specs call back into the local Wheels CLI server — point Playwright # at the right port. CI sets this explicitly before invoking the script; @@ -129,6 +133,10 @@ if [ -n "$FILTER" ]; then fi echo "Running tests: Lucee 7 + SQLite${FILTER:+ (filter: $FILTER)}" +# Clear it first. When the request fails outright — a server that is not up yet reports +# HTTP 000 — curl may write nothing, leaving the PREVIOUS run's results sitting there to +# be read as if they were this run's (issue #3352). A crashed run must leave no result. +rm -f "$RESULT_FILE" HTTP_CODE=$(curl -s -o "$RESULT_FILE" \ --max-time 600 \ --write-out "%{http_code}" \