httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Plüm, Rüdiger, Vodafone Group <ruediger.pl...@vodafone.com>
Subject RE: HTTPS connections lock-up with 2.4.18
Date Thu, 04 Feb 2016 07:50:15 GMT
Can you also post the backtrace when the server is hanging in the read?

Regards

Rüdiger

> -----Original Message-----
> From: Plüm, Rüdiger, Vodafone Group
> Sent: Donnerstag, 4. Februar 2016 08:39
> To: dev@httpd.apache.org
> Subject: RE: HTTPS connections lock-up with 2.4.18
> 
> Thanks. Which version of APR / APR-UTIL are you using?
> 
> Regards
> 
> Rüdiger
> 
> > -----Original Message-----
> > From: Joachim Achtzehnter [mailto:joachim@kraut.ca]
> > Sent: Donnerstag, 4. Februar 2016 03:56
> > To: dev@httpd.apache.org
> > Subject: Re: HTTPS connections lock-up with 2.4.18
> >
> > Perhaps, there is an important clue this time. When I retrieve a file
> > that works we see the following log messages near the time when the
> > reply is being written:
> >
> > > [Wed Feb 03 18:13:51.402289 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 271 bytes
> > > [Wed Feb 03 18:13:51.402463 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 4020 bytes
> > > [Wed Feb 03 18:13:51.402515 2016] [core:notice] [pid 1676] [client
> > 205.159.216.185:55978] core_output_filter: sent 4291 on 4291 bytes
> > > [Wed Feb 03 18:13:51.402527 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOS
> > > [Wed Feb 03 18:13:51.402581 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOR
> > > [Wed Feb 03 18:13:51.406356 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9db96d8] in: read 5 bytes
> > > [Wed Feb 03 18:13:51.406375 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9db96d8] in: read 26 bytes
> > > [Wed Feb 03 18:13:51.406392 2016] [http:notice] [pid 1676] (70014)End
> of
> > file found: [client 205.159.216.185:55978] check_pipeline: no data
> > > [Wed Feb 03 18:13:51.406476 2016] [http:notice] [pid 1676] (70014)End
> of
> > file found: [client 205.159.216.185:55978] check_pipeline:
> > data_in_input_filters = 0
> > > [Wed Feb 03 18:13:51.406492 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > > [Wed Feb 03 18:13:51.406591 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA FLUSH
> > > [Wed Feb 03 18:13:51.406613 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: METADATA EOC
> > > [Wed Feb 03 18:13:51.406624 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: pass 31 bytes
> > > [Wed Feb 03 18:13:51.406673 2016] [ssl:notice] [pid 1676] [client
> > 205.159.216.185:55978] bio[9dabd50] out: FLUSH
> > > [Wed Feb 03 18:13:51.406723 2016] [core:notice] [pid 1676] [client
> > 205.159.216.185:55978] core_output_filter: sent 31 on 31 bytes
> > > [Wed Feb 03 18:13:51.406735 2016] [ssl:debug] [pid 1676]
> > ssl_engine_io.c(1029): [client 205.159.216.185:55978] AH02001:
> Connection
> > closed to child 0 with standard shutdown (server localhost:443)
> >
> > Notice the call to check_pipeline returns quickly. Now the same part of
> > the log for the failing file:
> >
> > > [Wed Feb 03 17:56:55.424124 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: pass 271 bytes
> > > [Wed Feb 03 17:56:55.424192 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: pass 1727 bytes
> > > [Wed Feb 03 17:56:55.424223 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA EOS
> > > [Wed Feb 03 17:56:55.424235 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA EOR
> > > [Wed Feb 03 18:09:56.652288 2016] [http:notice] [pid 1663]
> (11)Resource
> > temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
> no
> > data
> > > [Wed Feb 03 18:09:56.652376 2016] [http:notice] [pid 1663]
> (11)Resource
> > temporarily unavailable: [client 205.159.216.185:55962] check_pipeline:
> > data_in_input_filters = 0
> > > [Wed Feb 03 18:09:56.652398 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
> > > [Wed Feb 03 18:09:56.652444 2016] [core:notice] [pid 1663] [client
> > 205.159.216.185:55962] core_output_filter: sent 1998 on 1998 bytes
> > > [Wed Feb 03 18:09:56.652510 2016] [ssl:info] [pid 1663] (70014)End of
> > file found: [client 205.159.216.185:55962] AH01991: SSL input filter
> read
> > failed.
> > > [Wed Feb 03 18:09:56.652519 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA FLUSH
> > > [Wed Feb 03 18:09:56.652525 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: METADATA EOC
> > > [Wed Feb 03 18:09:56.652545 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: pass 31 bytes
> > > [Wed Feb 03 18:09:56.652553 2016] [ssl:notice] [pid 1663] [client
> > 205.159.216.185:55962] bio[8158d50] out: FLUSH
> > > [Wed Feb 03 18:09:56.652568 2016] [core:notice] [pid 1663] [client
> > 205.159.216.185:55962] core_output_filter: sent 31 on 31 bytes
> > > [Wed Feb 03 18:09:56.652576 2016] [ssl:debug] [pid 1663]
> > ssl_engine_io.c(1029): [client 205.159.216.185:55962] AH02001:
> Connection
> > closed to child 0 with standard shutdown (server localhost:443)
> >
> > The check_pipeline call only returns when I kill the client. I first
> > noticed this in the debugger where httpd was sitting in a blocking read.
> > Somehow, in this case a blocking read is done instead of a non-blocking
> > read.
> >
> > To be specific, it ended up in the do/while loop that calls read in
> > function apr_socket_recv (sendrecv.c), called from socket_bucket_read in
> > apr_buckets_socket.c, called from ap_core_input_filter in
> > core_filters.c. The block parameter was APR_NONBLOCK_READ, but this
> > didn't stop the lower-level functions from blocking, somehow. The
> > apr_socket_recv function seems to do the select version of reading based
> > on the APR_INCOMPLETE_READ flag in sock->options.
> >
> > By the way, to answer an earlier question, this is a prefork server with
> > separate processes, not threaded.
> >
> > Thanks,
> >
> > Joachim
> >
> >
> > On 2016-02-03 8:06, Yann Ylavic wrote:
> > > On Wed, Feb 3, 2016 at 4:53 PM, Yann Ylavic <ylavic.dev@gmail.com>
> > wrote:
> > >>
> > >> I suggest you use the attached patch instead (replacing any previous
> > >> one), so that we log the output path taken when mod_ssl is in the
> > >> place.
> > >
> > > Forgot about the casting issue (SSL_get_app_data) with your
> compiler...
> > > This v5 (attached) should compile fine.
> > >
> > >>
> > >>> And maybe take network traces on the server side?
> > >>
> > >> That would be really nice too.
> > >>
> > >>>
> > >>> Thanks,
> > >>> Yann.
> >
> > --
> > joachim@kraut.ca http://www.kraut.ca
Mime
View raw message