Intermittent webflux test failures due to timeouts

[philwebb]

We're seeing tests regularly fail on CI due to timeout issues. Here's one example.

We keep bumping the timeouts but I feel like there must be an underlying cause that we've not yet identified.

[ERROR] eventsWithDateAfter[Reactive](org.springframework.boot.actuate.audit.AuditEventsEndpointWebIntegrationTests)  Time elapsed: 360.013 s  <<< ERROR!
java.lang.IllegalStateException: Timeout on blocking read for 360000 MILLISECONDS
	at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:110)
	at reactor.core.publisher.Mono.block(Mono.java:1185)
	at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.toResponseSpec(DefaultWebTestClient.java:293)
	at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.exchange(DefaultWebTestClient.java:271)
	at org.springframework.boot.actuate.audit.AuditEventsEndpointWebIntegrationTests.eventsWithDateAfter(AuditEventsEndpointWebIntegrationTests.java:55)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.springframework.boot.actuate.endpoint.web.test.AbstractWebEndpointRunner$3.evaluate(AbstractWebEndpointRunner.java:114)
	at org.springframework.boot.actuate.endpoint.web.test.AbstractWebEndpointRunner$4.evaluate(AbstractWebEndpointRunner.java:129)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.springframework.boot.actuate.endpoint.web.test.AbstractWebEndpointRunner$1.evaluate(AbstractWebEndpointRunner.java:81)
	at org.springframework.boot.actuate.endpoint.web.test.AbstractWebEndpointRunner$2.evaluate(AbstractWebEndpointRunner.java:95)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:27)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:369)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:275)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:239)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:160)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:373)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:334)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:119)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:407)

[INFO] Running org.springframework.boot.actuate.audit.AuditEventsJmxEndpointExtensionTests

[philwebb]

@bclozel Any ideas? Have you seen these kinds of issues in the Framework build?

[bclozel]

I've tried looking at that and couldn't reproduce it in a Linux VM (this might be OS-related).
We've had a few of those in Spring Framework but the build is super stable lately - maybe this is a reactor netty issue that was fixed in the recent versions (just speculating here).

I'll take another look at this.

[philwebb]

Thanks @bclozel !

[smaldini]

Could this run with reactor-netty 0.7.1.BUILD-SNAPSHOT for the next days ?

[bclozel]

Here's the current status of this issue.

I can't reproduce this behavior on my macOS laptop, nor inside a Ubuntu Linux VM.

I managed to reproduce it (thanks @wilkinsona) by running the actual Docker container we're using for our CI build. A few interesting facts:

• it does happen with a freshly started container and happens about 50% of the time
• if it doesn't happen during the first 2-3 runs, it's unlikely to happen at all

Two example of tests showing this issue:

1. AuditEventsEndpointWebIntegrationTests. eventsWithDateAfter (WebTestClient sends a GET request to the server)
2. AbstractWebEndpointIntegrationTests.writeOperation (WebTestClient sends a POST request to the server)

I managed to gather some data while number 2 was happening.

It seems the connection between client and server is up:

root@133e4cc506cf:/# lsof -i
COMMAND  PID USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
java    1284 root  466u  IPv4 1277812      0t0  TCP *:34569 (LISTEN)
java    1284 root  477u  IPv4 1277813      0t0  TCP localhost:40672->localhost:34569 (ESTABLISHED)
java    1284 root  478u  IPv4 1276755      0t0  TCP localhost:34569->localhost:40672 (ESTABLISHED)

The tested endpoint is up and available:

root@133e4cc506cf:/# curl -X POST -d '{"foo":"one"}' -H "Content-Type: application/json" http://localhost:34569/endpoints/test -vvv
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 34569 (#0)
> POST /endpoints/test HTTP/1.1
> Host: localhost:34569
> User-Agent: curl/7.52.1
> Accept: */*
> Content-Type: application/json
> Content-Length: 13
>
* upload completely sent off: 13 out of 13 bytes
< HTTP/1.1 204 No Content
<
* Curl_http_done: called premature == 0
* Connection #0 to host localhost left intact

A JStack dump shows that Reactor Netty Server threads are using EPoll (as expected on Linux). The HTTP client is waiting for data:

"main" #1 prio=5 os_prio=0 tid=0x00007f2cf400a000 nid=0x889 waiting on condition [0x00007f2cfcbc5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
  at sun.misc.Unsafe.park(Native Method)
  - parking to wait for  <0x00000000f2583860> (a java.util.concurrent.CountDownLatch$Sync)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
  at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
  at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:108)
  at reactor.core.publisher.Mono.block(Mono.java:1185)
  at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.exchange(DefaultWebTestClient.java:282)

Wireshark captures show that the HTTP client sends valid data to the server, but never receives a response:

POST /endpoints/test HTTP/1.1
user-agent: ReactorNetty/0.7.0.RELEASE
transfer-encoding: chunked
host: localhost:36195
accept: */*
accept-encoding: gzip
WebTestClient-Request-Id: 1
Content-Type: application/json;charset=UTF-8

19
{"bar":"two","foo":"one"}
0

I'll run the same tests with reactor Bismuth.BUILD-SNAPSHOT and report back here.

[bclozel]

I can't reproduce (for now) the same error on Bismuth SNAPSHOTs (see gh-10679). I've updated the Reactor BOM dependency on master and I'll close this issue if we don't see those failures in the next few days.
This also look quite familiar with reactor/reactor-netty#186, so I'm tracking that one as well.

[smaldini]

Ok a new snapshot is out if we can try it again 👍

[wilkinsona]

It's been 20+ builds since we last saw this. I think it's fixed by the Reactor Netty upgrade 🤞

[philwebb]

I think it happened again yesterday on the JDK 9 build https://ci.spring.io/teams/spring-boot/pipelines/spring-boot/jobs/jdk9-build/builds/105