Wiremock: Spring WebFlux reactive threads hanging, required Jetty 9.4.x

Created on 9 Apr 2018  ·  62Comments  ·  Source: tomakehurst/wiremock

Wiremock is using a version of Jetty 9.2.x and for the new version of Spring Boot with the WebFlux (2.0.0.RELEASE) Reactive threads sometimes the calling thread stops and hanging when calling Wiremock. This problem occurs only in version 9.2.x and not in 9.4.8.v20171121 of Jetty.

I understand that you want the JDK 7 support, but in that case you'll lose support for newer technologies/frameworks like Spring WebFlux, HTTP2 and so on...
Wiremock with version 9.2.x of Jetty is unusable with reactive threads because it randomly stops hanging.

I saw your conversation on https://github.com/tomakehurst/wiremock/pull/887 thread and the commit https://github.com/tomakehurst/wiremock/commit/4368d316ec239bac305f1faadedab24765bbe4b6, but somehow it will be very nice if you can provide support for the new Spring 5 WebFlux (Spring Boot WebFlux 2.0.0.RELEASE).

Add another JAR artifact to the build that's Java 8+ only and uses the latest Jetty version. This would probably involve splitting the source tree up into core and version-specific parts, which the build would include/exclude for the various output JARs.

Add some runtime detection of the environment i.e. are we on Java 8+ and Jetty 9.4+, and load the HTTP/2 code only under these conditions, such that NoClassDefFoundErrors and the like aren't thrown when running on Java 7.

Any of the above solution should be fine. The idea is to upgrade also the Wiremock Standalone which is used by spring-cloud-contract-wiremock.

Please see related issues:
https://github.com/spring-projects/spring-boot/issues/10569
https://github.com/reactor/reactor-netty/issues/264
https://github.com/spring-cloud/spring-cloud-contract/issues/606

Most helpful comment

I can confirm that this bug has two solutions now.

An example for each solution can be found under different branches in this project: https://github.com/ati90ati/bugreport-wiremock-webflux-hanging

Solution 1:
With Spring Boot 2.1.4.RELEASE the problem disappears.

Solution 2:
With using at least Wiremock 2.22.0 version and the wiremock options ChunkedEncodingPolicy.BODY_FILE the problem also can be fixed.

Solution 2 Method 1 (with configuring a new Options bean):

This solution with chunked body is described here: https://github.com/tomakehurst/wiremock/issues/914#issuecomment-474262581
Example config with static port:

@Configuration
public class WiremockConfig {
    @Bean
    public Options wiremockOptions() {
        final com.github.tomakehurst.wiremock.core.WireMockConfiguration wireMockConfiguration = WireMockSpring
                .options();

        wireMockConfiguration.useChunkedTransferEncoding(Options.ChunkedEncodingPolicy.BODY_FILE);
        wireMockConfiguration.port(12345);

        return wireMockConfiguration;
    }
}

Solution 2 Method 2 (with using WireMockConfigurationCustomizer from Spring Cloud Contract):

@Configuration
public class WiremockConfig {
    @Bean
    public WireMockConfigurationCustomizer wireMockConfigurationCustomizer() {
        return config -> config.useChunkedTransferEncoding(Options.ChunkedEncodingPolicy.BODY_FILE);
    }
}

So, the issue can be closed.

All 62 comments

Can you show how you're reproducing this problem, and isolating it to Jetty?

The issues you've linked to seem to be Netty rather than Jetty related. Also, as Marcin pointed out, if you're using the Spring Cloud WireMock integration lib, then you'll be using whatever web server you've configured for Spring, not Jetty 9.2.x. Have you tried your test case using this?

Isolating it to Jetty for me seems that I've tried with 9.2.22.v20170606 was hanging and with 9.4.8.v20171121 not.

I know that the bug what I've added there is from Reactor Netty, but I think that some similar bug existed also in Jetty, because with 9.2.x randomly hangs and for 9.4.x don't.

Please check this comment:
https://github.com/spring-cloud/spring-cloud-contract/issues/606#issuecomment-379725684

I've tried, and found out that for me only work with normal WireMock and Jetty 9.4.x.
With WireMock Standalone and Jetty 9.4.x doesn't worked.

Also https is not working with normal WireMock and Jetty 9.4.x.

I can see from the linked ticket that you're using the spring-cloud-wiremock dependency, but are you actually initialising WireMock in your code using the annotation? Or are you using WireMock's rule or server classes?

I'm using the @AutoConfigureWireMock(port = 0) annotation.
And in application.yml setting the url like this:

api:
    my-other-service.url: http://localhost:${wiremock.server.port}

I'm quite puzzled as to why you're seeing this problem at all in that case. You shouldn't have been using WireMock's version of Jetty either way.

Since we have started using WireMock-standalone as our dependency in Spring Cloud Contract, we take the Jetty version from WireMock.

Wiremock with version 9.2.x of Jetty is unusable with reactive threads because it randomly stops hanging.

Well, I just noticed my tests randomly hang while using wiremock-jre8 2.21.0 in Spring Boot 2.1.0.RELEASE application. At first I thought they hang only on Jenkins, but they also randomly hang even in IntelliJ. I just run all tests in package and sometimes everything is OK and sometimes execution hangs leaving such output on console:

2019-03-06 10:26:05.036  INFO 13136 --- [qtp399685190-67] o.e.j.s.handler.ContextHandler.ROOT      : RequestHandlerClass from context returned com.github.tomakehurst.wiremock.http.StubRequestHandler. Normalized mapped under returned 'null'
2019-03-06 10:26:05.043  INFO 13136 --- [qtp399685190-67] WireMock                                 : Request received:
127.0.0.1 - GET /url/goes/here

User-Agent: [ReactorNetty/0.8.2.RELEASE]
Host: [localhost:58294]
Accept-Encoding: [gzip]
Accept: [application/json;charset=UTF-8]
Content-Type: [application/json]



Matched response definition:
{
  "status" : 200,
  "body" : "{\"data\":\"value"}",
  "headers" : {
    "Content-Type" : "application/json"
  }
}

Response:
HTTP/1.1 200
Content-Type: [application/json]
Matched-Stub-Id: [47ef99f4-1788-4a78-9cb1-8610e925b6b1]


