Attaching full log of how it fails initially and then able to resolve dns lookup in 3 minutes
collected by setting debug_options ALL, 3
>>>>>
2016/05/31 16:55:05.157| 42,2| IcmpPinger.cc(211) SendResult: return result to squid. len=76
2016/05/31 16:55:05.157 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 12 Pinger Socket
2016/05/31 16:55:05.157| 42,2| IcmpPinger.cc(211) SendResult: return result to squid. len=7990
2016/05/31 16:55:05.157| 42,2| Icmp.cc(95) Log: pingerLog: 1464728105.157655 127.0.0.1 0 Echo Reply 0ms 1 hops
2016/05/31 16:55:05.635 kid1| 50,3| ModDaemon.cc(172) logfile_mod_daemon_append: logfile_mod_daemon_append: daemon:/var/log/squid/access.log: appending 2 bytes
2016/05/31 16:55:05.635 kid1| 50,3| ModDaemon.cc(176) logfile_mod_daemon_append: logfile_mod_daemon_append: current buffer has 6 of 32768 bytes before append
2016/05/31 16:55:05.635 kid1| 50,3| ModDaemon.cc(108) logfileHandleWrite: daemon:/var/log/squid/access.log: write returned 8
2016/05/31 16:55:05.635 kid1| storeLateRelease: released 0 objects
2016/05/31 16:55:25.176 kid1| 38,3| net_db.cc(1286) netdbExchangeStart: netdbExchangeStart: Requesting 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.176 kid1| 23,3| url.cc(357) urlParse: urlParse: Split URL 'http://127.0.0.1:50005/squid-internal-dynamic/netdb' into proto='http', host='127.0.0.1', port='50005', path='/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.176 kid1| 23,3| HttpRequest.h(82) SetHost: HttpRequest::SetHost() given IP: 127.0.0.1
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(774) storeCreatePureEntry: storeCreateEntry: 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.176 kid1| 20,3| MemObject.cc(97) MemObject: new MemObject 0x7f0f6646d960
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(499) setReleaseFlag: StoreEntry::setReleaseFlag: '[null_store_key]'
2016/05/31 16:55:25.176 kid1| 20,3| store_key_md5.cc(89) storeKeyPrivate: storeKeyPrivate: GET http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(447) hashInsert: StoreEntry::hashInsert: Inserting Entry e:=XI/0x7f0f66898f80*0 key '8296497AA8EBFF11C70A96598AA18956'
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(483) lock: storeCreateEntry locked key 8296497AA8EBFF11C70A96598AA18956 e:=XIV/0x7f0f66898f80*1
2016/05/31 16:55:25.176 kid1| 90,3| store_client.cc(200) copy: store_client::copy: 8296497AA8EBFF11C70A96598AA18956, from 0, for length 4096, cb 1, cbdata 0x7f0f6646c918
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(483) lock: store_client::copy locked key 8296497AA8EBFF11C70A96598AA18956 e:=XIV/0x7f0f66898f80*2
2016/05/31 16:55:25.176 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 8296497AA8EBFF11C70A96598AA18956
2016/05/31 16:55:25.176 kid1| 90,3| store_client.cc(341) doCopy: store_client::doCopy: Waiting for more
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(521) unlock: store_client::copy unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=XIV/0x7f0f66898f80*2
2016/05/31 16:55:25.176 kid1| 17,3| FwdState.cc(332) Start: 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.176 kid1| 17,2| FwdState.cc(133) FwdState: Forwarding client request , url="" href="http://127.0.0.1:50005/squid-internal-dynamic/netdb">http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.176 kid1| 20,3| store.cc(483) lock: FwdState locked key 8296497AA8EBFF11C70A96598AA18956 e:=XIV/0x7f0f66898f80*2
2016/05/31 16:55:25.176 kid1| 44,3| peer_select.cc(137) peerSelect: e:=XIWV/0x7f0f66898f80*2 http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.177 kid1| 20,3| store.cc(483) lock: peerSelect locked key 8296497AA8EBFF11C70A96598AA18956 e:=XIWV/0x7f0f66898f80*3
2016/05/31 16:55:25.177 kid1| 44,3| peer_select.cc(441) peerSelectFoo: GET 127.0.0.1
2016/05/31 16:55:25.177 kid1| 44,3| peer_select.cc(468) peerSelectFoo: peerSelectFoo: direct = DIRECT_YES (forwarding loop detected)
2016/05/31 16:55:25.177 kid1| 44,3| peer_select.cc(477) peerSelectFoo: peerSelectFoo: direct = DIRECT_YES
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(258) peerSelectDnsPaths: Find IP destination for: http://127.0.0.1:50005/squid-internal-dynamic/netdb' via 127.0.0.1
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(280) peerSelectDnsPaths: Found sources for 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(281) peerSelectDnsPaths: always_direct = DENIED
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(282) peerSelectDnsPaths: never_direct = DENIED
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(286) peerSelectDnsPaths: DIRECT = local=0.0.0.0 remote=127.0.0.1:50005 flags=1
2016/05/31 16:55:25.177 kid1| 44,2| peer_select.cc(295) peerSelectDnsPaths: timedout = 0
2016/05/31 16:55:25.177 kid1| 17,3| FwdState.cc(387) startConnectionOrFail: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.177 kid1| 17,3| FwdState.cc(806) connectStart: fwdConnectStart: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.177 kid1| 48,3| pconn.cc(439) pop: lookup for key {127.0.0.1:50005/127.0.0.1} failed.
2016/05/31 16:55:25.177 kid1| 17,3| FwdState.cc(1307) GetMarkingsToServer: from 0.0.0.0 netfilter mark 0
2016/05/31 16:55:25.177 kid1| 17,3| AsyncCall.cc(26) AsyncCall: The AsyncCall fwdConnectDoneWrapper constructed, this=0x7f0f6646dfa0 [call52]
2016/05/31 16:55:25.177 kid1| 44,3| peer_select.cc(79) ~ps_state: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.177 kid1| 20,3| store.cc(521) unlock: peerSelect unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=p2XIWV/0x7f0f66898f80*3
2016/05/31 16:55:25.177 kid1| 50,3| comm.cc(347) comm_openex: comm_openex: Attempt open socket for: 0.0.0.0
2016/05/31 16:55:25.177 kid1| 50,3| comm.cc(388) comm_openex: comm_openex: Opened socket local=0.0.0.0 remote=[::] FD 10 flags=1 : family=2, type=1, protocol=6
2016/05/31 16:55:25.177 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 10 127.0.0.1
2016/05/31 16:55:25.177 kid1| 5,3| ConnOpener.cc(289) createFd: local=0.0.0.0 remote=127.0.0.1:50005 flags=1 will timeout in 60
2016/05/31 16:55:25.177 kid1| 17,3| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(137) will call fwdConnectDoneWrapper(local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1, data="" [call52]
2016/05/31 16:55:25.177 kid1| 17,3| AsyncCallQueue.cc(55) fireNext: entering fwdConnectDoneWrapper(local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1, data="">
2016/05/31 16:55:25.177 kid1| 17,3| AsyncCall.cc(38) make: make call fwdConnectDoneWrapper [call52]
2016/05/31 16:55:25.177 kid1| 17,3| FwdState.cc(680) connectDone: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1: 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.177 kid1| 17,3| FwdState.cc(908) dispatch: : Fetching GET http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.177 kid1| 38,3| net_db.cc(325) netdbSendPing: netdbSendPing: pinging 127.0.0.1
2016/05/31 16:55:25.178 kid1| 37,2| IcmpSquid.cc(90) SendEcho: to 127.0.0.1, opcode 3, len 9
2016/05/31 16:55:25.178 kid1| 11,3| http.cc(2278) httpStart: GET http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.178 kid1| 20,3| store.cc(483) lock: Client locked key 8296497AA8EBFF11C70A96598AA18956 e:=p2XDIWV/0x7f0f66898f80*3
2016/05/31 16:55:25.178 kid1| 17,3| AsyncCallQueue.cc(57) fireNext: leaving fwdConnectDoneWrapper(local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1, data="">
2016/05/31 16:55:25.178 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 timeout 86400
2016/05/31 16:55:25.178 kid1| 22,3| refresh.cc(656) getMaxAge: getMaxAge: 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.178| 42,2| IcmpPinger.cc(198) Recv: Pass 127.0.0.1 off to ICMPv4 module.
2016/05/31 16:55:25.178 kid1| 11,2| http.cc(2234) sendRequest: HTTP Server local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:55:25.178 kid1| 11,2| http.cc(2235) sendRequest: HTTP Server REQUEST:
---------
GET /squid-internal-dynamic/netdb HTTP/1.1
Via: 1.1 SLES12-001-0 (squid/3.5.16)
X-Forwarded-For: ::
Host: 127.0.0.1:50005
Authorization: Basic UEFTU1RIUlU=
Cache-Control: max-age=259200
Connection: keep-alive
----------
2016/05/31 16:55:25.178| 42,2| Icmp.cc(95) Log: pingerLog: 1464728125.178329 127.0.0.1 32
2016/05/31 16:55:25.178 kid1| 5,3| IoCallback.cc(116) finish: called for local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 (0, 0)
2016/05/31 16:55:25.178 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 timeout 900
2016/05/31 16:55:25.178| 42,2| IcmpPinger.cc(211) SendResult: return result to squid. len=7990
2016/05/31 16:55:25.178| 42,2| Icmp.cc(95) Log: pingerLog: 1464728125.178565 127.0.0.1 0 Echo Reply 0ms 1 hops
2016/05/31 16:55:25.178 kid1| 38,3| net_db.cc(931) netdbHandlePingReply: netdbHandlePingReply: from 127.0.0.1
2016/05/31 16:55:25.178 kid1| 38,3| net_db.cc(950) netdbHandlePingReply: netdbHandlePingReply: 127.0.0.0; rtt= 1.00 hops=1.00
2016/05/31 16:55:25.180 kid1| 5,3| Read.cc(144) HandleRead: FD 10, size 16383, retval 99, errno 0
2016/05/31 16:55:25.180 kid1| 5,3| IoCallback.cc(116) finish: called for local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 (0, 0)
2016/05/31 16:55:25.180 kid1| ctx: enter level 0: 'http://127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.180 kid1| 11,3| http.cc(709) processReplyHeader: processReplyHeader: key '8296497AA8EBFF11C70A96598AA18956'
2016/05/31 16:55:25.180 kid1| 11,2| http.cc(750) processReplyHeader: HTTP Server local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:55:25.180 kid1| 11,2| http.cc(751) processReplyHeader: HTTP Server REPLY:
---------
HTTP/1.1 404 Not Found
Content-Length: 53
<html><body><h1>Resource not found</h1></body></html>
----------
2016/05/31 16:55:25.180 kid1| ctx: exit level 0
2016/05/31 16:55:25.180 kid1| 28,3| Checklist.cc(70) preCheck: 0x7f0f6689a1d8 checking slow rules
2016/05/31 16:55:25.180 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '[::]' found
2016/05/31 16:55:25.180 kid1| 28,3| Acl.cc(158) matches: checked: all = 1
2016/05/31 16:55:25.180 kid1| 28,3| Acl.cc(158) matches: checked: adaptation_access#1 = 1
2016/05/31 16:55:25.180 kid1| 28,3| Acl.cc(158) matches: checked: adaptation_access = 1
2016/05/31 16:55:25.180 kid1| 28,3| Checklist.cc(63) markFinished: 0x7f0f6689a1d8 answer ALLOWED for match
2016/05/31 16:55:25.180 kid1| 28,3| Checklist.cc(163) checkCallback: ACLChecklist::checkCallback: 0x7f0f6689a1d8 answer=ALLOWED
2016/05/31 16:55:25.180 kid1| 93,3| AccessCheck.cc(196) callBack: 0x7f0f66898b50*2
2016/05/31 16:55:25.180 kid1| 11,3| http.cc(1065) persistentConnStatus: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 eof=0
2016/05/31 16:55:25.180 kid1| 5,3| comm.cc(579) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:55:25.180 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 timeout -1
2016/05/31 16:55:25.180 kid1| 17,3| FwdState.cc(447) unregister: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.180 kid1| 48,3| pconn.cc(413) push: new IdleConnList for {127.0.0.1:50005/127.0.0.1}
2016/05/31 16:55:25.180 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 timeout 60
2016/05/31 16:55:25.180 kid1| 48,3| pconn.cc(425) push: pushed local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 for 127.0.0.1:50005/127.0.0.1
2016/05/31 16:55:25.180 kid1| 93,3| Xaction.cc(60) Xaction: Adaptation::Icap::ModXact constructed, this=0x7f0f6689c5b8 [icapxjob9]
2016/05/31 16:55:25.181 kid1| 93,3| Xaction.cc(60) Xaction: Adaptation::Icap::OptXact constructed, this=0x7f0f668bde58 [icapxjob11]
2016/05/31 16:55:25.181 kid1| 93,3| ServiceRep.cc(122) getConnection: got connection:
2016/05/31 16:55:25.181 kid1| 93,3| Xaction.cc(145) openConnection: Adaptation::Icap::OptXact opens connection to short.domain.name:1344
2016/05/31 16:55:25.181 kid1| 14,3| Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name or service not known
2016/05/31 16:55:25.181 kid1| 78,3| dns_internal.cc(1745) idnsALookup: idnsALookup: buf is 44 bytes for short.domain.name, id = 0x5c1f
2016/05/31 16:55:25.181 kid1| 50,3| comm.cc(957) comm_udp_sendto: comm_udp_sendto: Attempt to send UDP packet to 10.42.70.144:53 using FD 8 using Port 43651
2016/05/31 16:55:25.181 kid1| 78,3| dns_internal.cc(1683) idnsSendSlaveAAAAQuery: buf is 44 bytes for short.domain.name, id = 0xd1ee
2016/05/31 16:55:25.181 kid1| 50,3| comm.cc(957) comm_udp_sendto: comm_udp_sendto: Attempt to send UDP packet to 10.42.70.144:53 using FD 8 using Port 43651
2016/05/31 16:55:25.181 kid1| 93,3| Xaction.cc(71) ~Xaction: Adaptation::Icap::OptXact destructed, this=0x7f0f668bde58 [icapxjob11]
2016/05/31 16:55:25.181 kid1| 93,3| Launcher.cc(95) noteXactAbort: cannot retry or repeat a failed transaction
2016/05/31 16:55:25.181 kid1| 93,3| ServiceRep.cc(534) noteAdaptationAnswer: failed to fetch options [down,!opt]
2016/05/31 16:55:25.181 kid1| essential ICAP service is down after an options fetch failure: icap://short.domain.name:1344 [down,!opt]
2016/05/31 16:55:25.181 kid1| 93,3| ServiceRep.cc(571) handleNewOptions: got new options and is now [down,!opt]
2016/05/31 16:55:25.182 kid1| 93,3| ../../../src/base/AsyncJobCalls.h(177) dial: Adaptation::Icap::ModXact::noteServiceReady threw exception: ICAP service is unusable
2016/05/31 16:55:25.182 kid1| 93,3| Xaction.cc(71) ~Xaction: Adaptation::Icap::ModXact destructed, this=0x7f0f6689c5b8 [icapxjob9]
2016/05/31 16:55:25.182 kid1| 93,3| Launcher.cc(95) noteXactAbort: cannot retry or repeat a failed transaction
2016/05/31 16:55:25.182 kid1| 17,3| FwdState.cc(416) fail: ERR_ICAP_FAILURE "Internal Server Error"
http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.182 kid1| 17,2| FwdState.cc(655) handleUnregisteredServerEnd: self=0x7f0f6646dee8*2 err=0x7f0f668bda78 http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.182 kid1| 20,3| store.cc(521) unlock: Client unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=p2XDIWV/0x7f0f66898f80*3
2016/05/31 16:55:25.182 kid1| 17,3| FwdState.cc(266) ~FwdState: FwdState destructor starting
2016/05/31 16:55:25.182 kid1| 4,2| errorpage.cc(1262) BuildContent: No existing error page language negotiated for ERR_ICAP_FAILURE. Using default error file.
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%l --> '/*
* Copyright (C) 1996-2016 The Squid Software Foundation and contributors
*
* Squid software is distributed under GPLv2+ license and includes
* contributions from numerous individuals and organizations.
* Please see the COPYING and CONTRIBUTORS files for details.
*/
/*
Stylesheet for Squid Error pages
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('/squid-internal-static/icons/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/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%; --> '%;'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_ICAP_FAILURE'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%U --> 'http://PASSTHRU@127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%U --> 'http://PASSTHRU@127.0.0.1:50005/squid-internal-dynamic/netdb'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%E --> '[No Error]'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%T --> 'Tue, 31 May 2016 20:55:25 GMT'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%h --> 'SLES12-001-0'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%s --> 'squid/3.5.16'
2016/05/31 16:55:25.182 kid1| 4,3| errorpage.cc(1101) Convert: errorConvert: %%c --> 'ERR_ICAP_FAILURE'
2016/05/31 16:55:25.182 kid1| 20,3| store.cc(483) lock: StoreEntry::storeErrorResponse locked key 8296497AA8EBFF11C70A96598AA18956 e:=p2XDIWV/0x7f0f66898f80*3
2016/05/31 16:55:25.182 kid1| 20,3| store.cc(1862) replaceHttpReply: StoreEntry::replaceHttpReply: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.182 kid1| 20,2| store.cc(949) checkCachable: StoreEntry::checkCachable: NO: not cachable
2016/05/31 16:55:25.182 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 8296497AA8EBFF11C70A96598AA18956
2016/05/31 16:55:25.182 kid1| 90,3| store_client.cc(738) invokeHandlers: StoreEntry::InvokeHandlers: checking client #0
2016/05/31 16:55:25.182 kid1| 90,3| store_client.cc(297) storeClientCopy2: storeClientCopy2: 8296497AA8EBFF11C70A96598AA18956
2016/05/31 16:55:25.182 kid1| 90,3| store_client.cc(433) scheduleMemRead: store_client::doCopy: Copying normal from memory
2016/05/31 16:55:25.182 kid1| 38,3| net_db.cc(689) netdbExchangeHandleReply: netdbExchangeHandleReply: 3490 read bytes
2016/05/31 16:55:25.182 kid1| 38,3| net_db.cc(697) netdbExchangeHandleReply: netdbExchangeHandleReply: for '127.0.0.1:50005'
2016/05/31 16:55:25.182 kid1| 38,3| net_db.cc(710) netdbExchangeHandleReply: netdbExchangeHandleReply: 3490 bytes buf
2016/05/31 16:55:25.182 kid1| 38,3| net_db.cc(724) netdbExchangeHandleReply: netdbExchangeHandleReply: reply status 500
2016/05/31 16:55:25.182 kid1| 38,3| net_db.cc(865) netdbExchangeDone: netdbExchangeDone: http://127.0.0.1:50005/squid-internal-dynamic/netdb
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(664) storeUnregister: storeUnregister: called for '8296497AA8EBFF11C70A96598AA18956'
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(483) lock: storeUnregister locked key 8296497AA8EBFF11C70A96598AA18956 e:=p2XDIV/0x7f0f66898f80*4
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(768) CheckQuickAbortIsReasonable: entry=0x7f0f66898f80, mem=0x7f0f6646d960
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(771) CheckQuickAbortIsReasonable: quick-abort? YES !mem->request->flags.cachable
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(483) lock: StoreEntry::abort locked key 8296497AA8EBFF11C70A96598AA18956 e:=p2XDIV/0x7f0f66898f80*5
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(732) invokeHandlers: InvokeHandlers: 8296497AA8EBFF11C70A96598AA18956
2016/05/31 16:55:25.183 kid1| 20,3| store_swapout.cc(273) swapOutFileClose: storeSwapOutFileClose: 8296497AA8EBFF11C70A96598AA18956 how=1
2016/05/31 16:55:25.183 kid1| 20,3| store_swapout.cc(274) swapOutFileClose: storeSwapOutFileClose: sio = 0
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(521) unlock: StoreEntry::abort unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=sp2XDINVA/0x7f0f66898f80*5
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(521) unlock: storeUnregister unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=sp2XDINVA/0x7f0f66898f80*4
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(521) unlock: netdbExchangeDone unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=sp2XDINVA/0x7f0f66898f80*3
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(1048) complete: storeComplete: '8296497AA8EBFF11C70A96598AA18956'
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(521) unlock: StoreEntry::storeErrorResponse unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=sp2XDINVA/0x7f0f66898f80*2
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(521) unlock: FwdState unlocking key 8296497AA8EBFF11C70A96598AA18956 e:=sp2XDINVA/0x7f0f66898f80*1
2016/05/31 16:55:25.183 kid1| 90,3| store_client.cc(758) storePendingNClients: storePendingNClients: returning 0
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(1239) release: releasing e:=sp2XDINVA/0x7f0f66898f80*0 8296497AA8EBFF11C70A96598AA18956
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(402) destroyMemObject: destroyMemObject 0x7f0f6646d960
2016/05/31 16:55:25.183 kid1| 20,3| MemObject.cc(110) ~MemObject: del MemObject 0x7f0f6646d960
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(420) destroyStoreEntry: destroyStoreEntry: destroying 0x7f0f66898f88
2016/05/31 16:55:25.183 kid1| 20,3| store.cc(402) destroyMemObject: destroyMemObject 0
2016/05/31 16:55:25.183 kid1| 17,3| AsyncCall.cc(56) cancel: will not call fwdConnectDoneWrapper [call52] because FwdState destructed
2016/05/31 16:55:25.183 kid1| 17,3| FwdState.cc(293) ~FwdState: FwdState destructor done
2016/05/31 16:55:25.183 kid1| 78,3| dns_internal.cc(1277) idnsRead: idnsRead: starting with FD 8
2016/05/31 16:55:25.183 kid1| 78,3| dns_internal.cc(1323) idnsRead: idnsRead: FD 8: received 60 bytes from 10.42.70.144:53
2016/05/31 16:55:25.183 kid1| 78,3| dns_internal.cc(1130) idnsGrokReply: idnsGrokReply: QID 0x5c1f, 1 answers
2016/05/31 16:55:25.183 kid1| 78,3| dns_internal.cc(1323) idnsRead: idnsRead: FD 8: received 104 bytes from 10.42.70.144:53
2016/05/31 16:55:25.183 kid1| 78,3| dns_internal.cc(1130) idnsGrokReply: idnsGrokReply: QID 0xd1ee, 0 answers
2016/05/31 16:55:25.183 kid1| 14,3| ipcache.cc(364) ipcacheParse: ipcacheParse: 1 answers for 'short.domain.name'
2016/05/31 16:55:25.183 kid1| 14,3| ipcache.cc(422) ipcacheParse: ipcacheParse: short.domain.name #0 10.44.3.1
2016/05/31 16:56:25.231 kid1| 48,3| pconn.cc(310) Timeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:56:25.231 kid1| 48,3| pconn.cc(70) findIndexOf: found local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 at index 0
2016/05/31 16:56:25.231 kid1| 48,3| pconn.cc(156) clearHandlers: removing close handler for local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:56:25.231 kid1| 5,3| comm.cc(579) commUnsetConnTimeout: Remove timeout for local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1
2016/05/31 16:56:25.231 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=127.0.0.1:51409 remote=127.0.0.1:50005 FD 10 flags=1 timeout -1
2016/05/31 16:56:25.231 kid1| 48,3| pconn.cc(97) removeAt: deleting 127.0.0.1:50005/127.0.0.1
2016/05/31 16:56:25.231 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 10
2016/05/31 16:56:25.232 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 10
2016/05/31 16:56:25.232 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 10 Idle server: 127.0.0.1:50005/127.0.0.1
2016/05/31 16:58:25.182 kid1| 93,3| Xaction.cc(60) Xaction: Adaptation::Icap::OptXact constructed, this=0x7f0f668bde58 [icapxjob13]
2016/05/31 16:58:25.182 kid1| 93,3| ServiceRep.cc(122) getConnection: got connection:
2016/05/31 16:58:25.182 kid1| 93,3| Xaction.cc(145) openConnection: Adaptation::Icap::OptXact opens connection to short.domain.name:1344
2016/05/31 16:58:25.182 kid1| 14,3| Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name or service not known
2016/05/31 16:58:25.182 kid1| 93,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x7f0f6646fa60 [call502]
2016/05/31 16:58:25.182 kid1| 50,3| comm.cc(347) comm_openex: comm_openex: Attempt open socket for: 0.0.0.0
2016/05/31 16:58:25.182 kid1| 50,3| comm.cc(388) comm_openex: comm_openex: Opened socket local=0.0.0.0 remote=[::] FD 10 flags=1 : family=2, type=1, protocol=6
2016/05/31 16:58:25.182 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 10 short.domain.name
2016/05/31 16:58:25.182 kid1| 5,3| ConnOpener.cc(289) createFd: local=0.0.0.0 remote=10.44.3.1:1344 flags=1 will timeout in 60
2016/05/31 16:58:25.184 kid1| 93,3| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(137) will call Adaptation::Icap::Xaction::noteCommConnected(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="" [call502]
2016/05/31 16:58:25.184 kid1| 93,3| AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommConnected(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="">
2016/05/31 16:58:25.184 kid1| 93,3| AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommConnected [call502]
2016/05/31 16:58:25.184 kid1| 93,3| AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 10;/ job13]
2016/05/31 16:58:25.184 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout 60
2016/05/31 16:58:25.184 kid1| 93,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x7f0f665bb740 [call509]
2016/05/31 16:58:25.184 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout 900
2016/05/31 16:58:25.184 kid1| 23,3| url.cc(357) urlParse: urlParse: Split URL 'icap://short.domain.name:1344 ICAP/1.0
' into proto='icap', host='short.domain.name', port='1344', path=' ICAP/1.0'
2016/05/31 16:58:25.184 kid1| 23,2| url.cc(393) urlParse: urlParse: URI has whitespace: {icap://short.domain.name:1344 ICAP/1.0
}
2016/05/31 16:58:25.184 kid1| 14,3| Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name or service not known
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommWrote constructed, this=0x7f0f668e54a0 [call511]
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout 900
2016/05/31 16:58:25.185 kid1| 93,3| AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXact status out: [FD 10wr;/ job13]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommConnected(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="">
2016/05/31 16:58:25.185 kid1| 5,3| IoCallback.cc(116) finish: called for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 (0, 0)
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call Adaptation::Icap::Xaction::noteCommWrote(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="" [call511]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommWrote(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="">
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommWrote [call511]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 10wr;/ job13]
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout 900
2016/05/31 16:58:25.185 kid1| 93,3| AsyncJob.cc(152) callEnd: Adaptation::Icap::OptXact status out: [FD 10r;/ job13]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommWrote(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="">
2016/05/31 16:58:25.185 kid1| 5,3| Read.cc(144) HandleRead: FD 10, size 65535, retval 222, errno 0
2016/05/31 16:58:25.185 kid1| 5,3| IoCallback.cc(116) finish: called for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 (0, 0)
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call Adaptation::Icap::Xaction::noteCommRead(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="" size=222, buf=0x7f0f6689d4a0) [call509]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommRead(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="" size=222, buf=0x7f0f6689d4a0)
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommRead [call509]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [FD 10r;/ job13]
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(579) commUnsetConnTimeout: Remove timeout for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout -1
2016/05/31 16:58:25.185 kid1| 93,3| Xaction.cc(425) noteCommRead: read 222 bytes
2016/05/31 16:58:25.185 kid1| 93,3| ServiceRep.cc(132) putConnection: pushing pconn [FD 10;/ job13]
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(579) commUnsetConnTimeout: Remove timeout for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout -1
2016/05/31 16:58:25.185 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout 60
2016/05/31 16:58:25.185 kid1| 93,3| Xaction.cc(71) ~Xaction: Adaptation::Icap::OptXact destructed, this=0x7f0f668bde58 [icapxjob13]
2016/05/31 16:58:25.185 kid1| 93,3| AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommRead(local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1, data="" size=222, buf=0x7f0f6689d4a0)
2016/05/31 16:58:25.185 kid1| essential ICAP service is up: icap://short.domain.name:1344 [up]
2016/05/31 16:58:25.185 kid1| 93,3| ServiceRep.cc(571) handleNewOptions: got new options and is now [up]
2016/05/31 16:59:25.401 kid1| 48,3| pconn.cc(310) Timeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1
2016/05/31 16:59:25.401 kid1| 48,3| pconn.cc(70) findIndexOf: found local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 at index 0
2016/05/31 16:59:25.401 kid1| 48,3| pconn.cc(156) clearHandlers: removing close handler for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1
2016/05/31 16:59:25.402 kid1| 5,3| comm.cc(579) commUnsetConnTimeout: Remove timeout for local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1
2016/05/31 16:59:25.402 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=10.44.3.21:57084 remote=10.44.3.1:1344 FD 10 flags=1 timeout -1
2016/05/31 16:59:25.402 kid1| 5,3| comm.cc(868) _comm_close: comm_close: start closing FD 10
2016/05/31 16:59:25.402 kid1| 5,3| comm.cc(540) commUnsetFdTimeout: Remove timeout for FD 10
2016/05/31 16:59:25.402 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 10 short.domain.name
2016/05/31 17:35:05 kid1| Logfile: opening log stdio:/var/log/squid/netdb.state
2016/05/31 17:35:05.157 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 10 /var/log/squid/netdb.state
2016/05/31 17:35:05.157 kid1| Logfile: closing log stdio:/var/log/squid/netdb.state
2016/05/31 17:35:05.157 kid1| 51,3| fd.cc(93) fd_close: fd_close FD 10 /var/log/squid/netdb.state
2016/05/31 17:35:05.157 kid1| NETDB state saved; 1 entries, 0 msec
Thanks
Aashima
_______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
