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}" \