________________________________ From: Alex Rousskov <rousskov@xxxxxxxxxxxxxxxxxxxxxxx> > >> 1496665088.143 6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- >> text/html> > I recommend finding the place in the debugging cache.log where Squid > generates the above error response and then going backwards to find the > cause. OK Alex, got it. In the meantime, I searched for the events around the time this happened. BTW as a side question I'd like to know if I can change the timestamp in cache.log so it can print the unixtime as in access.log. In any case, here's the relevant part: [Mon Jun 5 14:18:08 2017].143 6 10.215.145.187 TAG_NONE/400 4428 NONE error:invalid-request - HIER_NONE/- text/html cache.log within 14:18:08: 2017/06/05 14:18:08 kid1| hold write on SSL connection on FD 30 2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(70) preCheck: 0x80d21df8 checking slow rules 2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rules) 2017/06/05 14:18:08.000 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/4 is banned 2017/06/05 14:18:08.000 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/5is not banned 2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking (ssl_bump rule) 2017/06/05 14:18:08.000 kid1| 28,5| Acl.cc(138) matches: checking all 2017/06/05 14:18:08.000 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.145.187' found 2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: all = 1 2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rule) = 1 2017/06/05 14:18:08.000 kid1| 28,3| Acl.cc(158) matches: checked: (ssl_bump rules) = 1 2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(63) markFinished: 0x80d21df8 answer ALLOWED for match 2017/06/05 14:18:08.000 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x80d21df8 answer=ALLOWED 2017/06/05 14:18:08.000 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80d21df8 2017/06/05 14:18:08.000 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x80d21df8 2017/06/05 14:18:08.000 kid1| 83,5| PeerConnector.cc(418) checkForPeekAndSpliceMatched: Will check for peek and splice on FD 30 2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=1, client_data=0x80d36e50, timeout=0 2017/06/05 14:18:08.000 kid1| 83,5| PeerConnector.cc(436) checkForPeekAndSpliceMatched: Retry the fwdNegotiateSSL on FD 30 2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(95) write: FD 30 wrote 150 <= 150 2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e60900 11(0, 0) 2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(118) read: FD 30 read -1 <= 5 2017/06/05 14:18:08.000 kid1| 83,5| bio.cc(123) read: error: 11 ignored: 1 2017/06/05 14:18:08.000 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25 timeout 59 2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=1, client_data=0x80d36e50, timeout=0 2017/06/05 14:18:08.000 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 5 <= 5 2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 1 <= 1 2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 5 <= 5 2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(118) read: FD 30 read 64 <= 64 2017/06/05 14:18:08.096 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e60900 7(0, 0x80e6f868) 2017/06/05 14:18:08.096 kid1| 83,5| PeerConnector.cc(307) serverCertificateVerified: HTTPS server CN: *.acms.com bumped: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25 2017/06/05 14:18:08.096 kid1| 5,5| comm.cc(1038) comm_remove_close_handler: comm_remove_close_handler: FD 30, AsyncCall=0x80e60820*2 2017/06/05 14:18:08.096 kid1| 9,5| AsyncCall.cc(56) cancel: will not call Ssl::PeerConnector::commCloseHandler [call2554] because comm_remove_close_handler 2017/06/05 14:18:08.096 kid1| 17,4| AsyncCall.cc(93) ScheduleCall: PeerConnector.cc(742) will call FwdState::ConnectedToPeer(0x80d4b730, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0) [call2552] 2017/06/05 14:18:08.096 kid1| 93,5| AsyncJob.cc(137) callEnd: Ssl::PeerConnector::negotiateSsl() ends job [ FD 30 job59] 2017/06/05 14:18:08.096 kid1| 83,5| PeerConnector.cc(58) ~PeerConnector: Peer connector 0x80d36e50 gone 2017/06/05 14:18:08.096 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d36e74 type=Ssl::PeerConnector [job59] 2017/06/05 14:18:08.096 kid1| 17,4| AsyncCallQueue.cc(55) fireNext: entering FwdState::ConnectedToPeer(0x80d4b730, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0) 2017/06/05 14:18:08.096 kid1| 17,4| AsyncCall.cc(38) make: make call FwdState::ConnectedToPeer [call2552] 2017/06/05 14:18:08.096 kid1| 17,3| FwdState.cc(905) dispatch: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: Fetching CONNECT 46.51.187.18:443 2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(501) ipcache_nbgethostbyname: ipcache_nbgethostbyname: Name '46.51.187.18'. 2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(810) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '46.51.187.18' == 46.51.187.18 2017/06/05 14:18:08.096 kid1| 14,4| ipcache.cc(514) ipcache_nbgethostbyname: ipcache_nbgethostbyname: BYPASS for '46.51.187.18' (already numeric) 2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(365) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24. 2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(369) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24. 2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(365) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24. 2017/06/05 14:18:08.096 kid1| 14,5| net_db.cc(369) networkFromInaddr: networkFromInaddr : Masked IPv4 Address to 46.51.187.18/24. 2017/06/05 14:18:08.097 kid1| 38,3| net_db.cc(325) netdbSendPing: netdbSendPing: pinging 46.51.187.18 2017/06/05 14:18:08.097 kid1| 37,4| IcmpSquid.cc(181) DomainPing: '46.51.187.18' (46.51.187.18) 2017/06/05 14:18:08.097 kid1| 37,2| IcmpSquid.cc(90) SendEcho: to 46.51.187.18, opcode 3, len 12 2017/06/05 14:18:08.097| 42,2| IcmpPinger.cc(198) Recv: Pass 46.51.187.18 off to ICMPv4 module. 2017/06/05 14:18:08.097| 42,5| Icmp4.cc(135) SendEcho: Send ICMP packet to 46.51.187.18. 2017/06/05 14:18:08.097| 42,2| Icmp.cc(95) Log: pingerLog: 1496665088.097213 46.51.187.18 32 2017/06/05 14:18:08.097 kid1| 17,4| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::ConnStateData::httpsPeeked constructed, this=0x80e60728 [call2561] 2017/06/05 14:18:08.097 kid1| 17,4| AsyncCall.cc(93) ScheduleCall: FwdState.cc(952) will call ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25) [call2561] 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(446) unregister: 46.51.187.18:443 2017/06/05 14:18:08.097 kid1| 5,5| comm.cc(1011) comm_remove_close_handler: comm_remove_close_handler: FD 30, handler=1, data=0x80d4b730 2017/06/05 14:18:08.097 kid1| 5,4| AsyncCall.cc(56) cancel: will not call SomeCloseHandler [call2551] because comm_remove_close_handler 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(471) complete: 46.51.187.18:443 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(1043) reforward: 46.51.187.18:443? 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(1058) reforward: No alternative forwarding paths left 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(495) complete: server (FD closed) not re-forwarding status 0 2017/06/05 14:18:08.097 kid1| 20,3| store.cc(1053) complete: storeComplete: '52E847A2F8AF07D9783AAE4A91F2E9E6' 2017/06/05 14:18:08.097 kid1| 20,3| store.cc(1342) validLength: storeEntryValidLength: Checking '52E847A2F8AF07D9783AAE4A91F2E9E6' 2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1344) validLength: storeEntryValidLength: object_len = 0 2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1345) validLength: storeEntryValidLength: hdr_sz = 0 2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1346) validLength: storeEntryValidLength: content_length = -1 2017/06/05 14:18:08.097 kid1| 20,5| store.cc(1349) validLength: storeEntryValidLength: Unspecified content length: 52E847A2F8AF07D9783AAE4A91F2E9E6 2017/06/05 14:18:08.097 kid1| 20,3| store.cc(985) checkCachable: StoreEntry::checkCachable: NO: private key 2017/06/05 14:18:08.097 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: '52E847A2F8AF07D9783AAE4A91F2E9E6' 2017/06/05 14:18:08.097 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable 2017/06/05 14:18:08.097 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 52E847A2F8AF07D9783AAE4A91F2E9E6 2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0 2017/06/05 14:18:08.097 kid1| 46,5| access_log.cc(289) stopPeerClock: First connection started: 1496665087.724223, current total response time value: -1 2017/06/05 14:18:08.097 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 1 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(265) ~FwdState: FwdState destructor starting 2017/06/05 14:18:08.097 kid1| 20,3| store.cc(522) unlock: FwdState unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2 2017/06/05 14:18:08.097 kid1| 17,3| AsyncCall.cc(56) cancel: will not call fwdConnectDoneWrapper [call2544] because FwdState destructed 2017/06/05 14:18:08.097 kid1| 17,3| FwdState.cc(292) ~FwdState: FwdState destructor done 2017/06/05 14:18:08.098 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving FwdState::ConnectedToPeer(0, local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25, 0/0) 2017/06/05 14:18:08.098 kid1| 17,4| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25) 2017/06/05 14:18:08.098 kid1| 17,4| AsyncCall.cc(38) make: make call ConnStateData::ConnStateData::httpsPeeked [call2561] 2017/06/05 14:18:08.098 kid1| 17,4| AsyncJob.cc(123) callStart: Http::Server status in: [ job56] 2017/06/05 14:18:08.098 kid1| 33,3| client_side.cc(5106) unpinConnection: 2017/06/05 14:18:08.098 kid1| 33,3| client_side.cc(4938) pinNewConnection: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25 2017/06/05 14:18:08.098 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientPinnedConnectionClosed constructed, this=0x80e84ea0 [call2562] 2017/06/05 14:18:08.098 kid1| 5,5| comm.cc(993) comm_add_close_handler: comm_add_close_handler: FD 30, AsyncCall=0x80e84ea0*1 2017/06/05 14:18:08.098 kid1| 33,3| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientPinnedConnectionRead constructed, this=0x80e84790 [call2563] 2017/06/05 14:18:08.098 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25; asynCall 0x80e84790*1 2017/06/05 14:18:08.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=1, client_data=0x808b490c, timeout=0 2017/06/05 14:18:08.098 kid1| 33,5| client_side.cc(4409) httpsPeeked: bumped HTTPS server: 46.51.187.18 2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39c38 2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39c38 2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(223) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x80d39bc8 2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39be8 2017/06/05 14:18:08.098 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39be8 2017/06/05 14:18:08.098 kid1| 33,3| client_side_request.cc(246) ~ClientHttpRequest: httpRequestFree: 46.51.187.18:443 2017/06/05 14:18:08.098 kid1| 33,5| client_side.cc(576) logRequest: logging half-baked transaction: 46.51.187.18:443 2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf839e8c checking fast ACLs 2017/06/05 14:18:08.098 kid1| 28,5| Acl.cc(138) matches: checking access_log daemon:/var/log/squid/access.test.log 2017/06/05 14:18:08.098 kid1| 28,5| Acl.cc(138) matches: checking (access_log daemon:/var/log/squid/access.test.log line) 2017/06/05 14:18:08.098 kid1| 28,3| Acl.cc(158) matches: checked: (access_log daemon:/var/log/squid/access.test.log line) = 1 2017/06/05 14:18:08.098 kid1| 28,3| Acl.cc(158) matches: checked: access_log daemon:/var/log/squid/access.test.log = 1 2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf839e8c answer ALLOWED for match 2017/06/05 14:18:08.098 kid1| 50,5| ModDaemon.cc(65) logfileNewBuffer: logfileNewBuffer: daemon:/var/log/squid/access.test.log: new buffer 2017/06/05 14:18:08.098 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/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append 2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.test.log: appending 107 bytes 2017/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append 2017/06/05 14:18:08.098 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/06/05 14:18:08.098 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 108 of 32768 bytes before append 2017/06/05 14:18:08.098 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=1, client_data=0x808fb030, timeout=0 2017/06/05 14:18:08.098 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf839e8c 2017/06/05 14:18:08.098 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf839e8c 2017/06/05 14:18:08.098 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x80e84cb0 [call2564] 2017/06/05 14:18:08.098 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: Initiator.cc(40) will call Initiate::noteInitiatorAborted() [call2564] 2017/06/05 14:18:08.098 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d37708 type=ClientHttpRequest [job57] 2017/06/05 14:18:08.098 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signUntrusted 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signUntrusted line) 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking ssl::certUntrusted 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: ssl::certUntrusted = 0 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signUntrusted line) = 0 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signUntrusted = 0 2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer DENIED for ACLs failed to match 2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signSelf 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signSelf line) 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking ssl::certSelfSigned 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: ssl::certSelfSigned = 0 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signSelf line) = 0 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signSelf = 0 2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer DENIED for ACLs failed to match 2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf83a14c checking fast ACLs 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking sslproxy_cert_sign signTrusted 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking (sslproxy_cert_sign signTrusted line) 2017/06/05 14:18:08.099 kid1| 28,5| Acl.cc(138) matches: checking all 2017/06/05 14:18:08.099 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '10.215.145.187' found 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: all = 1 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: (sslproxy_cert_sign signTrusted line) = 1 2017/06/05 14:18:08.099 kid1| 28,3| Acl.cc(158) matches: checked: sslproxy_cert_sign signTrusted = 1 2017/06/05 14:18:08.099 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf83a14c answer ALLOWED for match 2017/06/05 14:18:08.099 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf83a14c 2017/06/05 14:18:08.099 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf83a14c 2017/06/05 14:18:08.099 kid1| 33,5| client_side.cc(4135) getSslContextStart: Generating SSL certificate for *.acms.com using ssl_crtd. 2017/06/05 14:18:08.099 kid1| 33,5| client_side.cc(4139) getSslContextStart: SSL crtd request: new_certificate 5112 host=*.acms.com 2017/06/05 14:18:08.099 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5 2017/06/05 14:18:08.099 kid1| 5,5| AsyncCall.cc(26) AsyncCall: The AsyncCall helperDispatchWriteDone constructed, this=0x80e6f6b8 [call2565] 2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(35) Write: local=[::] remote=[::] FD 10 flags=1: sz 5134: asynCall 0x80e6f6b8*1 2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=1, client_data=0x808b42a4, timeout=0 2017/06/05 14:18:08.100 kid1| 84,5| helper.cc(1309) helperDispatch: helperDispatch: Request sent to ssl_crtd #Hlpr1, 5134 bytes 2017/06/05 14:18:08.100 kid1| 17,4| AsyncJob.cc(152) callEnd: Http::Server status out: [ job56] 2017/06/05 14:18:08.100 kid1| 17,4| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::ConnStateData::httpsPeeked(local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25) 2017/06/05 14:18:08.100 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted() 2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call2564] 2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call2564] because job gone 2017/06/05 14:18:08.100 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call2564] because of job gone 2017/06/05 14:18:08.100 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted() 2017/06/05 14:18:08.100 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.test.log: write returned 110 2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(66) HandleWrite: local=[::] remote=[::] FD 10 flags=1: off 0, sz 5134. 2017/06/05 14:18:08.100 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 5134 2017/06/05 14:18:08.100 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0) 2017/06/05 14:18:08.100 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608) [call2565] 2017/06/05 14:18:08.100 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608) 2017/06/05 14:18:08.100 kid1| 5,5| AsyncCall.cc(38) make: make call helperDispatchWriteDone [call2565] 2017/06/05 14:18:08.100 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving helperDispatchWriteDone(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=5134, buf=0x80dd0608) 2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.100 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.106 kid1| 5,3| Read.cc(144) HandleRead: FD 10, size 8191, retval 3161, errno 0 2017/06/05 14:18:08.106 kid1| 5,3| IoCallback.cc(116) finish: called for local=[::] remote=[::] FD 10 flags=1 (0, 0) 2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8) [call2299] 2017/06/05 14:18:08.106 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8) 2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(38) make: make call helperHandleRead [call2299] 2017/06/05 14:18:08.106 kid1| 84,5| helper.cc(866) helperHandleRead: helperHandleRead: 3161 bytes from ssl_crtd #Hlpr1 2017/06/05 14:18:08.106 kid1| 84,3| helper.cc(892) helperHandleRead: helperHandleRead: end of reply found 2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(29) parse: Parsing helper buffer 2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(48) parse: Buff length is larger than 2 2017/06/05 14:18:08.106 kid1| 84,3| Reply.cc(52) parse: helper Result = OK 2017/06/05 14:18:08.106 kid1| 33,5| client_side.cc(3992) sslCrtdHandleReply: Certificate for 46.51.187.18 was successfully recieved from ssl_crtd 2017/06/05 14:18:08.106 kid1| 33,5| client_side.cc(4394) doPeekAndSpliceStep: PeekAndSplice mode, proceed with client negotiation. Currrent state:SSLv2/v3 read client hello A 2017/06/05 14:18:08.106 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x80e07e00, timeout=0 2017/06/05 14:18:08.106 kid1| 84,5| helper.cc(1167) GetFirstAvailable: GetFirstAvailable: Running servers 5 2017/06/05 14:18:08.106 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall helperHandleRead constructed, this=0x80e84cb0 [call2566] 2017/06/05 14:18:08.106 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=[::] remote=[::] FD 10 flags=1; asynCall 0x80e84cb0*1 2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 10, type=1, handler=1, client_data=0x808b427c, timeout=0 2017/06/05 14:18:08.107 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving helperHandleRead(local=[::] remote=[::] FD 10 flags=1, data=0x808d9390, size=3161, buf=0x80d904b8) 2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 6(0, 0x80e14ad0) 2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(95) write: FD 29 wrote 1135 <= 1135 2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 11(0, 0) 2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(118) read: FD 29 read -1 <= 5 2017/06/05 14:18:08.107 kid1| 83,5| bio.cc(123) read: error: 11 ignored: 1 2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x80e07e00, timeout=0 2017/06/05 14:18:08.107 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.109 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5 2017/06/05 14:18:08.109 kid1| 83,5| bio.cc(118) read: FD 29 read 262 <= 262 2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5 2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 1 <= 1 2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5 2017/06/05 14:18:08.128 kid1| 83,5| bio.cc(118) read: FD 29 read 48 <= 48 2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(95) write: FD 29 wrote 59 <= 59 2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 11(0, 0) 2017/06/05 14:18:08.129 kid1| 83,5| bio.cc(576) squid_bio_ctrl: 0x80e07048 7(0, 0x80e14ad0) 2017/06/05 14:18:08.129 kid1| 83,5| support.cc(2097) store_session_cb: Request to store SSL Session 2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(45) openForWriting: trying to open slot for key 9E7C52DD3CBFFBD0304B94480415CC7C for writing in map [ssl_session_cache] 2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(81) openForWritingAt: opened slot at 41 for writing in map [ssl_session_cache] 2017/06/05 14:18:08.129 kid1| 54,5| MemMap.cc(94) closeForWriting: closing slot at 41 for writing and openning for reading in map [ssl_session_cache] 2017/06/05 14:18:08.129 kid1| 83,5| support.cc(2119) store_session_cb: wrote an ssl session entry of size 157 at pos 41 2017/06/05 14:18:08.129 kid1| 83,2| client_side.cc(3796) clientNegotiateSSL: clientNegotiateSSL: New session 0x80e80e30 on FD 29 (10.215.145.187:54815) 2017/06/05 14:18:08.129 kid1| 83,3| client_side.cc(3800) clientNegotiateSSL: clientNegotiateSSL: FD 29 negotiated cipher AES128-SHA 2017/06/05 14:18:08.129 kid1| 83,5| client_side.cc(3816) clientNegotiateSSL: clientNegotiateSSL: FD 29 has no certificate. 2017/06/05 14:18:08.129 kid1| 33,4| client_side.cc(231) readSomeData: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: reading request... 2017/06/05 14:18:08.129 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x80e80578 [call2567] 2017/06/05 14:18:08.129 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17; asynCall 0x80e80578*1 2017/06/05 14:18:08.129 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x808b48b8, timeout=0 2017/06/05 14:18:08.135 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0) 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00) [call2567] 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00) 2017/06/05 14:18:08.135 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call2567] 2017/06/05 14:18:08.135 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job56] 2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3251) clientReadRequest: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 5 <= 5 2017/06/05 14:18:08.136 kid1| 83,5| bio.cc(118) read: FD 29 read 1568 <= 1568 2017/06/05 14:18:08.136 kid1| 83,2| support.cc(1364) ssl_read_method: SSL FD 29 is pending 2017/06/05 14:18:08.136 kid1| 5,3| Read.cc(91) ReadNow: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, size 66, retval 66, errno 0 2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3200) clientParseRequests: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: attempting to parse 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(47) parseRequestFirstLine: parsing possible request: 2017/06/05 14:18:08.136 kid1| 74,5| HttpParser.cc(257) HttpParserParseReqLine: Parser: retval -1: from 0->4: method 0->-1; url -1->-1; version -1->-1 (0/0) 2017/06/05 14:18:08.136 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x80d227d0 type=ClientHttpRequest [job60] 2017/06/05 14:18:08.136 kid1| 87,3| clientStream.cc(144) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x80d39c38 with data 0x80d38b44 after head 2017/06/05 14:18:08.136 kid1| 33,5| client_side.cc(3221) clientParseRequests: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: done parsing a request 2017/06/05 14:18:08.136 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x80e14ad0 [call2568] 2017/06/05 14:18:08.136 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 timeout 86400 2017/06/05 14:18:08.136 kid1| 33,2| client_side.cc(2584) clientProcessRequest: clientProcessRequest: Invalid Request 2017/06/05 14:18:08.136 kid1| 33,4| client_side.cc(2455) quitAfterError: Will close after error: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 2017/06/05 14:18:08.136 kid1| 20,3| store.cc(779) storeCreatePureEntry: storeCreateEntry: 'error:invalid-request' 2017/06/05 14:18:08.136 kid1| 20,5| store.cc(371) StoreEntry: StoreEntry constructed, this=0x80e05f48 2017/06/05 14:18:08.136 kid1| 20,3| MemObject.cc(97) MemObject: new MemObject 0x80e71638 2017/06/05 14:18:08.136 kid1| 20,3| store.cc(500) setReleaseFlag: StoreEntry::setReleaseFlag: '[null_store_key]' 2017/06/05 14:18:08.136 kid1| 20,3| store_key_md5.cc(89) storeKeyPrivate: storeKeyPrivate: NONE error:invalid-request 2017/06/05 14:18:08.136 kid1| 20,3| store.cc(448) hashInsert: StoreEntry::hashInsert: Inserting Entry e:=XI/0x80e05f48*0 key '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.136 kid1| 20,3| store.cc(484) lock: storeCreateEntry locked key 908891323D546174B25B4E7FDFB415C7 e:=XIV/0x80e05f48*1 2017/06/05 14:18:08.137 kid1| 4,4| errorpage.cc(603) errorAppendEntry: Creating an error page for entry 0x80e05f48 with errorstate 0x80e80440 page id 20 2017/06/05 14:18:08.137 kid1| 4,2| errorpage.cc(1262) BuildContent: No existing error page language negotiated for ERR_INVALID_REQ. Using default error file. 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%l --> '/* 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%; --> '%;' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_INVALID_REQ' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%R --> '' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%W --> '?subject=CacheErrorInfo%20-%20ERR_INVALID_REQ&body=CacheHost%3A%20inf-fw1%0D%0AErrPage%3A%20ERR_INVALID_REQ%0D%0AErr%3A%20%5Bnone%5D%0D%0ATimeStamp%3A%20Mon,%2005%20Jun%202017%2012%3A18%3A08%20GMT%0D%0A%0D%0AClientIP%3A%2010.215.145.187%0D%0A%0D%0AHTTP%20Request%3A%0D%0A%0D%0A%0D%0A' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%w --> 'root' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%M --> '[unknown method]' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%u --> 'error:invalid-request' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%P --> '[unknown protocol]' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%T --> 'Mon, 05 Jun 2017 12:18:08 GMT' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%h --> 'inf-fw1' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%s --> 'squid/3.5.14' 2017/06/05 14:18:08.137 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_INVALID_REQ' 2017/06/05 14:18:08.137 kid1| 20,3| store.cc(484) lock: StoreEntry::storeErrorResponse locked key 908891323D546174B25B4E7FDFB415C7 e:=XIV/0x80e05f48*2 2017/06/05 14:18:08.137 kid1| 20,3| store.cc(1867) replaceHttpReply: StoreEntry::replaceHttpReply: error:invalid-request 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 26 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 6 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 3 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.137 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 29 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 12 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 23 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 14 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 13 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 17 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 15 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 16 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 2 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(834) write: storeWrite: writing 4062 bytes for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.138 kid1| 20,3| store_swapout.cc(381) mayStartSwapOut: not cachable 2017/06/05 14:18:08.138 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.138 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 908891323D546174B25B4E7FDFB415C7 2017/06/05 14:18:08.138 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0 2017/06/05 14:18:08.138 kid1| 20,3| store.cc(1053) complete: storeComplete: '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,3| store.cc(1342) validLength: storeEntryValidLength: Checking '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(1344) validLength: storeEntryValidLength: object_len = 4308 2017/06/05 14:18:08.138 kid1| 20,5| store.cc(1345) validLength: storeEntryValidLength: hdr_sz = 246 2017/06/05 14:18:08.139 kid1| 20,5| store.cc(1346) validLength: storeEntryValidLength: content_length = 4062 2017/06/05 14:18:08.139 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut: already rejected 2017/06/05 14:18:08.139 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 908891323D546174B25B4E7FDFB415C7 2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0 2017/06/05 14:18:08.139 kid1| 20,3| store.cc(522) unlock: StoreEntry::storeErrorResponse unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2 2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(1709) pullData: 0 written 0 into local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(1665) getNextRangeOffset: range: 0; http offset 0; reply 0 2017/06/05 14:18:08.139 kid1| 87,3| clientStream.cc(184) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x80d39bc8 from node 0x80d39c38 2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(200) copy: store_client::copy: 908891323D546174B25B4E7FDFB415C7, from 0, for length 4096, cb 1, cbdata 0x80d38b60 2017/06/05 14:18:08.139 kid1| 20,3| store.cc(484) lock: store_client::copy locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2 2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 908891323D546174B25B4E7FDFB415C7 2017/06/05 14:18:08.139 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 0, hi: 4308 2017/06/05 14:18:08.139 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory 2017/06/05 14:18:08.139 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: error:invalid-request, 4096 bytes (4096 new bytes) 2017/06/05 14:18:08.139 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 'error:invalid-request' out.offset=0 2017/06/05 14:18:08.139 kid1| 88,2| client_side_reply.cc(2001) processReplyAccessResult: The reply for NONE error:invalid-request is ALLOWED, because it matched all 2017/06/05 14:18:08.139 kid1| 20,3| store.cc(484) lock: ClientHttpRequest::loggingEntry locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.139 kid1| 88,3| client_side_reply.cc(2039) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 3850 bytes after 246 bytes of headers 2017/06/05 14:18:08.139 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x80d38b44 from node 0x80d39be8 2017/06/05 14:18:08.139 kid1| 11,2| client_side.cc(1391) sendStartOfMessage: HTTP Client local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 2017/06/05 14:18:08.139 kid1| 11,2| client_side.cc(1392) sendStartOfMessage: HTTP Client REPLY: 2017/06/05 14:18:08.139 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall clientWriteComplete constructed, this=0x80e73b48 [call2569] 2017/06/05 14:18:08.139 kid1| 5,5| Write.cc(35) Write: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: sz 4216: asynCall 0x80e73b48*1 2017/06/05 14:18:08.139 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x808b48e0, timeout=0 2017/06/05 14:18:08.139 kid1| 20,3| store.cc(522) unlock: store_client::copy unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.139 kid1| 33,5| client_side.cc(2422) consumeInput: in.buf has 0 unused bytes 2017/06/05 14:18:08.139 kid1| 33,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job56] 2017/06/05 14:18:08.139 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::clientReadRequest(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80e07e00) 2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(66) HandleWrite: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: off 0, sz 4216. 2017/06/05 14:18:08.140 kid1| 83,5| bio.cc(95) write: FD 29 wrote 4282 <= 4282 2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 4216 2017/06/05 14:18:08.140 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0) 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00) [call2569] 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00) 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(38) make: make call clientWriteComplete [call2569] 2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1845) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, sz 4216, err 0, off 4216, len 4308 2017/06/05 14:18:08.140 kid1| 58,3| HttpReply.cc(520) receivedBodyTooLarge: -246 >? -1 2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1709) pullData: 0x80e07350 written 4216 into local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 2017/06/05 14:18:08.140 kid1| 33,5| client_side.cc(1665) getNextRangeOffset: range: 0; http offset 3850; reply 0x80e07350 2017/06/05 14:18:08.140 kid1| 87,3| clientStream.cc(184) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x80d39bc8 from node 0x80d39c38 2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(200) copy: store_client::copy: 908891323D546174B25B4E7FDFB415C7, from 4096, for length 4096, cb 1, cbdata 0x80d38b60 2017/06/05 14:18:08.140 kid1| 20,3| store.cc(484) lock: store_client::copy locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 908891323D546174B25B4E7FDFB415C7 2017/06/05 14:18:08.140 kid1| 33,5| store_client.cc(329) doCopy: store_client::doCopy: co: 4096, hi: 4308 2017/06/05 14:18:08.140 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory 2017/06/05 14:18:08.140 kid1| 88,5| client_side_reply.cc(2154) sendMoreData: clientReplyContext::sendMoreData: error:invalid-request, 4308 bytes (212 new bytes) 2017/06/05 14:18:08.140 kid1| 88,5| client_side_reply.cc(2158) sendMoreData: clientReplyContext::sendMoreData:local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 'error:invalid-request' out.offset=3850 2017/06/05 14:18:08.140 kid1| 87,3| clientStream.cc(162) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x80d38b44 from node 0x80d39be8 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall clientWriteBodyComplete constructed, this=0x80e80578 [call2570] 2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(35) Write: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: sz 212: asynCall 0x80e80578*1 2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=1, client_data=0x808b48e0, timeout=0 2017/06/05 14:18:08.140 kid1| 20,3| store.cc(522) unlock: store_client::copy unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving clientWriteComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00) 2017/06/05 14:18:08.140 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(66) HandleWrite: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17: off 0, sz 212. 2017/06/05 14:18:08.140 kid1| 83,5| bio.cc(95) write: FD 29 wrote 282 <= 282 2017/06/05 14:18:08.140 kid1| 5,5| Write.cc(108) HandleWrite: write() returns 212 2017/06/05 14:18:08.140 kid1| 5,3| IoCallback.cc(116) finish: called for local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 (0, 0) 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10) [call2570] 2017/06/05 14:18:08.140 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10) 2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(38) make: make call clientWriteBodyComplete [call2570] 2017/06/05 14:18:08.141 kid1| 33,5| client_side.cc(1845) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17, sz 212, err 0, off 4428, len 4308 2017/06/05 14:18:08.141 kid1| 88,3| client_side_reply.cc(1098) storeOKTransferDone: storeOKTransferDone out.offset=4062 objectLen()=4308 headers_sz=246 2017/06/05 14:18:08.141 kid1| 88,5| client_side_reply.cc(1210) replyStatus: clientReplyStatus: transfer is DONE: 10 2017/06/05 14:18:08.141 kid1| 88,5| client_side_reply.cc(1236) replyStatus: clientReplyStatus: stream complete; keepalive=0 2017/06/05 14:18:08.141 kid1| 33,5| client_side.cc(1866) writeComplete: local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17 Stream complete, keepalive is 0 2017/06/05 14:18:08.141 kid1| 33,4| client_side.cc(1819) stopSending: sending error (local=46.51.187.18:443 remote=10.215.145.187 FD 29 flags=17): STREAM_COMPLETE NOKEEPALIVE; old receiving error: none 2017/06/05 14:18:08.141 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 29 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80e73b48 [call2571] 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 29) [call2571] 2017/06/05 14:18:08.141 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 29 2017/06/05 14:18:08.141 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 29 2017/06/05 14:18:08.141 kid1| 5,5| comm.cc(729) commCallCloseHandlers: commCallCloseHandlers: ch->handler=0x80dfaaf8*1 2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: comm.cc(730) will call ConnStateData::connStateClosed(FD -1, data=0x80e07e00) [call2541] 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80e14ad0 [call2572] 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 29) [call2572] 2017/06/05 14:18:08.141 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving clientWriteBodyComplete(local=46.51.187.18:443 remote=10.215.145.187 flags=17, data=0x80d37b00, size=212, buf=0x80d37b10) 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 29) 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call2571] 2017/06/05 14:18:08.141 kid1| 83,5| bio.cc(95) write: FD 29 wrote 37 <= 37 2017/06/05 14:18:08.141 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 29) 2017/06/05 14:18:08.141 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::connStateClosed(FD -1, data=0x80e07e00) 2017/06/05 14:18:08.141 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::connStateClosed [call2541] 2017/06/05 14:18:08.141 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job56] 2017/06/05 14:18:08.141 kid1| 93,4| AsyncJob.cc(55) deleteThis: Http::Server will NOT delete in-call job, reason: ConnStateData::connStateClosed 2017/06/05 14:18:08.142 kid1| 93,5| AsyncJob.cc(137) callEnd: ConnStateData::connStateClosed(FD -1, data=0x80e07e00) ends job [Stopped, reason:ConnStateData::connStateClosed job56] 2017/06/05 14:18:08.142 kid1| 33,2| client_side.cc(815) swanSong: local=46.51.187.18:443 remote=10.215.145.187 flags=17 2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39c38 2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39c38 2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(223) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x80d39bc8 2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(202) clientStreamDetach: clientStreamDetach: Detaching node 0x80d39be8 2017/06/05 14:18:08.142 kid1| 87,3| clientStream.cc(287) clientStreamFree: Freeing clientStreamNode 0x80d39be8 2017/06/05 14:18:08.142 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '908891323D546174B25B4E7FDFB415C7' 2017/06/05 14:18:08.142 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut: already rejected 2017/06/05 14:18:08.142 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.142 kid1| 20,3| store.cc(484) lock: storeUnregister locked key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.142 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0 2017/06/05 14:18:08.142 kid1| 20,3| store.cc(522) unlock: storeUnregister unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*3 2017/06/05 14:18:08.142 kid1| 20,3| store.cc(522) unlock: clientReplyContext::removeStoreReference unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*2 2017/06/05 14:18:08.142 kid1| 33,3| client_side_request.cc(246) ~ClientHttpRequest: httpRequestFree: error:invalid-request 2017/06/05 14:18:08.142 kid1| 28,3| Checklist.cc(70) preCheck: 0xbf839f2c checking fast ACLs 2017/06/05 14:18:08.143 kid1| 28,5| Acl.cc(138) matches: checking access_log daemon:/var/log/squid/access.test.log 2017/06/05 14:18:08.143 kid1| 28,5| Acl.cc(138) matches: checking (access_log daemon:/var/log/squid/access.test.log line) 2017/06/05 14:18:08.143 kid1| 28,3| Acl.cc(158) matches: checked: (access_log daemon:/var/log/squid/access.test.log line) = 1 2017/06/05 14:18:08.143 kid1| 28,3| Acl.cc(158) matches: checked: access_log daemon:/var/log/squid/access.test.log = 1 2017/06/05 14:18:08.143 kid1| 28,3| Checklist.cc(63) markFinished: 0xbf839f2c answer ALLOWED for match 2017/06/05 14:18:08.143 kid1| 50,5| ModDaemon.cc(65) logfileNewBuffer: logfileNewBuffer: daemon:/var/log/squid/access.test.log: new buffer 2017/06/05 14:18:08.143 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/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 0 of 32768 bytes before append 2017/06/05 14:18:08.143 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/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 1 of 32768 bytes before append 2017/06/05 14:18:08.143 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/06/05 14:18:08.143 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 107 of 32768 bytes before append 2017/06/05 14:18:08.143 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=1, client_data=0x808fb030, timeout=0 2017/06/05 14:18:08.143 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xbf839f2c 2017/06/05 14:18:08.143 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0xbf839f2c 2017/06/05 14:18:08.143 kid1| 20,3| store.cc(522) unlock: ClientHttpRequest::loggingEntry unlocking key 908891323D546174B25B4E7FDFB415C7 e:=sXINV/0x80e05f48*1 2017/06/05 14:18:08.143 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0 2017/06/05 14:18:08.143 kid1| 20,3| store.cc(1244) release: releasing e:=sXINV/0x80e05f48*0 908891323D546174B25B4E7FDFB415C7 2017/06/05 14:18:08.143 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0x80e71638 2017/06/05 14:18:08.143 kid1| 20,3| MemObject.cc(110) ~MemObject: del MemObject 0x80e71638 2017/06/05 14:18:08.144 kid1| 20,3| store.cc(421) destroyStoreEntry: destroyStoreEntry: destroying 0x80e05f4c 2017/06/05 14:18:08.144 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0 2017/06/05 14:18:08.144 kid1| 20,5| store.cc(376) ~StoreEntry: StoreEntry destructed, this=0x80e05f48 2017/06/05 14:18:08.144 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x80e717d0 [call2573] 2017/06/05 14:18:08.144 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: Initiator.cc(40) will call Initiate::noteInitiatorAborted() [call2573] 2017/06/05 14:18:08.144 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80d227d0 type=ClientHttpRequest [job60] 2017/06/05 14:18:08.144 kid1| 33,3| client_side.cc(5106) unpinConnection: local=10.215.145.187:39368 remote=46.51.187.18:443 FD 30 flags=25 2017/06/05 14:18:08.144 kid1| 5,5| comm.cc(1038) comm_remove_close_handler: comm_remove_close_handler: FD 30, AsyncCall=0x80e84ea0*2 2017/06/05 14:18:08.144 kid1| 33,5| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionClosed [call2562] because comm_remove_close_handler 2017/06/05 14:18:08.144 kid1| 33,3| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionRead [call2563] because comm_read_cancel 2017/06/05 14:18:08.144 kid1| 33,3| AsyncCall.cc(56) cancel: will not call ConnStateData::clientPinnedConnectionRead [call2563] also because comm_read_cancel 2017/06/05 14:18:08.144 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.144 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 30 2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x80e73a38 [call2574] 2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(902) will call commStartSslClose(FD 30) [call2574] 2017/06/05 14:18:08.144 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 30 2017/06/05 14:18:08.144 kid1| 5,5| comm.cc(721) commCallCloseHandlers: commCallCloseHandlers: FD 30 2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x80e84ea0 [call2575] 2017/06/05 14:18:08.144 kid1| 5,4| AsyncCall.cc(93) ScheduleCall: comm.cc(941) will call comm_close_complete(FD 30) [call2575] 2017/06/05 14:18:08.144 kid1| 33,3| client_side.cc(846) ~ConnStateData: local=46.51.187.18:443 remote=10.215.145.187 flags=17 2017/06/05 14:18:08.144 kid1| 33,4| ServerBump.cc(44) ~ServerBump: destroying 2017/06/05 14:18:08.144 kid1| 33,4| ServerBump.cc(46) ~ServerBump: e:=sp2XDIV/0x80e0a448*1 2017/06/05 14:18:08.144 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '52E847A2F8AF07D9783AAE4A91F2E9E6' 2017/06/05 14:18:08.144 kid1| 20,3| store_swapout.cc(356) mayStartSwapOut: already rejected 2017/06/05 14:18:08.144 kid1| 20,2| store.cc(954) checkCachable: StoreEntry::checkCachable: NO: not cachable 2017/06/05 14:18:08.144 kid1| 20,3| store.cc(484) lock: storeUnregister locked key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2 2017/06/05 14:18:08.144 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0 2017/06/05 14:18:08.144 kid1| 20,3| store.cc(522) unlock: storeUnregister unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*2 2017/06/05 14:18:08.145 kid1| 20,3| store.cc(522) unlock: Ssl::ServerBump unlocking key 52E847A2F8AF07D9783AAE4A91F2E9E6 e:=sp2XDIV/0x80e0a448*1 2017/06/05 14:18:08.145 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0 2017/06/05 14:18:08.145 kid1| 20,3| store.cc(1244) release: releasing e:=sp2XDIV/0x80e0a448*0 52E847A2F8AF07D9783AAE4A91F2E9E6 2017/06/05 14:18:08.145 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0x80e09f08 2017/06/05 14:18:08.145 kid1| 20,3| MemObject.cc(110) ~MemObject: del MemObject 0x80e09f08 2017/06/05 14:18:08.145 kid1| 20,3| store.cc(421) destroyStoreEntry: destroyStoreEntry: destroying 0x80e0a44c 2017/06/05 14:18:08.145 kid1| 20,3| store.cc(403) destroyMemObject: destroyMemObject 0 2017/06/05 14:18:08.145 kid1| 20,5| store.cc(376) ~StoreEntry: StoreEntry destructed, this=0x80e0a448 2017/06/05 14:18:08.145 kid1| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x80e07f24 type=Http::Server [job56] 2017/06/05 14:18:08.145 kid1| 33,5| AsyncCallQueue.cc(57) fireNext: leaving ConnStateData::connStateClosed(FD -1, data=0x80e07e00) 2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 29) 2017/06/05 14:18:08.145 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call2572] 2017/06/05 14:18:08.145 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 29 Reading next request 2017/06/05 14:18:08.145 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.145 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.145 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0 2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 29) 2017/06/05 14:18:08.145 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering Initiate::noteInitiatorAborted() 2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(38) make: make call Initiate::noteInitiatorAborted [call2573] 2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(56) cancel: will not call Initiate::noteInitiatorAborted [call2573] because job gone 2017/06/05 14:18:08.145 kid1| 93,5| AsyncCall.cc(48) make: will not call Initiate::noteInitiatorAborted [call2573] because of job gone 2017/06/05 14:18:08.145 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving Initiate::noteInitiatorAborted() 2017/06/05 14:18:08.145 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering commStartSslClose(FD 30) 2017/06/05 14:18:08.145 kid1| 5,4| AsyncCall.cc(38) make: make call commStartSslClose [call2574] 2017/06/05 14:18:08.146 kid1| 83,5| bio.cc(95) write: FD 30 wrote 53 <= 53 2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving commStartSslClose(FD 30) 2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(55) fireNext: entering comm_close_complete(FD 30) 2017/06/05 14:18:08.146 kid1| 5,4| AsyncCall.cc(38) make: make call comm_close_complete [call2575] 2017/06/05 14:18:08.146 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 30 [unknown] pinned connection for 10.215.145.187 (29) 2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=1, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 30, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.146 kid1| 5,5| AcceptLimiter.cc(55) kick: size=0 2017/06/05 14:18:08.146 kid1| 5,4| AsyncCallQueue.cc(57) fireNext: leaving comm_close_complete(FD 30) 2017/06/05 14:18:08.146 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.test.log: write returned 109 2017/06/05 14:18:08.146 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 21, type=2, handler=0, client_data=0, timeout=0 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The AsyncCall MaintainSwapSpace constructed, this=0x80d3d960 [call2576] 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(93) ScheduleCall: event.cc(237) will call MaintainSwapSpace() [call2576] 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering MaintainSwapSpace() 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(38) make: make call MaintainSwapSpace [call2576] 2017/06/05 14:18:08.786 kid1| 47,5| ufs/UFSSwapDir.cc(447) maintain: space still available in /var/cache/squid.test 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving MaintainSwapSpace() 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(26) AsyncCall: The AsyncCall logfileFlush constructed, this=0x80d3d960 [call2577] 2017/06/05 14:18:08.786 kid1| 41,5| AsyncCall.cc(93) ScheduleCall: event.cc(237) will call logfileFlush(0x808fb030*?) [call2577] 2017/06/05 14:18:08.787 kid1| 41,5| AsyncCallQueue.cc(55) fireNext: entering logfileFlush(0x808fb030*?) 2017/06/05 14:18:08.787 kid1| 41,5| AsyncCall.cc(38) make: make call logfileFlush [call2577] 2017/06/05 14:18:08.787 kid1| 41,5| AsyncCallQueue.cc(57) fireNext: leaving logfileFlush(0x808fb030*?) I tried to make something out of the log before the generation of ERR_INVALID_REQ, but I'm a bit lost here. Thanks, Vieri _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
