Skip to content

Commit 1987187

Browse files
authored
fix(cli): give wheels test its own timeout budget instead of the bridge default (#3359)
`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=<seconds>`, 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 ab901cf 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 <peter@alurium.com>
1 parent 4db616f commit 1987187

4 files changed

Lines changed: 108 additions & 11 deletions

File tree

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,2 @@
1+
- `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=<seconds>` 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)
2+
- `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)

cli/lucli/Module.cfc

Lines changed: 70 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -276,6 +276,7 @@ component extends="modules.BaseModule" {
276276
.option(name = "reporter", default = "simple", description = "Output format: simple, json, or tap")
277277
.option(name = "db", default = "sqlite", description = "Database the suite runs against")
278278
.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.")
279+
.option(name = "timeout", default = "", description = "Seconds to wait for the suite to finish (default 900). Also settable with WHEELS_TEST_TIMEOUT.")
279280
.flag(name = "verbose", default = false, description = "Print per-spec detail instead of the summary rollup")
280281
.flag(name = "ci", default = false, description = "CI mode output")
281282
.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" {
738739
db = parsed.db,
739740
dbExplicit = structKeyExists(arguments.coll, "db"),
740741
useTestDB = parsed["test-db"],
741-
basePath = parsed["base-path"]
742+
basePath = parsed["base-path"],
743+
timeout = $resolveTestTimeout(parsed.timeout)
742744
};
743745
}
744746

747+
/**
748+
* Seconds to wait for the test-runner response. `--timeout` wins, then
749+
* WHEELS_TEST_TIMEOUT, then 900.
750+
*
751+
* The shared HTTP helper reads for 120 seconds, which is right for the
752+
* request/response bridge commands but is a hard ceiling on how big a suite
753+
* `wheels test` can run: a suite that grows past roughly 140 seconds starts
754+
* failing with `Read timed out` and NO result document at all — not a failure
755+
* report, a crashed runner (issue #3352). The threshold moves with machine
756+
* speed, so a suite can pass locally and fail in CI. A test run is the one
757+
* command here whose duration is expected to scale with the project, so it
758+
* gets its own budget rather than inheriting the bridge default.
759+
*
760+
* Non-numeric or non-positive input falls back to the default rather than
761+
* throwing: a mistyped timeout should not be the thing that stops a test run.
762+
*/
763+
public numeric function $resolveTestTimeout(string parsedTimeout = "") {
764+
if (
765+
len(trim(arguments.parsedTimeout))
766+
&& isNumeric(trim(arguments.parsedTimeout))
767+
&& val(arguments.parsedTimeout) > 0
768+
) {
769+
return val(arguments.parsedTimeout);
770+
}
771+
// mirrors how $resolveTestBasePath() reads WHEELS_SUBPATH
772+
try {
773+
var envValue = createObject("java", "java.lang.System").getenv("WHEELS_TEST_TIMEOUT");
774+
if (!isNull(envValue) && len(trim(envValue)) && isNumeric(trim(envValue)) && val(envValue) > 0) {
775+
return val(envValue);
776+
}
777+
} catch (any e) {
778+
}
779+
return 900;
780+
}
781+
745782
/**
746783
* hint: Run test suite with optional filter and reporter
747784
*/
@@ -757,6 +794,7 @@ component extends="modules.BaseModule" {
757794
var dbExplicit = opts.dbExplicit;
758795
var useTestDB = opts.useTestDB;
759796
var basePath = opts.basePath;
797+
var timeoutSeconds = opts.timeout;
760798

761799
// Default to APP mode unless --core is set explicitly. The previous
762800
// auto-detection ("if vendor/wheels/tests/ exists, default to core")
@@ -775,7 +813,10 @@ component extends="modules.BaseModule" {
775813
// expects. Onboarding finding #2.
776814
filter = $normalizeTestFilter(filter, coreTests);
777815

778-
return runTests(filter, reporter, format, verboseOutput, coreTests, db, ciMode, useTestDB, dbExplicit, basePath);
816+
return runTests(
817+
filter, reporter, format, verboseOutput, coreTests,
818+
db, ciMode, useTestDB, dbExplicit, basePath, timeoutSeconds
819+
);
779820
}
780821

781822
/**
@@ -5709,7 +5750,8 @@ component extends="modules.BaseModule" {
57095750
boolean ciMode = false,
57105751
boolean useTestDB = true,
57115752
boolean dbExplicit = false,
5712-
string basePath = ""
5753+
string basePath = "",
5754+
numeric timeoutSeconds = 900
57135755
) {
57145756
var serverPort = $requireRunningServer([
57155757
"Start one with: wheels start",
@@ -5778,7 +5820,7 @@ component extends="modules.BaseModule" {
57785820
testUrl &= "&directory=#filter#";
57795821
}
57805822

5781-
var httpResult = makeHttpRequest(testUrl);
5823+
var httpResult = makeHttpRequest(testUrl, arguments.timeoutSeconds * 1000);
57825824

57835825
// Try to parse JSON result
57845826
if (isJSON(httpResult)) {
@@ -5821,7 +5863,18 @@ component extends="modules.BaseModule" {
58215863
}
58225864
} catch (any e) {
58235865
runState.crashed = true;
5824-
out("Test execution failed: #e.message#", "red");
5866+
// A read timeout here is indistinguishable from a hung app to anyone who has not
5867+
// seen it before, because the runner produced no document at all — the suite may
5868+
// well have passed (issue #3352). Say which side gave up, and how to give it longer.
5869+
if (reFindNoCase("(read timed out|SocketTimeout)", e.message)) {
5870+
out("Test run timed out after #arguments.timeoutSeconds#s waiting for the suite to finish.", "red");
5871+
out("The specs may have passed — the CLI stopped waiting, the runner did not stop running.", "yellow");
5872+
out("Give it longer: wheels test --timeout=#arguments.timeoutSeconds * 2#", "yellow");
5873+
out("Or set WHEELS_TEST_TIMEOUT=<seconds> for the whole environment.", "yellow");
5874+
out("Or scope the run: wheels test --filter=<subdirectory>", "yellow");
5875+
} else {
5876+
out("Test execution failed: #e.message#", "red");
5877+
}
58255878
}
58265879

58275880
// Exit non-zero when specs failed/errored so CI and shells can detect it.
@@ -7584,8 +7637,13 @@ component extends="modules.BaseModule" {
75847637
return result;
75857638
}
75867639

7587-
private string function makeHttpRequest(required string requestUrl) {
7588-
return makeHttpRequestWithStatus(arguments.requestUrl).body;
7640+
/**
7641+
* @readTimeout Milliseconds to wait for the response. Defaults to the
7642+
* request/response bridge budget; long-running callers such as
7643+
* `wheels test` pass their own (issue #3352).
7644+
*/
7645+
private string function makeHttpRequest(required string requestUrl, numeric readTimeout = 120000) {
7646+
return makeHttpRequestWithStatus(requestUrl = arguments.requestUrl, readTimeout = arguments.readTimeout).body;
75897647
}
75907648

75917649
/**
@@ -7601,14 +7659,15 @@ component extends="modules.BaseModule" {
76017659
*/
76027660
private struct function makeHttpRequestWithStatus(
76037661
required string requestUrl,
7604-
boolean followRedirects = true
7662+
boolean followRedirects = true,
7663+
numeric readTimeout = 120000
76057664
) {
76067665
var javaUrl = createObject("java", "java.net.URL").init(arguments.requestUrl);
76077666
var conn = javaUrl.openConnection();
76087667
conn.setRequestMethod("GET");
76097668
conn.setInstanceFollowRedirects(javacast("boolean", arguments.followRedirects));
76107669
conn.setConnectTimeout(5000);
7611-
conn.setReadTimeout(120000);
7670+
conn.setReadTimeout(javacast("int", arguments.readTimeout));
76127671

76137672
var responseCode = conn.getResponseCode();
76147673
var inputStream = responseCode >= 400 ? conn.getErrorStream() : conn.getInputStream();
@@ -8023,7 +8082,8 @@ component extends="modules.BaseModule" {
80238082
var testUrl = "http://localhost:#serverPort##runnerPath#?db=sqlite&format=json&directory=#directory#";
80248083

80258084
try {
8026-
var httpResult = makeHttpRequest(testUrl);
8085+
// same long-running suite over the same 120s-default helper (issue #3352)
8086+
var httpResult = makeHttpRequest(testUrl, $resolveTestTimeout() * 1000);
80278087
} catch (any e) {
80288088
out("Failed to reach test runner at: #testUrl#", "red");
80298089
out("Is the server running? Try: wheels start", "yellow");

cli/lucli/tests/specs/commands/TestCommandSpec.cfc

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -110,6 +110,33 @@ component extends="wheels.wheelstest.system.BaseSpec" {
110110

111111
});
112112

113+
// Issue #3352: the shared HTTP helper reads for 120 seconds, which is right for the
114+
// request/response bridge commands but is a hard ceiling on how big a suite `wheels
115+
// test` can run. Past roughly 140 seconds the run fails with `Read timed out` and NO
116+
// result document — not a failure report, a crashed runner — and the threshold moves
117+
// with machine speed, so a suite can pass locally and fail in CI.
118+
describe("$resolveTestTimeout", () => {
119+
120+
it("defaults to 900 seconds when nothing is supplied", () => {
121+
// generous enough that a multi-minute suite completes, which is the ask
122+
expect(mod.$resolveTestTimeout()).toBe(900);
123+
expect(mod.$resolveTestTimeout("")).toBe(900);
124+
expect(mod.$resolveTestTimeout(" ")).toBe(900);
125+
});
126+
127+
it("honours an explicit --timeout", () => {
128+
expect(mod.$resolveTestTimeout("1800")).toBe(1800);
129+
expect(mod.$resolveTestTimeout(" 45 ")).toBe(45);
130+
});
131+
132+
it("falls back to the default rather than throwing on junk input", () => {
133+
// a mistyped timeout must not be the thing that stops a test run
134+
expect(mod.$resolveTestTimeout("soon")).toBe(900);
135+
expect(mod.$resolveTestTimeout("0")).toBe(900);
136+
expect(mod.$resolveTestTimeout("-30")).toBe(900);
137+
});
138+
});
139+
113140
describe("$normalizeTestFilter (app mode)", () => {
114141

115142
it("returns empty string for empty input", () => {

tools/test-local.sh

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,11 @@ DB="${DB:-sqlite}"
3232
# Must match set(reloadPassword=...) in config/settings.cfm — a mismatch never
3333
# reloads and, since #3062, counts against the per-IP reload rate limit.
3434
PASSWORD="wheels-dev"
35-
RESULT_FILE="/tmp/wheels-local-test-results.json"
35+
# Per-checkout results file. A single fixed /tmp path is shared by every checkout on
36+
# the machine, so two working copies running the suite overwrite each other's results —
37+
# and a develop-vs-branch comparison silently becomes two copies of the same run
38+
# (issue #3352). Keyed on the project root so concurrent checkouts stay separate.
39+
RESULT_FILE="${WHEELS_TEST_RESULT_FILE:-/tmp/wheels-local-test-results-$(echo "$PROJECT_ROOT" | shasum | cut -c1-12).json}"
3640

3741
# Browser specs call back into the local Wheels CLI server — point Playwright
3842
# at the right port. CI sets this explicitly before invoking the script;
@@ -129,6 +133,10 @@ if [ -n "$FILTER" ]; then
129133
fi
130134

131135
echo "Running tests: Lucee 7 + SQLite${FILTER:+ (filter: $FILTER)}"
136+
# Clear it first. When the request fails outright — a server that is not up yet reports
137+
# HTTP 000 — curl may write nothing, leaving the PREVIOUS run's results sitting there to
138+
# be read as if they were this run's (issue #3352). A crashed run must leave no result.
139+
rm -f "$RESULT_FILE"
132140
HTTP_CODE=$(curl -s -o "$RESULT_FILE" \
133141
--max-time 600 \
134142
--write-out "%{http_code}" \

0 commit comments

Comments
 (0)