hamadodene
commented
3 months ago After some investigation, I discovered a peculiar issue in the tests, and I believe it could be the cause of the failures in several flaky tests we've been experiencing. I'll try to explain it as clearly as possible.
Given that the initial error was in testAlwaysServeStaticContent test:
AVVERTENZA: [aed4c0cc] Unknown channel option 'TCP_KEEPCOUNT' for channel '[id: 0xaed4c0cc]'
io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: no further information: localhost/127.0.0.1:56379
Caused by: java.net.ConnectException: Connection refused: no further information
at java.base/sun.nio.ch.Net.pollConnect(Native Method)
at java.base/sun.nio.ch.Net.pollConnectNow(Net.java:672)
at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:946)To try to resolve this issue, I attempted to set a fixed port for WireMock so that all tests would use the same port. In reality, the dynamics I will explain later are most likely the same thing that happened here.
When the test in testAlwaysServeStaticContent starts, I see from the logs that the listener has been configured as follows:
INFO: configured backend foo localhost:56.385 enabled:true
However, from the error, we see that Carapace is trying to call a port we did not expect. Looking at the preceding test, I see that it configured the port that the test testAlwaysServeStaticContent is launching.
INFORMAZIONI: configured backend foo localhost:56.379 enabled:true
To better understand and resolve this issue, I tried to choose a free port and assign it to WireMock. After that, the issue described below occurred. But I would say it is the same problem.
public class BasicStandardEndpointMapperTest {
static int port;
static {
try {
// Get a free port
ServerSocket s = new ServerSocket(0);
port = s.getLocalPort();
s.close();
} catch (IOException e) {
// No OPS
}
}
@Rule
public WireMockRule backend1 = new WireMockRule(port);I identified the problem by simultaneously running all the tests in the BasicStandardEndpointMapperTest class and analyzing the two tests, testServeACMEChallengeToken and testAlwaysServeStaticContent, where the latter is failing.
As you can see from my screenshot, the testServeACMEChallengeToken is executed before the testAlwaysServeStaticContent. Quite often, the testAlwaysServeStaticContent fails with the following error:
feb 16, 2024 3:51:54 PM org.carapaceproxy.core.Listeners bootListener
INFORMAZIONI: started listener at HostPort[host=0.0.0.0, port=1425]: reactor.netty.transport.ServerTransport$InetDisposableBind@402f8592
feb 16, 2024 3:51:54 PM org.carapaceproxy.server.cache.CacheByteBufMemoryUsageMetric start
INFORMAZIONI: Starting cache ByteBufAllocator usage, period: 5 seconds
request /not-exists.html
action match default-testServeAcme
feb 16, 2024 3:51:54 PM org.carapaceproxy.core.RequestsLogger logRequest
GRAVE: Request [2024-02-16 15:51:54.430] [GET localhost:1425 /not-exists.html] [uid:, sid:, ip:127.0.0.1] server=127.0.0.1, act=PROXY, route=default-testServeAcme, backend=localhost:49201. time t=0ms b=-1708095114430ms, protocol=HTTP/1.1 not logged to access log because RequestsLogger is closed
feb 16, 2024 3:51:54 PM reactor.util.Loggers$Slf4JLogger warn
AVVERTENZA: [d555f853] Unknown channel option 'TCP_KEEPCOUNT' for channel '[id: 0xd555f853]'
feb 16, 2024 3:51:54 PM reactor.util.Loggers$Slf4JLogger warn
AVVERTENZA: [d555f853] Unknown channel option 'TCP_KEEPINTERVAL' for channel '[id: 0xd555f853]'
feb 16, 2024 3:51:54 PM reactor.util.Loggers$Slf4JLogger warn
AVVERTENZA: [d555f853] Unknown channel option 'TCP_KEEPIDLE' for channel '[id: 0xd555f853]'
feb 16, 2024 3:51:54 PM com.github.tomakehurst.wiremock.common.Slf4jNotifier error
GRAVE:
Request was not matched
=======================
-----------------------------------------------------------------------------------------------------------------------
| Closest stub | Request |
-----------------------------------------------------------------------------------------------------------------------
|
GET | GET
/seconda.html | /not-exists.html <<<<< URL does not match
|
|
-----------------------------------------------------------------------------------------------------------------------
feb 16, 2024 3:51:59 PM org.eclipse.jetty.server.AbstractConnector doStopIn theory, this should not be possible since the route configuration specifies that requests matching .not-exists. should be directed to an action serving a static page.
public void testAlwaysServeStaticContent() throws Exception {
stubFor(get(urlEqualTo("/seconda.html"))
.willReturn(aResponse()
.withStatus(200)
.withHeader("Content-Type", "text/html")
.withBody("it <b>works</b> !!")));
try (HttpProxyServer server = new HttpProxyServer(null, tmpDir.newFolder())) {
{
Properties configuration = new Properties();
configuration.put("backend.1.id", "foo");
configuration.put("backend.1.host", "localhost");
configuration.put("backend.1.port", String.valueOf(port));
configuration.put("backend.1.enabled", "true");
configuration.put("director.1.id", "*");
configuration.put("director.1.backends", "*");
configuration.put("director.1.enabled", "true");
configuration.put("listener.1.host", "0.0.0.0");
configuration.put("listener.1.port", "1425");
configuration.put("listener.1.ssl", "false");
configuration.put("listener.1.enabled", "true");
configuration.put("route.10.id", "default");
configuration.put("route.10.enabled", "true");
configuration.put("route.10.match", "all");
configuration.put("route.10.action", "proxy-all");
configuration.put("action.1.id", "serve-static");
configuration.put("action.1.enabled", "true");
configuration.put("action.1.type", "static");
configuration.put("action.1.file", CLASSPATH_RESOURCE + "/test-static-page.html");
configuration.put("action.1.code", "200");
configuration.put("route.1.id", "static-page");
configuration.put("route.1.enabled", "true");
configuration.put("route.1.match", "request.uri ~ \".*index.*\"");
configuration.put("route.1.action", "serve-static");
configuration.put("action.2.id", "static-not-exists"); // file not exists
configuration.put("action.2.enabled", "true");
configuration.put("action.2.type", "static");
configuration.put("action.2.file", CLASSPATH_RESOURCE + "/not-exists.html");
configuration.put("action.2.code", "200");
configuration.put("route.2.id", "static-not-exists");
configuration.put("route.2.enabled", "true");
configuration.put("route.2.match", "request.uri ~ \".*not-exists.*\"");
configuration.put("route.2.action", "static-not-exists");
PropertiesConfigurationStore config = new PropertiesConfigurationStore(configuration);
server.configureAtBoot(config);
}
server.start();To understand the flow, I changed the names of the routes so that they were different between the two tests. From the logs, it is evident that the requests originating from the testAlwaysServeStaticContent method reach the server configured in the testServeACMEChallengeToken class.
In test testServeACMEChallengeToken i set:
configuration.put("route.10.id", "default-testServeAcme");
configuration.put("route.10.enabled", "true");
configuration.put("route.10.match", "all");
configuration.put("route.10.action", "proxy-all");and i added some logs in ProxyRequestsManager (method processRequest):
public Publisher<Void> processRequest(ProxyRequest request) {
request.setStartTs(System.currentTimeMillis());
request.setLastActivity(request.getStartTs());
parent.getFilters().forEach(filter -> filter.apply(request));
System.out.println("request " + request.getUri());
MapResult action = parent.getMapper().map(request);
System.out.println("action match " + action.getRouteId());
if (action == null) {
LOGGER.log(Level.INFO, "Mapper returned NULL action for {0}", this);
action = MapResult.internalError(MapResult.NO_ROUTE);
}And when i run testAlwaysServeStaticContent the result is:
NFORMAZIONI: Starting cache ByteBufAllocator usage, period: 5 seconds
request /not-exists.html
action match default-testServeAcme
feb 16, 2024 3:51:54 PM org.carapaceproxy.core.RequestsLogger logRequest
GRAVE: Request [2024-02-16 15:51:54.430] [GET localhost:1425 /not-exists.html] [uid:, sid:, ip:127.0.0.1] server=127.0.0.1, act=PROXY, route=default-testServeAcme, backend=localhost:49201. time t=0ms b=-1708095114430ms, protocol=HTTP/1.1 not logged to access log because RequestsLogger is closed
feb 16, 2024 3:51:54 PM reactor.util.Loggers$Slf4JLogger warnI cannot comprehend why this happens. Perhaps the HTTP server in testServeACMEChallengeToken has not closed properly when the testAlwaysServeStaticContent starts? However, theoretically, in that case, testAlwaysServeStaticContent should not initiate since the port is still occupied.
Or maybe there is another reason that I am not understanding?
NiccoMlt
Some flaky tests were found while implementing #437:
See https://github.com/diennea/carapaceproxy/actions/runs/5005242440/jobs/8969440561
But for example here https://github.com/NiccoMlt/carapaceproxy/actions/runs/5005216296/jobs/8969398591 I see different tests failing: