Hi Yann,Attached is file "ssl_log-v3.txt" with the log messages seen when using your v3 patch. The other two files are the corresponding Wireshark traces, collected on the client-side where Firefox was trying to retrieve the file.
While exploring a final fix for this, can I ask for your opinion about the following work-around we currently rely on until there is an official fix. We continue to use Apache 2.4.18, but have replaced mod_ssl.so with the one from Apache 2.4.12. Is this likely to be safe? or do you not recommend mixing versions?
Thanks, Joachim On 2016-02-02 4:46, Yann Ylavic wrote:
Back to the list... (Attaching the logs provided privately by Joachim, with the client IP - the only possible sensitive informatition - replaced with XXX.XXX.XXX.XXX). On Tue, Feb 2, 2016 at 11:08 AM, Joachim Achtzehnter <joac...@kraut.ca> wrote:Applied you patch, built, installed, and then tested. There was no improvement. I've attached the log messages as "ssl_log-v2.txt". The I changed "#if 0" to #if 1" and it is still not working. Th elog messages for this case are attached as "ssl_log-v2-if1.txt".These logs show that the flush on read is *not* necessary (at least from mod_ssl POV), provided each write is flushed during handshake. Unfortunately OpenSSL does not seem to do it by itself: there is no "bio[%pp] out: FLUSH" outside implicit onces from bio_filter_out_write(). So if the "#if 1" patch seems unnecessary, the "#if 0" one looks needed.So far, the only version that worked was the old approach, to always flush before blocking on the read.Everything is flushed (during handshake) with this new patch, however we can't say anything about the HTTP response itself at the end of the request (the flushes not initiated by mod_ssl are not logged with my patch, nor LogLevel debug). Attached is (yet) another patch which also outputs METADATA buckets passing through mod_ssl, so that we can see whether the HTTP response is finally flushed or not (there were other changes in 2.4.18 regarding this, i.e. in check_pipeline_flush). A simultaneous network capture (pcap) would also be very valuable (btw, where your previous capture taken from, on the server or client side?). This patch shouldn't make it work though, it's just more logging stuff compared to the previous one, unless maybe you change the new "#if 0" (elsewhere this time) to an "#if 1"? Thanks (again) for testing Joachim. Regards, Yann.
-- joac...@kraut.ca http://www.kraut.ca
No. Time Source Destination Protocol
Info
1 21:16:23.810518 205.159.216.152 205.159.216.171 TCP
58210 → https [SYN] Seq=760404415 Win=8192 Len=0 MSS=1460 WS=256 SACK_PERM=1
Frame 1: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760404415, Len: 0
No. Time Source Destination Protocol
Info
2 21:16:23.810698 205.159.216.171 205.159.216.152 TCP
https → 58210 [SYN, ACK] Seq=2136556075 Ack=760404416 Win=29200 Len=0 MSS=1460
SACK_PERM=1 WS=128
Frame 2: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136556075, Ack: 760404416, Len: 0
No. Time Source Destination Protocol
Info
3 21:16:23.810731 205.159.216.152 205.159.216.171 TCP
58210 → https [ACK] Seq=760404416 Ack=2136556076 Win=65536 Len=0
Frame 3: 54 bytes on wire (432 bits), 54 bytes captured (432 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760404416, Ack: 2136556076, Len: 0
No. Time Source Destination Protocol
Info
4 21:16:23.810883 205.159.216.152 205.159.216.171 TLSv1.2
Client Hello
Frame 4: 233 bytes on wire (1864 bits), 233 bytes captured (1864 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760404416, Ack: 2136556076, Len: 179
Secure Sockets Layer
TLSv1.2 Record Layer: Handshake Protocol: Client Hello
Content Type: Handshake (22)
Version: TLS 1.0 (0x0301)
Length: 174
Handshake Protocol: Client Hello
Handshake Type: Client Hello (1)
Length: 170
Version: TLS 1.2 (0x0303)
Random
Session ID Length: 0
Cipher Suites Length: 22
Cipher Suites (11 suites)
Compression Methods Length: 1
Compression Methods (1 method)
Extensions Length: 107
Extension: server_name
Extension: renegotiation_info
Extension: elliptic_curves
Extension: ec_point_formats
Extension: SessionTicket TLS
Extension: next_protocol_negotiation
Extension: Application Layer Protocol Negotiation
Extension: status_request
Extension: signature_algorithms
No. Time Source Destination Protocol
Info
5 21:16:23.811093 205.159.216.171 205.159.216.152 TCP
https → 58210 [ACK] Seq=2136556076 Ack=760404595 Win=30336 Len=0
Frame 5: 60 bytes on wire (480 bits), 60 bytes captured (480 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136556076, Ack: 760404595, Len: 0
No. Time Source Destination Protocol
Info
6 21:16:23.818162 205.159.216.171 205.159.216.152 TLSv1.2
Server Hello, Certificate, Server Key Exchange, Server Hello Done
Frame 6: 1045 bytes on wire (8360 bits), 1045 bytes captured (8360 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136556076, Ack: 760404595, Len: 991
Secure Sockets Layer
TLSv1.2 Record Layer: Handshake Protocol: Server Hello
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 76
Handshake Protocol: Server Hello
Handshake Type: Server Hello (2)
Length: 72
Version: TLS 1.2 (0x0303)
Random
Session ID Length: 0
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (0xc02f)
Compression Method: null (0)
Extensions Length: 32
Extension: renegotiation_info
Extension: ec_point_formats
Extension: SessionTicket TLS
Extension: Application Layer Protocol Negotiation
TLSv1.2 Record Layer: Handshake Protocol: Certificate
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 686
Handshake Protocol: Certificate
Handshake Type: Certificate (11)
Length: 682
Certificates Length: 679
Certificates (679 bytes)
TLSv1.2 Record Layer: Handshake Protocol: Server Key Exchange
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 205
Handshake Protocol: Server Key Exchange
Handshake Type: Server Key Exchange (12)
Length: 201
EC Diffie-Hellman Server Params
TLSv1.2 Record Layer: Handshake Protocol: Server Hello Done
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 4
Handshake Protocol: Server Hello Done
Handshake Type: Server Hello Done (14)
Length: 0
No. Time Source Destination Protocol
Info
7 21:16:23.824345 205.159.216.152 205.159.216.171 TLSv1.2
Client Key Exchange, Change Cipher Spec, Finished
Frame 7: 180 bytes on wire (1440 bits), 180 bytes captured (1440 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760404595, Ack: 2136557067, Len: 126
Secure Sockets Layer
TLSv1.2 Record Layer: Handshake Protocol: Client Key Exchange
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 70
Handshake Protocol: Client Key Exchange
Handshake Type: Client Key Exchange (16)
Length: 66
EC Diffie-Hellman Client Params
TLSv1.2 Record Layer: Change Cipher Spec Protocol: Change Cipher Spec
Content Type: Change Cipher Spec (20)
Version: TLS 1.2 (0x0303)
Length: 1
Change Cipher Spec Message
TLSv1.2 Record Layer: Handshake Protocol: Finished
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 40
Handshake Protocol: Finished
Handshake Type: Finished (20)
Length: 12
Verify Data
No. Time Source Destination Protocol
Info
8 21:16:23.825935 205.159.216.152 205.159.216.171 TCP
[TCP segment of a reassembled PDU]
Frame 8: 1514 bytes on wire (12112 bits), 1514 bytes captured (12112 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760404721, Ack: 2136557067, Len: 1460
No. Time Source Destination Protocol
Info
9 21:16:23.825941 205.159.216.152 205.159.216.171 TCP
[TCP segment of a reassembled PDU]
Frame 9: 1514 bytes on wire (12112 bits), 1514 bytes captured (12112 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760406181, Ack: 2136557067, Len: 1460
No. Time Source Destination Protocol
Info
10 21:16:23.826188 205.159.216.171 205.159.216.152 TCP
https → 58210 [ACK] Seq=2136557067 Ack=760407641 Win=36224 Len=0
Frame 10: 60 bytes on wire (480 bits), 60 bytes captured (480 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136557067, Ack: 760407641, Len: 0
No. Time Source Destination Protocol
Info
11 21:16:23.826208 205.159.216.152 205.159.216.171 HTTP
GET /css/subpage.css HTTP/1.1
Frame 11: 1494 bytes on wire (11952 bits), 1494 bytes captured (11952 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760407641, Ack: 2136557067, Len: 1440
[3 Reassembled TCP Segments (4360 bytes): #8(1460), #9(1460), #11(1440)]
Secure Sockets Layer
TLSv1.2 Record Layer: Application Data Protocol: http
Content Type: Application Data (23)
Version: TLS 1.2 (0x0303)
Length: 4355
Encrypted Application Data:
00000000000000015232b3dcb361f099811b744a7f0324de...
Hypertext Transfer Protocol
GET /css/subpage.css HTTP/1.1\r\n
[Expert Info (Chat/Sequence): GET /css/subpage.css HTTP/1.1\r\n]
[GET /css/subpage.css HTTP/1.1\r\n]
[Severity level: Chat]
[Group: Sequence]
Request Method: GET
Request URI: /css/subpage.css
Request Version: HTTP/1.1
Host: na171\r\n
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:43.0) Gecko/20100101
Firefox/43.0\r\n
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\r\n
Accept-Language: en-US,en;q=0.5\r\n
Accept-Encoding: gzip, deflate\r\n
[truncated]Cookie: map.sel=tick_sfid; dfd.inst=Data Flow 44;
sm.inst=SecurityManager; netcfg.inst=NET 0; serial.inst=7; siogen.inst=SIO
Generator 0; timemgr.inst=Time Manager; demux.inst=ComTunnel 7;
mux.inst=ComTunnel 0; bert.inst=BERT 0
Connection: keep-alive\r\n
\r\n
[Full request URI: https://na171/css/subpage.css]
[HTTP request 1/1]
No. Time Source Destination Protocol
Info
12 21:16:23.826696 205.159.216.171 205.159.216.152 TLSv1.2
New Session Ticket, Change Cipher Spec, Finished
Frame 12: 312 bytes on wire (2496 bits), 312 bytes captured (2496 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136557067, Ack: 760409081, Len: 258
Secure Sockets Layer
TLSv1.2 Record Layer: Handshake Protocol: New Session Ticket
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 202
Handshake Protocol: New Session Ticket
Handshake Type: New Session Ticket (4)
Length: 198
TLS Session Ticket
TLSv1.2 Record Layer: Change Cipher Spec Protocol: Change Cipher Spec
Content Type: Change Cipher Spec (20)
Version: TLS 1.2 (0x0303)
Length: 1
Change Cipher Spec Message
TLSv1.2 Record Layer: Handshake Protocol: Finished
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 40
Handshake Protocol: Finished
Handshake Type: Finished (20)
Length: 12
Verify Data
No. Time Source Destination Protocol
Info
13 21:16:24.027066 205.159.216.171 205.159.216.152 TCP
[TCP Retransmission] https → 58210 [PSH, ACK] Seq=2136557067 Ack=760409081
Win=39040 Len=258
Frame 13: 312 bytes on wire (2496 bits), 312 bytes captured (2496 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136557067, Ack: 760409081, Len: 258
No. Time Source Destination Protocol
Info
14 21:16:24.027100 205.159.216.152 205.159.216.171 TCP
58210 → https [ACK] Seq=760409081 Ack=2136557325 Win=64256 Len=0 SLE=2136557067
SRE=2136557325
Frame 14: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760409081, Ack: 2136557325, Len: 0
No. Time Source Destination Protocol
Info
15 21:16:33.831990 205.159.216.152 205.159.216.171 TCP
[TCP Keep-Alive] 58210 → https [ACK] Seq=760409080 Ack=2136557325 Win=64256
Len=1[Reassembly error, protocol TCP: New fragment overlaps old data
(retransmission?)]
Frame 15: 55 bytes on wire (440 bits), 55 bytes captured (440 bits)
Ethernet II, Src: AsustekC_fe:77:8a (00:26:18:fe:77:8a), Dst: Advantec_60:1c:9d
(00:0b:ab:60:1c:9d)
Internet Protocol Version 4, Src: 205.159.216.152, Dst: 205.159.216.171
Transmission Control Protocol, Src Port: 58210 (58210), Dst Port: https (443),
Seq: 760409080, Ack: 2136557325, Len: 1
[Reassembly error, protocol TCP: New fragment overlaps old data
(retransmission?)]
[Expert Info (Error/Malformed): New fragment overlaps old data
(retransmission?)]
[New fragment overlaps old data (retransmission?)]
[Severity level: Error]
[Group: Malformed]
No. Time Source Destination Protocol
Info
16 21:16:33.832203 205.159.216.171 205.159.216.152 TCP
[TCP Keep-Alive ACK] https → 58210 [ACK] Seq=2136557325 Ack=760409081 Win=39040
Len=0 SLE=760409080 SRE=760409081
Frame 16: 66 bytes on wire (528 bits), 66 bytes captured (528 bits)
Ethernet II, Src: Advantec_60:1c:9d (00:0b:ab:60:1c:9d), Dst: AsustekC_fe:77:8a
(00:26:18:fe:77:8a)
Internet Protocol Version 4, Src: 205.159.216.171, Dst: 205.159.216.152
Transmission Control Protocol, Src Port: https (443), Dst Port: 58210 (58210),
Seq: 2136557325, Ack: 760409081, Len: 0
[Tue Feb 02 21:16:24.089718 2016] [ssl:info] [pid 1356] [client 205.159.216.152:58210] AH01964: Connection to child 0 established (server localhost:443) [Tue Feb 02 21:16:24.090955 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 11bytes [Tue Feb 02 21:16:24.090983 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 168bytes [Tue Feb 02 21:16:24.091012 2016] [ssl:debug] [pid 1356] ssl_engine_kernel.c(2103): [client 205.159.216.152:58210] AH02044: No matching SSL virtual host for servername na171 found (using default/first virtual host) [Tue Feb 02 21:16:24.091022 2016] [core:debug] [pid 1356] protocol.c(1891): [client 205.159.216.152:58210] select protocol from , choices=h2,spdy/3.1,http/1.1 for server localhost [Tue Feb 02 21:16:24.091031 2016] [ssl:debug] [pid 1356] ssl_engine_kernel.c(2103): [client 205.159.216.152:58210] AH02044: No matching SSL virtual host for servername na171 found (using default/first virtual host) [Tue Feb 02 21:16:24.096688 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: flush 991 bytes [Tue Feb 02 21:16:24.096728 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: FLUSH [Tue Feb 02 21:16:24.103053 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 5bytes [Tue Feb 02 21:16:24.103068 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 70bytes [Tue Feb 02 21:16:24.105040 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 5bytes [Tue Feb 02 21:16:24.105049 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 1bytes [Tue Feb 02 21:16:24.105122 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 5bytes [Tue Feb 02 21:16:24.105152 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 40bytes [Tue Feb 02 21:16:24.105260 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: flush 258 bytes [Tue Feb 02 21:16:24.105278 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: FLUSH [Tue Feb 02 21:16:24.105313 2016] [ssl:debug] [pid 1356] ssl_engine_kernel.c(2023): [client 205.159.216.152:58210] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits) [Tue Feb 02 21:16:24.105340 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 5bytes [Tue Feb 02 21:16:24.105350 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[91796d8] in: read 4355bytes [Tue Feb 02 21:16:24.105509 2016] [ssl:debug] [pid 1356] ssl_engine_kernel.c(354): [client 205.159.216.152:58210] AH02034: Initial (No.1) HTTPS request received for child 0 (server localhost:443) [Tue Feb 02 21:16:24.105650 2016] [authz_core:debug] [pid 1356] mod_authz_core.c(809): [client 205.159.216.152:58210] AH01626: authorization result of Require all granted: granted [Tue Feb 02 21:16:24.105658 2016] [authz_core:debug] [pid 1356] mod_authz_core.c(809): [client 205.159.216.152:58210] AH01626: authorization result of <RequireAny>: granted [Tue Feb 02 21:16:24.105745 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: pass 327 bytes [Tue Feb 02 21:16:24.105823 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: pass 1727 bytes [Tue Feb 02 21:16:24.105835 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: METADATA EOS [Tue Feb 02 21:16:24.105846 2016] [ssl:notice] [pid 1356] [client 205.159.216.152:58210] bio[916bd50] out: METADATA EOR
ssltrace-v3.pcap
Description: Binary data
