Skip to content

Commit

Permalink
add debugging info for investigating flaky tests
Browse files Browse the repository at this point in the history
* store thread dumps to "target" folder 3 seconds after every test start.
* generate unique archive names for uploaded artifacts on different OSes
  • Loading branch information
asolntsev committed Feb 14, 2024
1 parent 5e26178 commit e7282cc
Show file tree
Hide file tree
Showing 8 changed files with 151 additions and 25 deletions.
7 changes: 6 additions & 1 deletion .github/workflows/main.yml
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,12 @@ jobs:
uses: actions/upload-artifact@v4
if: failure()
with:
name: test-report
name: test-report-${{matrix.platform}}
retention-days: 5
path: |
target/surefire-reports
target/site
target/*.hprof
target/*.txt
target/*.jks
target/*_cert*
9 changes: 6 additions & 3 deletions pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,11 @@
<artifactId>maven-surefire-plugin</artifactId>
<configuration>
<excludedGroups>slow-test</excludedGroups>
<includes>
<include>**/WebSocketClientServerTest*</include>
<include>**/KeepAliveTest*</include>
</includes>
<argLine>-ea -Xmx512m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=target/smoke-tests.hprof</argLine>
</configuration>
</plugin>
</plugins>
Expand All @@ -75,9 +80,7 @@
<artifactId>maven-surefire-plugin</artifactId>
<configuration>
<groups>slow-test</groups>
<excludes>
<exclude>**/WebSocketClientServerTest*</exclude>
</excludes>
<argLine>-ea -Xmx512m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=target/slow-tests.hprof</argLine>
</configuration>
</plugin>
</plugins>
Expand Down
10 changes: 10 additions & 0 deletions src/test/java/org/littleshoot/proxy/AbstractProxyTest.java
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,8 @@
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.littleshoot.proxy.impl.DefaultHttpProxyServer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.net.ssl.SSLSession;
import java.io.IOException;
Expand Down Expand Up @@ -63,6 +65,10 @@ public abstract class AbstractProxyTest {
private final AtomicInteger clientSSLHandshakeSuccesses = new AtomicInteger(0);
private final AtomicInteger clientDisconnects = new AtomicInteger(0);

protected Logger logger() {
return LoggerFactory.getLogger(getClass());
}

@BeforeEach
final void runSetUp() throws Exception {
webServer = TestUtils.startWebServer(true);
Expand All @@ -80,8 +86,10 @@ final void runSetUp() throws Exception {

webHost = new HttpHost("127.0.0.1", webServerPort);
httpsWebHost = new HttpHost("127.0.0.1", httpsWebServerPort, "https");
logger().info("Started webserver http:{}, https:{}", webServerPort, httpsWebServerPort);

setUp();
logger().info("Started proxy server {}", proxyServer.getListenAddress());
}

protected abstract void setUp() throws Exception;
Expand All @@ -93,10 +101,12 @@ final void runTearDown() throws Exception {
} finally {
try {
if (proxyServer != null) {
logger().info("Stop proxy server {}", proxyServer.getListenAddress());
proxyServer.abort();
}
} finally {
if (webServer != null) {
logger().info("Stop webserver http:{}, https:{}", webServerPort, httpsWebServerPort);
webServer.stop();
}
}
Expand Down
46 changes: 29 additions & 17 deletions src/test/java/org/littleshoot/proxy/KeepAliveTest.java
Original file line number Diff line number Diff line change
Expand Up @@ -16,10 +16,13 @@
import org.mockserver.integration.ClientAndServer;
import org.mockserver.matchers.Times;
import org.mockserver.model.ConnectionOptions;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.annotation.ParametersAreNonnullByDefault;
import java.io.IOException;
import java.net.Socket;
import java.time.Duration;
import java.util.Locale;
import java.util.concurrent.TimeUnit;

Expand All @@ -33,6 +36,7 @@
@Tag("slow-test")
@ParametersAreNonnullByDefault
public final class KeepAliveTest {
private static final Logger log = LoggerFactory.getLogger(KeepAliveTest.class);
private HttpProxyServer proxyServer;
private ClientAndServer mockServer;
private int mockServerPort;
Expand All @@ -42,8 +46,7 @@ public final class KeepAliveTest {
void setUp() {
mockServer = new ClientAndServer(0);
mockServerPort = mockServer.getLocalPort();
socket = null;
proxyServer = null;
log.info("Mock server port: {} (started: {})", mockServerPort, mockServer.hasStarted());
}

@AfterEach
Expand Down Expand Up @@ -72,15 +75,15 @@ void tearDown() throws Exception {
public void testHttp11DoesNotCloseConnectionByDefault() throws IOException, InterruptedException {
mockServer.when(request()
.withMethod("GET")
.withPath("/success"),
Times.exactly(2))
.withPath("/success"), Times.exactly(2))
.respond(response()
.withStatusCode(200)
.withBody("success"));

proxyServer = DefaultHttpProxyServer.bootstrap()
.withPort(0)
.start();
log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

// construct the basic request: METHOD + URI + HTTP version + CRLF (to indicate the end of the request)
Expand All @@ -89,11 +92,13 @@ public void testHttp11DoesNotCloseConnectionByDefault() throws IOException, Inte

// send the same request twice over the same connection
for (int i = 1; i <= 2; i++) {
log.debug("#{} Sending to socket {} packet '{}'...", i, socket.getLocalPort(), successfulGet);
SocketClientUtil.writeStringToSocket(successfulGet, socket);

// wait a bit to allow the proxy server to respond
Thread.sleep(750);

log.debug("#{} Reading from socket {}...", i, socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

assertThat(response)
Expand All @@ -120,8 +125,7 @@ public void testHttp11DoesNotCloseConnectionByDefault() throws IOException, Inte
public void testProxyKeepsClientConnectionOpenAfterServerDisconnect() throws IOException, InterruptedException {
mockServer.when(request()
.withMethod("GET")
.withPath("/success"),
Times.exactly(2))
.withPath("/success"), Times.exactly(2))
.respond(response()
.withStatusCode(200)
.withBody("success")
Expand All @@ -133,6 +137,7 @@ public void testProxyKeepsClientConnectionOpenAfterServerDisconnect() throws IOE
proxyServer = DefaultHttpProxyServer.bootstrap()
.withPort(0)
.start();
log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

// construct the basic request: METHOD + URI + HTTP version + CRLF (to indicate the end of the request)
Expand All @@ -141,11 +146,13 @@ public void testProxyKeepsClientConnectionOpenAfterServerDisconnect() throws IOE

// send the same request twice over the same connection
for (int i = 1; i <= 2; i++) {
log.debug("#{} Sending to socket {} packet '{}'...", i, socket.getLocalPort(), successfulGet);
SocketClientUtil.writeStringToSocket(successfulGet, socket);

// wait a bit to allow the proxy server to respond
Thread.sleep(750);

log.debug("#{} Reading from socket {}...", i, socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

assertThat(response)
Expand Down Expand Up @@ -177,28 +184,29 @@ public void testProxyKeepsClientConnectionOpenAfterServerDisconnect() throws IOE
public void testBadGatewayDoesNotCloseConnection() throws IOException, InterruptedException {
mockServer.when(request()
.withMethod("GET")
.withPath("/success"),
Times.exactly(1))
.withPath("/success"), Times.exactly(1))
.respond(response()
.withStatusCode(200)
.withBody("success"));

proxyServer = DefaultHttpProxyServer.bootstrap()
.withPort(0)
.start();

log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

String badGatewayGet = "GET http://localhost:0/success HTTP/1.1\r\n"
+ "\r\n";

// send the same request twice over the same connection
for (int i = 1; i <= 2; i++) {
log.debug("#{} Sending to socket {} packet '{}'...", i, socket.getLocalPort(), badGatewayGet);
SocketClientUtil.writeStringToSocket(badGatewayGet, socket);

// wait a bit to allow the proxy server to respond
Thread.sleep(1500);

log.debug("#{} Reading from socket {}...", i, socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

assertThat(response)
Expand All @@ -221,27 +229,28 @@ public void testBadGatewayDoesNotCloseConnection() throws IOException, Interrupt
public void testGatewayTimeoutDoesNotCloseConnection() throws IOException {
mockServer.when(request()
.withMethod("GET")
.withPath("/success"),
Times.exactly(2))
.withPath("/success"), Times.exactly(2))
.respond(response()
.withStatusCode(200)
.withDelay(TimeUnit.SECONDS, 10)
.withBody("success"));

proxyServer = DefaultHttpProxyServer.bootstrap()
.withIdleConnectionTimeout(2)
.withIdleConnectionTimeout(Duration.ofSeconds(2))
.withPort(0)
.start();

log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

String successfulGet = "GET http://localhost:" + mockServerPort + "/success HTTP/1.1\r\n"
+ "\r\n";

// send the same request twice over the same connection
for (int i = 1; i <= 2; i++) {
log.debug("#{} Sending to socket {} packet '{}'...", i, socket.getLocalPort(), successfulGet);
SocketClientUtil.writeStringToSocket(successfulGet, socket);

log.debug("#{} Reading from socket {}...", i, socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

// match the whole response to make sure that it's not repeated
Expand All @@ -267,8 +276,7 @@ public void testGatewayTimeoutDoesNotCloseConnection() throws IOException {
public void testShortCircuitResponseDoesNotCloseConnectionByDefault() throws IOException, InterruptedException {
mockServer.when(request()
.withMethod("GET")
.withPath("/success"),
Times.exactly(1))
.withPath("/success"), Times.exactly(1))
.respond(response()
.withStatusCode(500)
.withBody("this response should never be sent"));
Expand All @@ -295,19 +303,21 @@ public HttpResponse clientToProxyRequest(HttpObject httpObject) {
.withPort(0)
.withFiltersSource(filtersSource)
.start();

log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

String successfulGet = "GET http://localhost:" + mockServerPort + "/success HTTP/1.1\r\n"
+ "\r\n";

// send the same request twice over the same connection
for (int i = 1; i <= 2; i++) {
log.debug("#{} Sending to socket {} packet '{}'...", i, socket.getLocalPort(), successfulGet);
SocketClientUtil.writeStringToSocket(successfulGet, socket);

// wait a bit to allow the proxy server to respond
Thread.sleep(750);

log.debug("#{} Reading from socket {}...", i, socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

assertThat(response)
Expand Down Expand Up @@ -360,18 +370,20 @@ public HttpResponse clientToProxyRequest(HttpObject httpObject) {
.withPort(0)
.withFiltersSource(filtersSource)
.start();

log.info("Started proxy server {}", proxyServer.getListenAddress());
socket = SocketClientUtil.getSocketToProxyServer(proxyServer);

String successfulGet = "GET http://localhost:" + mockServerPort + "/success HTTP/1.1\r\n"
+ "\r\n";

// only send this request once, since we expect the short circuit response to close the connection
log.debug("Sending to socket {} packet '{}'...", socket.getLocalPort(), successfulGet);
SocketClientUtil.writeStringToSocket(successfulGet, socket);

// wait a bit to allow the proxy server to respond
Thread.sleep(750);

log.debug("Reading from socket {}...", socket.getLocalPort());
String response = SocketClientUtil.readStringFromSocket(socket);

assertThat(response)
Expand Down
94 changes: 94 additions & 0 deletions src/test/java/org/littleshoot/proxy/test/ThreadDumpExtension.java
Original file line number Diff line number Diff line change
@@ -0,0 +1,94 @@
package org.littleshoot.proxy.test;

import org.apache.commons.io.FileUtils;
import org.junit.jupiter.api.extension.AfterAllCallback;
import org.junit.jupiter.api.extension.AfterEachCallback;
import org.junit.jupiter.api.extension.BeforeAllCallback;
import org.junit.jupiter.api.extension.BeforeEachCallback;
import org.junit.jupiter.api.extension.ExtensionContext;
import org.junit.jupiter.api.extension.ExtensionContext.Namespace;
import org.opentest4j.TestAbortedException;
import org.slf4j.Logger;

import java.io.File;
import java.io.IOException;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.lang.reflect.Method;
import java.util.concurrent.ScheduledExecutorService;

import static java.nio.charset.StandardCharsets.UTF_8;
import static java.util.concurrent.Executors.newScheduledThreadPool;
import static java.util.concurrent.TimeUnit.MILLISECONDS;
import static org.slf4j.LoggerFactory.getLogger;

public class ThreadDumpExtension implements BeforeAllCallback, AfterAllCallback, BeforeEachCallback, AfterEachCallback {
private static final Namespace NAMESPACE = Namespace.create("ThreadDumpExtension");
private static final int INITIAL_DELAY_MS = 5000;
private static final int DELAY_MS = 1000;

@Override
public void beforeAll(ExtensionContext context) {
getLogger(context.getDisplayName()).info("Starting tests ({})", memory());
}

@Override
public void afterAll(ExtensionContext context) {
getLogger(context.getDisplayName()).info("Finished tests - {} ({})", verdict(context), memory());
}

@Override
public void beforeEach(ExtensionContext context) {
Logger log = logger(context);
log.info("starting {} ({})...", context.getDisplayName(), memory());
ScheduledExecutorService executor = newScheduledThreadPool(1);
executor.scheduleWithFixedDelay(() -> takeThreadDump(log), INITIAL_DELAY_MS, DELAY_MS, MILLISECONDS);
context.getStore(NAMESPACE).put("executor", executor);
}

@Override
public void afterEach(ExtensionContext context) {
logger(context).info("finished {} - {} ({})", context.getDisplayName(), verdict(context), memory());
ScheduledExecutorService executor = (ScheduledExecutorService) context.getStore(NAMESPACE).remove("executor");
executor.shutdown();
}

private static Logger logger(ExtensionContext context) {
return getLogger(context.getRequiredTestClass().getSimpleName() + '.' + context.getTestMethod().map(Method::getName).orElse("?"));
}

private String verdict(ExtensionContext context) {
return context.getExecutionException().isPresent() ?
(context.getExecutionException().get() instanceof TestAbortedException ? "skipped" : "NOK") :
"OK";
}

private String memory() {
long freeMemory = Runtime.getRuntime().freeMemory();
long maxMemory = Runtime.getRuntime().maxMemory();
long totalMemory = Runtime.getRuntime().totalMemory();
long usedMemory = totalMemory - freeMemory;
return "memory used:" + mb(usedMemory) + ", free:" + mb(freeMemory) + ", total:" + mb(totalMemory) + ", max:" + mb(maxMemory);
}

private long mb(long bytes) {
return bytes / 1024 / 1024;
}

private void takeThreadDump(Logger log) {
StringBuilder threadDump = new StringBuilder();
ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
for (ThreadInfo threadInfo : threadMXBean.dumpAllThreads(true, true, 50)) {
threadDump.append(threadInfo.toString());
}
File dump = new File("target/thread-dump-" + System.currentTimeMillis() + ".txt");
try {
FileUtils.writeStringToFile(dump, threadDump.toString(), UTF_8);
log.info("Saved thread dump to file {}", dump);
}
catch (IOException e) {
log.error("Failed to save thread dump to file {}", dump, e);
}
}
}
Loading

0 comments on commit e7282cc

Please sign in to comment.