> On Dec 8, 2016, at 10:41 AM, Alex Rousskov <rousskov@xxxxxxxxxxxxxxxxxxxxxxx> wrote:
>
> On 12/08/2016 09:15 AM, Greg Saylor wrote:
>
>> I'm trying to debug a situation where squid 3.4 would return a ERR_ACCESS_DENIED and version 3.5 does not.
>
> I trust you use Squid v3.5.22 or later. Some v3.5 releases have serious
> SslBump bugs so the minor version is important.
yes I tested this with 3.5.22. The original issue was noticed in 3.5.19 - but with something like this I’ll always pull down the latest version. To clarify the prior version was 3,4.6 - I can’t believe that I forgot to mention specific version numbers in the original post - apologies.
>> I started looking at the source code between 3.4 and 3.5. In 3.5 there is this code in src/client_side_request.cc.
>>
>> if (sslBumpNeeded()) {
>> // We have to serve an error, so bump the client first.
>> sslBumpNeed(Ssl::bumpClientFirst);
>> // set final error but delay sending until we bump
> ...
>> } else
>> // send the error to the client now
>
>
>> If I change:
>>
>> if (sslBumpNeeded()) {
>>
>> to:
>>
>> if (sslBumpNeeded() && 0) {
>>
>> Then it correctly responds with ERR_ACCESS_DENIED.
>
>
> Do you enable SslBump features in your Squid?
Yes. I should clarify: the purpose of this “hack” was to bypass that block of code and have it fall down to the “else” statement which returned immediately with an error.
> * If you enabled SslBump, then Squid tries to bump the client connection
> to serve the error message to the HTTPS client (because popular browsers
> ignore errors delivered as CONNECT responses). I do not recall whether
> Squid v3.4 did that, but that is pretty much irrelevant because v3.5
> behavior is deliberate (that behavior may need more configuration
> options, but that is unrelated to v3.4 anyway). There may be bugs with
> that code path, but they are not related to the sslBumpNeeded() result
> as such.
Regretfully, I have not been able to figure this out. But I agree this is not related to sslBumpNeeded(). I think its more around how the http_access rule result is being squirreled away and not being checked before proceeding with the SSL Bump. Or perhaps in more 3.5.22 terms: its not being consulted when deciding how to respond to the client request? Maybe its just not taking precedence?
>
>> It looks to me as if something is taking precedence over
>> calloutContext->error. But even if it was not, because the request
>> is actually being processed it would allow a security hole where an
>> attacker could map a private internal network of https services based
>> on the time it takes them to respond - even if it allowed the
>> connection.
>
> Agreed. If you are using SslBump, then, as the next step, I recommend
> ignoring Squid code and clearly demonstrating that Squid forwards a
> request that should be denied. A packet trace or Squid's HTTP request
> printouts would be helpful for those of us who do not know what exactly
> that "socat" command does in your environment, and what Squid does when
> processing that traffic.
>
It this what you mean?
2016/12/08 18:07:36.796 kid1| 5,2| src/comm/TcpAcceptor.cc(220) doAccept: New connection on FD 27
2016/12/08 18:07:36.796 kid1| 5,2| src/comm/TcpAcceptor.cc(295) acceptNext: connection on local=[::]:3130 remote=[::] FD 27 flags=1
2016/12/08 18:07:36.796 kid1| 50,5| src/comm/TcpAcceptor.cc(348) oldAccept: FD 27, [::] [ job21]: (11) Resource temporarily unavailable
2016/12/08 18:07:36.796 kid1| 5,5| src/comm/TcpAcceptor.cc(273) acceptOne: try later: local=[::]:3130 remote=[::] FD 27 flags=1 handler Subscription: 0x24b4210*1
2016/12/08 18:07:36.796 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 27, type=1, handler=1, client_data=0x24bc3c8, timeout=0
2016/12/08 18:07:36.796 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 27, type=1, handler=1, client_data=0x24bc3c8, timeout=0
2016/12/08 18:07:37.471 kid1| 41,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall MaintainSwapSpace constructed, this=0x2098170 [call14588]
2016/12/08 18:07:37.471 kid1| 41,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/event.cc(237) will call MaintainSwapSpace() [call14588]
2016/12/08 18:07:37.471 kid1| 41,5| src/base/AsyncCallQueue.cc(55) fireNext: entering MaintainSwapSpace()
2016/12/08 18:07:37.471 kid1| 41,5| src/base/AsyncCall.cc(38) make: make call MaintainSwapSpace [call14588]
2016/12/08 18:07:37.471 kid1| 41,7| src/event.cc(322) schedule: schedule: Adding 'MaintainSwapSpace', in 1.00 seconds
2016/12/08 18:07:37.471 kid1| 41,5| src/base/AsyncCallQueue.cc(57) fireNext: leaving MaintainSwapSpace()
2016/12/08 18:07:37.569 kid1| 41,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::ServiceRep::noteTimeToUpdate constructed, this=0x2098170 [call14589]
2016/12/08 18:07:37.569 kid1| 41,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/event.cc(237) will call Adaptation::Icap::ServiceRep::noteTimeToUpdate(0x24b7a68*?) [call14589]
2016/12/08 18:07:37.569 kid1| 41,5| src/base/AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::ServiceRep::noteTimeToUpdate(0x24b7a68*?)
2016/12/08 18:07:37.569 kid1| 41,5| src/base/AsyncCall.cc(38) make: make call Adaptation::Icap::ServiceRep::noteTimeToUpdate [call14589]
2016/12/08 18:07:37.569 kid1| 93,5| src/adaptation/icap/ServiceRep.cc(358) noteTimeToUpdate: performs a regular options update [up]
2016/12/08 18:07:37.569 kid1| 93,6| src/adaptation/icap/ServiceRep.cc(591) startGettingOptions: will get new options [up]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x21db6c8 type=Adaptation::Icap::OptXactLauncher [job789]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x2529e10 [call14590]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(26) will call AsyncJob::start() [call14590]
2016/12/08 18:07:37.569 kid1| 41,5| src/base/AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::ServiceRep::noteTimeToUpdate(0x24b7a68*?)
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start()
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(38) make: make call AsyncJob::start [call14590]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXactLauncher status in: [ job789]
2016/12/08 18:07:37.569 kid1| 93,4| src/adaptation/icap/Launcher.cc(49) launchXaction: launching first xaction #1
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x24d29b8 type=Adaptation::Icap::OptXact [job790]
2016/12/08 18:07:37.569 kid1| 93,3| src/adaptation/icap/Xaction.cc(60) Xaction: Adaptation::Icap::OptXact constructed, this=0x24d28b8 [icapxjob790]
2016/12/08 18:07:37.569 kid1| 55,7| src/HttpHeader.cc(446) HttpHeader: init-ing hdr: 0x2458c98 owner: 2
2016/12/08 18:07:37.569 kid1| 24,7| src/SBuf.cc(139) assign: assigning SBuf4091 from SBuf4092
2016/12/08 18:07:37.569 kid1| 93,5| src/adaptation/icap/Xaction.cc(92) disableRepeats: Adaptation::Icap::OptXact from now on cannot be repeated because over icap_retry_limit [/ job790]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x21bb480 [call14591]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(26) will call AsyncJob::start() [call14591]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXactLauncher status out: [ job789]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start()
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start()
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(38) make: make call AsyncJob::start [call14591]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [/ job790]
2016/12/08 18:07:37.569 kid1| 48,3| src/pconn.cc(156) clearHandlers: removing close handler for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1
2016/12/08 18:07:37.569 kid1| 5,4| src/base/AsyncCall.cc(56) cancel: will not call IdleConnList::Read [call14540] because old comm_read_cancel
2016/12/08 18:07:37.569 kid1| 5,4| src/base/AsyncCall.cc(56) cancel: will not call IdleConnList::Read [call14540] also because old comm_read_cancel
2016/12/08 18:07:37.569 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 35, type=1, handler=0, client_data=0, timeout=0
2016/12/08 18:07:37.569 kid1| 5,3| src/comm.cc(579) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1
2016/12/08 18:07:37.569 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout -1
2016/12/08 18:07:37.569 kid1| 93,3| src/adaptation/icap/ServiceRep.cc(122) getConnection: got connection: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x252d4e0 [call14592]
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/adaptation/icap/Xaction.cc(138) will call Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8) [call14592]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXact status out: [FD 35;/ job790]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start()
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8)
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommConnected [call14592]
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 35;/ job790]
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x25273d0 [call14593]
2016/12/08 18:07:37.569 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout 60
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommClosed constructed, this=0x25409d0 [call14594]
2016/12/08 18:07:37.569 kid1| 5,5| src/comm.cc(994) comm_add_close_handler: comm_add_close_handler: FD 35, AsyncCall=0x25409d0*1
2016/12/08 18:07:37.569 kid1| 93,3| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x21d0a00 [call14595]
2016/12/08 18:07:37.569 kid1| 5,5| src/comm/Read.cc(58) comm_read_base: comm_read, queueing read for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1; asynCall 0x21d0a00*1
2016/12/08 18:07:37.569 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 35, type=1, handler=1, client_data=0x7f1a3515a080, timeout=0
2016/12/08 18:07:37.569 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x20c54a0 [call14596]
2016/12/08 18:07:37.569 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout 900
2016/12/08 18:07:37.569 kid1| 24,7| src/SBuf.cc(139) assign: assigning SBuf4090 from SBuf4094
2016/12/08 18:07:37.569 kid1| 23,3| src/url.cc(359) urlParse: urlParse: Split URL 'icap://127.0.0.1:1344/foo_reqmod ICAP/1.0
' into proto='icap', host='127.0.0.1', port='1344', path='/foo_reqmod ICAP/1.0'
2016/12/08 18:07:37.569 kid1| 23,2| src/url.cc(395) urlParse: urlParse: URI has whitespace: {icap://127.0.0.1:1344/foo_reqmod ICAP/1.0
}
2016/12/08 18:07:37.569 kid1| 24,7| src/SBuf.cc(139) assign: assigning SBuf4090 from SBuf4090
2016/12/08 18:07:37.569 kid1| 23,3| src/HttpRequest.h(82) SetHost: HttpRequest::SetHost() given IP: 127.0.0.1
2016/12/08 18:07:37.569 kid1| 55,7| src/HttpHeader.cc(597) parse: parsing hdr: (0x2458c98)
Host: 127.0.0.1:1344
Allow: 206
2016/12/08 18:07:37.570 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x2458c98 adding entry: 29 at 0
2016/12/08 18:07:37.570 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x2458c98 adding entry: 6 at 1
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommWrote constructed, this=0x2540e50 [call14597]
2016/12/08 18:07:37.570 kid1| 5,5| src/comm/Write.cc(35) Write: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1: sz 94: asynCall 0x2540e50*1
2016/12/08 18:07:37.570 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 35, type=2, handler=1, client_data=0x7f1a3515a0b8, timeout=0
2016/12/08 18:07:37.570 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x2540ef0 [call14598]
2016/12/08 18:07:37.570 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout 900
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXact status out: [FD 35wr;/ job790]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8)
2016/12/08 18:07:37.570 kid1| 5,5| src/comm/Write.cc(66) HandleWrite: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1: off 0, sz 94.
2016/12/08 18:07:37.570 kid1| 5,5| src/comm/Write.cc(108) HandleWrite: write() returns 94
2016/12/08 18:07:37.570 kid1| 5,3| src/comm/IoCallback.cc(116) finish: called for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 (0, 0)
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(135) will call Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8) [call14597]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8)
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommWrote [call14597]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 35wr;/ job790]
2016/12/08 18:07:37.570 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x25273d0 [call14599]
2016/12/08 18:07:37.570 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout 900
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXact status out: [FD 35r;/ job790]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8)
2016/12/08 18:07:37.570 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 35, type=2, handler=0, client_data=0, timeout=0
2016/12/08 18:07:37.570 kid1| 5,3| src/comm/Read.cc(144) HandleRead: FD 35, size 65535, retval 210, errno 0
2016/12/08 18:07:37.570 kid1| 5,3| src/comm/IoCallback.cc(116) finish: called for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 (0, 0)
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(135) will call Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8, size=210, buf=0x24e0b90) [call14595]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8, size=210, buf=0x24e0b90)
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommRead [call14595]
2016/12/08 18:07:37.570 kid1| 93,3| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 35r;/ job790]
2016/12/08 18:07:37.570 kid1| 5,3| src/comm.cc(579) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1
2016/12/08 18:07:37.570 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout -1
2016/12/08 18:07:37.570 kid1| 93,3| src/adaptation/icap/Xaction.cc(425) noteCommRead: read 210 bytes
2016/12/08 18:07:37.570 kid1| 93,5| src/adaptation/icap/Xaction.cc(85) disableRetries: Adaptation::Icap::OptXact from now on cannot be retried [FD 35;/ job790]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/OptXact.cc(103) parseResponse: have 210 bytes to parse [FD 35;/ job790]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/OptXact.cc(104) parseResponse:
ICAP/1.0 200 OK
Date: Thu, 8 Dec 2016 18:07:37 UTC
ISTag: Socialware TAG Thu, 8 Dec 2016 18:07:37 UTC
Max-Connections: 1000
Methods: REQMOD
Server: Socialware ICAP Server/1.0
Encapsulated: null-body=0
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(446) HttpHeader: init-ing hdr: 0x24583e8 owner: 3
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Xaction.cc(450) parseHttpMsg: have 210 head bytes to parse
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(597) parse: parsing hdr: (0x24583e8)
Date: Thu, 8 Dec 2016 18:07:37 UTC
ISTag: Socialware TAG Thu, 8 Dec 2016 18:07:37 UTC
Max-Connections: 1000
Methods: REQMOD
Server: Socialware ICAP Server/1.0
Encapsulated: null-body=0
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 23 at 0
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 85 at 1
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 85 at 2
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 85 at 3
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 56 at 4
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(981) addEntry: 0x24583e8 adding entry: 85 at 5
2016/12/08 18:07:37.571 kid1| 55,2| src/HttpHeader.cc(1754) httpHeaderNoteParsedEntry: cannot parse hdr field: 'Date: Thu, 8 Dec 2016 18:07:37 UTC'
2016/12/08 18:07:37.571 kid1| 93,7| src/adaptation/icap/OptXact.cc(89) handleCommRead: readAll=1
2016/12/08 18:07:37.571 kid1| 93,4| src/adaptation/icap/Xaction.cc(514) setOutcome: ICAP_OPT
2016/12/08 18:07:37.571 kid1| 93,4| src/adaptation/Answer.cc(29) Forward: forwarding: 0x24583d0
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x20c54a0 [call14600]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/adaptation/Initiate.cc(83) will call Initiator::noteAdaptationAnswer(0) [call14600]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Xaction.cc(354) callEnd: Adaptation::Icap::OptXact done with I/O [FD 35;/ job790]
2016/12/08 18:07:37.571 kid1| 5,5| src/comm.cc(1039) comm_remove_close_handler: comm_remove_close_handler: FD 35, AsyncCall=0x25409d0*2
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(56) cancel: will not call Adaptation::Icap::Xaction::noteCommClosed [call14594] because comm_remove_close_handler
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Xaction.cc(85) disableRetries: Adaptation::Icap::OptXact still cannot be retried [FD 35;/ job790]
2016/12/08 18:07:37.571 kid1| 93,3| src/adaptation/icap/ServiceRep.cc(132) putConnection: pushing pconn [FD 35;/ job790]
2016/12/08 18:07:37.571 kid1| 5,3| src/comm.cc(579) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1
2016/12/08 18:07:37.571 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout -1
2016/12/08 18:07:37.571 kid1| 5,4| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall IdleConnList::Read constructed, this=0x252d4e0 [call14601]
2016/12/08 18:07:37.571 kid1| 5,5| src/comm/Read.cc(58) comm_read_base: comm_read, queueing read for local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1; asynCall 0x252d4e0*1
2016/12/08 18:07:37.571 kid1| 5,5| src/comm/ModEpoll.cc(116) SetSelect: FD 35, type=1, handler=1, client_data=0x7f1a3515a080, timeout=0
2016/12/08 18:07:37.571 kid1| 5,4| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall IdleConnList::Timeout constructed, this=0x24dcb50 [call14602]
2016/12/08 18:07:37.571 kid1| 5,3| src/comm.cc(553) commSetConnTimeout: local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1 timeout 60
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(137) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8, size=210, buf=0x24e0b90) ends job [/ job790]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/Initiate.cc(64) swanSong: swan sings [/ job790]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/Initiate.cc(71) swanSong: swan sang [/ job790]
2016/12/08 18:07:37.571 kid1| 93,3| src/adaptation/icap/Xaction.cc(71) ~Xaction: Adaptation::Icap::OptXact destructed, this=0x24d28b8 [icapxjob790]
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(480) clean: cleaning hdr: 0x2458c98 owner: 2
2016/12/08 18:07:37.571 kid1| 93,7| src/HttpRequest.cc(55) ~HttpRequest: destructed, this=0x2458c80
2016/12/08 18:07:37.571 kid1| 55,7| src/HttpHeader.cc(480) clean: cleaning hdr: 0x2458c98 owner: 2
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x24d29b8 type=Adaptation::Icap::OptXact [job790]
2016/12/08 18:07:37.571 kid1| 93,6| src/base/AsyncJob.cc(147) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8, size=210, buf=0x24e0b90) ended 0x24d29b8
2016/12/08 18:07:37.571 kid1| 93,3| src/base/AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:35366 remote=127.0.0.1:1344 FD 35 flags=1, data=0x24d28b8, size=210, buf=0x24e0b90)
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCallQueue.cc(55) fireNext: entering Initiator::noteAdaptationAnswer(0)
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(38) make: make call Initiator::noteAdaptationAnswer [call14600]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::OptXactLauncher status in: [ job789]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Launcher.cc(64) noteAdaptationAnswer: launches: 1 answer: 0
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x25409d0 [call14603]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/adaptation/Initiate.cc(83) will call Initiator::noteAdaptationAnswer(0) [call14603]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(137) callEnd: Initiator::noteAdaptationAnswer(0) ends job [ job789]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/Initiate.cc(64) swanSong: swan sings [ job789]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/Initiate.cc(71) swanSong: swan sang [ job789]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(40) ~AsyncJob: AsyncJob destructed, this=0x21db6c8 type=Adaptation::Icap::OptXactLauncher [job789]
2016/12/08 18:07:37.571 kid1| 93,6| src/base/AsyncJob.cc(147) callEnd: Initiator::noteAdaptationAnswer(0) ended 0x21db6c8
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCallQueue.cc(57) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCallQueue.cc(55) fireNext: entering Initiator::noteAdaptationAnswer(0)
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(38) make: make call Initiator::noteAdaptationAnswer [call14603]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncJob.cc(123) callStart: Adaptation::Icap::ServiceRep status in:[up,fetch]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/ServiceRep.cc(543) noteAdaptationAnswer: is interpreting new options [up]
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(153) cfgIntHeader: int header: Max-Connections: 1000
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(153) cfgIntHeader: int header: Options-TTL: -1
2016/12/08 18:07:37.571 kid1| 55,2| src/HttpHeader.cc(1754) httpHeaderNoteParsedEntry: cannot parse hdr field: 'Date: Thu, 8 Dec 2016 18:07:37 UTC'
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(153) cfgIntHeader: int header: Preview: -1
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(234) report: Adaptation::Icap::Options::cfgTransferList: no Transfer-Preview extensions
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(234) report: Adaptation::Icap::Options::cfgTransferList: no Transfer-Ignore extensions
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/Options.cc(234) report: Adaptation::Icap::Options::cfgTransferList: no Transfer-Complete extensions
2016/12/08 18:07:37.571 kid1| 93,3| src/adaptation/icap/ServiceRep.cc(571) handleNewOptions: got new options and is now [up]
2016/12/08 18:07:37.571 kid1| 93,7| src/adaptation/icap/ServiceRep.cc(642) optionsFetchTime: options expire on 1481220517 >= 1481220457
2016/12/08 18:07:37.571 kid1| 93,7| src/adaptation/icap/ServiceRep.cc(614) scheduleUpdate: raw OPTIONS fetch at 1481220497 or in 40 sec
2016/12/08 18:07:37.571 kid1| 93,5| src/adaptation/icap/ServiceRep.cc(629) scheduleUpdate: will fetch OPTIONS in 40 sec
2016/12/08 18:07:37.571 kid1| 41,7| src/event.cc(322) schedule: schedule: Adding 'Adaptation::Icap::ServiceRep::noteTimeToUpdate', in 40.00 seconds
2016/12/08 18:07:37.571 kid1| 93,7| src/adaptation/icap/ServiceRep.cc(436) scheduleNotification: will notify 0 clients
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::ServiceRep::noteTimeToNotify constructed, this=0x21bb480 [call14604]
2016/12/08 18:07:37.571 kid1| 93,5| src/base/AsyncCall.cc(93) ScheduleCall: /tmp/squid_source/src/adaptation/icap/ServiceRep.cc(437) will call Adaptation::Icap::ServiceRep::noteTimeToNotify() [call14604]
That is from 3.5.22
Here’s the same from 3.4.6, I tried to clean this up a bit there were substantially more log messages:
2016/12/08 18:14:35.927 kid2| src/comm/TcpAcceptor.cc(220) doAccept: New connection on FD 19
2016/12/08 18:14:35.927 kid2| src/comm/TcpAcceptor.cc(295) acceptNext: connection on local=[::]:3130 remote=[::] FD 19 flags=1
2016/12/08 18:14:35.927 kid2| src/fd.cc(221) fd_open: fd_open() FD 27 HTTP Request
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(203) lookup: id=0x2512c64 query ARP table
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(246) lookup: id=0x2512c64 query ARP on each interface (80 found)
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(252) lookup: id=0x2512c64 found interface lo
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(252) lookup: id=0x2512c64 found interface eth0
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(261) lookup: id=0x2512c64 looking up ARP address for 172.16.0.43 on eth0
2016/12/08 18:14:35.927 kid2| src/eui/Eui48.cc(540) lookup: id=0x2512c64 172.16.0.43 NOT found
2016/12/08 18:14:35.927 kid2| src/comm/TcpAcceptor.cc(287) acceptOne: Listener: local=[::]:3130 remote=[::] FD 19 flags=1 accepted new connection local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 handler Subscription: 0x2501b30*1
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall httpAccept constructed, this=0x2574f90 [call15371]
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/TcpAcceptor.cc(317) will call httpAccept(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x131d668, MXID_46) [call15371]
2016/12/08 18:14:35.927 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 19, type=1, handler=1, client_data=0x2501c08, timeout=0
2016/12/08 18:14:35.927 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering httpAccept(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x131d668, MXID_46)
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(30) make: make call httpAccept [call15371]
2016/12/08 18:14:35.927 kid2| src/client_side.cc(3412) httpAccept: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: accepted
2016/12/08 18:14:35.927 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x2513100 type=ConnStateData [job820]
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::connStateClosed constructed, this=0x2574aa0 [call15372]
2016/12/08 18:14:35.927 kid2| src/comm.cc(1208) comm_add_close_handler: comm_add_close_handler: FD 27, AsyncCall=0x2574aa0*1
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::requestTimeout constructed, this=0x2575470 [call15373]
2016/12/08 18:14:35.927 kid2| src/comm.cc(768) commSetConnTimeout: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 timeout 300
2016/12/08 18:14:35.927 kid2| src/client_side.cc(258) readSomeData: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: reading request...
2016/12/08 18:14:35.927 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x210d9c0 [call15374]
2016/12/08 18:14:35.927 kid2| src/comm.cc(167) comm_read: comm_read, queueing read for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1; asynCall 0x210d9c0*1
2016/12/08 18:14:35.927 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=1, client_data=0x7ff2cba7bcc0, timeout=0
2016/12/08 18:14:35.927 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving httpAccept(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x131d668, MXID_46)
2016/12/08 18:14:35.971 kid2| src/comm.cc(138) commHandleRead: comm_read_try: FD 27, size 4095, retval 41, errno 0
2016/12/08 18:14:35.971 kid2| src/comm/IoCallback.cc(108) finish: called for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 (0, 0)
2016/12/08 18:14:35.971 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=41, buf=0x24a20d0) [call15374]
2016/12/08 18:14:35.971 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=41, buf=0x24a20d0)
2016/12/08 18:14:35.971 kid2| src/base/AsyncCall.cc(30) make: make call ConnStateData::clientReadRequest [call15374]
2016/12/08 18:14:35.971 kid2| src/base/AsyncJob.cc(117) callStart: ConnStateData status in: [ job820]
2016/12/08 18:14:35.971 kid2| src/client_side.cc(3042) clientReadRequest: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 size 41
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2981) clientParseRequests: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: attempting to parse
2016/12/08 18:14:35.971 kid2| src/HttpParser.cc(29) reset: Request buffer is CONNECT www.facebook.com:443 HTTP/1.0
2016/12/08 18:14:35.971 kid2| src/HttpParser.cc(39) parseRequestFirstLine: parsing possible request: CONNECT www.facebook.com:443 HTTP/1.0
2016/12/08 18:14:35.971 kid2| src/HttpParser.cc(249) HttpParserParseReqLine: Parser: retval 1: from 0->38: method 0->6; url 8->27; version 29->36 (1/0)
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2322) parseHttpRequest: parseHttpRequest: req_hdr = {
}
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2326) parseHttpRequest: parseHttpRequest: end = {
}
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2330) parseHttpRequest: parseHttpRequest: prefix_sz = 41, req_line_sz = 39
2016/12/08 18:14:35.971 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x2513570 type=ClientHttpRequest [job821]
2016/12/08 18:14:35.971 kid2| src/clientStream.cc(167) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x25106f8 with data 0x2514c40 after head
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2346) parseHttpRequest: parseHttpRequest: Request Header is
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2367) parseHttpRequest: repare absolute URL from
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2404) parseHttpRequest: parseHttpRequest: Complete request received
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2407) parseHttpRequest: HTTP Client local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2408) parseHttpRequest: HTTP Client REQUEST:
---------
CONNECT www.facebook.com:443 HTTP/1.0
----------
2016/12/08 18:14:35.971 kid2| src/client_side.cc(3019) clientParseRequests: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: parsed a request
2016/12/08 18:14:35.971 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x2574f90 [call15375]
2016/12/08 18:14:35.971 kid2| src/comm.cc(768) commSetConnTimeout: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 timeout 86400
2016/12/08 18:14:35.971 kid2| src/url.cc(386) urlParse: urlParse: Split URL 'www.facebook.com:443' into proto='', host='www.facebook.com', port='443', path=''
2016/12/08 18:14:35.971 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x249f858 owner: 2
2016/12/08 18:14:35.971 kid2| src/HttpRequest.cc(70) HttpRequest: constructed, this=0x249f840 id=8
2016/12/08 18:14:35.971 kid2| src/ip/Address.cc(378) lookupHostIP: Given Non-IP 'www.facebook.com': Name or service not known
2016/12/08 18:14:35.971 kid2| src/HttpHeader.cc(557) parse: parsing hdr: (0x249f858)
2016/12/08 18:14:35.971 kid2| src/client_side.cc(925) clientSetKeepaliveFlag: clientSetKeepaliveFlag: http_ver = 1.0
2016/12/08 18:14:35.971 kid2| src/client_side.cc(927) clientSetKeepaliveFlag: clientSetKeepaliveFlag: method = CONNECT
2016/12/08 18:14:35.971 kid2| src/client_side.h(108) mayUseConnection: This 0x2513bc8 marked 1
2016/12/08 18:14:35.971 kid2| src/client_side.cc(2510) connNoteUseOfBuffer: conn->in.notYetUsed = 0
2016/12/08 18:14:35.971 kid2| src/client_side_request.cc(152) ClientRequestContext: 0x250fb88 ClientRequestContext constructed
2016/12/08 18:14:35.971 kid2| src/client_side_request.cc(1691) doCallouts: Doing calloutContext->hostHeaderVerify()
2016/12/08 18:14:35.971 kid2| src/client_side_request.cc(605) hostHeaderVerify: validate skipped with no Host: header present.
2016/12/08 18:14:35.971 kid2| src/client_side_request.cc(1698) doCallouts: Doing calloutContext->clientAccessCheck()
2016/12/08 18:14:35.971 kid2| src/acl/Checklist.cc(62) preCheck: 0x2516068 checking slow rules
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(157) matches: checking http_access
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(157) matches: checking http_access#1
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(157) matches: checking manager
2016/12/08 18:14:35.971 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'www.facebook.com:443'
2016/12/08 18:14:35.971 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2016/12/08 18:14:35.971 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(177) matches: checked: manager = 0
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(177) matches: checked: http_access#1 = 0
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(157) matches: checking http_access#2
2016/12/08 18:14:35.971 kid2| src/acl/Acl.cc(157) matches: checking manager
2016/12/08 18:14:35.972 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'www.facebook.com:443'
2016/12/08 18:14:35.972 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2016/12/08 18:14:35.972 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: manager = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access#2 = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking http_access#3
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking healthcheck
2016/12/08 18:14:35.972 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'www.facebook.com:443'
2016/12/08 18:14:35.972 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(sw_proxy_health_check$)'
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: healthcheck = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access#3 = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking http_access#4
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking !Safe_ports
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking Safe_ports
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: Safe_ports = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: !Safe_ports = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access#4 = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking http_access#5
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking CONNECT
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: CONNECT = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking !SSL_ports
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking SSL_ports
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: SSL_ports = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: !SSL_ports = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access#5 = 0
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking http_access#6
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking socialnetworks
2016/12/08 18:14:35.972 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking 'www.facebook.com'
2016/12/08 18:14:35.972 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: 'www.facebook.com' found
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: socialnetworks = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access#6 = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: http_access = 1
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(55) markFinished: 0x2516068 answer ALLOWED for match
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x2516068 answer=ALLOWED
2016/12/08 18:14:35.972 kid2| src/client_side_request.cc(759) clientAccessCheckDone: The request CONNECT www.facebook.com:443 is ALLOWED; last ACL checked: socialnetworks
2016/12/08 18:14:35.972 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x2511548 type=AccessCheck [job822]
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(49) AccessCheck: AccessCheck constructed for REQMOD PRECACHE
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x2560bd0 [call15376]
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(20) will call AsyncJob::start() [call15376]
2016/12/08 18:14:35.972 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x2516068
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x2516068
2016/12/08 18:14:35.972 kid2| src/client_side.cc(3029) clientParseRequests: Not parsing new requests, as this request may need the connection
2016/12/08 18:14:35.972 kid2| src/base/AsyncJob.cc(146) callEnd: ConnStateData status out: [ job820]
2016/12/08 18:14:35.972 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=41, buf=0x24a20d0)
2016/12/08 18:14:35.972 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(30) make: make call AsyncJob::start [call15376]
2016/12/08 18:14:35.972 kid2| src/base/AsyncJob.cc(117) callStart: AccessCheck status in: [ job822]
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(96) check: start checking
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(215) isCandidate: checking candidacy of 1, group service_test_resp
2016/12/08 18:14:35.972 kid2| src/adaptation/ServiceGroups.cc(136) findService: service_test_resp serves another location
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(225) isCandidate: service_test_resp ignores
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(215) isCandidate: checking candidacy of 2, group service_test_req
2016/12/08 18:14:35.972 kid2| src/adaptation/icap/Options.cc(46) transferKind: url matches no extensions; using default: Transfer-Complete
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(225) isCandidate: service_test_req wants
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(102) check: check: rule '2' is a candidate
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(118) checkCandidates: has 1 rules
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(62) preCheck: 0x2516068 checking slow rules
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking adaptation_access
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking adaptation_access#1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(157) matches: checking socialnetworks
2016/12/08 18:14:35.972 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking 'www.facebook.com'
2016/12/08 18:14:35.972 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: 'www.facebook.com' found
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: socialnetworks = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_access#1 = 1
2016/12/08 18:14:35.972 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_access = 1
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(55) markFinished: 0x2516068 answer ALLOWED for match
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x2516068 answer=ALLOWED
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::AccessCheck::noteAnswer constructed, this=0x23aa110 [call15377]
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/AccessCheck.cc(155) will call Adaptation::AccessCheck::noteAnswer(ALLOWED) [call15377]
2016/12/08 18:14:35.972 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x2516068
2016/12/08 18:14:35.972 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x2516068
2016/12/08 18:14:35.972 kid2| src/base/AsyncJob.cc(146) callEnd: AccessCheck status out: [ job822]
2016/12/08 18:14:35.972 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2016/12/08 18:14:35.972 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Adaptation::AccessCheck::noteAnswer(ALLOWED)
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(30) make: make call Adaptation::AccessCheck::noteAnswer [call15377]
2016/12/08 18:14:35.972 kid2| src/base/AsyncJob.cc(117) callStart: AccessCheck status in: [ job822]
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(164) noteAnswer: 2 answer=ALLOWED
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(198) topGroup: top group for 2 is 0x250e440*2
2016/12/08 18:14:35.972 kid2| src/adaptation/AccessCheck.cc(185) callBack: 0x250e440*2
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Initiator::noteAdaptationAclCheckDone constructed, this=0x22189f0 [call15378]
2016/12/08 18:14:35.972 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/AccessCheck.cc(187) will call Adaptation::Initiator::noteAdaptationAclCheckDone(0x250e440*5) [call15378]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(78) mustStop: AccessCheck will stop, reason: done
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(131) callEnd: Adaptation::AccessCheck::noteAnswer(ALLOWED) ends job [Stopped, reason:done job822]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x2511548 type=AccessCheck [job822]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(141) callEnd: Adaptation::AccessCheck::noteAnswer(ALLOWED) ended 0x2511548
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Adaptation::AccessCheck::noteAnswer(ALLOWED)
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Adaptation::Initiator::noteAdaptationAclCheckDone(0x250e440*2)
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(30) make: make call Adaptation::Initiator::noteAdaptationAclCheckDone [call15378]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(117) callStart: ClientHttpRequest status in: [ job821]
2016/12/08 18:14:35.973 kid2| src/client_side_request.cc(846) noteAdaptationAclCheckDone: 0x2513418 adaptationAclCheckDone called
2016/12/08 18:14:35.973 kid2| src/client_side_request.cc(1854) startAdaptation: adaptation needed for 0x2513418
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x2513328 type=Iterator [job823]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x2560bd0 [call15379]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(20) will call AsyncJob::start() [call15379]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(146) callEnd: ClientHttpRequest status out: [ job821]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Initiator::noteAdaptationAclCheckDone(0x250e440*3)
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(30) make: make call AsyncJob::start [call15379]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(117) callStart: Iterator status in: [ job823]
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/Options.cc(46) transferKind: url matches no extensions; using default: Transfer-Complete
2016/12/08 18:14:35.973 kid2| src/adaptation/Iterator.cc(54) step: #1 plan: service_test_req[0..1]
2016/12/08 18:14:35.973 kid2| src/HttpRequest.cc(508) clearError: old error details: 0/0
2016/12/08 18:14:35.973 kid2| src/adaptation/Iterator.cc(80) step: using adaptation service: service_test_req
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x25105e0 type=Adaptation::Icap::ModXactLauncher [job824]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x2574ed0 [call15380]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(20) will call AsyncJob::start() [call15380]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(146) callEnd: Iterator status out: [ job823]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(30) make: make call AsyncJob::start [call15380]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXactLauncher status in: [ job824]
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/Launcher.cc(43) launchXaction: launching first xaction #1
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x25163d8 type=Adaptation::Icap::ModXact [job825]
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/Xaction.cc(50) Xaction: Adaptation::Icap::ModXact constructed, this=0x2516228 [icapxjob825]
2016/12/08 18:14:35.973 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x25389e8 owner: 2
2016/12/08 18:14:35.973 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/ModXact.cc(74) ModXact: initialized. [G/R job825]
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/Xaction.cc(80) disableRepeats: Adaptation::Icap::ModXact from now on cannot be repeated because over icap_retry_limit [G/R job825]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x2560bd0 [call15381]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/base/AsyncJob.cc(20) will call AsyncJob::start() [call15381]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXactLauncher status out: [ job824]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(30) make: make call AsyncJob::start [call15381]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [G/R job825]
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/ModXact.cc(1783) estimateVirginBody: does not expect virgin body
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/ModXact.cc(1567) decideOnPreview: preview disabled by squid.conf
2016/12/08 18:14:35.973 kid2| src/pconn.cc(169) clearHandlers: removing close handler for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(48) cancel: will not call IdleConnList::Read [call15344] because old comm_read_cancel
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(48) cancel: will not call IdleConnList::Read [call15344] also because old comm_read_cancel
2016/12/08 18:14:35.973 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 28, type=1, handler=0, client_data=0, timeout=0
2016/12/08 18:14:35.973 kid2| src/comm.cc(794) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1
2016/12/08 18:14:35.973 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout -1
2016/12/08 18:14:35.973 kid2| src/adaptation/icap/ServiceRep.cc(116) getConnection: got connection: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x2223ab0 [call15382]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/icap/Xaction.cc(126) will call Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228) [call15382]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXact status out: [FD 28;rw(1)G/R job825]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2016/12/08 18:14:35.973 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228)
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommConnected [call15382]
2016/12/08 18:14:35.973 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 28;rw(1)G/R job825]
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x210d9c0 [call15383]
2016/12/08 18:14:35.973 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout 60
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommClosed constructed, this=0x221e470 [call15384]
2016/12/08 18:14:35.973 kid2| src/comm.cc(1208) comm_add_close_handler: comm_add_close_handler: FD 28, AsyncCall=0x221e470*1
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x2575290 [call15385]
2016/12/08 18:14:35.973 kid2| src/comm.cc(167) comm_read: comm_read, queueing read for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1; asynCall 0x2575290*1
2016/12/08 18:14:35.973 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 28, type=1, handler=1, client_data=0x7ff2cba7bd38, timeout=0
2016/12/08 18:14:35.973 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x20f8350 [call15386]
2016/12/08 18:14:35.973 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout 900
2016/12/08 18:14:35.973 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.974 kid2| src/url.cc(386) urlParse: urlParse: Split URL 'www.facebook.com:443' into proto='', host='www.facebook.com', port='443', path=''
2016/12/08 18:14:35.974 kid2| src/ip/Address.cc(378) lookupHostIP: Given Non-IP 'www.facebook.com': Name or service not known
2016/12/08 18:14:35.974 kid2| src/HttpHeader.cc(713) packInto: packing hdr: (0x2517ae8)
2016/12/08 18:14:35.974 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.974 kid2| src/HttpRequest.cc(78) ~HttpRequest: destructed, this=0x2517ad0
2016/12/08 18:14:35.974 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.974 kid2| src/adaptation/icap/ModXact.cc(1496) makeAllowHeader: Will write Allow: 204
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=13135
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=13135 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp13135
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp13135 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=13135 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=13135 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 13135, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=13148
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=13148 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp13148
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp13148 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=13148 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=13148 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 13148, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=13138
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=13138 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp13138
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp13138 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=13138 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=13138 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 13138, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=13146
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=13146 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp13146
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp13146 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=13146 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=13146 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 13146, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=13145
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=13145 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp13145
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp13145 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=13145 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=13145 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 13145, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=3128
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=3128 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp3128
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp3128 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=3128 line) = 0
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=3128 = 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer DENIED for ACLs failed to match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 3128, HttpRequest: 0x249f840 HttpReply: 0 matched: 0
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f440 checking fast ACLs
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking adaptation_meta X-Proxy-Port=3130
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking (adaptation_meta X-Proxy-Port=3130 line)
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(157) matches: checking lp3130
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: lp3130 = 1
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: (adaptation_meta X-Proxy-Port=3130 line) = 1
2016/12/08 18:14:35.974 kid2| src/acl/Acl.cc(177) matches: checked: adaptation_meta X-Proxy-Port=3130 = 1
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f440 answer ALLOWED for match
2016/12/08 18:14:35.974 kid2| src/Notes.cc(71) match: Check for header name: X-Proxy-Port: 3130, HttpRequest: 0x249f840 HttpReply: 0 matched: 1
2016/12/08 18:14:35.974 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97f440
2016/12/08 18:14:35.974 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97f440
2016/12/08 18:14:35.974 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x25389e8 owner: 2
2016/12/08 18:14:35.974 kid2| src/url.cc(386) urlParse: urlParse: Split URL 'icap://127.0.0.1:1344/foo_reqmod ICAP/1.0
' into proto='icap', host='127.0.0.1', port='1344', path='/foo_reqmod ICAP/1.0'
2016/12/08 18:14:35.974 kid2| src/url.cc(422) urlParse: urlParse: URI has whitespace: {icap://127.0.0.1:1344/foo_reqmod ICAP/1.0
}
2016/12/08 18:14:35.974 kid2| src/HttpRequest.h(103) SetHost: HttpRequest::SetHost() given IP: 127.0.0.1
2016/12/08 18:14:35.974 kid2| src/HttpHeader.cc(557) parse: parsing hdr: (0x25389e8)
Host: 127.0.0.1:1344
Date: Thu, 08 Dec 2016 18:14:35 GMT
Encapsulated: req-hdr=0, null-body=41
Allow: 204
X-Client-IP: 172.16.0.43
X-Proxy-Port: 3130
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommWrote constructed, this=0x2574d60 [call15387]
2016/12/08 18:14:35.975 kid2| src/comm/Write.cc(29) Write: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1: sz 256: asynCall 0x2574d60*1
2016/12/08 18:14:35.975 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 28, type=2, handler=1, client_data=0x7ff2cba7bd70, timeout=0
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x2574e00 [call15388]
2016/12/08 18:14:35.975 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout 900
2016/12/08 18:14:35.975 kid2| src/base/AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXact status out: [FD 28wr;rw(2)G/R job825]
2016/12/08 18:14:35.975 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228)
2016/12/08 18:14:35.975 kid2| src/comm/Write.cc(60) HandleWrite: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1: off 0, sz 256.
2016/12/08 18:14:35.975 kid2| src/comm/Write.cc(100) HandleWrite: write() returns 256
2016/12/08 18:14:35.975 kid2| src/comm/IoCallback.cc(108) finish: called for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 (0, 0)
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228) [call15387]
2016/12/08 18:14:35.975 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228)
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommWrote [call15387]
2016/12/08 18:14:35.975 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 28wr;rw(2)G/R job825]
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x20f8350 [call15389]
2016/12/08 18:14:35.975 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout 900
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(201) handleCommWrote: Wrote 256 bytes
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(502) stopWriting: will no longer write [FD 28r;rw(2)G/R job825]
2016/12/08 18:14:35.975 kid2| src/base/AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXact status out: [FD 28r;rG/Rw job825]
2016/12/08 18:14:35.975 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228)
2016/12/08 18:14:35.975 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 28, type=2, handler=0, client_data=0, timeout=0
2016/12/08 18:14:35.975 kid2| src/comm.cc(138) commHandleRead: comm_read_try: FD 28, size 65535, retval 99, errno 0
2016/12/08 18:14:35.975 kid2| src/comm/IoCallback.cc(108) finish: called for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 (0, 0)
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228, size=99, buf=0x25281d0) [call15385]
2016/12/08 18:14:35.975 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228, size=99, buf=0x25281d0)
2016/12/08 18:14:35.975 kid2| src/base/AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommRead [call15385]
2016/12/08 18:14:35.975 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 28r;rG/Rw job825]
2016/12/08 18:14:35.975 kid2| src/comm.cc(794) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1
2016/12/08 18:14:35.975 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout -1
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/Xaction.cc(413) noteCommRead: read 99 bytes
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/Xaction.cc(73) disableRetries: Adaptation::Icap::ModXact from now on cannot be retried [FD 28;rG/Rw job825]
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(646) parseMore: have 99 bytes to parse [FD 28;rG/Rw job825]
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(647) parseMore:
ICAP/1.0 200 OK
Encapsulated: req-hdr=0, null-body=41
CONNECT www.facebook.com:443 HTTP/1.0
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(742) parseHeaders: parse ICAP headers
2016/12/08 18:14:35.975 kid2| src/adaptation/icap/ModXact.cc(1072) parseHead: have 99 head bytes to parse; state: 0
2016/12/08 18:14:35.975 kid2| src/HttpHeader.cc(557) parse: parsing hdr: (0x249f3a8)
Encapsulated: req-hdr=0, null-body=41
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1087) parseHead: parse success, consume 58 bytes, return true
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(747) parseHeaders: parse HTTP headers
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Xaction.cc(502) setOutcome: ICAP_MOD
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1072) parseHead: have 41 head bytes to parse; state: 1
2016/12/08 18:14:35.976 kid2| src/url.cc(386) urlParse: urlParse: Split URL 'www.facebook.com:443' into proto='', host='www.facebook.com', port='443', path=''
2016/12/08 18:14:35.976 kid2| src/ip/Address.cc(378) lookupHostIP: Given Non-IP 'www.facebook.com': Name or service not known
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(557) parse: parsing hdr: (0x2517ae8)
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1087) parseHead: parse success, consume 41 bytes, return true
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1102) decideOnParsingBody: not expecting a body
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1165) stopParsing: will no longer parse [FD 28;rp(1)S(2)G/Rw job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(609) stopSending: Enter stop sending
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(612) stopSending: Proceed with stop sending
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(615) stopSending: will no longer send [FD 28;S(2)G/Rwrp job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Xaction.cc(80) disableRepeats: Adaptation::Icap::ModXact still cannot be repeated because sent headers [FD 28;G/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(715) disableBypass: not protecting group bypass because sent headers
2016/12/08 18:14:35.976 kid2| src/adaptation/Answer.cc(23) Forward: forwarding: 0x2517ad0
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x2223ab0 [call15390]
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call15390]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(542) readMore: returning from readMore because reader or doneReading()
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Xaction.cc(342) callEnd: Adaptation::Icap::ModXact done with I/O [FD 28;/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/comm.cc(1253) comm_remove_close_handler: comm_remove_close_handler: FD 28, AsyncCall=0x221e470*2
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(48) cancel: will not call Adaptation::Icap::Xaction::noteCommClosed [call15384] because comm_remove_close_handler
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Xaction.cc(73) disableRetries: Adaptation::Icap::ModXact still cannot be retried [FD 28;/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ServiceRep.cc(126) putConnection: pushing pconn [FD 28;/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/comm.cc(794) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1
2016/12/08 18:14:35.976 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout -1
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall IdleConnList::Read constructed, this=0x210d9c0 [call15391]
2016/12/08 18:14:35.976 kid2| src/comm.cc(167) comm_read: comm_read, queueing read for local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1; asynCall 0x210d9c0*1
2016/12/08 18:14:35.976 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 28, type=1, handler=1, client_data=0x7ff2cba7bd38, timeout=0
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall IdleConnList::Timeout constructed, this=0x2569cd0 [call15392]
2016/12/08 18:14:35.976 kid2| src/comm.cc(768) commSetConnTimeout: local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1 timeout 60
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(131) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228, size=99, buf=0x25281d0) ends job [/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1235) swanSong: swan sings [/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(609) stopSending: Enter stop sending
2016/12/08 18:14:35.976 kid2| src/adaptation/Initiate.cc(58) swanSong: swan sings [/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/Initiate.cc(65) swanSong: swan sang [/RwrpS job825]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Xaction.cc(59) ~Xaction: Adaptation::Icap::ModXact destructed, this=0x2516228 [icapxjob825]
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x25389e8 owner: 2
2016/12/08 18:14:35.976 kid2| src/HttpRequest.cc(78) ~HttpRequest: destructed, this=0x25389d0
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x25389e8 owner: 2
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:35.976 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x25163d8 type=Adaptation::Icap::ModXact [job825]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(141) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228, size=99, buf=0x25281d0) ended 0x25163d8
2016/12/08 18:14:35.976 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:53018 remote=127.0.0.1:1344 FD 28 flags=1, data=0x2516228, size=99, buf=0x25281d0)
2016/12/08 18:14:35.976 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call15390]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(117) callStart: Adaptation::Icap::ModXactLauncher status in: [ job824]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/Launcher.cc(58) noteAdaptationAnswer: launches: 1 answer: 0
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x2575290 [call15393]
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call15393]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(131) callEnd: Initiator::noteAdaptationAnswer(0) ends job [ job824]
2016/12/08 18:14:35.976 kid2| src/adaptation/icap/ModXact.cc(1966) swanSong: swan sings
2016/12/08 18:14:35.976 kid2| src/adaptation/Initiate.cc(58) swanSong: swan sings [ job824]
2016/12/08 18:14:35.976 kid2| src/adaptation/Initiate.cc(65) swanSong: swan sang [ job824]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x25105e0 type=Adaptation::Icap::ModXactLauncher [job824]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(141) callEnd: Initiator::noteAdaptationAnswer(0) ended 0x25105e0
2016/12/08 18:14:35.976 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.976 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call15393]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(117) callStart: Iterator status in: [ job823]
2016/12/08 18:14:35.976 kid2| src/adaptation/ServiceGroups.cc(181) findService: service_test_req has no matching services
2016/12/08 18:14:35.976 kid2| src/adaptation/Iterator.cc(54) step: #2 plan: service_test_req[1..1.]
2016/12/08 18:14:35.976 kid2| src/adaptation/Answer.cc(23) Forward: forwarding: 0x2517ad0
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x2223ab0 [call15394]
2016/12/08 18:14:35.976 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call15394]
2016/12/08 18:14:35.976 kid2| src/base/AsyncJob.cc(131) callEnd: Initiator::noteAdaptationAnswer(0) ends job [ job823]
2016/12/08 18:14:35.977 kid2| src/adaptation/Initiate.cc(58) swanSong: swan sings [ job823]
2016/12/08 18:14:35.977 kid2| src/adaptation/Initiate.cc(65) swanSong: swan sang [ job823]
2016/12/08 18:14:35.977 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x2513328 type=Iterator [job823]
2016/12/08 18:14:35.977 kid2| src/base/AsyncJob.cc(141) callEnd: Initiator::noteAdaptationAnswer(0) ended 0x2513328
2016/12/08 18:14:35.977 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.977 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.977 kid2| src/base/AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call15394]
2016/12/08 18:14:35.977 kid2| src/base/AsyncJob.cc(117) callStart: ClientHttpRequest status in: [ job821]
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1727) doCallouts: Doing calloutContext->clientAccessCheck2()
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(734) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(759) clientAccessCheckDone: The request CONNECT www.facebook.com:443 is ALLOWED; last ACL checked: lp3130
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1746) doCallouts: Doing clientInterpretRequestHeaders()
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1197) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_NOCACHE = NOT SET
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1199) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_CACHABLE = SET
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1201) clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_HIERARCHICAL = NOT SET
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1755) doCallouts: Doing calloutContext->checkNoCache()
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(62) preCheck: 0x2516068 checking slow rules
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking cache
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking cache#1
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking all
2016/12/08 18:14:35.977 kid2| src/acl/Ip.cc(560) match: aclIpMatchIp: '172.16.0.43:35114' found
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: all = 1
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: cache#1 = 1
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: cache = 1
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(55) markFinished: 0x2516068 answer DENIED for match
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x2516068 answer=DENIED
2016/12/08 18:14:35.977 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97f0c0
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97f0c0
2016/12/08 18:14:35.977 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97f0c0
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97f0c0
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1469) sslBumpAccessCheck: SslBump possible, checking ACL
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(62) preCheck: 0x2517878 checking slow rules
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking (ssl_bump rules)
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking (ssl_bump rule)
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking socialnetworksssl
2016/12/08 18:14:35.977 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking 'www.facebook.com'
2016/12/08 18:14:35.977 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: 'www.facebook.com' found
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: socialnetworksssl = 1
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: (ssl_bump rule) = 1
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(177) matches: checked: (ssl_bump rules) = 1
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(55) markFinished: 0x2517878 answer ALLOWED for match
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x2517878 answer=ALLOWED
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1551) sslBumpNeed: sslBump required: client-first
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(137) ~ClientRequestContext: 0x250fb88 ClientRequestContext destructed
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1835) doCallouts: calling processRequest()
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1513) processRequest: clientProcessRequest: CONNECT 'www.facebook.com:443'
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1597) sslBumpStart: Confirming client-first-bumped CONNECT tunnel on FD local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1
2016/12/08 18:14:35.977 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ClientSocketContext::sslBumpEstablish constructed, this=0x2575290 [call15395]
2016/12/08 18:14:35.977 kid2| src/comm/Write.cc(29) Write: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: sz 39: asynCall 0x2575290*1
2016/12/08 18:14:35.977 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=2, handler=1, client_data=0x7ff2cba7bcf8, timeout=0
2016/12/08 18:14:35.977 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x2517878
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x2517878
2016/12/08 18:14:35.977 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x2516068
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x2516068
2016/12/08 18:14:35.977 kid2| src/base/AsyncJob.cc(146) callEnd: ClientHttpRequest status out: [ job821]
2016/12/08 18:14:35.977 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2016/12/08 18:14:35.977 kid2| src/comm/Write.cc(60) HandleWrite: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: off 0, sz 39.
2016/12/08 18:14:35.977 kid2| src/comm/Write.cc(100) HandleWrite: write() returns 39
2016/12/08 18:14:35.977 kid2| src/comm/IoCallback.cc(108) finish: called for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 (0, 0)
2016/12/08 18:14:35.977 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call ClientSocketContext::sslBumpEstablish(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2513418, size=39, buf=0x797dd0) [call15395]
2016/12/08 18:14:35.977 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering ClientSocketContext::sslBumpEstablish(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2513418, size=39, buf=0x797dd0)
2016/12/08 18:14:35.977 kid2| src/base/AsyncCall.cc(30) make: make call ClientSocketContext::sslBumpEstablish [call15395]
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(1560) SslBumpEstablish: responded to CONNECT: 0x2513418 ? 0
2016/12/08 18:14:35.977 kid2| src/client_side.cc(4015) switchToHttps: converting local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 to SSL
2016/12/08 18:14:35.977 kid2| src/clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0x25106f8
2016/12/08 18:14:35.977 kid2| src/clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0x25106f8
2016/12/08 18:14:35.977 kid2| src/clientStream.cc(246) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x2515e98
2016/12/08 18:14:35.977 kid2| src/clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0x250bb78
2016/12/08 18:14:35.977 kid2| src/clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0x250bb78
2016/12/08 18:14:35.977 kid2| src/client_side_request.cc(265) ~ClientHttpRequest: httpRequestFree: www.facebook.com:443
2016/12/08 18:14:35.977 kid2| src/client_side.cc(617) logRequest: logging half-baked transaction: www.facebook.com:443
2016/12/08 18:14:35.977 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f4e0 checking fast ACLs
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking access_log stdio:/var/log/squid/access.log
2016/12/08 18:14:35.977 kid2| src/acl/Acl.cc(157) matches: checking (access_log stdio:/var/log/squid/access.log line)
2016/12/08 18:14:35.978 kid2| src/acl/Acl.cc(177) matches: checked: (access_log stdio:/var/log/squid/access.log line) = 1
2016/12/08 18:14:35.978 kid2| src/acl/Acl.cc(177) matches: checked: access_log stdio:/var/log/squid/access.log = 1
2016/12/08 18:14:35.978 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f4e0 answer ALLOWED for match
2016/12/08 18:14:35.978 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97f4e0
2016/12/08 18:14:35.978 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97f4e0
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x2560bd0 [call15396]
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/Initiator.cc(34) will call Initiate::noteInitiatorAborted() [call15396]
2016/12/08 18:14:35.978 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.978 kid2| src/HttpRequest.cc(78) ~HttpRequest: destructed, this=0x2517ad0
2016/12/08 18:14:35.978 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2517ae8 owner: 2
2016/12/08 18:14:35.978 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f858 owner: 2
2016/12/08 18:14:35.978 kid2| src/HttpRequest.cc(78) ~HttpRequest: destructed, this=0x249f840
2016/12/08 18:14:35.978 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f858 owner: 2
2016/12/08 18:14:35.978 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x2513570 type=ClientHttpRequest [job821]
2016/12/08 18:14:35.978 kid2| src/client_side.cc(3983) getSslContextDone: Using static ssl context.
2016/12/08 18:14:35.978 kid2| src/client_side.cc(3496) httpsCreate: httpsCreate: will negotate SSL on local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::requestTimeout constructed, this=0x23aa110 [call15397]
2016/12/08 18:14:35.978 kid2| src/comm.cc(768) commSetConnTimeout: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 timeout 300
2016/12/08 18:14:35.978 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=0, client_data=0, timeout=0
2016/12/08 18:14:35.978 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=1, client_data=0x2512f88, timeout=0
2016/12/08 18:14:35.978 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving ClientSocketContext::sslBumpEstablish(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2513418, size=39, buf=0x797dd0)
2016/12/08 18:14:35.978 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Initiate::noteInitiatorAborted()
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(30) make: make call Initiate::noteInitiatorAborted [call15396]
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(48) cancel: will not call Initiate::noteInitiatorAborted [call15396] because job gone
2016/12/08 18:14:35.978 kid2| src/base/AsyncCall.cc(40) make: will not call Initiate::noteInitiatorAborted [call15396] because of job gone
2016/12/08 18:14:35.978 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Initiate::noteInitiatorAborted()
2016/12/08 18:14:35.978 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=2, handler=0, client_data=0, timeout=0
2016/12/08 18:14:36.035 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=1, client_data=0x2512f88, timeout=0
-----BEGIN SSL SESSION PARAMETERS-----
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX=
-----END SSL SESSION PARAMETERS-----
2016/12/08 18:14:36.085 kid2| src/client_side.cc(3594) clientNegotiateSSL: clientNegotiateSSL: New session 0x2574d60 on FD 27 (172.16.0.43:35114)
2016/12/08 18:14:36.085 kid2| src/client_side.cc(3598) clientNegotiateSSL: clientNegotiateSSL: FD 27 negotiated cipher AES256-GCM-SHA384
2016/12/08 18:14:36.086 kid2| src/client_side.cc(3614) clientNegotiateSSL: clientNegotiateSSL: FD 27 has no certificate.
2016/12/08 18:14:36.086 kid2| src/client_side.cc(258) readSomeData: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: reading request...
2016/12/08 18:14:36.086 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x221e480 [call15398]
2016/12/08 18:14:36.086 kid2| src/comm.cc(167) comm_read: comm_read, queueing read for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1; asynCall 0x221e480*1
2016/12/08 18:14:36.086 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=1, client_data=0x7ff2cba7bcc0, timeout=0
2016/12/08 18:14:36.131 kid2| src/comm.cc(138) commHandleRead: comm_read_try: FD 27, size 4095, retval 40, errno 0
2016/12/08 18:14:36.131 kid2| src/comm/IoCallback.cc(108) finish: called for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 (0, 0)
2016/12/08 18:14:36.131 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=40, buf=0x24a20d0) [call15398]
2016/12/08 18:14:36.131 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=40, buf=0x24a20d0)
2016/12/08 18:14:36.131 kid2| src/base/AsyncCall.cc(30) make: make call ConnStateData::clientReadRequest [call15398]
2016/12/08 18:14:36.131 kid2| src/base/AsyncJob.cc(117) callStart: ConnStateData status in: [ job820]
2016/12/08 18:14:36.131 kid2| src/client_side.cc(3042) clientReadRequest: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 size 40
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2981) clientParseRequests: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: attempting to parse
2016/12/08 18:14:36.131 kid2| src/HttpParser.cc(29) reset: Request buffer is GET / HTTP/1.0
Host: 172.16.32.219:443
2016/12/08 18:14:36.131 kid2| src/HttpParser.cc(39) parseRequestFirstLine: parsing possible request: GET / HTTP/1.0
Host: 172.16.32.219:443
2016/12/08 18:14:36.131 kid2| src/HttpParser.cc(249) HttpParserParseReqLine: Parser: retval 1: from 0->14: method 0->2; url 4->4; version 6->13 (1/0)
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2322) parseHttpRequest: parseHttpRequest: req_hdr = {Host: 172.16.32.219:443
}
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2326) parseHttpRequest: parseHttpRequest: end = {
}
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2330) parseHttpRequest: parseHttpRequest: prefix_sz = 40, req_line_sz = 15
2016/12/08 18:14:36.131 kid2| src/base/AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x2513570 type=ClientHttpRequest [job826]
2016/12/08 18:14:36.131 kid2| src/clientStream.cc(167) clientStreamInsertHead: clientStreamInsertHead: Inserted node 0x25106f8 with data 0x2514c40 after head
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2346) parseHttpRequest: parseHttpRequest: Request Header is
Host: 172.16.32.219:443
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2367) parseHttpRequest: repare absolute URL from
2016/12/08 18:14:36.131 kid2| src/mime_header.cc(59) mime_get_header_field: mime_get_header: looking for 'Host'
2016/12/08 18:14:36.131 kid2| src/mime_header.cc(81) mime_get_header_field: mime_get_header: checking 'Host: 172.16.32.219:443'
2016/12/08 18:14:36.131 kid2| src/mime_header.cc(104) mime_get_header_field: mime_get_header: returning '172.16.32.219:443'
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2137) prepareAcceleratedURL: ACCEL VHOST REWRITE: vhost=172.16.32.219:443 + vport=0
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2157) prepareAcceleratedURL: ACCEL VHOST REWRITE: 'https://172.16.32.219:443/'
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2404) parseHttpRequest: parseHttpRequest: Complete request received
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2407) parseHttpRequest: HTTP Client local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1
2016/12/08 18:14:36.131 kid2| src/client_side.cc(2408) parseHttpRequest: HTTP Client REQUEST:
---------
GET / HTTP/1.0
Host: 172.16.32.219:443
----------
2016/12/08 18:14:36.131 kid2| src/client_side.cc(3019) clientParseRequests: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: parsed a request
2016/12/08 18:14:36.131 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall clientLifetimeTimeout constructed, this=0x2223ab0 [call15399]
2016/12/08 18:14:36.131 kid2| src/comm.cc(768) commSetConnTimeout: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 timeout 86400
2016/12/08 18:14:36.131 kid2| src/url.cc(386) urlParse: urlParse: Split URL 'https://172.16.32.219:443/' into proto='https', host='172.16.32.219', port='443', path='/'
2016/12/08 18:14:36.131 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x249f858 owner: 2
2016/12/08 18:14:36.131 kid2| src/HttpRequest.cc(70) HttpRequest: constructed, this=0x249f840 id=9
2016/12/08 18:14:36.131 kid2| src/HttpRequest.h(103) SetHost: HttpRequest::SetHost() given IP: 172.16.32.219
2016/12/08 18:14:36.131 kid2| src/HttpHeader.cc(557) parse: parsing hdr: (0x249f858)
Host: 172.16.32.219:443
2016/12/08 18:14:36.131 kid2| src/client_side.cc(925) clientSetKeepaliveFlag: clientSetKeepaliveFlag: http_ver = 1.0
2016/12/08 18:14:36.131 kid2| src/client_side.cc(927) clientSetKeepaliveFlag: clientSetKeepaliveFlag: method = GET
2016/12/08 18:14:36.131 kid2| src/client_side_request.cc(152) ClientRequestContext: 0x250fb88 ClientRequestContext constructed
2016/12/08 18:14:36.131 kid2| src/client_side_request.cc(1691) doCallouts: Doing calloutContext->hostHeaderVerify()
2016/12/08 18:14:36.131 kid2| src/client_side_request.cc(648) hostHeaderVerify: validate host=172.16.32.219, port=443, portStr=443
2016/12/08 18:14:36.131 kid2| src/client_side_request.cc(662) hostHeaderVerify: validate skipped.
2016/12/08 18:14:36.131 kid2| src/client_side_request.cc(1698) doCallouts: Doing calloutContext->clientAccessCheck()
2016/12/08 18:14:36.131 kid2| src/acl/Checklist.cc(62) preCheck: 0x2516068 checking slow rules
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking http_access
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking http_access#1
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking manager
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'https://172.16.32.219/'
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: manager = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: http_access#1 = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking http_access#2
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking manager
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'https://172.16.32.219/'
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^cache_object://)'
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(^https?://[^/]+/squid-internal-mgr/)'
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: manager = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: http_access#2 = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking http_access#3
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking healthcheck
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(71) match: aclRegexData::match: checking 'https://172.16.32.219/'
2016/12/08 18:14:36.131 kid2| src/acl/RegexData.cc(82) match: aclRegexData::match: looking for '(sw_proxy_health_check$)'
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: healthcheck = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(177) matches: checked: http_access#3 = 0
2016/12/08 18:14:36.131 kid2| src/acl/Acl.cc(157) matches: checking http_access#4
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking !Safe_ports
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking Safe_ports
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: Safe_ports = 1
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: !Safe_ports = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: http_access#4 = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking http_access#5
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking CONNECT
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: CONNECT = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: http_access#5 = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking http_access#6
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking socialnetworks
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking '172.16.32.219'
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: '172.16.32.219' NOT found
2016/12/08 18:14:36.132 kid2| src/ipcache.cc(961) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '172.16.32.219' == 172.16.32.219
2016/12/08 18:14:36.132 kid2| src/acl/DestinationDomain.cc(109) match: aclMatchAcl: Can't yet compare 'socialnetworks' ACL for '172.16.32.219'
2016/12/08 18:14:36.132 kid2| src/fqdncache.cc(542) fqdncache_nbgethostbyaddr: fqdncache_nbgethostbyaddr: Name '172.16.32.219'.
2016/12/08 18:14:36.132 kid2| src/fqdncache.cc(564) fqdncache_nbgethostbyaddr: fqdncache_nbgethostbyaddr: HIT for '172.16.32.219'
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking 'none'
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: 'none' NOT found
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: socialnetworks = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: http_access#6 = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking http_access#7
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(157) matches: checking passthrough
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking '172.16.32.219'
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: '172.16.32.219' NOT found
2016/12/08 18:14:36.132 kid2| src/ipcache.cc(961) ipcacheCheckNumeric: ipcacheCheckNumeric: HIT_BYPASS for '172.16.32.219' == 172.16.32.219
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(131) match: aclMatchDomainList: checking 'none'
2016/12/08 18:14:36.132 kid2| src/acl/DomainData.cc(135) match: aclMatchDomainList: 'none' NOT found
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: passthrough = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: http_access#7 = 0
2016/12/08 18:14:36.132 kid2| src/acl/Acl.cc(177) matches: checked: http_access = 0
2016/12/08 18:14:36.132 kid2| src/acl/Checklist.cc(378) calcImplicitAnswer: 0x2516068 NO match found, last action ALLOWED so returning DENIED
2016/12/08 18:14:36.132 kid2| src/acl/Checklist.cc(55) markFinished: 0x2516068 answer DENIED for implicit rule won
2016/12/08 18:14:36.132 kid2| src/acl/Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x2516068 answer=DENIED
2016/12/08 18:14:36.132 kid2| src/client_side_request.cc(759) clientAccessCheckDone: The request GET https://172.16.32.219:443/ is DENIED; last ACL checked: passthrough
2016/12/08 18:14:36.132 kid2| src/acl/Gadgets.cc(103) aclIsProxyAuth: aclIsProxyAuth: called for passthrough
2016/12/08 18:14:36.132 kid2| src/acl/Gadgets.cc(108) aclIsProxyAuth: aclIsProxyAuth: returning 0
2016/12/08 18:14:36.132 kid2| src/client_side_request.cc(775) clientAccessCheckDone: Access Denied: https://172.16.32.219:443/
2016/12/08 18:14:36.132 kid2| src/client_side_request.cc(776) clientAccessCheckDone: AclMatchedName = passthrough
2016/12/08 18:14:36.132 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97ebe0
2016/12/08 18:14:36.132 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97ebe0
2016/12/08 18:14:36.132 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97ebe0
2016/12/08 18:14:36.132 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97ebe0
2016/12/08 18:14:36.132 kid2| src/client_side_request.cc(1443) sslBumpAccessCheck: SslBump already decided (1), ignoring ssl_bump for 0x2512f88
2016/12/08 18:14:36.132 kid2| src/HttpRequest.cc(711) storeId: sent back canonicalUrl:https://172.16.32.219/
2016/12/08 18:14:36.132 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.132 kid2| src/store_key_md5.cc(109) storeKeyPrivate: storeKeyPrivate: GET https://172.16.32.219/
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(615) errorAppendEntry: Creating an error page for entry 0x255f7f0 with errorstate 0x255f698 page id 1
2016/12/08 18:14:36.132 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x2559a68 owner: 3
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1278) BuildContent: No existing error page language negotiated for ERR_ACCESS_DENIED. Using default error file.
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%l --> '/*
Stylesheet for Squid Error pages
Adapted from design by Free CSS Templates
http://www.freecsstemplates.org
Released for free under a Creative Commons Attribution 2.5 License
*/
/* Page basics */
* {
font-family: verdana, sans-serif;
}
html body {
margin: 0;
padding: 0;
background: #efefef;
font-size: 12px;
color: #1e1e1e;
}
/* Page displayed title area */
#titles {
margin-left: 15px;
padding: 10px;
padding-left: 100px;
background: url('http://www.squid-cache.org/Artwork/SN.png') no-repeat left;
}
/* initial title */
#titles h1 {
color: #000000;
}
#titles h2 {
color: #000000;
}
/* special event: FTP success page titles */
#titles ftpsuccess {
background-color:#00ff00;
width:100%;
}
/* Page displayed body content area */
#content {
padding: 10px;
background: #ffffff;
}
/* General text */
p {
}
/* error brief description */
#error p {
}
/* some data which may have caused the problem */
#data {
}
/* the error message received from the system or other software */
#sysmsg {
}
pre {
font-family:sans-serif;
}
/* special event: FTP / Gopher directory listing */
#dirmsg {
font-family: courier;
color: black;
font-size: 10pt;
}
#dirlisting {
margin-left: 2%;
margin-right: 2%;
}
#dirlisting tr.entry td.icon,td.filename,td.size,td.date {
border-bottom: groove;
}
#dirlisting td.size {
width: 50px;
text-align: right;
padding-right: 5px;
}
/* horizontal lines */
hr {
margin: 0;
}
/* page displayed footer area */
#footer {
font-size: 9px;
padding-left: 10px;
}
'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%; --> '%;'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%c --> 'ERR_ACCESS_DENIED'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%U --> 'https://172.16.32.219/'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%U --> 'https://172.16.32.219/'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%w --> 'webmaster'
2016/12/08 18:14:36.132 kid2| src/HttpHeader.cc(713) packInto: packing hdr: (0x249f858)
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%W --> '?subject=CacheErrorInfo%20-%20ERR_ACCESS_DENIED&body=CacheHost%3A%20localhost%0D%0AErrPage%3A%20ERR_ACCESS_DENIED%0D%0AErr%3A%20%5Bnone%5D%0D%0ATimeStamp%3A%20Thu,%2008%20Dec%202016%2018%3A14%3A36%20GMT%0D%0A%0D%0AClientIP%3A%20172.16.0.43%0D%0A%0D%0AHTTP%20Request%3A%0D%0AGET%20%2F%20HTTP%2F1.0%0AHost%3A%20172.16.32.219%3A443%0D%0A%0D%0A%0D%0A'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%w --> 'webmaster'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%T --> 'Thu, 08 Dec 2016 18:14:36 GMT'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%h --> 'localhost'
2016/12/08 18:14:36.132 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%s --> 'squid'
2016/12/08 18:14:36.133 kid2| src/errorpage.cc(1117) Convert: errorConvert: %%c --> 'ERR_ACCESS_DENIED'
2016/12/08 18:14:36.133 kid2| src/HttpRequest.cc(496) detailError: current error details: 1/0
2016/12/08 18:14:36.133 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.133 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.133 kid2| src/HttpHeader.cc(713) packInto: packing hdr: (0x2559a68)
2016/12/08 18:14:36.134 kid2| src/store_dir.cc(824) maybeTrimMemory: keepInLocalMemory: 1
2016/12/08 18:14:36.134 kid2| src/store_client.cc(761) invokeHandlers: InvokeHandlers: FB0F4AC67B901ACF463CE31BE1D89D3C
2016/12/08 18:14:36.134 kid2| src/store_client.cc(767) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2016/12/08 18:14:36.134 kid2| src/store_dir.cc(824) maybeTrimMemory: keepInLocalMemory: 1
2016/12/08 18:14:36.134 kid2| src/store_client.cc(761) invokeHandlers: InvokeHandlers: FB0F4AC67B901ACF463CE31BE1D89D3C
2016/12/08 18:14:36.134 kid2| src/store_client.cc(767) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2016/12/08 18:14:36.134 kid2| src/clientStream.cc(207) clientStreamRead: clientStreamRead: Calling 1 with cbdata 0x2515e98 from node 0x25106f8
2016/12/08 18:14:36.134 kid2| src/store_client.cc(222) copy: store_client::copy: FB0F4AC67B901ACF463CE31BE1D89D3C, from 0, for length 4096, cb 1, cbdata 0x2514de8
2016/12/08 18:14:36.134 kid2| src/store_client.cc(317) storeClientCopy2: storeClientCopy2: FB0F4AC67B901ACF463CE31BE1D89D3C
2016/12/08 18:14:36.134 kid2| src/store_client.cc(349) doCopy: store_client::doCopy: co: 0, hi: 3282
2016/12/08 18:14:36.134 kid2| src/store_client.cc(450) scheduleMemRead: store_client::doCopy: Copying normal from memory
2016/12/08 18:14:36.134 kid2| src/client_side_reply.cc(2122) sendMoreData: clientReplyContext::sendMoreData: https://172.16.32.219/, 3282 bytes (3282 new bytes)
2016/12/08 18:14:36.134 kid2| src/client_side_reply.cc(2126) sendMoreData: clientReplyContext::sendMoreData:local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 'https://172.16.32.219/' out.offset=0
2016/12/08 18:14:36.134 kid2| src/HttpHeader.cc(407) HttpHeader: init-ing hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.134 kid2| src/HttpHeader.cc(491) append: appending hdr: 0x249f3a8 += 0x2559a68
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(1474) buildReplyHeader: clientBuildReplyHeader: bumped reply forces close
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(1969) processReplyAccessResult: The reply for GET https://172.16.32.219/ is ALLOWED, because it matched 'passthrough'
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(2007) processReplyAccessResult: clientReplyContext::sendMoreData: Appending 3057 bytes after 225 bytes of headers
2016/12/08 18:14:36.135 kid2| src/clientStream.cc(185) clientStreamCallback: clientStreamCallback: Calling 1 with cbdata 0x2514c40 from node 0x250bb78
2016/12/08 18:14:36.135 kid2| src/HttpHeader.cc(713) packInto: packing hdr: (0x249f3a8)
2016/12/08 18:14:36.135 kid2| src/client_side.cc(1459) sendStartOfMessage: HTTP Client local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1
2016/12/08 18:14:36.135 kid2| src/client_side.cc(1460) sendStartOfMessage: HTTP Client REPLY:
---------
HTTP/1.1 403 Forbidden
Server: squid
Mime-Version: 1.0
Date: Thu, 08 Dec 2016 18:14:36 GMT
Content-Type: text/html
Content-Length: 3057
X-Squid-Error: ERR_ACCESS_DENIED 0
Vary: Accept-Language
Content-Language: en
X-Cache: MISS from localhost
Via: 1.1 localhost (squid)
Connection: close
----------
2016/12/08 18:14:36.135 kid2| src/client_side.cc(1483) sendStartOfMessage: sendStartOfMessage schedules clientWriteComplete
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall clientWriteComplete constructed, this=0x25135a0 [call15400]
2016/12/08 18:14:36.135 kid2| src/comm/Write.cc(29) Write: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: sz 3359: asynCall 0x25135a0*1
2016/12/08 18:14:36.135 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=2, handler=1, client_data=0x7ff2cba7bcf8, timeout=0
2016/12/08 18:14:36.135 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x2516068
2016/12/08 18:14:36.135 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x2516068
2016/12/08 18:14:36.135 kid2| src/client_side.cc(2510) connNoteUseOfBuffer: conn->in.notYetUsed = 0
2016/12/08 18:14:36.135 kid2| src/client_side.cc(258) readSomeData: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: reading request...
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x2513630 [call15401]
2016/12/08 18:14:36.135 kid2| src/comm.cc(167) comm_read: comm_read, queueing read for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1; asynCall 0x2513630*1
2016/12/08 18:14:36.135 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=1, client_data=0x7ff2cba7bcc0, timeout=0
2016/12/08 18:14:36.135 kid2| src/base/AsyncJob.cc(146) callEnd: ConnStateData status out: [ job820]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2512f88, size=40, buf=0x24a20d0)
2016/12/08 18:14:36.135 kid2| src/comm/Write.cc(60) HandleWrite: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1: off 0, sz 3359.
2016/12/08 18:14:36.135 kid2| src/comm/Write.cc(100) HandleWrite: write() returns 3359
2016/12/08 18:14:36.135 kid2| src/comm/IoCallback.cc(108) finish: called for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 (0, 0)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call clientWriteComplete(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2513bc8) [call15400]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering clientWriteComplete(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, data=0x2513bc8)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(30) make: make call clientWriteComplete [call15400]
2016/12/08 18:14:36.135 kid2| src/client_side.cc(1943) writeComplete: local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, sz 3359, err 0, off 3359, len 3282
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(1073) storeOKTransferDone: storeOKTransferDone out.offset=3057 objectLen()=3282 headers_sz=225
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(1185) replyStatus: clientReplyStatus: transfer is DONE
2016/12/08 18:14:36.135 kid2| src/client_side_reply.cc(1210) replyStatus: clientReplyStatus: stream was not expected to complete!
2016/12/08 18:14:36.135 kid2| src/client_side.cc(1917) stopSending: sending error (local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1): STREAM_UNPLANNED_COMPLETE; old receiving error: none
2016/12/08 18:14:36.135 kid2| src/comm.cc(1080) _comm_close: comm_close: start closing FD 27
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall commStartSslClose constructed, this=0x25776a0 [call15402]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm.cc(1114) will call commStartSslClose(FD 27) [call15402]
2016/12/08 18:14:36.135 kid2| src/comm.cc(755) commUnsetFdTimeout: Remove timeout for FD 27
2016/12/08 18:14:36.135 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=0, client_data=0, timeout=0
2016/12/08 18:14:36.135 kid2| src/comm/IoCallback.cc(108) finish: called for local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1 (-10, 0)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm/IoCallback.cc(127) will call ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 FD 27 flags=1, flag=-10, data=0x2512f88, size=0, buf=0x24a20d0) [call15401]
2016/12/08 18:14:36.135 kid2| src/comm.cc(933) commCallCloseHandlers: commCallCloseHandlers: FD 27
2016/12/08 18:14:36.135 kid2| src/comm.cc(941) commCallCloseHandlers: commCallCloseHandlers: ch->handler=0x2574aa0*1
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm.cc(942) will call ConnStateData::connStateClosed(FD -1, data=0x2512f88) [call15372]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall comm_close_complete constructed, this=0x2223ab0 [call15403]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/comm.cc(1156) will call comm_close_complete(FD 27) [call15403]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving clientWriteComplete(local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1, data=0x2513bc8)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering commStartSslClose(FD 27)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(30) make: make call commStartSslClose [call15402]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving commStartSslClose(FD 27)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1, flag=-10, data=0x2512f88, size=0, buf=0x24a20d0)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(30) make: make call ConnStateData::clientReadRequest [call15401]
2016/12/08 18:14:36.135 kid2| src/base/AsyncJob.cc(117) callStart: ConnStateData status in: [ job820]
2016/12/08 18:14:36.135 kid2| src/client_side.cc(3042) clientReadRequest: local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1 size 0
2016/12/08 18:14:36.135 kid2| src/client_side.cc(3049) clientReadRequest: local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1 closing Bailout.
2016/12/08 18:14:36.135 kid2| src/base/AsyncJob.cc(146) callEnd: ConnStateData status out: [ job820]
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving ConnStateData::clientReadRequest(local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1, flag=-10, data=0x2512f88, size=0, buf=0x24a20d0)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering ConnStateData::connStateClosed(FD -1, data=0x2512f88)
2016/12/08 18:14:36.135 kid2| src/base/AsyncCall.cc(30) make: make call ConnStateData::connStateClosed [call15372]
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(117) callStart: ConnStateData status in: [ job820]
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(49) deleteThis: ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(131) callEnd: ConnStateData::connStateClosed(FD -1, data=0x2512f88) ends job [Stopped, reason:ConnStateData::connStateClosed job820]
2016/12/08 18:14:36.136 kid2| src/client_side.cc(864) swanSong: local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1
2016/12/08 18:14:36.136 kid2| src/clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0x25106f8
2016/12/08 18:14:36.136 kid2| src/clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0x25106f8
2016/12/08 18:14:36.136 kid2| src/clientStream.cc(246) clientStreamDetach: clientStreamDetach: Calling 1 with cbdata 0x2515e98
2016/12/08 18:14:36.136 kid2| src/clientStream.cc(225) clientStreamDetach: clientStreamDetach: Detaching node 0x250bb78
2016/12/08 18:14:36.136 kid2| src/clientStream.cc(310) clientStreamFree: Freeing clientStreamNode 0x250bb78
2016/12/08 18:14:36.136 kid2| src/store_client.cc(689) storeUnregister: storeUnregister: called for 'FB0F4AC67B901ACF463CE31BE1D89D3C'
2016/12/08 18:14:36.136 kid2| src/store_dir.cc(824) maybeTrimMemory: keepInLocalMemory: 1
2016/12/08 18:14:36.136 kid2| src/store_client.cc(786) storePendingNClients: storePendingNClients: returning 0
2016/12/08 18:14:36.136 kid2| src/client_side_request.cc(265) ~ClientHttpRequest: httpRequestFree: https://172.16.32.219/
2016/12/08 18:14:36.136 kid2| src/acl/Checklist.cc(62) preCheck: 0x7ffdea97f4e0 checking fast ACLs
2016/12/08 18:14:36.136 kid2| src/acl/Acl.cc(157) matches: checking access_log stdio:/var/log/squid/access.log
2016/12/08 18:14:36.136 kid2| src/acl/Acl.cc(157) matches: checking (access_log stdio:/var/log/squid/access.log line)
2016/12/08 18:14:36.136 kid2| src/acl/Acl.cc(177) matches: checked: (access_log stdio:/var/log/squid/access.log line) = 1
2016/12/08 18:14:36.136 kid2| src/acl/Acl.cc(177) matches: checked: access_log stdio:/var/log/squid/access.log = 1
2016/12/08 18:14:36.136 kid2| src/acl/Checklist.cc(55) markFinished: 0x7ffdea97f4e0 answer ALLOWED for match
2016/12/08 18:14:36.136 kid2| src/acl/FilledChecklist.cc(61) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffdea97f4e0
2016/12/08 18:14:36.136 kid2| src/acl/Checklist.cc(189) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffdea97f4e0
2016/12/08 18:14:36.136 kid2| src/store_client.cc(786) storePendingNClients: storePendingNClients: returning 0
2016/12/08 18:14:36.136 kid2| ctx: enter level 0: 'https://172.16.32.219/'
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2559a68 owner: 3
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x2559a68 owner: 3
2016/12/08 18:14:36.136 kid2| ctx: exit level 0
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x2560bd0 [call15404]
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/adaptation/Initiator.cc(34) will call Initiate::noteInitiatorAborted() [call15404]
2016/12/08 18:14:36.136 kid2| src/client_side_request.cc(137) ~ClientRequestContext: 0x250fb88 ClientRequestContext destructed
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f3a8 owner: 3
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f858 owner: 2
2016/12/08 18:14:36.136 kid2| src/HttpRequest.cc(78) ~HttpRequest: destructed, this=0x249f840
2016/12/08 18:14:36.136 kid2| src/HttpHeader.cc(442) clean: cleaning hdr: 0x249f858 owner: 2
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x2513570 type=ClientHttpRequest [job826]
2016/12/08 18:14:36.136 kid2| src/client_side.cc(4644) unpinConnection:
2016/12/08 18:14:36.136 kid2| src/client_side.cc(895) ~ConnStateData: local=172.16.32.96:3130 remote=172.16.0.43:35114 flags=1
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x2513100 type=ConnStateData [job820]
2016/12/08 18:14:36.136 kid2| src/base/AsyncJob.cc(141) callEnd: ConnStateData::connStateClosed(FD -1, data=0x2512f88) ended 0x2513100
2016/12/08 18:14:36.136 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving ConnStateData::connStateClosed(FD -1, data=0x2512f88)
2016/12/08 18:14:36.136 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering comm_close_complete(FD 27)
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(30) make: make call comm_close_complete [call15403]
2016/12/08 18:14:36.136 kid2| src/fd.cc(116) fd_close: fd_close FD 27 Reading next request
2016/12/08 18:14:36.136 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=1, handler=0, client_data=0, timeout=0
2016/12/08 18:14:36.136 kid2| src/comm/ModEpoll.cc(139) SetSelect: FD 27, type=2, handler=0, client_data=0, timeout=0
2016/12/08 18:14:36.136 kid2| src/comm/AcceptLimiter.cc(47) kick: size=0
2016/12/08 18:14:36.136 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving comm_close_complete(FD 27)
2016/12/08 18:14:36.136 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering Initiate::noteInitiatorAborted()
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(30) make: make call Initiate::noteInitiatorAborted [call15404]
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(48) cancel: will not call Initiate::noteInitiatorAborted [call15404] because job gone
2016/12/08 18:14:36.136 kid2| src/base/AsyncCall.cc(40) make: will not call Initiate::noteInitiatorAborted [call15404] because of job gone
2016/12/08 18:14:36.136 kid2| src/base/AsyncCallQueue.cc(53) fireNext: leaving Initiate::noteInitiatorAborted()
2016/12/08 18:14:36.725 kid2| src/base/AsyncCall.cc(18) AsyncCall: The AsyncCall MaintainSwapSpace constructed, this=0x2560bd0 [call15405]
2016/12/08 18:14:36.725 kid2| src/base/AsyncCall.cc(85) ScheduleCall: /tmp/squid_source/src/event.cc(261) will call MaintainSwapSpace() [call15405]
2016/12/08 18:14:36.725 kid2| src/base/AsyncCallQueue.cc(51) fireNext: entering MaintainSwapSpace()
- Greg
_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users
