diff --git a/src/test/java/com/testingbot/tunnel/Await.java b/src/test/java/com/testingbot/tunnel/Await.java new file mode 100644 index 0000000..c2af8db --- /dev/null +++ b/src/test/java/com/testingbot/tunnel/Await.java @@ -0,0 +1,129 @@ +package com.testingbot.tunnel; + +import java.io.IOException; +import java.net.InetAddress; +import java.net.InetSocketAddress; +import java.net.Socket; +import java.util.function.BooleanSupplier; +import java.util.function.Supplier; + +/** + * Waits for a condition instead of sleeping for a guess. + * + *

Tests here used {@code Thread.sleep(500)} before asserting on something another thread had + * to produce -- a server finishing its bind, a log record being written, a statistic being + * updated. That is wrong in both directions at once. It is too long whenever the thing is + * already done, which it almost always is: {@code InsightServerTest} spent 5.5 of its 6.3 + * seconds asleep. And it is too short whenever the machine is loaded, which is exactly when CI + * runs, so the failure arrives as an assertion about logging or statistics that says nothing + * about timing. + * + *

Polling fixes both: it returns as soon as the condition holds, and it can afford a timeout + * long enough to cover a slow runner because that cost is only paid on a genuine failure. + * + *

This does not suit every wait. Asserting that something did not happen has to give + * it time to happen first, and there is no condition to poll for -- see {@code ProxyLoopTest}, + * which keeps its sleep and says why. + */ +public final class Await { + + /** Long enough for a loaded CI runner; only ever paid in full when the test is failing. */ + public static final long DEFAULT_TIMEOUT_MS = 10_000; + + private static final long POLL_INTERVAL_MS = 20; + + private Await() { + } + + /** + * @param what described in the failure message, so a timeout says what never happened + * @param condition polled until true + * @throws AssertionError if it is still false when the timeout expires + */ + public static void until(String what, BooleanSupplier condition) { + until(what, DEFAULT_TIMEOUT_MS, condition); + } + + public static void until(String what, long timeoutMs, BooleanSupplier condition) { + long deadline = System.currentTimeMillis() + timeoutMs; + AssertionError lastFailure = null; + while (System.currentTimeMillis() < deadline) { + try { + if (condition.getAsBoolean()) { + return; + } + lastFailure = null; + } catch (AssertionError notYet) { + // A condition expressed as an assertion is allowed to fail while we wait; only + // the last one matters, and only if we run out of time. + lastFailure = notYet; + } + sleep(); + } + if (lastFailure != null) { + throw lastFailure; + } + throw new AssertionError("Timed out after " + timeoutMs + "ms waiting for: " + what); + } + + /** + * As {@link #until}, for a condition that produces a value. + * + * @return the first non-null, non-empty value the supplier returns + */ + public static T value(String what, Supplier supplier) { + long deadline = System.currentTimeMillis() + DEFAULT_TIMEOUT_MS; + while (System.currentTimeMillis() < deadline) { + T candidate = supplier.get(); + if (candidate != null + && !(candidate instanceof CharSequence text && text.length() == 0) + && !(candidate instanceof java.util.Collection c && c.isEmpty())) { + return candidate; + } + sleep(); + } + throw new AssertionError( + "Timed out after " + DEFAULT_TIMEOUT_MS + "ms waiting for: " + what); + } + + /** + * Polls for up to {@code timeoutMs} and reports whether the condition held, without failing. + * + *

For a helper shared by tests that expect something and tests that expect nothing: the + * first kind returns as soon as it appears, the second pays the full wait it needs, and + * neither has to know which it is. + * + * @return true if the condition became true within the timeout + */ + public static boolean atMost(long timeoutMs, BooleanSupplier condition) { + long deadline = System.currentTimeMillis() + timeoutMs; + while (System.currentTimeMillis() < deadline) { + if (condition.getAsBoolean()) { + return true; + } + sleep(); + } + return condition.getAsBoolean(); + } + + /** Waits until something accepts connections on {@code port}. */ + public static void serverOn(int port) { + until("a server listening on port " + port, () -> { + try (Socket probe = new Socket()) { + probe.connect(new InetSocketAddress(InetAddress.getLoopbackAddress(), port), 200); + return true; + } catch (IOException notYet) { + return false; + } + }); + } + + private static void sleep() { + try { + Thread.sleep(POLL_INTERVAL_MS); + } catch (InterruptedException interrupted) { + Thread.currentThread().interrupt(); + throw new AssertionError("Interrupted while waiting", interrupted); + } + } +} diff --git a/src/test/java/com/testingbot/tunnel/HealthEndpointsTest.java b/src/test/java/com/testingbot/tunnel/HealthEndpointsTest.java index b5de147..c751264 100644 --- a/src/test/java/com/testingbot/tunnel/HealthEndpointsTest.java +++ b/src/test/java/com/testingbot/tunnel/HealthEndpointsTest.java @@ -41,7 +41,7 @@ void setUp() throws Exception { app.setClientSecret("test_secret"); app.setMetricsPort(metricsPort); insightServer = new InsightServer(app); - waitForPort(metricsPort); + Await.serverOn(metricsPort); } @AfterEach @@ -56,16 +56,6 @@ void tearDown() { } } - private static void waitForPort(int port) throws Exception { - for (int i = 0; i < 100; i++) { - try (java.net.Socket s = new java.net.Socket("127.0.0.1", port)) { - return; - } catch (IOException retry) { - Thread.sleep(50); - } - } - throw new IllegalStateException("Insight server did not start on port " + port); - } private static int status(int port, String path) throws Exception { try (CloseableHttpClient client = HttpClients.createDefault()) { @@ -124,14 +114,20 @@ void healthEndpoints_areReachableWithoutMetricsAuth() throws Exception { app.setClientSecret("test_secret"); app.setMetricsPort(port); app.setMetricsAuth("user:password"); - new InsightServer(app); - waitForPort(port); - - // Probes cannot easily carry credentials, so these must not be behind auth... - assertThat(status(port, "/healthz")).isEqualTo(200); - assertThat(status(port, "/readyz")).isEqualTo(503); - // ...but /metrics still is. - assertThat(status(port, "/metrics")).isEqualTo(401); + // A second server, so it needs stopping too: tearDown only knows about the one from + // setUp. Left running, it held this port for the rest of the JVM. + InsightServer authed = new InsightServer(app); + try { + Await.serverOn(port); + + // Probes cannot easily carry credentials, so these must not be behind auth... + assertThat(status(port, "/healthz")).isEqualTo(200); + assertThat(status(port, "/readyz")).isEqualTo(503); + // ...but /metrics still is. + assertThat(status(port, "/metrics")).isEqualTo(401); + } finally { + authed.stop(); + } } @Test diff --git a/src/test/java/com/testingbot/tunnel/InsightServerTest.java b/src/test/java/com/testingbot/tunnel/InsightServerTest.java index 8776746..fee21cb 100644 --- a/src/test/java/com/testingbot/tunnel/InsightServerTest.java +++ b/src/test/java/com/testingbot/tunnel/InsightServerTest.java @@ -50,12 +50,19 @@ void setUp() throws Exception { @AfterEach void tearDown() throws Exception { resetStatistics(); + // Every test here leaked a Jetty server and a bound port. That leak is why the tests + // below each needed a *different* hardcoded port: the previous one was still held. + if (insightServer != null) { + insightServer.stop(); + insightServer = null; + } } @Test void constructor_shouldStartServer() throws Exception { // Given: App with metrics port configured - app.setMetricsPort(8999); + int port = freePort(); + app.setMetricsPort(port); // When: Creating InsightServer insightServer = new InsightServer(app); @@ -64,19 +71,20 @@ void constructor_shouldStartServer() throws Exception { assertThat(insightServer).isNotNull(); // Give server time to start - Thread.sleep(500); + Await.serverOn(port); } @Test void metricsEndpoint_shouldReturnJson() throws Exception { // Given: Running InsightServer - app.setMetricsPort(8998); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); // Wait for server to start + Await.serverOn(port); // When: Making request to metrics endpoint try (CloseableHttpClient client = HttpClients.createDefault()) { - HttpGet request = new HttpGet("http://localhost:8998/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { // Then: Should return 200 OK assertThat(response.getCode()).isEqualTo(200); @@ -101,13 +109,14 @@ void metricsEndpoint_shouldReturnJson() throws Exception { @Test void metricsEndpoint_shouldReturnCorrectVersion() throws Exception { // Given: Running InsightServer - app.setMetricsPort(8997); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); // When: Getting metrics try (CloseableHttpClient client = HttpClients.createDefault()) { - HttpGet request = new HttpGet("http://localhost:8997/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { String body = EntityUtils.toString(response.getEntity()); JsonNode json = objectMapper.readTree(body); @@ -125,13 +134,14 @@ void metricsEndpoint_shouldReturnUptime() throws Exception { long startTime = System.currentTimeMillis() - 5000; // 5 seconds ago Statistics.setStartTime(startTime); - app.setMetricsPort(8996); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); // When: Getting metrics try (CloseableHttpClient client = HttpClients.createDefault()) { - HttpGet request = new HttpGet("http://localhost:8996/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { String body = EntityUtils.toString(response.getEntity()); JsonNode json = objectMapper.readTree(body); @@ -152,13 +162,14 @@ void metricsEndpoint_shouldReturnNumberOfRequests() throws Exception { Statistics.addRequest(); Statistics.addRequest(); - app.setMetricsPort(8995); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); // When: Getting metrics try (CloseableHttpClient client = HttpClients.createDefault()) { - HttpGet request = new HttpGet("http://localhost:8995/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { String body = EntityUtils.toString(response.getEntity()); JsonNode json = objectMapper.readTree(body); @@ -176,13 +187,14 @@ void metricsEndpoint_shouldReturnBytesTransferred() throws Exception { resetStatistics(); Statistics.addBytesTransferred(2048); - app.setMetricsPort(8994); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); // When: Getting metrics try (CloseableHttpClient client = HttpClients.createDefault()) { - HttpGet request = new HttpGet("http://localhost:8994/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { String body = EntityUtils.toString(response.getEntity()); JsonNode json = objectMapper.readTree(body); @@ -197,14 +209,15 @@ void metricsEndpoint_shouldReturnBytesTransferred() throws Exception { @Test void metricsEndpoint_shouldHandleMultipleRequests() throws Exception { // Given: Running InsightServer - app.setMetricsPort(8993); + int port = freePort(); + app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); // When: Making multiple requests try (CloseableHttpClient client = HttpClients.createDefault()) { for (int i = 0; i < 5; i++) { - HttpGet request = new HttpGet("http://localhost:8993/"); + HttpGet request = new HttpGet("http://localhost:" + port + "/"); client.execute(request, response -> { // Then: Each request should succeed assertThat(response.getCode()).isEqualTo(200); @@ -230,7 +243,7 @@ void prometheusEndpoint_shouldReturnExpositionFormat() throws Exception { int port = freePort(); app.setMetricsPort(port); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); try (CloseableHttpClient client = HttpClients.createDefault()) { HttpGet request = new HttpGet("http://localhost:" + port + "/metrics"); @@ -254,7 +267,7 @@ void prometheusEndpoint_withAuth_shouldRejectAnonymous() throws Exception { app.setMetricsPort(port); app.setMetricsAuth("user:secret"); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); try (CloseableHttpClient client = HttpClients.createDefault()) { HttpGet request = new HttpGet("http://localhost:" + port + "/metrics"); @@ -273,7 +286,7 @@ void prometheusEndpoint_withAuth_shouldAcceptCorrectCredentials() throws Excepti app.setMetricsPort(port); app.setMetricsAuth("user:secret"); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); String credentials = java.util.Base64.getEncoder() .encodeToString("user:secret".getBytes(java.nio.charset.StandardCharsets.UTF_8)); @@ -296,7 +309,7 @@ void prometheusEndpoint_withAuth_shouldStillServeJsonStatusUnprotected() throws app.setMetricsPort(port); app.setMetricsAuth("user:secret"); insightServer = new InsightServer(app); - Thread.sleep(500); + Await.serverOn(port); try (CloseableHttpClient client = HttpClients.createDefault()) { HttpGet request = new HttpGet("http://localhost:" + port + "/"); diff --git a/src/test/java/com/testingbot/tunnel/integration/ConnectLoggingTest.java b/src/test/java/com/testingbot/tunnel/integration/ConnectLoggingTest.java index 10829be..827a6fd 100644 --- a/src/test/java/com/testingbot/tunnel/integration/ConnectLoggingTest.java +++ b/src/test/java/com/testingbot/tunnel/integration/ConnectLoggingTest.java @@ -135,6 +135,8 @@ void aConnectProducesNoPerRequestLineWhenLoggingIsOff() throws Exception { } catch (IOException expected) { // the tunnel cannot be established; only the logging matters here } + // A deliberate wait, not a guess at readiness: this asserts a line never appears, so + // there is nothing to poll for and the only way to be wrong is to look too early. Thread.sleep(300); assertThat(captured.messages()) @@ -176,7 +178,8 @@ void aConnectIsLoggedAtUrlLevel() throws Exception { } catch (IOException expected) { // the dial cannot succeed; the line is written on the way in regardless } - Thread.sleep(300); + com.testingbot.tunnel.Await.until("a CONNECT line from the proxy logger", + () -> urlCaptured.messages().stream().anyMatch(m -> m.contains("CONNECT"))); assertThat(urlCaptured.messages()) .as("--log-http url must log the CONNECT") @@ -221,7 +224,8 @@ void debugDumpsTheConnectHeaders() throws Exception { } catch (IOException expected) { // the destination does not resolve; only the logging matters here } - Thread.sleep(300); + com.testingbot.tunnel.Await.until("the CONNECT headers to be logged", + () -> debugCaptured.messages().stream().anyMatch(m -> m.contains("X-Marker"))); String log = String.join("\n", debugCaptured.messages()); assertThat(log).contains("X-Marker: seen"); diff --git a/src/test/java/com/testingbot/tunnel/integration/ForwarderLoggingTest.java b/src/test/java/com/testingbot/tunnel/integration/ForwarderLoggingTest.java index 2374315..b3f438e 100644 --- a/src/test/java/com/testingbot/tunnel/integration/ForwarderLoggingTest.java +++ b/src/test/java/com/testingbot/tunnel/integration/ForwarderLoggingTest.java @@ -141,7 +141,10 @@ private List relayOneRequest(String logHttp) throws Exception { } catch (IOException expected) { // only the logging matters here } - Thread.sleep(300); + // Shared by the tests that expect a line and the ones that expect none, so it cannot + // simply poll: it returns as soon as something is logged, and otherwise waits the full + // window before reporting nothing, which is what the absence assertions need. + com.testingbot.tunnel.Await.atMost(300, () -> !captured.messages().isEmpty()); return captured.messages(); } diff --git a/src/test/java/com/testingbot/tunnel/integration/HttpLoggingTest.java b/src/test/java/com/testingbot/tunnel/integration/HttpLoggingTest.java index 17f24a1..b9d3a20 100644 --- a/src/test/java/com/testingbot/tunnel/integration/HttpLoggingTest.java +++ b/src/test/java/com/testingbot/tunnel/integration/HttpLoggingTest.java @@ -44,6 +44,19 @@ class HttpLoggingTest { private CapturingHandler captured; private Logger logHandlerLogger; + /** + * The captured log, once there is one. + * + *

The record is written by the handler on another thread, so the helpers used to sleep + * 200ms and hope. Too long when the record is already there -- which is almost always -- + * and too short on a loaded runner, where it failed as an assertion about logging that said + * nothing about timing. + */ + private String awaitLogged() { + return com.testingbot.tunnel.Await.value("a log record from HttpLogHandler", + captured::all); + } + /** Collects what HttpLogHandler emits. */ private static final class CapturingHandler extends Handler { private final List messages = new ArrayList<>(); @@ -186,7 +199,6 @@ private String proxyGetEchoing(String extraHeaders) throws Exception { while ((line = reader.readLine()) != null) { all.append(line).append('\n'); } - Thread.sleep(200); return all.toString(); } } @@ -206,7 +218,6 @@ private void proxyGet(String extraHeaders) throws Exception { // drain so the exchange completes before we look at the log } } - Thread.sleep(200); } @Test @@ -216,6 +227,9 @@ void none_logsNothing() throws Exception { proxyGet(""); + // A deliberate wait, not a guess at readiness: this asserts a record never appears, + // so there is nothing to poll for and the only way to be wrong is to look too early. + Thread.sleep(200); assertThat(captured.count()).isZero(); } @@ -226,7 +240,7 @@ void url_logsOneLinePerRequestWithoutHeaders() throws Exception { proxyGet("X-Custom: visible\r\n"); - String logged = captured.all(); + String logged = awaitLogged(); assertThat(logged).contains("GET"); assertThat(logged).contains("/page"); assertThat(logged).contains("200"); @@ -240,7 +254,7 @@ void headers_includesRequestHeaders() throws Exception { proxyGet("X-Custom: visible\r\n"); - assertThat(captured.all()).contains("X-Custom: visible"); + assertThat(awaitLogged()).contains("X-Custom: visible"); } @Test @@ -251,7 +265,7 @@ void headers_redactsCredentials() throws Exception { proxyGet("Authorization: Bearer super-secret-token\r\n"); - String logged = captured.all(); + String logged = awaitLogged(); assertThat(logged).contains("Authorization"); assertThat(logged).doesNotContain("super-secret-token"); } @@ -263,6 +277,9 @@ void errors_staysQuietForSuccessfulRequests() throws Exception { proxyGet(""); + // A deliberate wait, not a guess at readiness: this asserts a record never appears, + // so there is nothing to poll for and the only way to be wrong is to look too early. + Thread.sleep(200); assertThat(captured.count()).isZero(); } @@ -273,7 +290,7 @@ void errors_logsWithHeadersOnServerError() throws Exception { proxyGet("X-Custom: visible\r\n"); - String logged = captured.all(); + String logged = awaitLogged(); assertThat(logged).contains("500"); assertThat(logged).contains("X-Custom: visible"); } @@ -286,7 +303,7 @@ void reusesAnIncomingCorrelationId() throws Exception { proxyGet("X-Request-Id: caller-supplied-id\r\n"); - assertThat(captured.all()).contains("[caller-supplied-id]"); + assertThat(awaitLogged()).contains("[caller-supplied-id]"); } @Test @@ -296,7 +313,7 @@ void generatesACorrelationIdWhenTheCallerSuppliesNone() throws Exception { proxyGet(""); - assertThat(captured.all()).matches("(?s).*\\[[0-9a-f]+\\].*"); + assertThat(awaitLogged()).matches("(?s).*\\[[0-9a-f]+\\].*"); } @Test @@ -308,7 +325,7 @@ void passesTheCorrelationIdToTheOrigin() throws Exception { String seenByOrigin = proxyGetEchoing("X-Request-Id: caller-supplied-id\r\n"); assertThat(seenByOrigin).contains("caller-supplied-id"); - assertThat(captured.all()).contains("[caller-supplied-id]"); + assertThat(awaitLogged()).contains("[caller-supplied-id]"); } @Test @@ -329,6 +346,6 @@ void honoursACustomCorrelationHeader() throws Exception { proxyGet("X-Trace: my-trace-id\r\n"); - assertThat(captured.all()).contains("[my-trace-id]"); + assertThat(awaitLogged()).contains("[my-trace-id]"); } } diff --git a/src/test/java/com/testingbot/tunnel/integration/ProxyAuthSchemeConnectTest.java b/src/test/java/com/testingbot/tunnel/integration/ProxyAuthSchemeConnectTest.java index a6cb71b..6668c0c 100644 --- a/src/test/java/com/testingbot/tunnel/integration/ProxyAuthSchemeConnectTest.java +++ b/src/test/java/com/testingbot/tunnel/integration/ProxyAuthSchemeConnectTest.java @@ -121,7 +121,10 @@ private String connectThroughTunnel() throws Exception { BufferedReader reader = new BufferedReader( new InputStreamReader(socket.getInputStream(), StandardCharsets.UTF_8)); String status = reader.readLine(); - Thread.sleep(200); + // The upstream records the CONNECT headers on its own thread, and every caller + // asserts on them, so wait for them rather than guessing how long that takes. + com.testingbot.tunnel.Await.until("the upstream to record the CONNECT headers", + () -> !connectHeaders.isEmpty()); return status == null ? "" : status; } } diff --git a/src/test/java/com/testingbot/tunnel/integration/ProxyLoopTest.java b/src/test/java/com/testingbot/tunnel/integration/ProxyLoopTest.java index 73d57d7..38a59cb 100644 --- a/src/test/java/com/testingbot/tunnel/integration/ProxyLoopTest.java +++ b/src/test/java/com/testingbot/tunnel/integration/ProxyLoopTest.java @@ -87,6 +87,10 @@ void anAbsoluteFormRequestNamingTheProxyIsRefusedOnce() throws Exception { assertThat(statusOf(response)).contains("508"); assertThat(response).contains("loop-detected"); + // A deliberate wait, not a guess at readiness. This asserts the request did *not* + // re-enter the handler, so there is no condition that becomes true and nothing to poll + // for -- looking too early would pass whether the loop guard works or not. Too short + // weakens the test rather than flaking it, which is why it stays generous. Thread.sleep(300); assertThat(Statistics.getNumberOfRequests()) .as("the request must not re-enter the handler") diff --git a/src/test/java/ssh/SchedulerTest.java b/src/test/java/ssh/SchedulerTest.java index f237a3b..9305b64 100644 --- a/src/test/java/ssh/SchedulerTest.java +++ b/src/test/java/ssh/SchedulerTest.java @@ -57,6 +57,8 @@ void cancelStopsFurtherRuns() throws Exception { scheduler.cancel(); int afterCancel = runs.get(); assertThat(afterCancel).isPositive(); + // Absence again: a cancelled scheduler must run nothing more, and "nothing more" + // only becomes observable by giving it time to misbehave. Thread.sleep(100); assertThat(runs.get()).isEqualTo(afterCancel); @@ -130,6 +132,7 @@ void schedulingAgainReplacesTheOutstandingTask() throws Exception { int afterReplace = first.get(); assertThat(afterReplace).isPositive(); assertThat(second.await(5, TimeUnit.SECONDS)).isTrue(); + // As above: the replaced task must not fire again, which cannot be polled for. Thread.sleep(50); assertThat(first.get()).isEqualTo(afterReplace);