2019-03-06 10:26:05.044  INFO 13136 --- [ctor-http-nio-3] <class>      : 200 OK GET http://localhost:58294/url/goes/here took 27ms

Is there any way to fix this issue?

  • unfortunately also upgrading to Spring Boot 2.1.3-RELEASE (ReactorNetty/0.8.5.RELEASE) does not fix the issue.

Whats more, sometimes when problem occur I get something else written on console:

10:54:00.746 [main] DEBUG org.springframework.web.reactive.function.client.ExchangeFunctions - [8bd86c8] HTTP GET http://localhost:60338/url/goes/here
10:54:00.749 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62] Created new pooled channel, now 0 active connections and 2 inactive connections
10:54:00.749 [reactor-http-nio-2] DEBUG reactor.netty.channel.BootstrapHandlers - [id: 0x7beeaa62] Initialized pipeline DefaultChannelPipeline{(BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.decompressor = io.netty.handler.codec.http.HttpContentDecompressor), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
10:54:00.752 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] onStateChange(PooledConnection{channel=[id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338]}, [connected])
10:54:00.753 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338]}}, [configured])
10:54:00.753 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Registering pool release on close event for channel
10:54:00.753 [reactor-http-nio-2] DEBUG reactor.netty.http.client.HttpClientConnect - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Handler is being applied: {uri=http://localhost:60338/url/goes/here, method=GET}
10:54:00.753 [reactor-http-nio-2] DEBUG reactor.netty.channel.ChannelOperationsHandler - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
GET /url/goes/here HTTP/1.1
accept-encoding: gzip
user-agent: ReactorNetty/0.8.5.RELEASE
host: localhost:60338
accept: */*
10:54:00.754 [qtp1248276879-15-acceptor-0@2d84cb86-NetworkTrafficServerConnector@7ea4d397{HTTP/1.1,[http/1.1]}{0.0.0.0:60338}] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ManagedSelector$Accept@7ab86bf7 on ManagedSelector@c3fa05a{STARTED} id=0 keys=0 selected=0 updates=0
10:54:00.754 [qtp1248276879-15-acceptor-0@2d84cb86-NetworkTrafficServerConnector@7ea4d397{HTTP/1.1,[http/1.1]}{0.0.0.0:60338}] DEBUG org.eclipse.jetty.io.ManagedSelector - Wakeup on submit ManagedSelector@c3fa05a{STARTED} id=0 keys=0 selected=0 updates=1
10:54:00.760 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken with none selected
10:54:00.760 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken up from select, 0/0/0 selected
10:54:00.760 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 processing 0 keys, 1 updates
10:54:00.760 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
10:54:00.760 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Accept@7ab86bf7
10:54:00.761 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$Accept@7ab86bf7
10:54:00.761 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
10:54:00.761 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 waiting with 1 keys
10:54:00.761 [reactor-http-nio-2] DEBUG reactor.netty.channel.ChannelOperationsHandler - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Writing object EmptyLastHttpContent
10:54:00.761 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] onStateChange(GET{uri=/url/goes/here, connection=PooledConnection{channel=[id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338]}}, [request_sent])
10:54:00.761 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Channel connected, now 1 active connections and 1 inactive connections
10:54:00.761 [qtp1248276879-20] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$Accept@7ab86bf7
10:54:00.766 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.IdleTimeout - NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}-><null> idle timeout check, elapsed: 4 ms, remaining: 29996 ms
10:54:00.766 [qtp1248276879-20] DEBUG org.eclipse.jetty.server.HttpChannel - new HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0} -> NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@3f4672b3{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
10:54:00.766 [qtp1248276879-20] DEBUG org.eclipse.jetty.server.HttpConnection - New HTTP Connection HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}-><null>
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.AbstractEndPoint - onOpen NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.AbstractConnection - onOpen HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=5/30000}{io=0/0,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.AbstractConnection - fillInterested HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=5/30000}{io=0/0,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.FillInterest - interested FillInterest@27528027{AC.ReadCB@3a76b3ef{HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/0,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}}}
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.ChannelEndPoint - changeInterests p=false 0->1 for NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/1,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94 on ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=0
10:54:00.767 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.ManagedSelector - Wakeup on submit ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=1
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken with none selected
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken up from select, 0/0/1 selected
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 processing 0 keys, 1 updates
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94
10:54:00.767 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - Key interests updated 0 -> 1 on NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 waiting with 1 keys
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken up from select, 1/1/1 selected
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 processing 1 keys, 0 updates
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - selected 1 channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:60338 remote=/127.0.0.1:60352], selector=sun.nio.ch.WindowsSelectorImpl@6eb3cf03, interestOps=1, readyOps=1 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0} 
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - onSelected 1->0 r=true w=false for NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=1/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - task CEP:NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=1/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING
10:54:00.768 [qtp1248276879-20] DEBUG org.eclipse.jetty.io.ManagedSelector - Created NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/1,kio=0,kro=0}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=1/1,p=0} tryExecute EatWhatYouKill@3ff57625/SelectorProducer@1517f633/PRODUCING/p=false/QueuedThreadPool[qtp1248276879]@4a67318f{STARTED,8<=8<=10,i=2,q=0}[ReservedThreadExecutor@4a183d02{s=1/1,p=0}][pc=0,pic=0,pec=0,epc=0]@2019-03-06T10:54:00.7681236+01:00
10:54:00.768 [qtp1248276879-20] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - ran org.eclipse.jetty.io.ManagedSelector$Accept@7ab86bf7
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=0/1,p=0}@4018b5c9 offer EatWhatYouKill@3ff57625/SelectorProducer@1517f633/PRODUCING/p=false/QueuedThreadPool[qtp1248276879]@4a67318f{STARTED,8<=8<=10,i=2,q=0}[ReservedThreadExecutor@4a183d02{s=0/1,p=0}][pc=0,pic=0,pec=0,epc=0]@2019-03-06T10:54:00.7681236+01:00
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=0/1,p=1} startReservedThread p=1
10:54:00.768 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue ReservedThreadExecutor@4a183d02{s=0/1,p=1}@7b270707
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@3ff57625/SelectorProducer@1517f633/IDLE/p=true/QueuedThreadPool[qtp1248276879]@4a67318f{STARTED,8<=8<=10,i=3,q=1}[ReservedThreadExecutor@4a183d02{s=0/1,p=1}][pc=0,pic=0,pec=0,epc=0]@2019-03-06T10:54:00.7681236+01:00 m=EXECUTE_PRODUCE_CONSUME t=CEP:NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=1/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING/BLOCKING
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.FillInterest - fillable FillInterest@27528027{AC.ReadCB@3a76b3ef{HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0}}}
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@3f4672b3{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - filled 143 HeapByteBuffer@574b6d16[p=0,l=143,c=8192,r=143]={<<<GET /url/goes/here...accept: */*\r\n\r\n>>>ent-Encoding: gzi...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=0/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0} filled 143 HeapByteBuffer@574b6d16[p=0,l=143,c=8192,r=143]={<<<GET /url/goes/here...accept: */*\r\n\r\n>>>ent-Encoding: gzi...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=0/30000}{io=1/0,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=0,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@574b6d16[p=0,l=143,c=8192,r=143]={<<<GET /url/goes/here...accept: */*\r\n\r\n>>>ent-Encoding: gzi...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - parseNext s=START HeapByteBuffer@574b6d16[p=0,l=143,c=8192,r=143]={<<<GET /url/goes/here...accept: */*\r\n\r\n>>>ent-Encoding: gzi...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - START --> SPACE1
10:54:00.769 [qtp1248276879-19] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=0/1,p=1}@4018b5c9 task=EatWhatYouKill@3ff57625/SelectorProducer@1517f633/IDLE/p=true/QueuedThreadPool[qtp1248276879]@4a67318f{STARTED,8<=8<=10,i=3,q=1}[ReservedThreadExecutor@4a183d02{s=0/1,p=1}][pc=0,pic=0,pec=0,epc=1]@2019-03-06T10:54:00.7691241+01:00
10:54:00.769 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - SPACE1 --> URI
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - URI --> SPACE2
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - SPACE2 --> REQUEST_VERSION
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - REQUEST_VERSION --> HEADER
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Accept-Encoding: gzip --> IN_VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Accept-Encoding: gzip --> FIELD
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:User-Agent --> VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:User-Agent --> IN_VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:User-Agent --> FIELD
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Host --> VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Host --> IN_VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Host --> FIELD
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Accept: */* --> IN_VALUE
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER:Accept: */* --> FIELD
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - HEADER --> END
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - REQUEST for //localhost:60338/url/goes/here on HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=0}
GET //localhost:60338/url/goes/here HTTP/1.1
Accept-Encoding: gzip
User-Agent: ReactorNetty/0.8.5.RELEASE
Host: localhost:60338
Accept: */*


10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=0} onContentComplete
10:54:00.770 [qtp1248276879-21] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run ReservedThreadExecutor@4a183d02{s=0/1,p=1}@7b270707
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=0} onRequestComplete
10:54:00.770 [qtp1248276879-19] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@3ff57625/SelectorProducer@1517f633/IDLE/p=true/QueuedThreadPool[qtp1248276879]@4a67318f{STARTED,8<=8<=10,i=3,q=1}[ReservedThreadExecutor@4a183d02{s=0/1,p=1}][pc=0,pic=0,pec=0,epc=1]@2019-03-06T10:54:00.7701252+01:00 tryProduce true
10:54:00.770 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 0
10:54:00.770 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpInput - HttpInputOverHTTP@b1c14b7[c=0,q=0,[0]=null,s=STREAM] addContent EOF
10:54:00.770 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
10:54:00.770 [qtp1248276879-21] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=1/1,p=1}@7b270707 started
10:54:00.771 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=1} parsed true HttpParser{s=END,0 of -1}
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - releaseRequestBuffer HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=3}
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=3} handle //localhost:60338/url/goes/here 
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannelState - handling HttpChannelState@3f4672b3{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false}
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=false,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=3} action DISPATCH
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.Server - REQUEST GET /url/goes/here on HttpChannelOverHttp@553904d3{r=1,c=false,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=3}
10:54:00.773 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.handler.ContextHandler - scope null||/url/goes/here @ o.e.j.s.ServletContextHandler@654c1a54{/__admin,null,AVAILABLE}
10:54:00.774 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.handler.gzip.GzipHandler - GzipHandler@89c65d5{STARTED} handle Request(GET //localhost:60338/url/goes/here)@59572bf3 in null
10:54:00.774 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.handler.ContextHandler - scope null||/url/goes/here @ o.e.j.s.ServletContextHandler@265c5d69{/,null,AVAILABLE}
10:54:00.774 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.handler.ContextHandler - context=||/url/goes/here @ o.e.j.s.ServletContextHandler@265c5d69{/,null,AVAILABLE}
10:54:00.774 [qtp1248276879-21] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@4a183d02{s=1/1,p=0}@7b270707 waiting
10:54:00.773 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ChannelEndPoint - Key interests updated 1 -> 0 on NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=//localhost:60338/url/goes/here,age=3}
10:54:00.774 [qtp1248276879-14] DEBUG org.eclipse.jetty.servlet.ServletHandler - servlet |/url/goes/here|null -> com.github.tomakehurst.wiremock.servlet.WireMockHandlerDispatchingServlet-241a0c3a@c0346ce1==com.github.tomakehurst.wiremock.servlet.WireMockHandlerDispatchingServlet,jsp=null,order=-1,inst=true,async=true
10:54:00.774 [qtp1248276879-14] DEBUG org.eclipse.jetty.servlet.ServletHandler - chain=null
10:54:00.776 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannelState - onEof HttpChannelState@3f4672b3{s=DISPATCHED a=NOT_ASYNC i=true r=IDLE w=false}
10:54:00.776 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 waiting with 1 keys
10:54:00.784 [qtp1248276879-14] INFO WireMock - Request received:
127.0.0.1 - GET /url/goes/here

User-Agent: [ReactorNetty/0.8.5.RELEASE]
Host: [localhost:60338]
Accept-Encoding: [gzip]
Accept: [*/*]



Matched response definition:
{
  "status" : 200,
  "bodyFileName" : "contact/1/relation.json",
  "headers" : {
    "Content-Type" : "application/json"
  }
}

Response:
HTTP/1.1 200
Content-Type: [application/json]
Matched-Stub-Id: [433efe16-90ae-4d86-b578-2de31e01a62a]


10:54:00.788 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor - org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor@63923c7 compressing java.util.zip.Deflater@283e130e
10:54:00.788 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - sendResponse info=null content=HeapByteBuffer@36688ca5[p=0,l=10,c=32768,r=10]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\x00>>>\x7f\x08\xA9-\\\x95\xE5\xE97X\xD9X\xA8,1\x99\xF5...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=false committing=true callback=GzipBufferCB@45650338
10:54:00.788 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - COMMIT for /url/goes/here on HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=18}
200 null HTTP/1.1
Content-Type: application/json
Matched-Stub-Id: 433efe16-90ae-4d86-b578-2de31e01a62a
Vary: Accept-Encoding, User-Agent
Content-Encoding: gzip


10:54:00.788 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4edfa019] generate: NEED_HEADER (null,[p=0,l=10,c=32768,r=10],false)@START
10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpGenerator - generateHeaders HTTP/1.1{s=200,h=4,cl=-1} last=false content=HeapByteBuffer@36688ca5[p=0,l=10,c=32768,r=10]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\x00>>>\x7f\x08\xA9-\\\x95\xE5\xE97X\xD9X\xA8,1\x99\xF5...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpGenerator - Content-Type: application/json
Matched-Stub-Id: 433efe16-90ae-4d86-b578-2de31e01a62a
Vary: Accept-Encoding, User-Agent
Content-Encoding: gzip


10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpGenerator - CHUNKED_CONTENT
10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4edfa019] generate: FLUSH ([p=0,l=229,c=8192,r=229],[p=0,l=10,c=32768,r=10],false)@COMMITTED
10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - write: WriteFlusher@137951e{IDLE}->null [HeapByteBuffer@574b6d16[p=0,l=229,c=8192,r=229]={<<<HTTP/1.1 200 OK\r\n...0181114)\r\n\r\nA\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@36688ca5[p=0,l=10,c=32768,r=10]={<<<\x1f\x8b\x08\x00\x00\x00\x00\x00\x00\x00>>>\x7f\x08\xA9-\\\x95\xE5\xE97X\xD9X\xA8,1\x99\xF5...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
10:54:00.789 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{WRITING}->null:IDLE-->WRITING
10:54:00.791 [reactor-http-nio-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Received response (auto-read:false) : [Content-Type=application/json, Matched-Stub-Id=433efe16-90ae-4d86-b578-2de31e01a62a, Vary=Accept-Encoding, User-Agent, Transfer-Encoding=chunked, Server=Jetty(9.4.14.v20181114)]
10:54:00.791 [reactor-http-nio-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] onStateChange(GET{uri=/url/goes/here, connection=PooledConnection{channel=[id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338]}}, [response_received])
10:54:00.791 [reactor-http-nio-2] DEBUG org.springframework.web.reactive.function.client.ExchangeFunctions - [8bd86c8] Response 200 OK
10:54:00.799 [reactor-http-nio-2] DEBUG reactor.netty.channel.FluxReceive - [id: 0x7beeaa62, L:/127.0.0.1:60352 - R:localhost/127.0.0.1:60338] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
10:54:00.800 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - flushed 229 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=W,to=30/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=COMMITTED}]=>HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=30}
10:54:00.801 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - flushed 10 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=W,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=COMMITTED}]=>HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=31}
10:54:00.804 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - Flushed=true written=239 remaining=0 WriteFlusher@137951e{WRITING}->null
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{IDLE}->null:WRITING-->IDLE
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=HTTP/1.1{s=200,h=4,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$CommitCallback@4edfa019] generate: DONE ([p=229,l=229,c=8192,r=0],[p=10,l=10,c=32768,r=0],false)@COMMITTED
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - sendResponse info=null content=HeapByteBuffer@36688ca5[p=0,l=150,c=32768,r=150]={<<<\x8b\xE6\xE5RP\xA8\x06\x11\n\nJ\x99)JV\n\x86...\xA4\xAa\x83x\xB9b\x01\x9f9\xC8\xC9G\x02\x00\x00>>>b\xF6<=WH\xD0\xEch\x1f\xCa\xB8\xF0\xCe\x80\xD3\xD0...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=true committing=false callback=GzipBufferCB@6c263ac3
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$ContentCallback@7af302ae] generate: NEED_CHUNK (null,[p=0,l=150,c=32768,r=150],true)@COMMITTED
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$ContentCallback@7af302ae] generate: FLUSH (null,[p=0,l=150,c=32768,r=150],true)@COMPLETING
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - write: WriteFlusher@137951e{IDLE}->null [HeapByteBuffer@3cac51ef[p=0,l=6,c=1024,r=6]={<<<\r\n96\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@36688ca5[p=0,l=150,c=32768,r=150]={<<<\x8b\xE6\xE5RP\xA8\x06\x11\n\nJ\x99)JV\n\x86...\xA4\xAa\x83x\xB9b\x01\x9f9\xC8\xC9G\x02\x00\x00>>>b\xF6<=WH\xD0\xEch\x1f\xCa\xB8\xF0\xCe\x80\xD3\xD0...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
10:54:00.805 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{WRITING}->null:IDLE-->WRITING
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - flushed 6 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=W,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=COMPLETING}]=>HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=36}
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - flushed 150 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=W,to=0/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=COMPLETING}]=>HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=36}
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - Flushed=true written=156 remaining=0 WriteFlusher@137951e{WRITING}->null
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{IDLE}->null:WRITING-->IDLE
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$ContentCallback@7af302ae] generate: FLUSH (null,[p=150,l=150,c=32768,r=0],true)@COMPLETING
10:54:00.806 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - write: WriteFlusher@137951e{IDLE}->null [HeapByteBuffer@3cac51ef[p=0,l=7,c=1024,r=7]={<<<\r\n0\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}]
10:54:00.807 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{WRITING}->null:IDLE-->WRITING
10:54:00.807 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - flushed 7 NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=W,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=END,0 of -1},g=HttpGenerator@3a501422{s=COMPLETING}]=>HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=37}
10:54:00.807 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - Flushed=true written=7 remaining=0 WriteFlusher@137951e{WRITING}->null
10:54:00.807 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.WriteFlusher - update WriteFlusher@137951e{IDLE}->null:WRITING-->IDLE
10:54:00.807 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - org.eclipse.jetty.server.HttpConnection$SendCallback@2eb71e8f[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$ContentCallback@7af302ae] generate: DONE (null,[p=150,l=150,c=32768,r=0],true)@END
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.Server - handled=true async=false committed=true on HttpChannelOverHttp@553904d3{r=1,c=true,a=DISPATCHED,uri=//localhost:60338/url/goes/here,age=37}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannelState - unhandle HttpChannelState@3f4672b3{s=DISPATCHED a=NOT_ASYNC i=true r=READY w=false}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=true,a=COMPLETING,uri=//localhost:60338/url/goes/here,age=38} action COMPLETE
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannelState - onComplete HttpChannelState@3f4672b3{s=COMPLETING a=NOT_ASYNC i=false r=READY w=false}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - COMPLETE for /url/goes/here written=160
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannelState - recycle HttpChannelState@3f4672b3{s=COMPLETED a=NOT_ASYNC i=false r=READY w=false}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - reset HttpParser{s=END,0 of -1}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - END --> START
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpChannel - HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} handle exit, result COMPLETE
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - filled 0 HeapByteBuffer@574b6d16[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - filled 0 HeapByteBuffer@574b6d16[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} filled 0 HeapByteBuffer@574b6d16[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@574b6d16[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.http.HttpParser - parseNext s=START HeapByteBuffer@574b6d16[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:54:00.808 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} parsed false HttpParser{s=START,0 of -1}
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - releaseRequestBuffer HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.AbstractConnection - fillInterested HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=2/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.FillInterest - interested FillInterest@27528027{AC.ReadCB@3a76b3ef{HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}}}
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ChannelEndPoint - changeInterests p=false 0->1 for NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/1,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94 on ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=0
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.io.ManagedSelector - Wakeup on submit ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=1
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken with none selected
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken up from select, 0/0/1 selected
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 processing 0 keys, 1 updates
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ChannelEndPoint - Key interests updated 0 -> 1 on NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
10:54:00.809 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 waiting with 1 keys
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.server.HttpConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=0/30000}{io=0/1,kio=0,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} onFillable exit HttpChannelState@3f4672b3{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null
10:54:00.809 [qtp1248276879-14] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - ran org.eclipse.jetty.io.ManagedSelector$$Lambda$306/0x00000008002d2040@6ce90bc5
10:54:30.763 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.IdleTimeout - NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=29954/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 29954 ms, remaining: 46 ms
10:54:30.811 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.IdleTimeout - NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 30002 ms, remaining: -2 ms
10:54:30.811 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.IdleTimeout - NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} idle timeout expired
10:54:30.811 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.FillInterest - onFail FillInterest@27528027{AC.ReadCB@3a76b3ef{HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=FI,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}}}
java.util.concurrent.TimeoutException: Idle timeout expired: 30002/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
    at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
10:54:30.811 [Scheduler-1921553024] DEBUG org.eclipse.jetty.http.HttpParser - close HttpParser{s=START,0 of -1}
10:54:30.812 [Scheduler-1921553024] DEBUG org.eclipse.jetty.http.HttpParser - START --> CLOSE
10:54:30.812 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.AbstractConnection - HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=30003/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0} onFillInterestedFailed {}
10:54:30.812 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.AbstractEndPoint - shutdownOutput NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OPEN,fill=-,flush=-,to=30003/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:30.812 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.AbstractConnection - fillInterested HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OSHUT,fill=-,flush=-,to=30003/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.FillInterest - interested FillInterest@27528027{AC.ReadCB@3a76b3ef{HttpConnection@3a76b3ef::NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OSHUT,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}}}
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.ChannelEndPoint - changeInterests p=false 1->1 for NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OSHUT,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94 on ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=0
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.ManagedSelector - Wakeup on submit ManagedSelector@c3fa05a{STARTED} id=0 keys=1 selected=0 updates=1
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken with none selected
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 woken up from select, 0/0/1 selected
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 processing 0 keys, 1 updates
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ChannelEndPoint$1@2b0dad94
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.WriteFlusher - ignored: WriteFlusher@137951e{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30002/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
    at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ChannelEndPoint - Key interests updated 1 -> 1 on NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OSHUT,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
10:54:30.813 [qtp1248276879-19] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.WindowsSelectorImpl@6eb3cf03 waiting with 1 keys
10:54:30.813 [Scheduler-1921553024] DEBUG org.eclipse.jetty.io.AbstractEndPoint - Ignored idle endpoint NetworkTrafficSelectChannelEndPoint@11d22e85{/127.0.0.1:60352<->/127.0.0.1:60338,OSHUT,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3a76b3ef[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3a501422{s=START}]=>HttpChannelOverHttp@553904d3{r=1,c=false,a=IDLE,uri=null,age=0}

I created also jetty issue: https://github.com/eclipse/jetty.project/issues/3436

It seems that in my case tests randomly hang both on Windows and Linux machines. But the difference is that on Linux machine they can correctly time out (and execution of tests is continued) while on Windows they hang forever. This ticket has been referenced: https://github.com/eclipse/jetty.project/issues/2205

@jmayday have you tried upgrading to wiremock-jre8, which has the latest Jetty version?

Yes, as I stated in previous post - I'm already using wiremock-jre8 dependency (in newest version available - 2.21.0)

Sorry, I saw that just after I'd submitted the post, which is why I deleted it!

We've encountered the same problem.
When we use wiremock to test our webflux code, about 1 out of 4 times, it will cause the test to hang and wait indefinitely.

Does anybody have a fix or workaroud for this?

@GideonLiem I'm working on upgrading to the latest Jetty version, hopefully for release in the next few days.

However, I don't know whether this will make any difference. I did a little bit of analysis on this (see https://github.com/tomakehurst/wiremock/issues/1084) and I suspect there may be a race condition in the WebClient handling of pooled connections.

You might find you can work around the problem by turning off connection pooling in your client when testing, or setting a Connection: close header.

@tomakehurst (jetty dev here) out of curiosity, is any of the testing that is hanging dealing with a Client using Transfer-Encoding: chunked?

@joakime Yes, the test linked from #1084 involves Transfer-Encoding: chunked responses

@tomakehurst take a close look at the reading of the input streams when using Transfer-Encoding: chunked, as libraries (such as json) often do not read to the -1/EOF for the stream.
That's a problem when you combine HTTP/1.1 and Transfer-Encoding: chunked as not reading to EOF for the inputstream means the Connection is in an invalid state and cannot be reused for subsequent requests (persistent connections and HTTP/1.1).

The fact that people have pointed out that String works, but JSON does not, seems to indicate that the JSON implementation isn't reading to EOF on a Chunked transfer.

The fact that this is also reported as random fits really well into this Transfer-Encoding: chunked behavior.
Due to networking buffers and whatnot, the final "chunk" could be part of the fill/read sometimes, and sometimes it's in another fill/read pending another read from the application.

Hello,

We had the same issue, and managed to solve it (at least we didn't reproduce since the workaround) via this Transformer, that explicitly adds "Connection: Close" header :

public class ConnectionCloseExtension extends ResponseTransformer {

    @Override
    public Response transform(Request request, Response response, FileSource files, Parameters parameters) {
        return Response.Builder
                .like(response)
                .headers(HttpHeaders.copyOf(response.getHeaders())
                        .plus(new HttpHeader("Connection", "Close")))
                .build();
    }

    @Override
    public String getName() {
        return "ConnectionCloseExtension";
    }
}

(inspired by discussion at https://github.com/tomakehurst/wiremock/issues/485)

Hope this helps going further with the diagnostic.

@GideonLiem I'm working on upgrading to the latest Jetty version, hopefully for release in the next few days.

However, I don't know whether this will make any difference. I did a little bit of analysis on this (see #1084) and I suspect there may be a race condition in the WebClient handling of pooled connections.

You might find you can work around the problem by turning off connection pooling in your client when testing, or setting a Connection: close header.

Thanks for your reply.
We have tried the Connection: close header already but it didn't make any difference.

I've learnt two interesting things about this problem today.

1) Creating a very large, fixed connection pool for the WebClient fixes the test in #1084 e.g.

WebClient client = WebClient.builder()
                    .clientConnector(new ReactorClientHttpConnector(
                            HttpClient.create(ConnectionProvider.fixed("blah", 5000))
                    ))
                    .build();

2) Sending a Content-Length header in WireMock responses (and hence not using chunked transfer encoding - good shout @joakime) also fixes the tests.

I'm going to add a configuration switch or stub element (or both) in the next version of WireMock to specify whether you want responses to be chunk encoded.

I still don't know what this means in terms of root cause. My best guess is that WebClient struggles with chunked responses when it has to close the connection, but there's a chance Jetty is (also) doing something dodgy here.

I still don't know what this means in terms of root cause. My best guess is that WebClient struggles with chunked responses when it has to close the connection, but there's a chance Jetty is (also) doing something dodgy here.

We are actually doing our tests with TestRestTemplate.. so this problem not only occurs for WebClient.

@GideonLiem which underlying HTTP client are you using with TestRestTemplate?

Do you have a failing test project you could share?

@GideonLiem which underlying HTTP client are you using with TestRestTemplate?

Do you have a failing test project you could share?

I am using the standard one for Spring TestRestTemplate. No change in configuration.
I don't have a failing test project available, since the code is part of a big project which is confidential.

OK, so it's probably defaulting to Java's HttpURLConnection as its backend. It might be worth you switching it to use the Apache HTTP client implementation instead. This works in some cases.

Hello guys,
I succeed to create an example project where using the WebClient from Webflux the tests with Wiremock randomly fails.

https://github.com/ati90ati/bugreport-wiremock-webflux-hanging

I'm getting this error:

java.lang.IllegalStateException: Timeout on blocking read for 5000 MILLISECONDS

    at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:117)
    at reactor.core.publisher.Mono.block(Mono.java:1518)
    at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.exchange(DefaultWebTestClient.java:283)
    at org.anagy.bugreport.controller.NumberControllerIntegrationTest.testGetNumbers(NumberControllerIntegrationTest.java:62)

Initially I wanted to have 10 services but I observed that running the tests many times even with one service randomly fails, so at now I've decided to leave 2 services.

Sometimes it fails after 218 tests, sometimes does not fail, sometimes only after a few thousands.

If it's needed I can add / refine the tests to have it more systematic (more tests less upper range) or add more services to have more mocks.

NOTE: The tests in our bigger project failed even using Java 8, even with Java 11.

I've just released WireMock 2.22.0, which includes the ability to switch between chunked encoding and Content-Length. I'd be interesting to see how you get on with this.

Sorry, but I cannot find the version 2.22.0 on the Maven Central repo. Even the wiremock-jre8 what I'm using in the project.

Sometimes it takes a while to sync over from Sonatype. However, I can see it there:
https://repo1.maven.org/maven2/com/github/tomakehurst/wiremock-jre8/2.22.0/

BTW, you can grab releases straight from Sonatype if they're not yet in M2 e.g.
https://oss.sonatype.org/content/groups/public/com/github/tomakehurst/wiremock-jre8/2.22.0/

The sample project https://github.com/ati90ati/bugreport-wiremock-webflux-hanging can be run from command line without failure reported. (been on a loop for the past 15 hours).
I need to be able to run it from an IDE, but that project is rejected as invalid by Eclipse IDE 2018-12, and IntelliJ 2018.3.5 (CE and Ultimate) as uncompilable, so not runnable.
This would allow me to setup some debugging, and hopefully at least point to the specific behavior that is tripping you up.

I've removed the lombok plugin from the sample project so everyone can use it.

Actually now I've run it 3 times and each time it failed for me.

As I observed this random failure occurs more often if the PC (CPU Frequency) used has less performance.

I've get less time failures at a Desktop PC with 3.4Ghz 8 cores, and more often failures with a laptop 2.3Ghz (turbo boost 3.1) 8 core CPU.

For me it's failing even from IDE even from command line.

NOTE: the tests are not run in parallel.

Screenshot from 2019-03-18 19-57-15
Screenshot from 2019-03-18 19-59-11
Screenshot from 2019-03-18 20-00-45

I'll try a little bit later with the wiremock 2.22.0 version and Content-Length, but on the Maven Central I still cannot see the new version (I'll use the suggested from @tomakehurst ):

image

@ati90ati mvnrepository.com is not a great site, its often wrong (not up to date, missing entries, pointing to entries at repositories not part of the maven repository system, and generally has bad data all around)

Use the official search for maven central.
https://search.maven.org/search?q=a:wiremock

https://search.maven.org/artifact/com.github.tomakehurst/wiremock/2.22.0/pom

Hello guys, you are really awesome!

I've increased Wiremock version to 2.22.0 and used the Options.ChunkedEncodingPolicy.NEVER or Options.ChunkedEncodingPolicy.BODY_FILE new options and no more hanging in tests.

I've tested with 300.000 request to Wiremock and no one is remains hanging.
Before from 5000 calls for me approx 2 remains in hanging state.
I've rechecked it with the Options.ChunkedEncodingPolicy.ALWAYS option and it again started to hang.

I've crated a branch to show my solution, maybe I'll merge it in the future,

I've also checked the chunked encoding policy (NEVER, BODY_FILE) setting in our bigger project and seems there also to be ok, no tests hanging util now.
We can finally re-enable our integration test :smile: !

I've created a WiremockConfig class for just testing purposes but I'm using the spring-cloud-contract-wiremock.
Maybe if @tomakehurst have a little bit of time can you help to find the best solution how to put Options using spring-cloud-contract-wiremock?

Thank you really much for your help! It is really appreciated!

Hello guys, you are really awesome!

I've increased Wiremock version to 2.22.0 and used the Options.ChunkedEncodingPolicy.NEVER or Options.ChunkedEncodingPolicy.BODY_FILE new options and no more hanging in tests.

I've tested with 300.000 request to Wiremock and no one is remains hanging.
Before from 5000 calls for me approx 2 remains in hanging state.
I've rechecked it with the Options.ChunkedEncodingPolicy.ALWAYS option and it again started to hang.

I've crated a branch to show my solution, maybe I'll merge it in the future,

I've also checked the chunked encoding policy (NEVER, BODY_FILE) setting in our bigger project and seems there also to be ok, no tests hanging util now.
We can finally re-enable our integration test 😄 !

I've created a WiremockConfig class for just testing purposes but I'm using the spring-cloud-contract-wiremock.
Maybe if @tomakehurst have a little bit of time can you help to find the best solution how to put Options using spring-cloud-contract-wiremock?

Thank you really much for your help! It is really appreciated!

Do you have an example project to see this working with the options you mentioned?

@ati90ati marvellous, glad we're making some progress finally! Thanks for sharing your test results.

For help getting this into Spring Cloud Contract I think we need to hail @marcingrzejszczak

@GideonLiem as I posted in my comments above there are a sample project under:
https://github.com/ati90ati/bugreport-wiremock-webflux-hanging
There is a branch named fix-hanging there you can find my dirty quick solution.
As I mentioned maybe I'll merge that branch in the master, so future visitors will be able to find the fix there.

Sure, can you file an issue in Spring Cloud Contract directly?

The bug is in the expectations on the server side.
Since the JSON parser is setup to read from the Request.inputStream/reader, it doesn't handle situations like Chunked transfer-encoding properly.
The server side should read the entire stream, what if the content submitted was {}{} ? would it read the second json? should it throw an error? (the most common response for this would be to respond with a status code 400 Bad Request)
From Jetty's point of view, it cannot know when the application is finished with the stream.

What happens in the failing cases with chunked transfer encoding is that the chunks arrive via the network buffers and the application (the json parser in this specific case) reads only to the final closing } and stops.

If the network buffers happen to contain the final closing chunk 0\r\n\r\n then it works.
But if the network buffers that have been read to satisfy the request.inputStream has only read active chunks (but not yet the closing chunk) then the stream is still open, waiting for the application to issue another read of the connection. (this is especially aggravated if using Async I/O features of Servlet 3.1)
If you don't finish reading, this is an "unconsumed input" scenario, and as such the HTTP/1.1 persistent connection is now in an unsatisfied state on the server side (you have a request that hasn't been finished being read, so that connection cannot be reused for another request).
The combination of the server side not reading till EOF (aka the final closing chunk) and the HTTP Client not realizing this state making the followup request that the HTTP Client is sending on that same connection not able to be processed by Jetty. Hence the timeout you see.

Proper REST endpoints will read the entire stream and if there is anything amiss about the content (eg: there is non-whitespace after the first JSON body content) it will fail the request.

Thanks for your analysis @joakime.

One thing I'm not totally clear about - you're saying the problem is on the server side due to the JSON parser, but in the test linked to from #1084 the server is only handling GETs and isn't doing any JSON parsing. Since switching away from chunked encoding for responses fixes the problem, it seems somewhat unlikely to me that server-side request handling is the problem.

Perhaps you were referring to the JSON parsing on the client?

The solution that brought the fix for us was writing our own extension. After that we hhad no more problems.

public class CustomResponseTransformExtension extends ResponseTransformer {
    @Override
    public Response transform(Request request, Response response, FileSource files, Parameters parameters) {
        return Response.Builder
                .like(response)
                .headers(HttpHeaders.copyOf(response.getHeaders())
                        .plus(new HttpHeader("Connection", "close"),
                                new HttpHeader("Content-Encoding", "none")))
                .build();
    }

    @Override
    public String getName() {
        return "ConnectionCloseExtension";
    }
}

And using the extension in our Spock integration test:

@Shared
@ClassRule
WireMockClassRule wireMockRule = new WireMockClassRule(WireMockConfiguration.wireMockConfig()
        .extensions(CustomResponseTransformExtension).port(WIREMOCK_PORT))

@GideonLiem so it turned out that disabling chunked encoding wasn't sufficient?

@tomakehurst Yes. We tried that as well.. and we still got the same problems.

@GideonLiem could you share a test project that illustrates this? In the project linked to from this thread, disabling chunked response encoding fixed it, so I'm not sure how to go about replicating now.

Unfortunately I don't have a sample test project with isolated problem available. But I thought it was fair to at least share our solution ;-)

We've seen disabling of connection reuse work in the past, but I haven't been able to isolate the circumstances in which it's the correct solution.

Also, it shouldn't ever be necessary (you'd never consider disabling it in a production system). It either indicates a server or client bug IMO, but without a reliable failing test I can't investigate which it is.

Even a wireshark/tcpdump of the failing scenario would be useful.

I think this issue is fixed by https://github.com/netty/netty/pull/8922

I think this issue is fixed by netty/netty#8922

I'm still getting the same error even with the netty/netty#8922 fix included in Netty 4.1.34.Final on the classpath.

Really?
With netty 4.1.34, this problem no longer reproduces.
@ati90ati 's example project (https://github.com/ati90ati/bugreport-wiremock-webflux-hanging)

@tomakehurst WebFlux/reactor-netty connection pooling is brittle, especially in combination with Jetty 9.4 server. We had this setup in production and it did not work. In particular, reactor-netty does not handle racy close(from server)/write (from client) scenario well - it actually does not handle it at all (reactor/reactor-netty#612). If you have just the right workload, you can run in racy close(from server)/write (from client) scenario very often.
I think Jetty 9.4 likes to kill idle connections after 30 seconds by default while it seems like reactor-netty would love to have idle connections around forever.

@timpeeters Have you tried Jetty client based WebFlux client from SB 2.1/Spring 5.1?

@kimec Yes, we are running SB 2.1.4.RELEASE which depends on Spring 5.1.6.RELEASE. Dependency tree looks clean (no version conflicts) and the latest WireMock version 2.23.2.

However, I do need to add that we run Spring Cloud Gateway on top of SB. We mainly run into this issue during integration tests using WireMock as a stub for our backend services.

@timpeeters I see. Have you also tried to configure your WebFlux client connecting to WireMock to use JettyClientHttpConnector?

@kimec no, we do not use the JettyClientHttpConnector. We use the default WebFlux client created by Spring Cloud Gateway in GatewayAutoConfiguration > NettyConfiguration > httpClient().
It does not use the Jetty connector.

I think this issue is fixed by netty/netty#8922

Yessss!!! A was getting at least one case of WebClient&WireMock hanging whenever I ran our integration test suite, and with a Spring Boot update from 2.1.3.RELEASE to 2.1.4.RELEASE (which entails netty 4.1.33.Final -> 4.1.34.Final), the problem is gone! :-)

@oberlies that's great news, thanks for sharing!

I can confirm that this bug has two solutions now.

An example for each solution can be found under different branches in this project: https://github.com/ati90ati/bugreport-wiremock-webflux-hanging

Solution 1:
With Spring Boot 2.1.4.RELEASE the problem disappears.

Solution 2:
With using at least Wiremock 2.22.0 version and the wiremock options ChunkedEncodingPolicy.BODY_FILE the problem also can be fixed.

Solution 2 Method 1 (with configuring a new Options bean):

This solution with chunked body is described here: https://github.com/tomakehurst/wiremock/issues/914#issuecomment-474262581
Example config with static port:

@Configuration
public class WiremockConfig {
    @Bean
    public Options wiremockOptions() {
        final com.github.tomakehurst.wiremock.core.WireMockConfiguration wireMockConfiguration = WireMockSpring
                .options();

        wireMockConfiguration.useChunkedTransferEncoding(Options.ChunkedEncodingPolicy.BODY_FILE);
        wireMockConfiguration.port(12345);

        return wireMockConfiguration;
    }
}

Solution 2 Method 2 (with using WireMockConfigurationCustomizer from Spring Cloud Contract):

@Configuration
public class WiremockConfig {
    @Bean
    public WireMockConfigurationCustomizer wireMockConfigurationCustomizer() {
        return config -> config.useChunkedTransferEncoding(Options.ChunkedEncodingPolicy.BODY_FILE);
    }
}

So, the issue can be closed.

@ati90ati thanks for sharing

does the Flux stream close automatically and frees the thread for the next call in this case
}).flatMapMany(sess -> { InputStreamReader inputStreamReader = new InputStreamReader(sess.getStdout()); BufferedReader bufferedReader = new BufferedReader(inputStreamReader); connectionMap.put(inputStream, inputStreamReader); connectionMap.put(bufferedR, bufferedReader); Flux<Long> interval = Flux.interval(Duration.ofMillis(50)); return stream ? interval.map(i -> { try { return bufferedReader.ready() ? bufferedReader.readLine() : ""; } catch (Exception ignore) { } return ""; }) : Flux.zip(Flux.fromStream(bufferedReader.lines()), interval, (key, value) -> key); }).doOnTerminate(runnable).doOnCancel(runnable).doOnComplete(runnable).doOnError(throwable -> {
i see the application is hanging on opening multiple sessions

I'm using compile group: 'com.github.tomakehurst', name: 'wiremock-jre8', version: '2.26.3' which contains dependency to jetty 9.4.20. I have this problem too: my tests randomly hang. When I turn off wiremock (not start it) in my tests everything runs without any problem (thus tests don't pass but that is obviuos)
Spring Boot WebFlux 2.2.5

@mkopylec are you using a version of Netty newer than 4.1.34 - the one that fixes the bug causing this?

If so, please can you provide a failing test project.

I'm using Netty 4.1.43, I can't provide a test project cause it is an internal company project :(

Not a lot I can do about it then I'm afraid 🤷‍♂️

Was this page helpful?
0 / 5 - 0 ratings

Related issues

jbadeau picture jbadeau  ·  18Comments

khanh-nguyen picture khanh-nguyen  ·  18Comments

AnCh7 picture AnCh7  ·  15Comments

asarkar picture asarkar  ·  19Comments

arokhmistrov picture arokhmistrov  ·  23Comments