|
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="">
> > [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@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
