Hi, I can't seem to be able to bump Twitter. Whenever a client tries to browse https://twitter.com there's a connection refusal error page (111). Any clue as to what I could try? # grep -v ^# squid.test.conf | grep -v ^$ http_access allow localhost manager http_access deny manager http_port 3227 http_port 3228 tproxy https_port 3229 tproxy ssl-bump generate-host-certificates=on dynamic_cert_mem_cache_size=16MB cert=/etc/ssl/squid/proxyserver.pem acl localnet src 10.0.0.0/8 # RFC1918 possible internal network acl localnet src 192.168.0.0/16 # RFC1918 possible internal network acl localnet src fc00::/7 # RFC 4193 local private network range acl interceptedhttp myportname 3228 acl interceptedhttps myportname 3229 http_access deny interceptedhttp !localnet http_access deny interceptedhttps !localnet sslcrtd_program /usr/libexec/squid/ssl_crtd -s /var/lib/squid/ssl_db_test -M 16MB sslcrtd_children 10 reply_header_access Alternate-Protocol deny all ssl_bump stare all ssl_bump bump all cache_dir diskd /var/cache/squid.test 100 16 256 http_access allow localnet http_access allow localhost http_access deny all coredump_dir /var/cache/squid refresh_pattern ^ftp: 1440 20% 10080 refresh_pattern ^gopher: 1440 0% 1440 refresh_pattern -i (/cgi-bin/|\?) 0 0% 0 refresh_pattern . 0 20% 4320 pid_filename /run/squid.test.pid access_log daemon:/var/log/squid/access.test.log squid cache_log /var/log/squid/cache.test.log debug_options rotate=1 ALL,5 # cat /var/log/squid/access.test.log 1496266616.296 200 10.215.144.48 TAG_NONE/200 0 CONNECT 199.16.156.6:443 - ORIGINAL_DST/199.16.156.6 - 1496266616.322 2 10.215.144.48 TAG_NONE/503 3902 GET https://twitter.com/ - HIER_NONE/- text/html # cat /var/log/squid/cache.test.log 2017/05/31 23:36:55.778 kid1| 41,5| AsyncCall.cc(38) make: make call logfileFlush [call140] 2017/05/31 23:36:55.778 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving logfileFlush(0x80945048*?) 2017/05/31 23:36:56.093 kid1| 5,2| TcpAcceptor.cc(220) doAccept: New connection on FD 33 2017/05/31 23:36:56.093 kid1| 5,2| TcpAcceptor.cc(295) acceptNext: connection on local=[::]:3229 remote=[::] FD 33 flags=25 2017/05/31 23:36:56.093 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 13 HTTP Request 2017/05/31 23:36:56.093 kid1| 89,5| Intercept.cc(375) Lookup: address BEGIN: me/client= 199.16.156.6:443, destination/me= 10.215.144.48:42597 2017/05/31 23:36:56.093 kid1| 89,5| Intercept.cc(169) TproxyTransparent: address TPROXY: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.093 kid1| 28,4| Eui48.cc(178) lookup: id=0x80cefb18 query ARP table 2017/05/31 23:36:56.093 kid1| 28,4| Eui48.cc(221) lookup: id=0x80cefb18 query ARP on each interface (512 found) 2017/05/31 23:36:56.093 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface lo 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp1s7 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp1s7 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp1s7 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp1s7 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp1s8 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp1s8 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp2s0f0 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp2s0f0 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp2s0f1 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp2s0f1 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(227) lookup: id=0x80cefb18 found interface enp0s8 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(236) lookup: id=0x80cefb18 looking up ARP address for 10.215.144.48 on enp0s8 2017/05/31 23:36:56.094 kid1| 28,4| Eui48.cc(279) lookup: id=0x80cefb18 got address 64:31:50:17:9a:fd on enp0s8 2017/05/31 23:36:56.094 kid1| 5,5| TcpAcceptor.cc(287) acceptOne: Listener: local=[::]:3229 remote=[::] FD 33 flags=25 accepted new connection local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 handler Subscription: 0x80cef9d8*1 2017/05/31 23:36:56.094 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall httpsAccept constructed, this=0x80d66d88 [call141] 2017/05/31 23:36:56.094 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: TcpAcceptor.cc(317) will call httpsAccept(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, MXID_2) [call141] 2017/05/31 23:36:56.094 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 33, type=1, handler=1, client_data=0x80cef6e8, timeout=0 2017/05/31 23:36:56.094 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering httpsAccept(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, MXID_2) 2017/05/31 23:36:56.094 kid1| 5,5| AsyncCall.cc(38) make: make call httpsAccept [call141] 2017/05/31 23:36:56.094 kid1| 33,4| client_side.cc(3920) httpsAccept: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 accepted, starting SSL negotiation. 2017/05/31 23:36:56.094 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d60a74 type=Http::Server [job8] 2017/05/31 23:36:56.094 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x80d77ce0 [call142] 2017/05/31 23:36:56.094 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: AsyncJob.cc(26) will call AsyncJob::start() [call142] 2017/05/31 23:36:56.094 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving httpsAccept(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, MXID_2) 2017/05/31 23:36:56.094 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start() 2017/05/31 23:36:56.094 kid1| 93,5| AsyncCall.cc(38) make: make call AsyncJob::start [call142] 2017/05/31 23:36:56.094 kid1| 93,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job8] 2017/05/31 23:36:56.094 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::connStateClosed constructed, this=0x80924868 [call143] 2017/05/31 23:36:56.094 kid1| 5,5| comm.cc(993) comm_add_close_handler: comm_add_close_handler: FD 13, AsyncCall=0x80924868*1 2017/05/31 23:36:56.094 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbfb501bc 2017/05/31 23:36:56.094 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbfb501bc 2017/05/31 23:36:56.094 kid1| 33,5| client_side.cc(3938) postHttpsAccept: accept transparent connection: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.094 kid1| 23,3| HttpRequest.h(82) SetHost: HttpRequest::SetHost() given IP: 199.16.156.6 2017/05/31 23:36:56.094 kid1| 28,3| Checklist.cc(70) preCheck: 0x80d634c8 checking slow rules 2017/05/31 23:36:56.094 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rules) 2017/05/31 23:36:56.094 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/4is not banned 2017/05/31 23:36:56.094 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rule) 2017/05/31 23:36:56.094 kid1| 28,5| Acl.cc(138) matches: checking all 2017/05/31 23:36:56.094 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.48' found 2017/05/31 23:36:56.094 kid1| 28,3| Acl.cc(158) matches: checked: all = 1 2017/05/31 23:36:56.094 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rule) = 1 2017/05/31 23:36:56.094 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rules) = 1 2017/05/31 23:36:56.094 kid1| 28,3| Checklist.cc(63) markFinished: 0x80d634c8 answer ALLOWED for match 2017/05/31 23:36:56.095 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80d634c8 answer=ALLOWED 2017/05/31 23:36:56.095 kid1| 33,2| client_side.cc(3896) httpsSslBumpAccessCheckDone: sslBump needed for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 method 4 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: attempting to parse 2017/05/31 23:36:56.095 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is CONNECT 199.16.156.6:443 HTTP/1.1 Host: 199.16.156.6:443 2017/05/31 23:36:56.095 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request: CONNECT 199.16.156.6:443 HTTP/1.1 Host: 199.16.156.6:443 2017/05/31 23:36:56.095 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval 1: from 0->34: method 0->6; url 8->23; version 25->32 (1/1) 2017/05/31 23:36:56.095 kid1| 33,3| client_side.cc(2258) parseHttpRequest: parseHttpRequest: req_hdr = {Host: 199.16.156.6:443 } 2017/05/31 23:36:56.095 kid1| 33,3| client_side.cc(2262) parseHttpRequest: parseHttpRequest: end = { } 2017/05/31 23:36:56.095 kid1| 33,3| client_side.cc(2266) parseHttpRequest: parseHttpRequest: prefix_sz = 61, req_line_sz = 35 2017/05/31 23:36:56.095 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d63e80 type=ClientHttpRequest [job9] 2017/05/31 23:36:56.095 kid1| 87,3| clientStream.cc(144) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x80d65688 with data 0x80d6561c after head 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(2282) parseHttpRequest: parseHttpRequest: Request Header is Host: 199.16.156.6:443 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(2303) parseHttpRequest: Prepare absolute URL from intercept 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(2342) parseHttpRequest: parseHttpRequest: Complete request received 2017/05/31 23:36:56.095 kid1| 11,2| client_side.cc(2345) parseHttpRequest: HTTP Client local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.095 kid1| 11,2| client_side.cc(2346) parseHttpRequest: HTTP Client REQUEST: --------- CONNECT 199.16.156.6:443 HTTP/1.1 Host: 199.16.156.6:443 ---------- 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(3221) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: done parsing a request 2017/05/31 23:36:56.095 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x80d66d88 [call144] 2017/05/31 23:36:56.095 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 timeout 86400 2017/05/31 23:36:56.095 kid1| 23,3| url.cc(357) urlParse: urlParse: Split URL '199.16.156.6:443' into proto='', host='199.16.156.6', port='443', path='' 2017/05/31 23:36:56.095 kid1| 23,3| HttpRequest.h(82) SetHost: HttpRequest::SetHost() given IP: 199.16.156.6 2017/05/31 23:36:56.095 kid1| 33,3| client_side.cc(873) clientSetKeepaliveFlag: http_ver = HTTP/1.1 2017/05/31 23:36:56.095 kid1| 33,3| client_side.cc(874) clientSetKeepaliveFlag: method = CONNECT 2017/05/31 23:36:56.095 kid1| 33,3| client_side.h(96) mayUseConnection: This 0x80d645d8 marked 1 2017/05/31 23:36:56.095 kid1| 33,5| client_side.cc(2422) consumeInput: in.buf has 0 unused bytes 2017/05/31 23:36:56.095 kid1| 85,3| client_side_request.cc(130) ClientRequestContext: 0x80d67898 ClientRequestContext constructed 2017/05/31 23:36:56.095 kid1| 83,3| client_side_request.cc(1684) doCallouts: Doing calloutContext->hostHeaderVerify() 2017/05/31 23:36:56.095 kid1| 85,3| client_side_request.cc(631) hostHeaderVerify: validate host=199.16.156.6, port=443, portStr=443 2017/05/31 23:36:56.095 kid1| 14,4| ipcache.cc(501) ipcache_nbgethostbyname: ipcache_nbgethostbyname: Name '199.16.156.6'. 2017/05/31 23:36:56.095 kid1| 14,4| ipcache.cc(810) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '199.16.156.6' == 199.16.156.6 2017/05/31 23:36:56.095 kid1| 14,4| ipcache.cc(514) ipcache_nbgethostbyname: ipcache_nbgethostbyname: BYPASS for '199.16.156.6' (already numeric) 2017/05/31 23:36:56.095 kid1| 85,3| client_side_request.cc(524) hostHeaderIpVerify: validate IP 199.16.156.6:443 possible from Host: 2017/05/31 23:36:56.095 kid1| 83,3| client_side_request.cc(1691) doCallouts: Doing calloutContext->clientAccessCheck() 2017/05/31 23:36:56.095 kid1| 28,3| Checklist.cc(70) preCheck: 0x80d678e0 checking slow rules 2017/05/31 23:36:56.095 kid1| 28,5| Acl.cc(138) matches: checking http_access 2017/05/31 23:36:56.095 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/0is not banned 2017/05/31 23:36:56.095 kid1| 28,5| Acl.cc(138) matches: checking http_access#1 2017/05/31 23:36:56.095 kid1| 28,5| Acl.cc(138) matches: checking localhost 2017/05/31 23:36:56.095 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.48' NOT found 2017/05/31 23:36:56.095 kid1| 28,3| Acl.cc(158) matches: checked: localhost = 0 2017/05/31 23:36:56.095 kid1| 28,3| Acl.cc(158) matches: checked: http_access#1 = 0 2017/05/31 23:36:56.095 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned 2017/05/31 23:36:56.095 kid1| 28,5| Acl.cc(138) matches: checking http_access#2 2017/05/31 23:36:56.095 kid1| 28,5| Acl.cc(138) matches: checking manager 2017/05/31 23:36:56.095 kid1| 28,3| RegexData.cc(51) match: aclRegexData::match: checking '199.16.156.6:443' 2017/05/31 23:36:56.095 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(^cache_object://)' 2017/05/31 23:36:56.095 kid1| 28,3| RegexData.cc(62) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)' 2017/05/31 23:36:56.095 kid1| 28,3| Acl.cc(158) matches: checked: manager = 0 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: http_access#2 = 0 2017/05/31 23:36:56.096 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking http_access#3 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking interceptedhttp 2017/05/31 23:36:56.096 kid1| 28,3| StringData.cc(34) match: aclMatchStringList: checking '3229' 2017/05/31 23:36:56.096 kid1| 28,3| StringData.cc(37) match: aclMatchStringList: '3229' NOT found 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: interceptedhttp = 0 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: http_access#3 = 0 2017/05/31 23:36:56.096 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'DENIED/0is not banned 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking http_access#4 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking interceptedhttps 2017/05/31 23:36:56.096 kid1| 28,3| StringData.cc(34) match: aclMatchStringList: checking '3229' 2017/05/31 23:36:56.096 kid1| 28,3| StringData.cc(37) match: aclMatchStringList: '3229' found 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: interceptedhttps = 1 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking !localnet 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking localnet 2017/05/31 23:36:56.096 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.48' found 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: localnet = 1 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: !localnet = 0 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: http_access#4 = 0 2017/05/31 23:36:56.096 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/0is not banned 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking http_access#5 2017/05/31 23:36:56.096 kid1| 28,5| Acl.cc(138) matches: checking localnet 2017/05/31 23:36:56.096 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.48' found 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: localnet = 1 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: http_access#5 = 1 2017/05/31 23:36:56.096 kid1| 28,3| Acl.cc(158) matches: checked: http_access = 1 2017/05/31 23:36:56.096 kid1| 28,3| Checklist.cc(63) markFinished: 0x80d678e0 answer ALLOWED for match 2017/05/31 23:36:56.096 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80d678e0 answer=ALLOWED 2017/05/31 23:36:56.096 kid1| 85,2| client_side_request.cc(741) clientAccessCheckDone: The request CONNECT 199.16.156.6:443 is ALLOWED; last ACL checked: localnet 2017/05/31 23:36:56.096 kid1| 83,3| AccessCheck.cc(42) Start: adaptation off, skipping 2017/05/31 23:36:56.096 kid1| 83,3| client_side_request.cc(1719) doCallouts: Doing calloutContext->clientAccessCheck2() 2017/05/31 23:36:56.096 kid1| 85,2| client_side_request.cc(717) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW 2017/05/31 23:36:56.096 kid1| 85,2| client_side_request.cc(741) clientAccessCheckDone: The request CONNECT 199.16.156.6:443 is ALLOWED; last ACL checked: localnet 2017/05/31 23:36:56.096 kid1| 83,3| client_side_request.cc(1737) doCallouts: Doing clientInterpretRequestHeaders() 2017/05/31 23:36:56.096 kid1| 85,5| client_side_request.cc(1173) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET 2017/05/31 23:36:56.096 kid1| 85,5| client_side_request.cc(1175) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_CACHABLE = SET 2017/05/31 23:36:56.096 kid1| 85,5| client_side_request.cc(1177) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_HIERARCHICAL = NOT SET 2017/05/31 23:36:56.096 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbfb4f34c 2017/05/31 23:36:56.096 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbfb4f34c 2017/05/31 23:36:56.096 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbfb4f34c 2017/05/31 23:36:56.096 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbfb4f34c 2017/05/31 23:36:56.096 kid1| 85,5| client_side_request.cc(1419) sslBumpAccessCheck: SslBump already decided (4), ignoring ssl_bump for 0x80d60950 2017/05/31 23:36:56.096 kid1| 83,3| client_side_request.cc(1528) sslBumpNeed: sslBump required: stare 2017/05/31 23:36:56.096 kid1| 85,3| client_side_request.cc(115) ~ClientRequestContext: 0x80d67898 ClientRequestContext destructed 2017/05/31 23:36:56.096 kid1| 83,3| client_side_request.cc(1828) doCallouts: calling processRequest() 2017/05/31 23:36:56.096 kid1| 85,4| client_side_request.cc(1491) processRequest: CONNECT 199.16.156.6:443 2017/05/31 23:36:56.096 kid1| 85,5| client_side_request.cc(1574) sslBumpStart: Confirming stare-bumped CONNECT tunnel on FD local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.096 kid1| 85,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ClientSocketContext::sslBumpEstablish constructed, this=0x80d60a90 [call145] 2017/05/31 23:36:56.096 kid1| 85,5| AsyncCall.cc(93) ScheduleCall: client_side_request.cc(1584) will call ClientSocketContext::sslBumpEstablish(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d63dc8) [call145] 2017/05/31 23:36:56.096 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80d678e0 2017/05/31 23:36:56.096 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x80d678e0 2017/05/31 23:36:56.096 kid1| 33,3| client_side.cc(3233) clientParseRequests: Not parsing new requests, as this request may need the connection 2017/05/31 23:36:56.097 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80d634c8 2017/05/31 23:36:56.097 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x80d634c8 2017/05/31 23:36:56.097 kid1| 93,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job8] 2017/05/31 23:36:56.097 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start() 2017/05/31 23:36:56.097 kid1| 85,5| AsyncCallQueue.cc(55) fireNext: entering ClientSocketContext::sslBumpEstablish(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d63dc8) 2017/05/31 23:36:56.097 kid1| 85,5| AsyncCall.cc(38) make: make call ClientSocketContext::sslBumpEstablish [call145] 2017/05/31 23:36:56.097 kid1| 85,5| client_side_request.cc(1537) SslBumpEstablish: responded to CONNECT: 0x80d63dc8 ? 0 2017/05/31 23:36:56.097 kid1| 33,5| client_side.cc(4237) switchToHttps: converting local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 to SSL 2017/05/31 23:36:56.097 kid1| 33,4| ServerBump.cc(27) ServerBump: will peek at 199.16.156.6:443 2017/05/31 23:36:56.097 kid1| 20,3| store.cc(779) storeCreatePureEntry: storeCreateEntry: '199.16.156.6:443' 2017/05/31 23:36:56.097 kid1| 20,5| store.cc(371) StoreEntry: StoreEntry constructed, this=0x80c213e0 2017/05/31 23:36:56.097 kid1| 20,3| MemObject.cc(97) MemObject: new MemObject 0x80d63708 2017/05/31 23:36:56.097 kid1| 20,3| store.cc(484) lock: storeCreateEntry locked key [null_store_key] e:=V/0x80c213e0*1 2017/05/31 23:36:56.097 kid1| 20,3| store_key_md5.cc(89) storeKeyPrivate: storeKeyPrivate: CONNECT 199.16.156.6:443 2017/05/31 23:36:56.097 kid1| 20,3| store.cc(448) hashInsert: StoreEntry::hashInsert: Inserting Entry e:=IV/0x80c213e0*1 key 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.097 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80d8fe20 104(6000, 0xbfb50158) 2017/05/31 23:36:56.097 kid1| 33,5| client_side.cc(3693) httpsCreate: will negotate SSL on local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.097 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.097 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.097 kid1| 85,5| AsyncCallQueue.cc(57) fireNext: leaving ClientSocketContext::sslBumpEstablish(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d63dc8) 2017/05/31 23:36:56.097 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.097 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.097 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.097 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.097 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.097 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.097 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.097 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.098 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.098 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.098 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.099 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.099 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.099 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.099 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.100 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.100 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.100 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.100 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 11 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 11 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 11 bytes of TLS client Hello 2017/05/31 23:36:56.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.100 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.100 kid1| 83,5| client_side.cc(4267) clientPeekAndSpliceSSL: Start peek and splice on FD 13 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(118) read: FD 13 read 8 <= 11 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(144) readAndBuffer: read 8 out of 11 bytes 2017/05/31 23:36:56.100 kid1| 83,5| bio.cc(148) readAndBuffer: recorded 8 bytes of TLS client Hello 2017/05/31 23:36:56.101 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.101 kid1| 83,2| client_side.cc(4270) clientPeekAndSpliceSSL: SSL_accept failed. 2017/05/31 23:36:56.101 kid1| 83,5| client_side.cc(4284) clientPeekAndSpliceSSL: I got hello. Start forwarding the request!!! 2017/05/31 23:36:56.101 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.101 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.101 kid1| 28,3| Checklist.cc(70) preCheck: 0x80d634c8 checking slow rules 2017/05/31 23:36:56.101 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rules) 2017/05/31 23:36:56.101 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/4is not banned 2017/05/31 23:36:56.101 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rule) 2017/05/31 23:36:56.101 kid1| 28,5| Acl.cc(138) matches: checking all 2017/05/31 23:36:56.101 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.144.48' found 2017/05/31 23:36:56.101 kid1| 28,3| Acl.cc(158) matches: checked: all = 1 2017/05/31 23:36:56.101 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rule) = 1 2017/05/31 23:36:56.101 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rules) = 1 2017/05/31 23:36:56.101 kid1| 28,3| Checklist.cc(63) markFinished: 0x80d634c8 answer ALLOWED for match 2017/05/31 23:36:56.101 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80d634c8 answer=ALLOWED 2017/05/31 23:36:56.101 kid1| 33,5| client_side.cc(4322) httpsSslBumpStep2AccessCheckDone: Answer: ALLOWED kind:4 2017/05/31 23:36:56.101 kid1| 17,3| FwdState.cc(331) Start: '199.16.156.6:443' 2017/05/31 23:36:56.101 kid1| 17,2| FwdState.cc(132) FwdState: Forwarding client request local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, url=199.16.156.6:443 2017/05/31 23:36:56.101 kid1| 20,3| store.cc(484) lock: FwdState locked key D1806996FC89FCA8A2553AF78760C5D4 e:=IV/0x80c213e0*2 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(137) peerSelect: e:=IWV/0x80c213e0*2 199.16.156.6:443 2017/05/31 23:36:56.101 kid1| 20,3| store.cc(484) lock: peerSelect locked key D1806996FC89FCA8A2553AF78760C5D4 e:=IWV/0x80c213e0*3 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(441) peerSelectFoo: CONNECT 199.16.156.6 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(401) peerCheckNetdbDirect: peerCheckNetdbDirect: MY RTT = 0 msec 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(402) peerCheckNetdbDirect: peerCheckNetdbDirect: minimum_direct_rtt = 400 msec 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(409) peerCheckNetdbDirect: peerCheckNetdbDirect: MY hops = 0 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(410) peerCheckNetdbDirect: peerCheckNetdbDirect: minimum_direct_hops = 4 2017/05/31 23:36:56.101 kid1| 15,3| neighbors.cc(100) whichPeer: whichPeer: from [::] 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(474) peerSelectFoo: peerSelectFoo: direct = DIRECT_MAYBE (default) 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(477) peerSelectFoo: peerSelectFoo: direct = DIRECT_MAYBE 2017/05/31 23:36:56.101 kid1| 14,3| ipcache.cc(619) ipcache_gethostbyname: ipcache_gethostbyname: '199.16.156.6', flags=0 2017/05/31 23:36:56.101 kid1| 14,4| ipcache.cc(810) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '199.16.156.6' == 199.16.156.6 2017/05/31 23:36:56.101 kid1| 14,5| net_db.cc(365) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 199.16.156.6/24. 2017/05/31 23:36:56.101 kid1| 14,5| net_db.cc(369) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 199.16.156.6/24. 2017/05/31 23:36:56.101 kid1| 44,3| peer_select.cc(110) peerSelectIcpPing: peerSelectIcpPing: 199.16.156.6:443 2017/05/31 23:36:56.101 kid1| 44,5| peer_select.cc(940) peerAddFwdServer: peerAddFwdServer: adding DIRECT HIER_DIRECT 2017/05/31 23:36:56.101 kid1| 44,2| peer_select.cc(280) peerSelectDnsPaths: Found sources for '199.16.156.6:443' 2017/05/31 23:36:56.101 kid1| 44,2| peer_select.cc(281) peerSelectDnsPaths: always_direct = DENIED 2017/05/31 23:36:56.101 kid1| 44,2| peer_select.cc(282) peerSelectDnsPaths: never_direct = DENIED 2017/05/31 23:36:56.101 kid1| 44,2| peer_select.cc(288) peerSelectDnsPaths: ORIGINAL_DST = local=10.215.144.48 remote=199.16.156.6:443 flags=25 2017/05/31 23:36:56.101 kid1| 44,2| peer_select.cc(295) peerSelectDnsPaths: timedout = 0 2017/05/31 23:36:56.101 kid1| 17,3| FwdState.cc(386) startConnectionOrFail: 199.16.156.6:443 2017/05/31 23:36:56.101 kid1| 17,3| FwdState.cc(804) connectStart: fwdConnectStart: 199.16.156.6:443 2017/05/31 23:36:56.101 kid1| 48,3| pconn.cc(439) pop: lookup for key {199.16.156.6:443/199.16.156.6} failed. 2017/05/31 23:36:56.102 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbfb4fabc 2017/05/31 23:36:56.102 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbfb4fabc 2017/05/31 23:36:56.102 kid1| 17,3| FwdState.cc(1304) GetMarkingsToServer: from 10.215.144.48 netfilter mark 0 2017/05/31 23:36:56.102 kid1| 17,3| AsyncCall.cc(26) AsyncCall: The AsyncCall fwdConnectDoneWrapper constructed, this=0x80d92248 [call146] 2017/05/31 23:36:56.102 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d78b40 type=Comm::ConnOpener [job10] 2017/05/31 23:36:56.102 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x80d92290 [call147] 2017/05/31 23:36:56.102 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: AsyncJob.cc(26) will call AsyncJob::start() [call147] 2017/05/31 23:36:56.102 kid1| 44,3| peer_select.cc(79) ~ps_state: 199.16.156.6:443 2017/05/31 23:36:56.102 kid1| 20,3| store.cc(522) unlock: peerSelect unlocking key D1806996FC89FCA8A2553AF78760C5D4 e:=p2IWV/0x80c213e0*3 2017/05/31 23:36:56.102 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80d634c8 2017/05/31 23:36:56.102 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x80d634c8 2017/05/31 23:36:56.102 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start() 2017/05/31 23:36:56.102 kid1| 93,5| AsyncCall.cc(38) make: make call AsyncJob::start [call147] 2017/05/31 23:36:56.102 kid1| 93,5| AsyncJob.cc(123) callStart: Comm::ConnOpener status in: [ job10] 2017/05/31 23:36:56.102 kid1| 50,3| comm.cc(347) comm_openex: comm_openex: Attempt open socket for: 10.215.144.48 2017/05/31 23:36:56.102 kid1| 50,3| comm.cc(388) comm_openex: comm_openex: Opened socket local=10.215.144.48 remote=[::] FD 15 flags=1 : family=2, type=1, protocol=6 2017/05/31 23:36:56.102 kid1| 5,5| comm.cc(420) comm_init_opened: local=10.215.144.48 remote=[::] FD 15 flags=1 is a new socket 2017/05/31 23:36:56.102 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 15 199.16.156.6 2017/05/31 23:36:56.102 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall Comm::ConnOpener::earlyAbort constructed, this=0x80d90490 [call148] 2017/05/31 23:36:56.102 kid1| 5,5| comm.cc(993) comm_add_close_handler: comm_add_close_handler: FD 15, AsyncCall=0x80d90490*1 2017/05/31 23:36:56.102 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall Comm::ConnOpener::timeout constructed, this=0x80d904e0 [call149] 2017/05/31 23:36:56.102 kid1| 5,3| ConnOpener.cc(289) createFd: local=10.215.144.48 remote=199.16.156.6:443 flags=25 will timeout in 60 2017/05/31 23:36:56.102 kid1| 5,5| comm.cc(644) comm_connect_addr: sock=15, addrinfo( flags=4, family=2, socktype=1, protocol=6, &addr=0x80d922d0, addrlen=16 ) 2017/05/31 23:36:56.102 kid1| 5,5| ConnOpener.cc(343) doConnect: local=10.215.144.48 remote=199.16.156.6:443 flags=25: Comm::INPROGRESS 2017/05/31 23:36:56.102 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 15, type=2, handler=1, client_data=0x80d90530, timeout=0 2017/05/31 23:36:56.102 kid1| 93,5| AsyncJob.cc(152) callEnd: Comm::ConnOpener status out: [ job10] 2017/05/31 23:36:56.102 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start() 2017/05/31 23:36:56.293 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 15, type=1, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall Comm::ConnOpener::doConnect constructed, this=0x80d92290 [call150] 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(460) will call Comm::ConnOpener::doConnect() [call150] 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering Comm::ConnOpener::doConnect() 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(38) make: make call Comm::ConnOpener::doConnect [call150] 2017/05/31 23:36:56.293 kid1| 5,4| AsyncJob.cc(123) callStart: Comm::ConnOpener status in: [ job10] 2017/05/31 23:36:56.293 kid1| 5,5| ConnOpener.cc(365) doConnect: local=10.215.144.48 remote=199.16.156.6:443 flags=25: * - ERR tried too many times already. 2017/05/31 23:36:56.293 kid1| 17,3| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(137) will call fwdConnectDoneWrapper(local=10.215.144.48 remote=199.16.156.6:443 flags=25, errno=111, flag=-8, data=0x80d67d10) [call146] 2017/05/31 23:36:56.293 kid1| 93,5| AsyncJob.cc(84) mustStop: Comm::ConnOpener will stop, reason: Comm::ConnOpener::doConnect 2017/05/31 23:36:56.293 kid1| 93,5| AsyncJob.cc(137) callEnd: Comm::ConnOpener::doConnect() ends job [Stopped, reason:Comm::ConnOpener::doConnect job10] 2017/05/31 23:36:56.293 kid1| 5,4| ConnOpener.cc(153) cleanFd: local=10.215.144.48 remote=199.16.156.6:443 flags=25 closing temp FD 15 2017/05/31 23:36:56.293 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 15, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(56) cancel: will not call Comm::ConnOpener::timeout [call149] because Comm::ConnOpener::cleanFd 2017/05/31 23:36:56.293 kid1| 5,5| comm.cc(1038) comm_remove_close_handler: comm_remove_close_handler: FD 15, AsyncCall=0x80d90490*2 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(56) cancel: will not call Comm::ConnOpener::earlyAbort [call148] because comm_remove_close_handler 2017/05/31 23:36:56.293 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 15 2017/05/31 23:36:56.293 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 15 2017/05/31 23:36:56.293 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 15 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80d90490 [call151] 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 15) [call151] 2017/05/31 23:36:56.293 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d78b40 type=Comm::ConnOpener [job10] 2017/05/31 23:36:56.293 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving Comm::ConnOpener::doConnect() 2017/05/31 23:36:56.293 kid1| 17,3| AsyncCallQueue.cc(55) fireNext: entering fwdConnectDoneWrapper(local=10.215.144.48 remote=199.16.156.6:443 flags=25, errno=111, flag=-8, data=0x80d67d10) 2017/05/31 23:36:56.293 kid1| 17,3| AsyncCall.cc(38) make: make call fwdConnectDoneWrapper [call146] 2017/05/31 23:36:56.293 kid1| 17,3| FwdState.cc(415) fail: ERR_CONNECT_FAIL "Service Unavailable" 199.16.156.6:443 2017/05/31 23:36:56.293 kid1| 17,3| FwdState.cc(616) retryOrBail: re-forwarding (0 tries, 0 secs) 2017/05/31 23:36:56.293 kid1| 17,3| FwdState.cc(386) startConnectionOrFail: 199.16.156.6:443 2017/05/31 23:36:56.293 kid1| 17,3| FwdState.cc(403) startConnectionOrFail: Connection failed: 199.16.156.6:443 2017/05/31 23:36:56.293 kid1| 17,3| FwdState.cc(265) ~FwdState: FwdState destructor starting 2017/05/31 23:36:56.293 kid1| 46,5| access_log.cc(289) stopPeerClock: First connection started: 1496266616.101970, current total response time value: -1 2017/05/31 23:36:56.293 kid1| 4,4| errorpage.cc(603) errorAppendEntry: Creating an error page for entry 0x80c213e0 with errorstate 0x80d93298 page id 11 2017/05/31 23:36:56.293 kid1| 4,2| errorpage.cc(1262) BuildContent: No existing error page language negotiated for ERR_CONNECT_FAIL. Using default error file. 2017/05/31 23:36:56.293 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%l --> '/* * Copyright (C) 1996-2015 The Squid Software Foundation and contributors * * Squid software is distributed under GPLv2+ license and includes * contributions from numerous individuals and organizations. * Please see the COPYING and CONTRIBUTORS files for details. */ /* Stylesheet for Squid Error pages [REMOVED FOR A SHORTER POST] ' 2017/05/31 23:36:56.293 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%; --> '%;' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_CONNECT_FAIL' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%U --> 'https://199.16.156.6/*' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%U --> 'https://199.16.156.6/*' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%I --> '199.16.156.6' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%E --> '(111) Connection refused' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%W --> '?subject=CacheErrorInfo%20-%20ERR_CONNECT_FAIL&body=CacheHost%3A%20inf-fw1%0D%0AErrPage%3A%20ERR_CONNECT_FAIL%0D%0AErr%3A%20(111)%20Connection%20refused%0D%0ATimeStamp%3A%20Wed,%2031%20May%202017%2021%3A36%3A56%20GMT%0D%0A%0D%0AClientIP%3A%2010.215.144.48%0D%0AServerIP%3A%20199.16.156.6%0D%0A%0D%0AHTTP%20Request%3A%0D%0ACONNECT%20%2F%20HTTP%2F1.1%0AHost%3A%20199.16.156.6%3A443%0D%0A%0D%0A%0D%0A' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%T --> 'Wed, 31 May 2017 21:36:56 GMT' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%h --> 'inf-fw1' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%s --> 'squid/3.5.14' 2017/05/31 23:36:56.294 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_CONNECT_FAIL' 2017/05/31 23:36:56.294 kid1| 11,5| HttpRequest.cc(474) detailError: current error details: 11/111 2017/05/31 23:36:56.294 kid1| 20,3| store.cc(484) lock: StoreEntry::storeErrorResponse locked key D1806996FC89FCA8A2553AF78760C5D4 e:=p2IWV/0x80c213e0*3 2017/05/31 23:36:56.294 kid1| 20,3| store.cc(1867) replaceHttpReply: StoreEntry::replaceHttpReply: 199.16.156.6:443 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 34 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 6 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 3 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 29 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 23 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 14 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 13 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.294 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 20 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 15 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 16 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(834) write: storeWrite: writing 3525 bytes for 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(985) checkCachable: StoreEntry::checkCachable: NO: private key 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable 2017/05/31 23:36:56.295 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/05/31 23:36:56.295 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: D1806996FC89FCA8A2553AF78760C5D4 2017/05/31 23:36:56.295 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(1053) complete: storeComplete: 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(1342) validLength: storeEntryValidLength: Checking 'D1806996FC89FCA8A2553AF78760C5D4' 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(1344) validLength: storeEntryValidLength: object_len = 3782 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(1345) validLength: storeEntryValidLength: hdr_sz = 257 2017/05/31 23:36:56.295 kid1| 20,5| store.cc(1346) validLength: storeEntryValidLength: content_length = 3525 2017/05/31 23:36:56.295 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut: already rejected 2017/05/31 23:36:56.295 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/05/31 23:36:56.295 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: D1806996FC89FCA8A2553AF78760C5D4 2017/05/31 23:36:56.295 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(522) unlock: StoreEntry::storeErrorResponse unlocking key D1806996FC89FCA8A2553AF78760C5D4 e:=sp2XINV/0x80c213e0*3 2017/05/31 23:36:56.295 kid1| 17,4| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::ConnStateData::httpsPeeked constructed, this=0x80d93320 [call152] 2017/05/31 23:36:56.295 kid1| 17,4| AsyncCall.cc(93) ScheduleCall: FwdState.cc(248) will call ConnStateData::ConnStateData::httpsPeeked() [call152] 2017/05/31 23:36:56.295 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 1 2017/05/31 23:36:56.295 kid1| 20,3| store.cc(522) unlock: FwdState unlocking key D1806996FC89FCA8A2553AF78760C5D4 e:=sp2XINV/0x80c213e0*2 2017/05/31 23:36:56.295 kid1| 17,3| AsyncCall.cc(56) cancel: will not call fwdConnectDoneWrapper [call146] because FwdState destructed 2017/05/31 23:36:56.295 kid1| 17,3| FwdState.cc(292) ~FwdState: FwdState destructor done 2017/05/31 23:36:56.295 kid1| 17,3| AsyncCallQueue.cc(57) fireNext: leaving fwdConnectDoneWrapper(local=10.215.144.48 remote=199.16.156.6:443 flags=25, errno=111, flag=-8, data=0x80d67d10) 2017/05/31 23:36:56.295 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 15) 2017/05/31 23:36:56.295 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call151] 2017/05/31 23:36:56.295 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 15 199.16.156.6 2017/05/31 23:36:56.295 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 15, type=1, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.295 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 15, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.295 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0 2017/05/31 23:36:56.295 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 15) 2017/05/31 23:36:56.295 kid1| 17,4| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::ConnStateData::httpsPeeked() 2017/05/31 23:36:56.295 kid1| 17,4| AsyncCall.cc(38) make: make call ConnStateData::ConnStateData::httpsPeeked [call152] 2017/05/31 23:36:56.295 kid1| 17,4| AsyncJob.cc(123) callStart: Http::Server status in: [ job8] 2017/05/31 23:36:56.295 kid1| 33,5| client_side.cc(4411) httpsPeeked: Error while bumping: 199.16.156.6 2017/05/31 23:36:56.295 kid1| 11,5| HttpRequest.cc(473) detailError: old error details: 11/111 2017/05/31 23:36:56.296 kid1| 11,5| HttpRequest.cc(474) detailError: current error details: 11/111 2017/05/31 23:36:56.296 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d65688 2017/05/31 23:36:56.296 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d65688 2017/05/31 23:36:56.296 kid1| 87,3| clientStream.cc(223) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x80d66a08 2017/05/31 23:36:56.296 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d65638 2017/05/31 23:36:56.296 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d65638 2017/05/31 23:36:56.296 kid1| 33,3| client_side_request.cc(246) ~ClientHttpRequest: httpRequestFree: 199.16.156.6:443 2017/05/31 23:36:56.296 kid1| 33,5| client_side.cc(576) logRequest: logging half-baked transaction: 199.16.156.6:443 2017/05/31 23:36:56.296 kid1| 28,3| Checklist.cc(70) preCheck: 0xbfb4fe7c checking fast ACLs 2017/05/31 23:36:56.296 kid1| 28,5| Acl.cc(138) matches: checking access_log daemon:/var/log/squid/access.test.log 2017/05/31 23:36:56.296 kid1| 28,5| Acl.cc(138) matches: checking (access_log daemon:/var/log/squid/access.test.log line) 2017/05/31 23:36:56.296 kid1| 28,3| Acl.cc(158) matches: checked: (access_log daemon:/var/log/squid/access.test.log line) = 1 2017/05/31 23:36:56.296 kid1| 28,3| Acl.cc(158) matches: checked: access_log daemon:/var/log/squid/access.test.log = 1 2017/05/31 23:36:56.296 kid1| 28,3| Checklist.cc(63) markFinished: 0xbfb4fe7c answer ALLOWED for match 2017/05/31 23:36:56.296 kid1| 50,5| ModDaemon.cc(65) logfileNewBuffer: logfileNewBuffer: daemon:/var/log/squid/access.test.log: new buffer 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 1 bytes 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 106 bytes 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 2 bytes 2017/05/31 23:36:56.296 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 107 of 32768 bytes before append 2017/05/31 23:36:56.296 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=1, client_data=0x80945048, timeout=0 2017/05/31 23:36:56.296 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbfb4fe7c 2017/05/31 23:36:56.296 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbfb4fe7c 2017/05/31 23:36:56.296 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x80d92248 [call153] 2017/05/31 23:36:56.296 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: Initiator.cc(40) will call Initiate::noteInitiatorAborted() [call153] 2017/05/31 23:36:56.296 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d63e80 type=ClientHttpRequest [job9] 2017/05/31 23:36:56.296 kid1| 33,5| client_side.cc(4135) getSslContextStart: Generating SSL certificate for twitter.com using ssl_crtd. 2017/05/31 23:36:56.296 kid1| 33,5| client_side.cc(4139) getSslContextStart: SSL crtd request: new_certificate 3238 host=twitter.com Sign=signTrusted SignHash=SHA256 -----BEGIN CERTIFICATE----- MII [REMOVED FOR A SHORTER POST] -----END CERTIFICATE----- -----BEGIN PRIVATE KEY----- MII [REMOVED FOR A SHORTER POST] -----END PRIVATE KEY----- 2017/05/31 23:36:56.296 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5 2017/05/31 23:36:56.296 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0x80d8eef8 [call154] 2017/05/31 23:36:56.296 kid1| 5,5| Write.cc(35) Write: local=[::] remote=[::] FD 10 flags=1: sz 3260: asynCall 0x80d8eef8*1 2017/05/31 23:36:56.296 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=1, client_data=0x808fe194, timeout=0 2017/05/31 23:36:56.296 kid1| 84,5| helper.cc(1309) helperDispatch: helperDispatch: Request sent to ssl_crtd #Hlpr1, 3260 bytes 2017/05/31 23:36:56.296 kid1| 17,4| AsyncJob.cc(152) callEnd: Http::Server status out: [ job8] 2017/05/31 23:36:56.296 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::ConnStateData::httpsPeeked() 2017/05/31 23:36:56.297 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted() 2017/05/31 23:36:56.297 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call153] 2017/05/31 23:36:56.297 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call153] because job gone 2017/05/31 23:36:56.297 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call153] because of job gone 2017/05/31 23:36:56.297 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted() 2017/05/31 23:36:56.297 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.test.log: write returned 109 2017/05/31 23:36:56.297 kid1| 5,5| Write.cc(66) HandleWrite: local=[::] remote=[::] FD 10 flags=1: off 0, sz 3260. 2017/05/31 23:36:56.297 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 3260 2017/05/31 23:36:56.297 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0) 2017/05/31 23:36:56.297 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=3260, buf=0x80d7ae10) [call154] 2017/05/31 23:36:56.297 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=3260, buf=0x80d7ae10) 2017/05/31 23:36:56.297 kid1| 5,5| AsyncCall.cc(38) make: make call helperDispatchWriteDone [call154] 2017/05/31 23:36:56.297 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=3260, buf=0x80d7ae10) 2017/05/31 23:36:56.297 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.297 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.300 kid1| 5,3| Read.cc(144) HandleRead: FD 10, size 4095, retval 2905, errno 0 2017/05/31 23:36:56.300 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0) 2017/05/31 23:36:56.300 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=2905, buf=0x809234f0) [call111] 2017/05/31 23:36:56.300 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=2905, buf=0x809234f0) 2017/05/31 23:36:56.300 kid1| 5,4| AsyncCall.cc(38) make: make call helperHandleRead [call111] 2017/05/31 23:36:56.300 kid1| 84,5| helper.cc(866) helperHandleRead: helperHandleRead: 2905 bytes from ssl_crtd #Hlpr1 2017/05/31 23:36:56.300 kid1| 84,3| helper.cc(892) helperHandleRead: helperHandleRead: end of reply found 2017/05/31 23:36:56.300 kid1| 84,3| Reply.cc(29) parse: Parsing helper buffer 2017/05/31 23:36:56.300 kid1| 84,3| Reply.cc(48) parse: Buff length is larger than 2 2017/05/31 23:36:56.300 kid1| 84,3| Reply.cc(52) parse: helper Result = OK 2017/05/31 23:36:56.300 kid1| 33,5| client_side.cc(3992) sslCrtdHandleReply: Certificate for 199.16.156.6 was successfully recieved from ssl_crtd 2017/05/31 23:36:56.300 kid1| 33,5| client_side.cc(4394) doPeekAndSpliceStep: PeekAndSplice mode, proceed with client negotiation. Currrent state:SSLv2/v3 read client hello A 2017/05/31 23:36:56.300 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.301 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5 2017/05/31 23:36:56.301 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall helperHandleRead constructed, this=0x80d78220 [call155] 2017/05/31 23:36:56.301 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=[::] remote=[::] FD 10 flags=1; asynCall 0x80d78220*1 2017/05/31 23:36:56.301 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=1, handler=1, client_data=0x808fe16c, timeout=0 2017/05/31 23:36:56.301 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x809233a8, size=2905, buf=0x809234f0) 2017/05/31 23:36:56.301 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80d8fe20 6(0, 0x80d92248) 2017/05/31 23:36:56.301 kid1| 83,5| support.cc(2154) get_session_cb: Request to search for SSL Session of len:32272931686:268141813 2017/05/31 23:36:56.301 kid1| 54,5| MemMap.cc(148) openForReading: trying to open slot for key 669B4410F584FB0F9A063B581AD8A05B for reading in map [ssl_session_cache] 2017/05/31 23:36:56.301 kid1| 54,5| MemMap.cc(169) openForReadingAt: trying to open slot at 51 for reading in map [ssl_session_cache] 2017/05/31 23:36:56.301 kid1| 54,5| MemMap.cc(161) openForReading: failed to open slot for key 669B4410F584FB0F9A063B581AD8A05B for reading in map [ssl_session_cache] 2017/05/31 23:36:56.301 kid1| 83,5| support.cc(2169) get_session_cb: Failed to retrieved from cache 2017/05/31 23:36:56.301 kid1| 83,5| bio.cc(95) write: FD 13 wrote 918 <= 918 2017/05/31 23:36:56.301 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80d8fe20 11(0, 0) 2017/05/31 23:36:56.301 kid1| 83,5| bio.cc(118) read: FD 13 read -1 <= 5 2017/05/31 23:36:56.301 kid1| 83,5| bio.cc(123) read: error: 11 ignored: 1 2017/05/31 23:36:56.301 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x80d60950, timeout=0 2017/05/31 23:36:56.301 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.302 kid1| 83,5| bio.cc(118) read: FD 13 read 5 <= 5 2017/05/31 23:36:56.302 kid1| 83,5| bio.cc(118) read: FD 13 read 262 <= 262 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(118) read: FD 13 read 5 <= 5 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(118) read: FD 13 read 1 <= 1 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(118) read: FD 13 read 5 <= 5 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(118) read: FD 13 read 64 <= 64 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(95) write: FD 13 wrote 266 <= 266 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80d8fe20 11(0, 0) 2017/05/31 23:36:56.318 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80d8fe20 7(0, 0x80d92248) -----BEGIN SSL SESSION PARAMETERS----- MGACAQECAgMDBAIALwQABDDdX0DcPIcUITJcdR7aVovBoj+LZ/5wkReoH845k907 vgdlroH/auAfzPOm6P9xXIehBgIEWS83eKIEAgIBLKQCBACmDQQLdHdpdHRlci5j b20= -----END SSL SESSION PARAMETERS----- 2017/05/31 23:36:56.318 kid1| 83,2| client_side.cc(3796) clientNegotiateSSL: clientNegotiateSSL: New session 0x80d8b330 on FD 13 (10.215.144.48:42597) 2017/05/31 23:36:56.318 kid1| 83,3| client_side.cc(3800) clientNegotiateSSL: clientNegotiateSSL: FD 13 negotiated cipher AES128-SHA 2017/05/31 23:36:56.318 kid1| 83,5| client_side.cc(3816) clientNegotiateSSL: clientNegotiateSSL: FD 13 has no certificate. 2017/05/31 23:36:56.318 kid1| 33,4| client_side.cc(231) readSomeData: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: reading request... 2017/05/31 23:36:56.318 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80d7abc8 [call156] 2017/05/31 23:36:56.318 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17; asynCall 0x80d7abc8*1 2017/05/31 23:36:56.318 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x808fe268, timeout=0 2017/05/31 23:36:56.318 kid1| 5,3| IoCallback.cc(116) finish: called for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 (0, 0) 2017/05/31 23:36:56.318 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) [call156] 2017/05/31 23:36:56.318 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) 2017/05/31 23:36:56.318 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call156] 2017/05/31 23:36:56.318 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job8] 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.319 kid1| 83,5| bio.cc(118) read: FD 13 read 5 <= 5 2017/05/31 23:36:56.319 kid1| 83,5| bio.cc(118) read: FD 13 read 432 <= 432 2017/05/31 23:36:56.319 kid1| 83,2| support.cc(1364) ssl_read_method: SSL FD 13 is pending 2017/05/31 23:36:56.319 kid1| 5,3| Read.cc(91) ReadNow: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, size 66, retval 66, errno 0 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: attempting to parse 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Window 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request: GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Window 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval 1: from 0->15: method 0->2; url 4->4; version 6->13 (1/1) 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(2194) parseHttpRequest: Incomplete request, waiting for end of headers 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3238) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: not enough request data: 66 < 65536 2017/05/31 23:36:56.319 kid1| 33,4| client_side.cc(231) readSomeData: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: reading request... 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80d8ea80 [call157] 2017/05/31 23:36:56.319 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17; asynCall 0x80d8ea80*1 2017/05/31 23:36:56.319 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x808fe268, timeout=0 2017/05/31 23:36:56.319 kid1| 33,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job8] 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) 2017/05/31 23:36:56.319 kid1| 5,3| IoCallback.cc(116) finish: called for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 (0, 0) 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) [call157] 2017/05/31 23:36:56.319 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call157] 2017/05/31 23:36:56.319 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job8] 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.319 kid1| 83,2| support.cc(1364) ssl_read_method: SSL FD 13 is pending 2017/05/31 23:36:56.319 kid1| 5,3| Read.cc(91) ReadNow: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, size 61, retval 61, errno 0 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: attempting to parse 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/ 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request: GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/ 2017/05/31 23:36:56.319 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval 1: from 0->15: method 0->2; url 4->4; version 6->13 (1/1) 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(2194) parseHttpRequest: Incomplete request, waiting for end of headers 2017/05/31 23:36:56.319 kid1| 33,5| client_side.cc(3238) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: not enough request data: 127 < 65536 2017/05/31 23:36:56.319 kid1| 33,4| client_side.cc(231) readSomeData: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: reading request... 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80d7abc8 [call158] 2017/05/31 23:36:56.319 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17; asynCall 0x80d7abc8*1 2017/05/31 23:36:56.319 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=1, handler=1, client_data=0x808fe268, timeout=0 2017/05/31 23:36:56.319 kid1| 33,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job8] 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) 2017/05/31 23:36:56.319 kid1| 5,3| IoCallback.cc(116) finish: called for local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 (0, 0) 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) [call158] 2017/05/31 23:36:56.319 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=0, client_data=0, timeout=0 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, data=0x80d60950) 2017/05/31 23:36:56.319 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call158] 2017/05/31 23:36:56.319 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job8] 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.320 kid1| 33,2| client_side.cc(2370) maybeMakeSpaceAvailable: growing request buffer: available=385 used=127 2017/05/31 23:36:56.320 kid1| 5,3| Read.cc(91) ReadNow: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17, size 385, retval 268, errno 0 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: attempting to parse 2017/05/31 23:36:56.320 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: es-ES,es;q=0.8,en-US;q=0.5,en;q=0.3 Accept-Encoding: gzip, deflate, br Cookie: guest_id=v1%3A149087497487789376; personalization_id="v1_zoGltEgEbV7jirFVg/rLKg==" Connection: keep-alive 2017/05/31 23:36:56.320 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request: GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: es-ES,es;q=0.8,en-US;q=0.5,en;q=0.3 Accept-Encoding: gzip, deflate, br Cookie: guest_id=v1%3A149087497487789376; personalization_id="v1_zoGltEgEbV7jirFVg/rLKg==" Connection: keep-alive 2017/05/31 23:36:56.320 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval 1: from 0->15: method 0->2; url 4->4; version 6->13 (1/1) 2017/05/31 23:36:56.320 kid1| 33,3| client_side.cc(2258) parseHttpRequest: parseHttpRequest: req_hdr = {Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: es-ES,es;q=0.8,en-US;q=0.5,en;q=0.3 Accept-Encoding: gzip, deflate, br Cookie: guest_id=v1%3A149087497487789376; personalization_id="v1_zoGltEgEbV7jirFVg/rLKg==" Connection: keep-alive } 2017/05/31 23:36:56.320 kid1| 33,3| client_side.cc(2262) parseHttpRequest: parseHttpRequest: end = { } 2017/05/31 23:36:56.320 kid1| 33,3| client_side.cc(2266) parseHttpRequest: parseHttpRequest: prefix_sz = 395, req_line_sz = 16 2017/05/31 23:36:56.320 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d8c238 type=ClientHttpRequest [job11] 2017/05/31 23:36:56.320 kid1| 87,3| clientStream.cc(144) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x80d65688 with data 0x80d6561c after head 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(2282) parseHttpRequest: parseHttpRequest: Request Header is Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: es-ES,es;q=0.8,en-US;q=0.5,en;q=0.3 Accept-Encoding: gzip, deflate, br Cookie: guest_id=v1%3A149087497487789376; personalization_id="v1_zoGltEgEbV7jirFVg/rLKg==" Connection: keep-alive 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(2303) parseHttpRequest: Prepare absolute URL from intercept 2017/05/31 23:36:56.320 kid1| 25,5| mime_header.cc(37) mime_get_header_field: mime_get_header: looking for 'Host' 2017/05/31 23:36:56.320 kid1| 25,5| mime_header.cc(59) mime_get_header_field: mime_get_header: checking 'Host: twitter.com' 2017/05/31 23:36:56.320 kid1| 25,5| mime_header.cc(82) mime_get_header_field: mime_get_header: returning 'twitter.com' 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(2125) prepareTransparentURL: TRANSPARENT HOST REWRITE: 'https://twitter.com/' 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(2342) parseHttpRequest: parseHttpRequest: Complete request received 2017/05/31 23:36:56.320 kid1| 11,2| client_side.cc(2345) parseHttpRequest: HTTP Client local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.320 kid1| 11,2| client_side.cc(2346) parseHttpRequest: HTTP Client REQUEST: --------- GET / HTTP/1.1 Host: twitter.com User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:45.0) Gecko/20100101 Firefox/45.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: es-ES,es;q=0.8,en-US;q=0.5,en;q=0.3 Accept-Encoding: gzip, deflate, br Cookie: guest_id=v1%3A149087497487789376; personalization_id="v1_zoGltEgEbV7jirFVg/rLKg==" Connection: keep-alive ---------- 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(3221) clientParseRequests: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17: done parsing a request 2017/05/31 23:36:56.320 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x80d92248 [call159] 2017/05/31 23:36:56.320 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 timeout 86400 2017/05/31 23:36:56.320 kid1| 23,3| url.cc(357) urlParse: urlParse: Split URL 'https://twitter.com/' into proto='https', host='twitter.com', port='443', path='/' 2017/05/31 23:36:56.320 kid1| 14,3| Address.cc(389) lookupHostIP: Given Non-IP 'twitter.com': Name or service not known 2017/05/31 23:36:56.320 kid1| 33,3| client_side.cc(873) clientSetKeepaliveFlag: http_ver = HTTP/1.1 2017/05/31 23:36:56.320 kid1| 33,3| client_side.cc(874) clientSetKeepaliveFlag: method = GET 2017/05/31 23:36:56.320 kid1| 33,4| client_side.cc(2455) quitAfterError: Will close after error: local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(2476) serveDelayedError: Responding with delated error for https://twitter.com/ 2017/05/31 23:36:56.320 kid1| 20,3| store.cc(484) lock: clientReplyContext::setReplyToStoreEntry locked key D1806996FC89FCA8A2553AF78760C5D4 e:=sp2XINV/0x80c213e0*2 2017/05/31 23:36:56.320 kid1| 11,5| HttpRequest.cc(474) detailError: current error details: 11/111 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(1709) pullData: 0 written 0 into local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.320 kid1| 33,5| client_side.cc(1665) getNextRangeOffset: range: 0; http offset 0; reply 0 2017/05/31 23:36:56.320 kid1| 87,3| clientStream.cc(184) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x80d66a08 from node 0x80d65688 2017/05/31 23:36:56.320 kid1| 90,3| store_client.cc(200) copy: store_client::copy: D1806996FC89FCA8A2553AF78760C5D4, from 0, for length 4096, cb 1, cbdata 0x80d659a0 2017/05/31 23:36:56.320 kid1| 20,3| store.cc(484) lock: store_client::copy locked key D1806996FC89FCA8A2553AF78760C5D4 e:=sp2XINV/0x80c213e0*3 2017/05/31 23:36:56.320 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: D1806996FC89FCA8A2553AF78760C5D4 2017/05/31 23:36:56.320 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 0, hi: 3782 2017/05/31 23:36:56.320 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory 2017/05/31 23:36:56.320 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: https://twitter.com/, 3782 bytes (3782 new bytes) 2017/05/31 23:36:56.320 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 '199.16.156.6:443' out.offset=0 2017/05/31 23:36:56.321 kid1| 88,2| client_side_reply.cc(2001) processReplyAccessResult: The reply for GET https://twitter.com/ is ALLOWED, because it matched (access_log daemon:/var/log/squid/access.test.log line) 2017/05/31 23:36:56.321 kid1| 20,3| store.cc(484) lock: ClientHttpRequest::loggingEntry locked key D1806996FC89FCA8A2553AF78760C5D4 e:=sp2XINV/0x80c213e0*4 2017/05/31 23:36:56.321 kid1| 88,3| client_side_reply.cc(2039) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 3525 bytes after 257 bytes of headers 2017/05/31 23:36:56.321 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x80d6561c from node 0x80d65638 2017/05/31 23:36:56.321 kid1| 11,2| client_side.cc(1391) sendStartOfMessage: HTTP Client local=199.16.156.6:443 remote=10.215.144.48 FD 13 flags=17 2017/05/31 23:36:56.321 kid1| 11,2| client_side.cc(1392) sendStartOfMessage: HTTP Client REPLY: --------- HTTP/1.1 503 Service Unavailable Server: squid/3.5.14 Mime-Version: 1.0 Date: Wed, 31 May 2017 21:36:56 GMT Content-Type: text/html;charset=utf-8 Content-Length: 3525 X-Squid-Error: ERR_CONNECT_FAIL 111 Vary: Accept-Language Content-Language: en X-Cache: MISS from inf-fw1 X-Cache-Lookup: NONE from inf-fw1:3227 Via: 1.1 inf-fw1 (squid/3.5.14) Connection: close Thanks, Vieri _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
