[squid-users] DNS lookup fails initially for FQDN in squid
Aashima Madaan
amadaan at ncsu.edu
Tue May 31 22:22:23 UTC 2016
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=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=0x7f0f6646dee8) [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=0x7f0f6646dee8)
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=0x7f0f6646dee8)
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*
<http://short.domain.name/>:1344
2016/05/31 16:55:25.181 kid1| 14,3| Address.cc(389) lookupHostIP: Given
Non-IP '*short.domain.name* <http://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*
<http://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*
<http://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*
<http://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* <http://short.domain.name/>
'
2016/05/31 16:55:25.183 kid1| 14,3| ipcache.cc(422) ipcacheParse:
ipcacheParse: *short.domain.name* <http://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*
<http://short.domain.name/>:1344
2016/05/31 16:58:25.182 kid1| 14,3| Address.cc(389) lookupHostIP: Given
Non-IP '*short.domain.name* <http://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* <http://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 <http://10.44.73.133:1344/> FD 10 flags=1,
data=0x7f0f668bde58) [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=0x7f0f668bde58)
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* <http://short.domain.name/>:1344 ICAP/1.0
' into proto='icap', host='*short.domain.name* <http://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* <http://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* <http://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=0x7f0f668bde58)
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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58) [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
<http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58)
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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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
<http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58)
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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58, 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
<http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58, 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 <http://10.44.73.219:57084/>
remote=10.44.3.1:1344 <http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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 <http://10.44.73.219:57084/>
remote=10.44.3.1:1344 <http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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
<http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133:1344/> FD 10 flags=1, data=0x7f0f668bde58, size=222,
buf=0x7f0f6689d4a0)
2016/05/31 16:58:25.185 kid1| essential ICAP service is up: icap://
*short.domain.name* <http://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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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 <http://10.44.73.219:57084/>
remote=10.44.3.1:1344 <http://10.44.73.133: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 <http://10.44.73.219:57084/>
remote=10.44.3.1:1344 <http://10.44.73.133: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 <http://10.44.73.219:57084/> remote=10.44.3.1:1344
<http://10.44.73.133: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* <http://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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20160531/da498cfe/attachment-0001.html>
More information about the squid-users
mailing list