Hi Alex, sorry for the late reply.
> > 2015/11/10 19:24:30.181 kid1| 33,5|... > > 2015/11/10 19:25:30.016 kid1| 33,3| AsyncCall.cc(93) ScheduleCall: > > IoCallback.cc(135) will call > > ConnStateData::clientPinnedConnectionRead(local=172.31.1.15:49421 > > remote=212.45.105.89:443 FD 15 flags=1, flag=-10, data=0x19ced08) > > [call349]> > > This one second gap after a successful SSL negotiation with the > origin server is rather suspicious, but I am going to ignore it ... This is not one second but one minute and just the default timeout of curl. Nevertheless I have built a new RPM package with the latest 3.5.11 source and the patch you mentioned. The result is the same. I have reduced the curl timeout to 10 seconds: Client: # curl -vvv --connect-timeout 10 https://school.bettermarks.com/static/flexclient4/bm_exerciseseries.swf -o /dev/null * About to connect() to school.bettermarks.com port 443 (#0) * Trying 212.45.105.89... connected * Connected to school.bettermarks.com (212.45.105.89) port 443 (#0) * Initializing NSS with certpath: sql:/etc/pki/nssdb * CAfile: /etc/pki/tls/certs/ca-bundle.crt CApath: none * NSS error -5990 * Closing connection #0 * SSL connect error curl: (35) SSL connect error Now there is a 10 second gap in Squid's cache log. Squid: 2015/11/23 10:20:05.152 kid1| 33,5| client_side.cc(3693) httpsCreate: will negotate SSL on local=212.45.105.89:443 remote=10.0.0.2:41428 FD 11 flags=33 2015/11/23 10:20:05.152 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::requestTimeout constructed, this=0x1ff6340 [call77] 2015/11/23 10:20:14.992 kid1| 83,7| bio.cc(168) stateChanged: FD 11 now: 0x10 UNKWN (before/accept initialization) 2015/11/23 10:20:14.992 kid1| 83,7| bio.cc(168) stateChanged: FD 11 now: 0x2001 UNKWN (before/accept initialization) 2015/11/23 10:20:14.992 kid1| 83,5| bio.cc(118) read: FD 11 read 0 <= 11 2015/11/23 10:20:14.992 kid1| 83,5| bio.cc(144) readAndBuffer: read 0 out of 11 bytes 2015/11/23 10:20:14.992 kid1| 83,2| client_side.cc(3725) Squid_SSL_accept: Error negotiating SSL connection on FD 11: Aborted by client: 5 I digged deeper into the traffic using Wireshark. As a reminder my network setup: Client (10.0.0.2) <---> (10.0.0.1) Squid (10.31.1.15) <---> 212.45.105.89 (Origin) Here is the relevant packet flow. I have stripped off DNS, NTP, etc. and time format is UTC (Squid's cache log above shows UTC+1): Client: 10 2015-11-23 09:20:04.971734836 10.0.0.2 212.45.105.89 TCP 74 41428→443 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=5322725 TSecr=0 WS=128 12 2015-11-23 09:20:04.971946983 212.45.105.89 10.0.0.2 TCP 74 443→41428 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=2202045 TSecr=5322725 WS=128 13 2015-11-23 09:20:04.971968589 10.0.0.2 212.45.105.89 TCP 66 41428→443 [ACK] Seq=1 Ack=1 Win=14720 Len=0 TSval=5322726 TSecr=2202045 17 2015-11-23 09:20:05.047529339 10.0.0.2 212.45.105.89 SSL 174 Client Hello 19 2015-11-23 09:20:05.047868761 212.45.105.89 10.0.0.2 TCP 66 443→41428 [ACK] Seq=1 Ack=109 Win=14592 Len=0 TSval=2202121 TSecr=5322801 26 2015-11-23 09:20:14.980851745 10.0.0.2 212.45.105.89 TCP 66 41428→443 [FIN, ACK] Seq=109 Ack=1 Win=14720 Len=0 TSval=5332735 TSecr=2202121 27 2015-11-23 09:20:14.982049717 212.45.105.89 10.0.0.2 TCP 66 443→41428 [FIN, ACK] Seq=1 Ack=110 Win=14592 Len=0 TSval=2212055 TSecr=5332735 28 2015-11-23 09:20:14.982087279 10.0.0.2 212.45.105.89 TCP 66 41428→443 [ACK] Seq=110 Ack=2 Win=14720 Len=0 TSval=5332736 TSecr=2212055 Squid: 13 2015-11-23 09:20:04.983024000 10.0.0.2 212.45.105.89 TCP 74 41428→443 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=5322725 TSecr=0 WS=128 14 2015-11-23 09:20:04.983080000 212.45.105.89 10.0.0.2 TCP 74 443→41428 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=2202045 TSecr=5322725 WS=128 17 2015-11-23 09:20:04.983252000 10.0.0.2 212.45.105.89 TCP 66 41428→443 [ACK] Seq=1 Ack=1 Win=14720 Len=0 TSval=5322726 TSecr=2202045 26 2015-11-23 09:20:05.058868000 10.0.0.2 212.45.105.89 SSL 174 Client Hello 27 2015-11-23 09:20:05.058927000 212.45.105.89 10.0.0.2 TCP 66 443→41428 [ACK] Seq=1 Ack=109 Win=14592 Len=0 TSval=2202121 TSecr=5322801 32 2015-11-23 09:20:05.060596000 172.31.1.15 212.45.105.89 TCP 74 34995→443 [SYN] Seq=0 Win=14600 Len=0 MSS=1460 SACK_PERM=1 TSval=2202122 TSecr=0 WS=128 33 2015-11-23 09:20:05.081926000 212.45.105.89 172.31.1.15 TCP 74 443→34995 [SYN, ACK] Seq=0 Ack=1 Win=4380 Len=0 MSS=1460 TSval=866426570 TSecr=2202122 SACK_PERM=1 34 2015-11-23 09:20:05.081976000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [ACK] Seq=1 Ack=1 Win=14600 Len=0 TSval=2202144 TSecr=866426570 35 2015-11-23 09:20:05.082267000 172.31.1.15 212.45.105.89 TLSv1.2 359 Client Hello 36 2015-11-23 09:20:05.114617000 212.45.105.89 172.31.1.15 TLSv1.2 1514 Server Hello 37 2015-11-23 09:20:05.114654000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [ACK] Seq=294 Ack=1449 Win=17376 Len=0 TSval=2202177 TSecr=866426602 38 2015-11-23 09:20:05.124909000 212.45.105.89 172.31.1.15 TLSv1.2 2149 Certificate 39 2015-11-23 09:20:05.124936000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [ACK] Seq=294 Ack=3532 Win=20272 Len=0 TSval=2202187 TSecr=866426602 40 2015-11-23 09:20:05.126685000 172.31.1.15 212.45.105.89 TLSv1.2 424 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message 41 2015-11-23 09:20:05.147837000 212.45.105.89 172.31.1.15 TCP 66 443→34995 [ACK] Seq=3532 Ack=652 Win=5031 Len=0 TSval=866426637 TSecr=2202189 42 2015-11-23 09:20:05.151336000 212.45.105.89 172.31.1.15 TLSv1.2 157 Change Cipher Spec, Encrypted Handshake Message 43 2015-11-23 09:20:05.190587000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [ACK] Seq=652 Ack=3623 Win=20272 Len=0 TSval=2202253 TSecr=866426640 56 2015-11-23 09:20:14.992348000 10.0.0.2 212.45.105.89 TCP 66 41428→443 [FIN, ACK] Seq=109 Ack=1 Win=14720 Len=0 TSval=5332735 TSecr=2202121 57 2015-11-23 09:20:14.993270000 212.45.105.89 10.0.0.2 TCP 66 443→41428 [FIN, ACK] Seq=1 Ack=110 Win=14592 Len=0 TSval=2212055 TSecr=5332735 58 2015-11-23 09:20:14.993435000 172.31.1.15 212.45.105.89 TLSv1.2 135 Encrypted Alert 59 2015-11-23 09:20:14.993656000 10.0.0.2 212.45.105.89 TCP 66 41428→443 [ACK] Seq=110 Ack=2 Win=14720 Len=0 TSval=5332736 TSecr=2212055 60 2015-11-23 09:20:14.993822000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [FIN, ACK] Seq=721 Ack=3623 Win=20272 Len=0 TSval=2212056 TSecr=866426640 65 2015-11-23 09:20:15.014254000 212.45.105.89 172.31.1.15 TCP 66 443→34995 [ACK] Seq=3623 Ack=721 Win=5100 Len=0 TSval=866436502 TSecr=2212055 66 2015-11-23 09:20:15.017891000 212.45.105.89 172.31.1.15 TCP 66 443→34995 [FIN, ACK] Seq=3623 Ack=721 Win=5100 Len=0 TSval=866436502 TSecr=2212055 67 2015-11-23 09:20:15.017918000 172.31.1.15 212.45.105.89 TCP 66 34995→443 [ACK] Seq=722 Ack=3624 Win=20272 Len=0 TSval=2212080 TSecr=866436502 68 2015-11-23 09:20:15.018618000 212.45.105.89 172.31.1.15 TCP 66 443→34995 [ACK] Seq=3624 Ack=722 Win=5100 Len=0 TSval=866436506 TSecr=2212056 The curl command returned an error after the timeout of 10 seconds. These 10 seconds are visible in both Wireshark packet capture logs. I added "generate-host-certificates=off" to https_port to avoid any certificate issues since Squid and the origin have exactly the same official certificate and key. Do you have an idea what is going wrong? Best, Stefan
_______________________________________________ squid-users mailing list squid-users@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-users
