Hi, I'm using squid on Ubuntu Gutsy, package version 2.6.14-1ubuntu2.
I'm experiencing some troubles with a https web service call that is
going via the proxy. Approximately 3 out of 1000 calls to the https
service result in a communication problem but no errors show in the
squid log. The calling application gives a time-out and the web
service doesn't register a vaild request. We've done packet tracing on
both sides of the proxy and from both web facing ends. We've ruled out
any Internet IP issues and were wondering if anyone could assist with
the problem. I couldn't see any similar bug reports or known issues
with the version but maybe it is known and someone can point me in the
right direction.
The exact problem can be described by the packet traces.
=A good call flows as follows:=
No. Time Source Destination
Protocol Info
1 13:44:45.818945 source proxy
TCP 38761 > ndl-aas [SYN] Seq=0 Win=5840 Len=0 MSS=1380
TSV=1340786445 TSER=0 WS=6
2 13:44:45.818945 proxy source
TCP ndl-aas > 38761 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0
MSS=1460 TSV=344727123 TSER=1340786445 WS=7
3 13:44:45.818945 source proxy
TCP 38761 > ndl-aas [ACK] Seq=1 Ack=1 Win=5888 Len=0
TSV=1340786445 TSER=344727123
4 13:44:45.818945 source proxy
HTTP CONNECT www.payway.com.au:443 HTTP/1.0
5 13:44:45.818945 proxy source
TCP ndl-aas > 38761 [ACK] Seq=1 Ack=77 Win=5888 Len=0
TSV=344727124 TSER=1340786445
6 13:44:45.818945 proxy webservice
TCP 39869 > https [SYN] Seq=0 Win=5840 Len=0 MSS=1460
TSV=344727124 TSER=0 WS=7
7 13:44:45.838945 webservice proxy
TCP https > 39869 [SYN, ACK] Seq=0 Ack=1 Win=4140 Len=0 MSS=1380
WS=0 TSV=1074414652 TSER=344727124
8 13:44:45.838945 proxy webservice
TCP 39869 > https [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=344727126
TSER=1074414652
9 13:44:45.838945 proxy source
HTTP HTTP/1.0 200 Connection established
10 13:44:45.838945 source proxy
TCP 38761 > ndl-aas [ACK] Seq=77 Ack=40 Win=5888 Len=0
TSV=1340786448 TSER=344727126
11 13:44:45.838945 source proxy
TLSv1 Client Hello
12 13:44:45.838945 proxy webservice
TLSv1 Client Hello
13 13:44:45.848946 webservice proxy
TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
14 13:44:45.848946 proxy webservice
TCP 39869 > https [ACK] Seq=117 Ack=123 Win=5888 Len=0
TSV=344727127 TSER=1074414678
15 13:44:45.858946 proxy source
TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
16 13:44:45.858946 source proxy
TLSv1 Change Cipher Spec
17 13:44:45.858946 proxy webservice
TLSv1 Change Cipher Spec
18 13:44:45.898947 proxy source
TCP ndl-aas > 38761 [ACK] Seq=162 Ack=199 Win=5888 Len=0
TSV=344727132 TSER=1340786449
19 13:44:45.898947 source proxy
TLSv1 Encrypted Handshake Message, Application Data, Application
Data
20 13:44:45.898947 proxy source
TCP ndl-aas > 38761 [ACK] Seq=162 Ack=988 Win=7424 Len=0
TSV=344727132 TSER=1340786453
21 13:44:45.898947 proxy webservice
TLSv1 Encrypted Handshake Message, Application Data, Application
Data
22 13:44:45.928948 webservice proxy
TCP https > 39869 [ACK] Seq=123 Ack=912 Win=4262 Len=0
TSV=1074414739 TSER=344727128
23 13:44:46.918978 webservice proxy
TLSv1 Application Data
24 13:44:46.918978 webservice proxy
TCP https > 39869 [FIN, ACK] Seq=683 Ack=912 Win=5051 Len=0
TSV=1074415735 TSER=344727128
25 13:44:46.918978 proxy webservice
TCP 39869 > https [ACK] Seq=912 Ack=684 Win=7040 Len=0
TSV=344727234 TSER=1074415735
26 13:44:46.918978 proxy webservice
TCP 39869 > https [FIN, ACK] Seq=912 Ack=684 Win=7040 Len=0
TSV=344727234 TSER=1074415735
27 13:44:46.918978 proxy source
TLSv1 Application Data
28 13:44:46.918978 proxy source
TCP ndl-aas > 38761 [FIN, ACK] Seq=722 Ack=988 Win=7424 Len=0
TSV=344727234 TSER=1340786453
29 13:44:46.918978 source proxy
TCP 38761 > ndl-aas [ACK] Seq=988 Ack=723 Win=6976 Len=0
TSV=1340786555 TSER=344727234
30 13:44:46.918978 source proxy
TLSv1 Encrypted Alert
31 13:44:46.918978 proxy source
TCP ndl-aas > 38761 [RST] Seq=723 Win=0 Len=0
32 13:44:46.918978 source proxy
TCP 38761 > ndl-aas [FIN, ACK] Seq=1011 Ack=723 Win=6976 Len=0
TSV=1340786556 TSER=344727234
33 13:44:46.918978 proxy source
TCP ndl-aas > 38761 [RST] Seq=723 Win=0 Len=0
34 13:44:46.928978 webservice proxy
TCP https > 39869 [ACK] Seq=684 Ack=913 Win=5051 Len=0
TSV=1074415752 TSER=344727234
=A bad call flows as follows:=
No. Time Source Destination
Protocol Info
1 13:49:43.087913 source proxy
TCP 48783 > ndl-aas [SYN] Seq=0 Win=5840 Len=0 MSS=1380
TSV=1053112932 TSER=0 WS=6
2 13:49:43.087913 proxy source
TCP ndl-aas > 48783 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0
MSS=1460 TSV=344756850 TSER=1053112932 WS=7
3 13:49:43.087913 source proxy
TCP 48783 > ndl-aas [ACK] Seq=1 Ack=1 Win=5888 Len=0
TSV=1053112932 TSER=344756850
4 13:49:43.087913 source proxy
HTTP CONNECT www.payway.com.au:443 HTTP/1.0
5 13:49:43.087913 proxy source
TCP ndl-aas > 48783 [ACK] Seq=1 Ack=77 Win=5888 Len=0
TSV=344756850 TSER=1053112932
6 13:49:43.087913 proxy webservice
TCP 41155 > https [SYN] Seq=0 Win=5840 Len=0 MSS=1460
TSV=344756850 TSER=0 WS=7
7 13:49:43.097914 webservice proxy
TCP https > 41155 [SYN, ACK] Seq=0 Ack=1 Win=4140 Len=0 MSS=1380
WS=0 TSV=1074711886 TSER=344756850
8 13:49:43.097914 proxy webservice
TCP 41155 > https [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=344756851
TSER=1074711886
9 13:49:43.097914 proxy source
HTTP HTTP/1.0 200 Connection established
10 13:49:43.097914 source proxy
TCP 48783 > ndl-aas [ACK] Seq=77 Ack=40 Win=5888 Len=0
TSV=1053112934 TSER=344756851
11 13:49:43.097914 source proxy
SSL Client Hello
12 13:49:43.097914 proxy webservice
TLSv1 Client Hello
13 13:49:43.117914 webservice proxy
TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
14 13:49:43.137915 proxy source
TCP ndl-aas > 48783 [ACK] Seq=40 Ack=193 Win=5888 Len=0
TSV=344756855 TSER=1053112934
15 13:49:43.807935 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
16 13:49:43.807935 webservice proxy
TCP [TCP Dup ACK 13#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
17 13:49:44.317951 webservice proxy
TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec,
Encrypted Handshake Message
18 13:49:45.227978 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
19 13:49:45.227978 webservice proxy
TCP [TCP Dup ACK 17#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
20 13:49:46.548018 webservice proxy
TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec,
Encrypted Handshake Message
21 13:49:48.068064 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
22 13:49:48.068064 webservice proxy
TCP [TCP Dup ACK 20#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
23 13:49:50.778145 webservice proxy
TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec,
Encrypted Handshake Message
24 13:49:53.748235 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
25 13:49:53.748235 webservice proxy
TCP [TCP Dup ACK 23#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
26 13:49:58.928391 webservice proxy
TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec,
Encrypted Handshake Message
27 13:50:05.108578 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
28 13:50:05.108578 webservice proxy
TCP [TCP Dup ACK 26#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
29 13:50:15.288885 webservice proxy
TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec,
Encrypted Handshake Message
30 13:50:27.829263 proxy webservice
TLSv1 [TCP Retransmission] Client Hello
31 13:50:27.829263 webservice proxy
TCP [TCP Dup ACK 29#1] https > 41155 [PSH, ACK] Seq=123 Ack=117
Win=4256 Len=0 TSV=1074711900 TSER=344756851
32 13:50:43.119725 webservice proxy
TCP https > 41155 [RST, ACK] Seq=123 Ack=117 Win=4256 Len=0
33 13:50:43.119725 proxy source
TCP ndl-aas > 48783 [FIN, ACK] Seq=40 Ack=193 Win=5888 Len=0
TSV=344762853 TSER=1053112934
34 13:50:43.159726 source proxy
TCP 48783 > ndl-aas [ACK] Seq=193 Ack=41 Win=5888 Len=0
TSV=1053118940 TSER=344762853
As you can see packet 13 which is the server hello never seems to be
proxied back to the source. This leads the source to keep retrying
it's client hello and the call failing. So the question is why is the
proxy not passing the server hello back to the source for
approximately 3 out of 1000 calls? Also I note that the source port
(proxy > webservice) has often been re-used recently for failed
transactions.
=Our squid.conf is:=
http_port 3128
hierarchy_stoplist cgi-bin ?
acl QUERY urlpath_regex cgi-bin \?
cache deny QUERY
acl apache rep_header Server ^Apache
broken_vary_encoding allow apache
cache_dir ufs /var/spool/squid 100 16 256
access_log /var/log/squid/access.log squid
hosts_file /etc/hosts
refresh_pattern ^ftp: 1440 20% 10080
refresh_pattern ^gopher: 1440 0% 1440
refresh_pattern . 0 20% 4320
acl all src 0.0.0.0/0.0.0.0
acl manager proto cache_object
acl localhost src 127.0.0.1/255.255.255.255
acl to_localhost dst 127.0.0.0/8
acl SSL_ports port 443 # https
acl SSL_ports port 563 # snews
acl SSL_ports port 873 # rsync
acl Safe_ports port 80 # http
acl Safe_ports port 21 # ftp
acl Safe_ports port 443 # https
acl Safe_ports port 70 # gopher
acl Safe_ports port 210 # wais
acl Safe_ports port 1025-65535 # unregistered ports
acl Safe_ports port 280 # http-mgmt
acl Safe_ports port 488 # gss-http
acl Safe_ports port 591 # filemaker
acl Safe_ports port 777 # multiling http
acl Safe_ports port 631 # cups
acl Safe_ports port 873 # rsync
acl Safe_ports port 901 # SWAT
acl purge method PURGE
acl CONNECT method CONNECT
http_access allow manager localhost
http_access deny manager
http_access allow purge localhost
http_access deny purge
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
acl our_networks src 172.28.0.0/16
http_access allow our_networks
http_access allow localhost
http_access deny all
icp_access allow all
coredump_dir /var/spool/squid
extension_methods REPORT MERGE MKACTIVITY CHECKOUT
Any help would be much appreciated!
--
Sincerely,
Joel Duckworth
http://jpd.id.au - joel@xxxxxxxxx
No. Time Source Destination Protocol Info
1 13:44:45.818945 source proxy TCP 38761 > ndl-aas [SYN] Seq=0 Win=5840 Len=0 MSS=1380 TSV=1340786445 TSER=0 WS=6
2 13:44:45.818945 proxy source TCP ndl-aas > 38761 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=344727123 TSER=1340786445 WS=7
3 13:44:45.818945 source proxy TCP 38761 > ndl-aas [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=1340786445 TSER=344727123
4 13:44:45.818945 source proxy HTTP CONNECT www.payway.com.au:443 HTTP/1.0
5 13:44:45.818945 proxy source TCP ndl-aas > 38761 [ACK] Seq=1 Ack=77 Win=5888 Len=0 TSV=344727124 TSER=1340786445
6 13:44:45.818945 proxy webservice TCP 39869 > https [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=344727124 TSER=0 WS=7
7 13:44:45.838945 webservice proxy TCP https > 39869 [SYN, ACK] Seq=0 Ack=1 Win=4140 Len=0 MSS=1380 WS=0 TSV=1074414652 TSER=344727124
8 13:44:45.838945 proxy webservice TCP 39869 > https [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=344727126 TSER=1074414652
9 13:44:45.838945 proxy source HTTP HTTP/1.0 200 Connection established
10 13:44:45.838945 source proxy TCP 38761 > ndl-aas [ACK] Seq=77 Ack=40 Win=5888 Len=0 TSV=1340786448 TSER=344727126
11 13:44:45.838945 source proxy TLSv1 Client Hello
12 13:44:45.838945 proxy webservice TLSv1 Client Hello
13 13:44:45.848946 webservice proxy TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
14 13:44:45.848946 proxy webservice TCP 39869 > https [ACK] Seq=117 Ack=123 Win=5888 Len=0 TSV=344727127 TSER=1074414678
15 13:44:45.858946 proxy source TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
16 13:44:45.858946 source proxy TLSv1 Change Cipher Spec
17 13:44:45.858946 proxy webservice TLSv1 Change Cipher Spec
18 13:44:45.898947 proxy source TCP ndl-aas > 38761 [ACK] Seq=162 Ack=199 Win=5888 Len=0 TSV=344727132 TSER=1340786449
19 13:44:45.898947 source proxy TLSv1 Encrypted Handshake Message, Application Data, Application Data
20 13:44:45.898947 proxy source TCP ndl-aas > 38761 [ACK] Seq=162 Ack=988 Win=7424 Len=0 TSV=344727132 TSER=1340786453
21 13:44:45.898947 proxy webservice TLSv1 Encrypted Handshake Message, Application Data, Application Data
22 13:44:45.928948 webservice proxy TCP https > 39869 [ACK] Seq=123 Ack=912 Win=4262 Len=0 TSV=1074414739 TSER=344727128
23 13:44:46.918978 webservice proxy TLSv1 Application Data
24 13:44:46.918978 webservice proxy TCP https > 39869 [FIN, ACK] Seq=683 Ack=912 Win=5051 Len=0 TSV=1074415735 TSER=344727128
25 13:44:46.918978 proxy webservice TCP 39869 > https [ACK] Seq=912 Ack=684 Win=7040 Len=0 TSV=344727234 TSER=1074415735
26 13:44:46.918978 proxy webservice TCP 39869 > https [FIN, ACK] Seq=912 Ack=684 Win=7040 Len=0 TSV=344727234 TSER=1074415735
27 13:44:46.918978 proxy source TLSv1 Application Data
28 13:44:46.918978 proxy source TCP ndl-aas > 38761 [FIN, ACK] Seq=722 Ack=988 Win=7424 Len=0 TSV=344727234 TSER=1340786453
29 13:44:46.918978 source proxy TCP 38761 > ndl-aas [ACK] Seq=988 Ack=723 Win=6976 Len=0 TSV=1340786555 TSER=344727234
30 13:44:46.918978 source proxy TLSv1 Encrypted Alert
31 13:44:46.918978 proxy source TCP ndl-aas > 38761 [RST] Seq=723 Win=0 Len=0
32 13:44:46.918978 source proxy TCP 38761 > ndl-aas [FIN, ACK] Seq=1011 Ack=723 Win=6976 Len=0 TSV=1340786556 TSER=344727234
33 13:44:46.918978 proxy source TCP ndl-aas > 38761 [RST] Seq=723 Win=0 Len=0
34 13:44:46.928978 webservice proxy TCP https > 39869 [ACK] Seq=684 Ack=913 Win=5051 Len=0 TSV=1074415752 TSER=344727234
No. Time Source Destination Protocol Info
1 13:49:43.087913 source proxy TCP 48783 > ndl-aas [SYN] Seq=0 Win=5840 Len=0 MSS=1380 TSV=1053112932 TSER=0 WS=6
2 13:49:43.087913 proxy source TCP ndl-aas > 48783 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=344756850 TSER=1053112932 WS=7
3 13:49:43.087913 source proxy TCP 48783 > ndl-aas [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=1053112932 TSER=344756850
4 13:49:43.087913 source proxy HTTP CONNECT www.payway.com.au:443 HTTP/1.0
5 13:49:43.087913 proxy source TCP ndl-aas > 48783 [ACK] Seq=1 Ack=77 Win=5888 Len=0 TSV=344756850 TSER=1053112932
6 13:49:43.087913 proxy webservice TCP 41155 > https [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=344756850 TSER=0 WS=7
7 13:49:43.097914 webservice proxy TCP https > 41155 [SYN, ACK] Seq=0 Ack=1 Win=4140 Len=0 MSS=1380 WS=0 TSV=1074711886 TSER=344756850
8 13:49:43.097914 proxy webservice TCP 41155 > https [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=344756851 TSER=1074711886
9 13:49:43.097914 proxy source HTTP HTTP/1.0 200 Connection established
10 13:49:43.097914 source proxy TCP 48783 > ndl-aas [ACK] Seq=77 Ack=40 Win=5888 Len=0 TSV=1053112934 TSER=344756851
11 13:49:43.097914 source proxy SSL Client Hello
12 13:49:43.097914 proxy webservice TLSv1 Client Hello
13 13:49:43.117914 webservice proxy TLSv1 Server Hello, Change Cipher Spec, Encrypted Handshake Message
14 13:49:43.137915 proxy source TCP ndl-aas > 48783 [ACK] Seq=40 Ack=193 Win=5888 Len=0 TSV=344756855 TSER=1053112934
15 13:49:43.807935 proxy webservice TLSv1 [TCP Retransmission] Client Hello
16 13:49:43.807935 webservice proxy TCP [TCP Dup ACK 13#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
17 13:49:44.317951 webservice proxy TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec, Encrypted Handshake Message
18 13:49:45.227978 proxy webservice TLSv1 [TCP Retransmission] Client Hello
19 13:49:45.227978 webservice proxy TCP [TCP Dup ACK 17#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
20 13:49:46.548018 webservice proxy TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec, Encrypted Handshake Message
21 13:49:48.068064 proxy webservice TLSv1 [TCP Retransmission] Client Hello
22 13:49:48.068064 webservice proxy TCP [TCP Dup ACK 20#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
23 13:49:50.778145 webservice proxy TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec, Encrypted Handshake Message
24 13:49:53.748235 proxy webservice TLSv1 [TCP Retransmission] Client Hello
25 13:49:53.748235 webservice proxy TCP [TCP Dup ACK 23#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
26 13:49:58.928391 webservice proxy TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec, Encrypted Handshake Message
27 13:50:05.108578 proxy webservice TLSv1 [TCP Retransmission] Client Hello
28 13:50:05.108578 webservice proxy TCP [TCP Dup ACK 26#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
29 13:50:15.288885 webservice proxy TLSv1 [TCP Retransmission] Server Hello, Change Cipher Spec, Encrypted Handshake Message
30 13:50:27.829263 proxy webservice TLSv1 [TCP Retransmission] Client Hello
31 13:50:27.829263 webservice proxy TCP [TCP Dup ACK 29#1] https > 41155 [PSH, ACK] Seq=123 Ack=117 Win=4256 Len=0 TSV=1074711900 TSER=344756851
32 13:50:43.119725 webservice proxy TCP https > 41155 [RST, ACK] Seq=123 Ack=117 Win=4256 Len=0
33 13:50:43.119725 proxy source TCP ndl-aas > 48783 [FIN, ACK] Seq=40 Ack=193 Win=5888 Len=0 TSV=344762853 TSER=1053112934
34 13:50:43.159726 source proxy TCP 48783 > ndl-aas [ACK] Seq=193 Ack=41 Win=5888 Len=0 TSV=1053118940 TSER=344762853
