[squid-users] failed to bump Twitter
Vieri
rentorbuy at yahoo.com
Wed May 31 21:49:11 UTC 2017
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
More information about the squid-users
mailing list