[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