[squid-users] SSL bumping without faked server certificates

Mon Nov 23 11:08:37 UTC 2015

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20151123/0ff45dc3/attachment-0001.html>