On 2016-02-01 4:19, Yann Ylavic wrote:
This restores the previous (pre 2.4.18) behaviour of flushing output
on every read, which I'd prefer to avoid, if possible.
Could you provide some network capture (tcpdump, wireshark...) when
the lock-up occurs?
I'll work on capturing this, in the meantime I tried your patch below.
Is EnableMMap somehow always involded here (you mention it in the
original message)?
I had mentioned this because we have some requests passed through a
custom handler, not serviced from the filesystem, and these never seem
to exhibit the problem. All the failing requests I've debugged were
serviced by Apache itself directly from the filesystem, and Apache used
mmap for this. I can try disabling mmap to see if the problem goes away.
That would help to build a reproducer...
Maybe the attached patch could be "enough" to fix the issue?
It does not. The behaviour is exactly as with the original 2.4.18
version. Note, that the problem is reproduced consistently. Requests
that get stuck always get stuck every time I try to repeat it. If this
was somehow related to renegotiation, would it not be more variable?
This patch also includes some minimal logging (level NOTICE) to help
diagnose in case of lock-up, still.
The log output for a failing request is attached.
Thanks,
Joachim
--
joac...@kraut.ca http://www.kraut.ca
[Mon Feb 01 12:30:12.289534 2016] [ssl:info] [pid 2436] [client
205.159.216.185:47084] AH01964: Connection to child 0 established (server
localhost:443)
[Mon Feb 01 12:30:12.289915 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.290009 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.290058 2016] [ssl:debug] [pid 2436]
ssl_engine_kernel.c(2103): [client 205.159.216.185:47084] AH02044: No matching
SSL virtual host for servername na171 found (using default/first virtual host)
[Mon Feb 01 12:30:12.295817 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] out: passing 1004 bytes
[Mon Feb 01 12:30:12.295897 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.300456 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302417 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302429 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302542 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302554 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.302656 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] out: passing 51 bytes
[Mon Feb 01 12:30:12.302757 2016] [socache_shmcb:debug] [pid 2436]
mod_socache_shmcb.c(491): AH00831: socache_shmcb_store (0x9e -> subcache 30)
[Mon Feb 01 12:30:12.302775 2016] [socache_shmcb:debug] [pid 2436]
mod_socache_shmcb.c(845): AH00847: insert happened at idx=0, data=(0:32)
[Mon Feb 01 12:30:12.302782 2016] [socache_shmcb:debug] [pid 2436]
mod_socache_shmcb.c(850): AH00848: finished insert, subcache:
idx_pos/idx_used=0/1, data_pos/data_used=0/189
[Mon Feb 01 12:30:12.302838 2016] [socache_shmcb:debug] [pid 2436]
mod_socache_shmcb.c(512): AH00834: leaving socache_shmcb_store successfully
[Mon Feb 01 12:30:12.302883 2016] [ssl:debug] [pid 2436]
ssl_engine_kernel.c(2023): [client 205.159.216.185:47084] AH02041: Protocol:
TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
[Mon Feb 01 12:30:12.302938 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.303955 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
[Mon Feb 01 12:30:12.304074 2016] [ssl:debug] [pid 2436]
ssl_engine_kernel.c(354): [client 205.159.216.185:47084] AH02034: Initial
(No.1) HTTPS request received for child 0 (server localhost:443)
[Mon Feb 01 12:30:12.304248 2016] [authz_core:debug] [pid 2436]
mod_authz_core.c(809): [client 205.159.216.185:47084] AH01626: authorization
result of Require all granted: granted
[Mon Feb 01 12:30:12.304259 2016] [authz_core:debug] [pid 2436]
mod_authz_core.c(809): [client 205.159.216.185:47084] AH01626: authorization
result of <RequireAny>: granted
[Mon Feb 01 12:30:12.304398 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] out: passing 271 bytes
[Mon Feb 01 12:30:12.304509 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] out: passing 1727 bytes
[Mon Feb 01 12:30:12.304568 2016] [ssl:notice] [pid 2436] [client
205.159.216.185:47084] bio[9813d50] in: not flushing
