<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
p.MsoListParagraph, li.MsoListParagraph, div.MsoListParagraph
{mso-style-priority:34;
margin-top:0in;
margin-right:0in;
margin-bottom:0in;
margin-left:.5in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
/* List Definitions */
@list l0
{mso-list-id:2088190775;
mso-list-type:hybrid;
mso-list-template-ids:-856633050 67698705 67698713 67698715 67698703 67698713 67698715 67698703 67698713 67698715;}
@list l0:level1
{mso-level-text:"%1\)";
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level2
{mso-level-number-format:alpha-lower;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level3
{mso-level-number-format:roman-lower;
mso-level-tab-stop:none;
mso-level-number-position:right;
text-indent:-9.0pt;}
@list l0:level4
{mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level5
{mso-level-number-format:alpha-lower;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level6
{mso-level-number-format:roman-lower;
mso-level-tab-stop:none;
mso-level-number-position:right;
text-indent:-9.0pt;}
@list l0:level7
{mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level8
{mso-level-number-format:alpha-lower;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;}
@list l0:level9
{mso-level-number-format:roman-lower;
mso-level-tab-stop:none;
mso-level-number-position:right;
text-indent:-9.0pt;}
ol
{margin-bottom:0in;}
ul
{margin-bottom:0in;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal">Hi,<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I am using Squid 4.5 with WCCP. Intercepting SSL by peeking at step1 and then deciding to either splice or bump upon the SNI.<o:p></o:p></p>
<p class="MsoNormal">I am noticing a weird behavior for some of my TCP connections. Squid is taking over 20s to decide what do with the ClientHello sent by the browser. It is only after 20s that it decides to send out a ClientHello to the origin server and
at the same time reply to the client with a ServerHello.<o:p></o:p></p>
<p class="MsoNormal">This behavior is hard to reproduce and only some clients are affected.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I will try to summarize what I see in cache.log with ALL, 6 debug options.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">1)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Squid's INTERCEPTION thread/program receives a TCP SYN from workstation.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.070 kid1| 89,5| Intercept.cc(405) Lookup: address BEGIN: me/client=
<b><SQUID_IP>:</b>23129, destination/me= <b><CLIENT/BROWSER_IP>:</b>58232<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">2)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Squid becomes the origin server and sets up the TCP connection.
<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.070 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: TcpAcceptor.cc(339) will call httpsAccept(local<b>=<ORIGIN_SERVER_ON_THE_INTERNET></b>:443 remote=<b><CLIENT/BROWSER_IP>:</b>58232 FD 40 flags=33,
MXID_1101703) [call34733258]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.070 kid1| 5,5| AsyncCall.cc(38) make: make call httpsAccept [call34733258]<o:p></o:p></p>
<p class="MsoNormal"> 2019/02/06 17:23:19.070 kid1| 33,4| client_side.cc(2776) httpsAccept: local<b>=<ORIGIN_SERVER_ON_THE_INTERNET></b>:443 remote=<b><CLIENT/BROWSER_IP></b>:58232 FD 40 flags=33 accepted, starting SSL negotiation.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">3)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Squid checks the SSL ACLs for the destination IP.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,5| Acl.cc(124) matches: checking (ssl_bump rules)<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,5| Checklist.cc(397) bannedAction: Action 'ALLOWED/6' is not banned<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,5| Acl.cc(124) matches: checking (ssl_bump rule)<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,5| Acl.cc(124) matches: checking no_ssl_bump_src_ip<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,3| Ip.cc(538) match: aclIpMatchIp: '<b><CLIENT/BROWSER_IP></b>:58232' NOT found<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,3| Acl.cc(151) matches: checked: no_ssl_bump_src_ip = 0<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">4)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Squid decides to allow connections to the remote IP i.e <b>
<ORIGIN_SERVER_ON_THE_INTERNET></b> and decides to peek at the SNI (will accept ClientHello), hence fakes a CONNECT request<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x1fb19fd8 answer=ALLOWED<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 33,2| client_side.cc(2744) httpsSslBumpAccessCheckDone: sslBump action peekneeded for local=<b><ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 remote=<<b>CLIENT/BROWSER_IP>:</b>58232 FD 40
flags=33<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.071 kid1| 33,2| client_side.cc(3395) fakeAConnectRequest: fake a CONNECT request to force connState to tunnel for ssl-bump<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">5)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>The FAKE connect requests again runs through ACLs. 20ms are spent for DNS PTR lookup. A total of 30ms is spent parsing ACLs.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.103 kid1| 85,2| client_side_request.cc(758) clientAccessCheckDone: The request CONNECT
<b><ORIGIN_SERVER_ON_THE_INTERNET></b> is ALLOWED; last ACL checked: localnet<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.103 kid1| 93,4| AccessCheck.cc(145) checkCandidates: NO candidates left<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.103 kid1| 93,3| AccessCheck.cc(196) callBack: NULL<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.103 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Initiator::noteAdaptationAclCheckDone constructed, this=0x1552b0b0 [call34733267]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">6)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>FAKE connect is processed and Squid reads the TCP connection, gets the ClientHello and reads the SNI.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 33,5| AsyncCall.cc(38) make: make call Server::doClientRead [call34733270]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 33,5| AsyncJob.cc(123) callStart: Http1::Server status in: [ job2971436]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 33,5| Server.cc(104) doClientRead: local<b>=<ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 remote<b>=<CLIENT/BROWSER_IP></b>:58232 FD 40 flags=33<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 5,3| Read.cc(92) ReadNow: local=<<b>ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 remote=<<b>CLIENT/BROWSER_IP</b>>:58232 FD 40 flags=33, size 4096, retval 203, errno 0<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::requestTimeout constructed, this=0x3d42d40 [call34733271]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 5,3| comm.cc(559) commSetConnTimeout: local=<b><ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 remote=<b><CLIENT/BROWSER_IP>:</b>58232 FD 40 flags=33 timeout 300<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 83,5| Handshake.cc(404) parseExtensions: first unsupported extension: 19018<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.104 kid1| 83,3| Handshake.cc(497) parseSniExtension: host_name=<b><ORIGIN_SERVER_SNI></b><o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">7)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>This is followed by another round of ACL processing now that we have the SNI.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.106 kid1| 33,3| Pipeline.cc(35) front: Pipeline 0xc2d7b60 front 0x1ae2e730*2<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.106 kid1| 33,3| Pipeline.cc(35) front: Pipeline 0xc2d7b60 front 0x1ae2e730*3<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 83,5| Session.cc(103) NewSessionObject: SSL_new session=0x78136a0<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 83,5| bio.cc(616) squid_bio_ctrl: 0xcd0fe80 104(6000, 0x7ffc32a6e6b4)<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 83,5| Session.cc(162) CreateSession: link FD 40 to TLS session=0x78136a0<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 33,5| client_side.cc(2535) httpsCreate: will negotiate TLS on local=<<b>ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 remote=<<b>CLIENT/BROWSER_IP</b>>:58232 FD 40 flags=33<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 5,5| ModEpoll.cc(117) SetSelect: FD 40, type=1, handler=0, client_data=0, timeout=0<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 83,5| client_side.cc(3324) startPeekAndSplice: Peek and splice at step2 done. Start forwarding the request!!!<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.107 kid1| 17,3| FwdState.cc(340) Start: '<<b>ORIGIN_SERVER_ON_THE_INTERNET</b>>:443'<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">8)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>No ServerHello has been sent back to the client yet, Squid starts a TCP connection with the origin server<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.110 kid1| 5,4| AsyncJob.cc(123) callStart: Comm::ConnOpener status in: [ job2971439]<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.110 kid1| 5,5| ConnOpener.cc(350) doConnect: local=0.0.0.0 remote<b>=<ORIGIN_SERVER_ON_THE_INTERNET>:</b>443 flags=1: Comm::OK - connected<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.110 kid1| 5,4| ConnOpener.cc(155) cleanFd: local=0.0.0.0 remote=<<b>ORIGIN_SERVER_ON_THE_INTERNET</b>>:443 flags=1 closing temp FD 50<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoListParagraph" style="text-indent:-.25in;mso-list:l0 level1 lfo1"><![if !supportLists]><span style="mso-list:Ignore">9)<span style="font:7.0pt "Times New Roman"">
</span></span><![endif]>Squid starts a TLS session with the remote/origin server, sends the ClientHello. A total of 0.4 seconds in Squid sending clienthello to origin server. This is probably when Squid decides to send back the ServerHello to the browser.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.110 kid1| 83,5| Session.cc(103) NewSessionObject: SSL_new session=0x14899390<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.111 kid1| 83,5| bio.cc(616) squid_bio_ctrl: 0x1492ef80 104(6001, 0x7ffc32a6e884)<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.111 kid1| 83,5| Session.cc(162) CreateSession: link FD 50 to TLS session=0x14899390<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">2019/02/06 17:23:19.111 kid1| 83,5| PeerConnector.cc(123) initialize: local=<b><SQUID_IP></b>:44498 remote=<b><ORIGIN_SERVER_ON_THE_INTERNET></b>:443 FD 50 flags=1, session=0x14899390<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">So somewhere between Step 8 and Step 9, Squid is taking over 20s.
<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">What could possibly be keeping it busy ?
<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">I have external ACL helpers but they work just fine. Average service time is 1ms. Squid has not even spawning all helpers that it has been configured to do. (not exhausted the upper limit).
<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in">DNS resolution is also good. All CPU/MEM resources look just fine and again this affects only a subset of the traffic. I don’t have the failure logs from when this actually happens.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">UPDATE: This problem statement seems local to a few websites. Outside of the proxy, those websites quite quickly as is expected.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">Any thoughts on where to look ? other bits and pieces I could check ? I have jumbo frames enabled (9000 bytes) but am running the proxies at L2 1500 MTU.<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal" style="margin-left:.25in">-Ahmad<o:p></o:p></p>
<p class="MsoNormal" style="margin-left:.25in"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
</body>
</html>