Hi All: I have an app that exhibits a problem that I was able to reproduce using AsyncReverseProxyExample.
To do so, I only changed a few of its IO reactor configuration parameters. These changes may seem silly but that is what I had to do to reproduce my use-case with the example. The biggest change to the example is that I had to comment out all of the System.out.println() calls (except the ones on start up) which seems to affect speed just enough for my setup. Steps to reproduce are further below. In org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(), the call: final int readyCount = this.selector.select(this.selectTimeoutMillis); returns 0, the processEvents() is never called, and the callbacks in my proxy never see data in the exchange state's output buffer. Eventually, a timeout is detected and logged. With my app, but not the example, I can leave Log4j logging enabled, and reproduce the problem which I describe here. You can think of these log entries are equal to the ones from the example since my code is based on the example with extra bits here and there. What I think happens based on the log: - The proxy receives a request (1) and passes it to the origin server (7-8). - The origin server replies OK at (9) - The IncomingExchangeHandler checks to see if there is any data and there is not (14) - The OutgoingExchangeHandler reads the data from the origin serverand puts it in the exchange object's output buffer (outBuf) in (15-17) - The server-dispatch-1 thread wakes up in SingleCoreIOReactor.doExecute() and sets readyCount to 0. The processEvents() method is never called. The IncomingExchangeHandler's available() method is never called. No data is returned to the client for that request. 1. 2018-11-09 12:31:29,077 DEBUG [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [client -> proxy] GET /temp/one-byte.txt 2. 2018-11-09 12:31:29,077 DEBUG [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.localhost] [client -> proxy] 0000075E GET /temp/one-byte.txt 3. 2018-11-09 12:31:29,078 DEBUG [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.localhost] [proxy -> origin] 0000075E request connection to http://localhost:8080 4. 2018-11-09 12:31:29,078 DEBUG [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [proxy -> origin] connection leased http://localhost:8080 5. 2018-11-09 12:31:29,082 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.localhost] [proxy -> origin] 0000075E connection leased 6. 2018-11-09 12:31:29,082 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy -> origin] Rewriting request GET http://localhost:9093/temp/one-byte.txt -> http://localhost:8080/one-byte.txt 7. 2018-11-09 12:31:29,082 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy -> origin] 0000075E GET /one-byte.txt 8. 2018-11-09 12:31:29,082 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [proxy -> origin] GET /one-byte.txt 9. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [proxy <- origin] status 200 OK 10. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy <- origin] 0000075E consumeResponse() status 200 11. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [client <- proxy] status 200 OK 12. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.localhost] [client <- proxy] 0000075E produce output 13. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [client <- proxy] 0000075E consumeResponse() status 200 14. 2018-11-09 12:31:29,084 DEBUG [server-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.IncomingExchangeHandler.localhost] [client <- proxy] 0000075E output available: 0 15. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy <- origin] 0000075E 1 bytes received 16. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy -> origin] 0000075E input capacity: 4095 17. 2018-11-09 12:31:29,084 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy.OutgoingExchangeHandler.localhost] [proxy <- origin] 0000075E streamEnd() end of input 18. 2018-11-09 12:31:29,085 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [proxy <- origin] connection 127.0.0.1:60845->127.0.0.1:8080 kept alive 19. 2018-11-09 12:31:29,085 DEBUG [requester-dispatch-1][com.rs.seagull.httpmonitor.NHttpReverseProxy] [proxy -> origin] connection released http://localhost:8080; total kept alive: 0; total allocated: 0 of 100 What JMeter reports is: *Response message: Non HTTP response message: Premature end of Content-Length delimited message body (expected: 1; received: 0* Somehow, it seems that the requester-dispatch-1 thread puts data in the outBuf that is never seen by server-dispatch-1 because the select call returns with 0. The stars must be aligned just so to reproduce this. Sometime I can reproduce it after 300 requests, sometimes after 4000 requests. Steps to reproduce: - To set up an origin server, install Node.js https://nodejs.org/en/ - Install the Node.js http-server module like this: npm install http-server -g - Open a command line and 'cd \temp' and run 'http-server -p 8080' This starts a simple HTTP server and serves files in the current folder on port 8080. - Create a 1 byte file called 'one-byte.txt' and put a single character in it; save this file to \temp - Make sure you can GET this file in Postman or Curl http://localhost:8080/one-byte.txt - You now have an origin server for the simplest file. - Import the Java code https://pastebin.com/JuRQU950 which is a version of AsyncReverseProxyExample called AsyncReverseProxyExampleNoLogging without System.println() and silly IO reactor settings that manage to reproduce my set up. - Run AsyncReverseProxyExampleNoLogging with the arguments: localhost:8080 9094 - Your proxy to 8080 is now up on 9490 - Make sure you can GET this file in Postman or Curl through the proxy: http://localhost:9094/one-byte.txt - Install Apache JMeter 5 https://jmeter.apache.org/download_jmeter.cgi - Copy the JMeter configuration https://pastebin.com/b5Vqu689 to OneByteHttpCore.jmx - You can run JMeter from the command line or its UI. Unfortuntely running it from the UI does not give you all the error information you need but it is the recommended way to run a test if you want to run it for a long time. Adjust the following to your paths: For Windows: rmdir /q/s c:\test\jmeter-OneByteHttpCore & del /F c:\test\OneByteHttpCore.csv & jmeter -n -t C:\Users\ggregory\Downloads\OneByteHttpCore.jmx -l c:\test\OneByteHttpCore.csv -e -o c:\test\jmeter-OneByteHttpCore - To start the JMeter UI, from its bin folder; on Windows you can just double click on jmeter.bat. - In the JMeter UI, open the OneByteHttpCore.jmx and click on the Start button (green arrow) You may not always get the failure. Here is the one I got: This is what I have in the Eclipse Console running AsyncReverseProxyExampleNoLogging: Reverse proxy to http://localhost:8080 Listening on port 9094 java.net.SocketTimeoutException: 10 SECONDS at org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTimeoutExceptionFactory.java:50) at org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeout(AbstractHttp1StreamDuplexer.java:418) at org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout(AbstractHttp1IOEventHandler.java:81) at org.apache.hc.core5.http.impl.nio.ServerHttp1IOEventHandler.timeout(ServerHttp1IOEventHandler.java:40) at org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDataChannel.java:184) at org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChannel.java:67) at org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCoreIOReactor.java:232) at org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannels(SingleCoreIOReactor.java:165) at org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127) at org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:80) at org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44) at java.lang.Thread.run(Thread.java:745) JMeter: Request number 3630 --- Request Body --- GET http://localhost:9094/one-byte.txt GET data: [no cookies] --- Sampler Result --- Thread Name: Thread Group 1-1 Sample Start: 2018-11-11 16:30:54 MST Load time: 10019 Connect Time: 7 Latency: 0 Size in bytes: 1330 Sent bytes:0 Headers size in bytes: 0 Body size in bytes: 1330 Sample Count: 1 Error Count: 1 Data type ("text"|"bin"|""): text Response code: Non HTTP response code: org.apache.http.ConnectionClosedException *Response message: Non HTTP response message: Premature end of Content-Length delimited message body (expected: 1; received: 0* HTTPSampleResult fields: ContentType: text/plain; charset=UTF-8 DataEncoding: UTF-8 --- Response Data --- This shows the internals of JMeter that use HttpClient 4: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 1; received: 0 at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178) at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135) at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:148) at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.readResponse(HTTPSamplerBase.java:1856) at org.apache.jmeter.protocol.http.sampler.HTTPAbstractImpl.readResponse(HTTPAbstractImpl.java:468) at org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:589) at org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:67) at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1231) at org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1220) at org.apache.jmeter.threads.JMeterThread.doSampling(JMeterThread.java:622) at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:546) at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:486) at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:253) at java.base/java.lang.Thread.run(Unknown Source) --- I am looking for guidance here. I suppose this could be a bug in the example, or in the core, or that the example could/should be adjusted to avoid this unfortunate sequence. Again, the IO rector parameters I used are only to demonstrate the problem. In my set up, I use the default select timeout of 1 second and reactor IO thread counts of 2. Thank you, Gary
