On Fri, 2014-09-19 at 11:31 +0200, Tobias Bieniek wrote: > Hi Oleg, > > we've finally managed to freeze the log file after the spinning was > first detected and this is the output of the spinning session: > > https://gist.github.com/Turbo87/db7365bac349c7e56690 > > Tobias >
Thanks Good Lord it happens over a plain connection as TLS/SSL encryption layer makes everything more complex by an order of magnitude. There appears to be multiple coinciding issues that lead to the spin. Firstly, something must have gone sideways while reading incoming data on a persistent connection. --- consumeInput : http-incoming-33955: Consume input submitResponse : http-incoming-33955: HTTP/1.1 500 Internal Server Error --- The handler attempts to send back a 500 status back to the client. Given that mo data appears to have been received in the first place, this might actually be be a bug. The problem is I cannot see the exception logged, which is likely a problem with your application code. It would help a lot to find out what exactly caused the 500 status. Secondly, the protocol handler writes out the message to the session buffer but leaves the underlying channel open until the buffer is fully flushed. --- produceOutput : http-incoming-33955: Produce output close : http-incoming-33955: Close connection --- For some reason nothing gets ever flushed and no I/O exception is thrown. The session spins. I do not understand two things here: (1) why connection #close keeps on getting called? It does not seem to match the 4.3.2 source code. (2) why there is no I/O exception if the underlying channel can no longer accept output? I'll need to digest all this. In the meantime can I ask you the following? Is there a chance you could find out what kind of exception (with the full stack trace) caused the initial 500 status and triggered the whole sequence of events. Could you please confirm that you are _really_ using version 4.3.2? Could you also consider upgrading to the latest snapshot of the 4.3.x branch? http://svn.apache.org/repos/asf/httpcomponents/httpcore/branches/4.3.x/ And of course, a reproducer that I could run locally would be awesome. Oleg > > > 2014-09-16 13:36 GMT+02:00 Oleg Kalnichevski <[email protected]>: > > On Tue, 2014-09-16 at 13:08 +0200, Tobias Bieniek wrote: > >> > If you do not want me to make wild guesses, please make available a > >> > _complete_ context / header log of the session. > >> > >> I'll see what I can do. The problem is that with our production > >> traffic on the server the log files are rotating very fast and it is > >> hard to catch a log of one entire request session, but without the > >> production traffic the problem doesn't seem to be reproducible. > >> > >> Since yesterday more of the I/O workers have started spinning again > >> and are cluttering the log files now. > >> > >> I know it is wild guessing, but could the problem be related to > >> streaming file downloads over SSL that are cancelled on the client > >> side? It appears as if the SSL session might be staying in the CLOSING > >> state forever with some data in the buffer but unable to flush it out. > >> > >> Tobias > >> > > > > Tobias > > > > This is quite likely to be related to abnormal SSL connection > > termination causing the I/O session to spin while trying to complete SSL > > session handshake. But I need to see the session log to be 100% sure. > > > > Oleg > > > > > > > > --------------------------------------------------------------------- > > To unsubscribe, e-mail: [email protected] > > For additional commands, e-mail: [email protected] > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
