Discussion:
DNS lookup fails initially for FQDN in squid
(too old to reply)
Aashima Madaan
2016-05-27 14:12:47 UTC
Permalink
Hi,

In my squid configuration file, I am adding a Fully Qualified Domain Name
instead of an IP address for my ICAP server but it is not able to resolve
that name initially and the service goes down saying

essential ICAP service is down after an options fetch failure: icap://
short.domain.name:4321 [down,!opt]

It remains shut down for 3 minutes and then the icap service is up after
that much time. My concern is why there is so much delay in resolving fqdn
of an ip.

Plus, adding that IP with FQDN in my /etc/hosts file resolves the name
immediately on starting the service. But I dont want to do that since that
should not be required thing if know DNS entry for that particular IP works
through ping or nslookup or directly accessing that gateway console admin
from browser with fqdn.

Thanks

Aashima
Antony Stone
2016-05-27 14:45:51 UTC
Permalink
Post by Aashima Madaan
Hi,
In my squid configuration file, I am adding a Fully Qualified Domain Name
instead of an IP address for my ICAP server but it is not able to resolve
that name initially
Please define "initially" - do you mean:

- when the squid server is booted up
- when the squid service is started on an already-running server
- something else?
Post by Aashima Madaan
My concern is why there is so much delay in resolving fqdn of an ip.
What is your DNS setup? Where is the Squid server pointing for its DNS
resolver? Is that DNS server running and answering queries before the Squid
server/service starts up?


Antony.
--
How I want a drink, alcoholic of course, after the heavy chapters involving
quantum mechanics.

- mnemonic for 3.14159265358979

Please reply to the list;
please *don't* CC me.
Aashima Madaan
2016-05-27 15:10:48 UTC
Permalink
* Hi,
*> >* In my squid configuration file, I am adding a Fully Qualified Domain Name
*>* instead of an IP address for my ICAP server but it is not able to resolve
*>* that name initially
*
Please define "initially" - do you mean:

- when the squid server is booted up
- when the squid service is started on an already-running server
- something else?

@Aashima - initially here means when I start squid service
* My concern is why there is so much delay in resolving fqdn of an ip. *
What is your DNS setup?

@Aashima - We got company DNS servers which we have added in our
/etc/resolv.conf of that squid machine.

Where is the Squid server pointing for its DNS
resolver?

@Aashima - I see in cache.log that its adding nameservers from /etc/resolv.conf

Initializing IP Cache...

2016/05/27 10:32:52 kid1| DNS Socket created at [::], FD 6

2016/05/27 10:32:52 kid1| DNS Socket created at 0.0.0.0, FD 8

2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from /etc/resolv.conf

2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from /etc/resolv.conf

2016/05/27 10:32:52 kid1| Adding nameserver 8.8.8.8 from /etc/resolv.conf

Is that DNS server running and answering queries before the Squid

server/service starts up?

@Aashima I do curl/ping/nslookup for icap server from squid machine,
it is able to resolve that particular ip.


Thanks
Antony Stone
2016-05-27 15:28:21 UTC
Permalink
Post by Aashima Madaan
Post by Antony Stone
- when the squid server is booted up
- when the squid service is started on an already-running server
- something else?
initially here means when I start squid service
So, does the problem exist if you:

1. Stop Squid
2. Type "host short.domain.name" to resolve the ICAP server manually
3. Start Squid

(The last two commands in as quick succession as possible - preferably on a
single line separated by a semi-colon)
Post by Aashima Madaan
I see in cache.log that its adding nameservers from /etc/resolv.conf
2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from /etc/resolv.conf
2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from /etc/resolv.conf
2016/05/27 10:32:52 kid1| Adding nameserver 8.8.8.8 from /etc/resolv.conf
Why have you added 10.32.1.1 twice?
Post by Aashima Madaan
Post by Antony Stone
Is that DNS server running and answering queries before the Squid
server/service starts up?
I do curl/ping/nslookup for icap server from squid machine, it is able to
resolve that particular ip.
You do this before starting Squid, and it works, and then when you start
Squid, it fails for 3 minutes??


Antony.
--
I wasn't sure about having a beard at first, but then it grew on me.

Please reply to the list;
please *don't* CC me.
Aashima Madaan
2016-05-27 15:51:36 UTC
Permalink
Post by Antony Stone
1. Stop Squid
2. Type "host short.domain.name" to resolve the ICAP server manually
3. Start Squid
(The last two commands in as quick succession as possible - preferably on a
single line separated by a semi-colon)
yes the problem still exists
Post by Antony Stone
* I see in cache.log that its adding nameservers from /etc/resolv.conf
*>> >>* 2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from
/etc/resolv.conf
*>>* 2016/05/27 10:32:52 kid1| Adding nameserver 10.32.1.1 from /etc/resolv.conf
*>>* 2016/05/27 10:32:52 kid1| Adding nameserver 8.8.8.8 from /etc/resolv.conf
*
Post by Antony Stone
Why have you added 10.32.1.1 twice?
That was by chance. Its 10.32.1.2.
Post by Antony Stone
* > Is that DNS server running and answering queries before the Squid
*>* > server/service starts up?
*> >* I do curl/ping/nslookup for icap server from squid machine, it is able to
*>* resolve that particular ip.
*
Post by Antony Stone
You do this before starting Squid, and it works, and then when you start
Squid, it fails for 3 minutes??

Yes, after 3 minutes it's able to resolve DNS and brings up the service.

on additional debugging by switching on tcpflow, I see squid sends
OPTIONS request to icap server and that is when it is able to resolve
DNS and which brings the service up in 3 minutes.

###Request

OPTIONS icap://short.domain.name:1344 ICAP/1.0

Host: short.domain.name:1344

Allow: 206

###Response

ICAP/1.0 200 OK

Methods: REQMOD, RESPMOD

Options-TTL: 3600

Encapsulated: null-body=0

Max-Connections: 400

Preview: 30

Service: Gateway 7.5.2

ISTag: "00005042-2.94.230-00008178"

Allow: 204

--------

Additionally, i increased debug level and saw this in cache logs

Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name
or service not known

Thanks
Antony Stone
2016-05-27 16:49:02 UTC
Permalink
Post by Aashima Madaan
Post by Antony Stone
1. Stop Squid
2. Type "host short.domain.name" to resolve the ICAP server manually
3. Start Squid
(The last two commands in as quick succession as possible - preferably on
a single line separated by a semi-colon)
yes the problem still exists
That tells me that the problem is not DNS, then.

Command 2 verifies that DNS resolution is working.

Command 3 results in the problem.

Therefore whatever is causing the problem is not DNS.
Post by Aashima Madaan
on additional debugging by switching on tcpflow, I see squid sends
OPTIONS request to icap server and that is when it is able to resolve
DNS and which brings the service up in 3 minutes.
Have you tried running some sort of packet tracer (eg: wireshark) to check
when Squid is sending the DNS request, where it is sending it to, and whether
it gets a response?
Post by Aashima Madaan
Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name
or service not known
Can anyone else shed some light on what this particular message means?


Antony.
--
Wanted: telepath. You know where to apply.

Please reply to the list;
please *don't* CC me.
Amos Jeffries
2016-05-28 11:38:00 UTC
Permalink
Post by Antony Stone
Post by Aashima Madaan
Post by Antony Stone
1. Stop Squid
2. Type "host short.domain.name" to resolve the ICAP server manually
3. Start Squid
(The last two commands in as quick succession as possible - preferably on
a single line separated by a semi-colon)
yes the problem still exists
That tells me that the problem is not DNS, then.
Command 2 verifies that DNS resolution is working.
Command 3 results in the problem.
Therefore whatever is causing the problem is not DNS.
What is causing the problem is that ICAP services need to be working
*immediately* and do not wait for DNS results to come back. If they are
not available immediately then the service is not contactable for that
transaction.

Adding /etc/hosts entries makes Squid load the name+IP details on
startup before ICAP is used. So the problem does not appear.

Also, once Squid has looked it up and got the IP back operations with
the ICAP service will start to succeed.
Post by Antony Stone
Post by Aashima Madaan
on additional debugging by switching on tcpflow, I see squid sends
OPTIONS request to icap server and that is when it is able to resolve
DNS and which brings the service up in 3 minutes.
Have you tried running some sort of packet tracer (eg: wireshark) to check
when Squid is sending the DNS request, where it is sending it to, and whether
it gets a response?
Post by Aashima Madaan
Address.cc(389) lookupHostIP: Given Non-IP 'short.domain.name': Name
or service not known
Can anyone else shed some light on what this particular message means?
That is Squid checking to see if the ICAP hostname is a raw-IP. It is
not, so that correctly wont succeed.

Amos
Nishant Sharma
2016-05-28 05:46:12 UTC
Permalink
Hi,
Post by Antony Stone
(The last two commands in as quick succession as possible - preferably on a
Post by Antony Stone
single line separated by a semi-colon)
yes the problem still exists
Could it be because squid is trying to resolve and connect to IPv6 address
first?

Try setting "dns_v4_first on" and try.

Regards,
Nishant
Aashima Madaan
2016-05-31 20:02:57 UTC
Permalink
Hi Nishant,
Post by Nishant Sharma
* (The last two commands in as quick succession as possible - preferably on a
*>>>* single line separated by a semi-colon)
*>>>>>>* yes the problem still exists
*>>>>
Post by Nishant Sharma
Could it be because squid is trying to resolve and connect to IPv6 address
first?
Try setting "dns_v4_first on" and try.
I tried setting this option but still the behavior is same.


Thanks

Aashima
Aashima Madaan
2016-05-31 21:05:40 UTC
Permalink
Hey Amos,
Post by Amos Jeffries
What is causing the problem is that ICAP services need to be working
*immediately* and do not wait for DNS results to come back. If they are
not available immediately then the service is not contactable for that
transaction.
Adding /etc/hosts entries makes Squid load the name+IP details on
startup before ICAP is used. So the problem does not appear.
Is there a configuration for squid where we can ask it to perform DNS lookup immediately rather than doing later when it sends an OPTIONS request again.

Thanks
Aashima
Amos Jeffries
2016-06-01 11:27:12 UTC
Permalink
Post by Aashima Madaan
Hey Amos,
Post by Amos Jeffries
What is causing the problem is that ICAP services need to be working
*immediately* and do not wait for DNS results to come back. If they are
not available immediately then the service is not contactable for that
transaction.
Adding /etc/hosts entries makes Squid load the name+IP details on
startup before ICAP is used. So the problem does not appear.
Is there a configuration for squid where we can ask it to perform DNS lookup immediately rather than doing later when it sends an OPTIONS request again.
No. DNS lookups are done when they are identified as being needed.

We could perhapse perform a 'seed' lookup while parsing the config.
Though that would be a bit tricky if DNS is differently configured later
in squid.conf than ICAP.

Does the attached patch resolve the issue for you?

Amos
Aashima Madaan
2016-05-31 22:22:23 UTC
Permalink
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://***@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://***@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
Aashima Madaan
2016-06-01 15:50:34 UTC
Permalink
Hey Amos,

I am trying to apply patch but it fails to apply for both hunks. It seems the source code is different .
I am using latest squid version src code 3.5.19

Can you send patch from the latest one or let me know which version you are using.

Thanks
Aashima Madaan
2016-06-02 14:45:10 UTC
Permalink
Hi Amos,

After applying the patch I dont find any issues in make and make install, but running the file /usr/sbin/squid gives segmentation fault.

Thanks
Aashima Madaan
2016-06-02 15:23:24 UTC
Permalink
Hey,

The patch mentioned is applicable to 4.0.10 beta release . For older versions I was not able to merge the patch.
So even for beta release it throws segmentation fault. Let me know if am using wrong version of code

Backtrace from gdb tool if it can be of any help

Program received signal SIGSEGV, Segmentation fault.
hash_lookup (hid=0x0, k=0xcd4200) at hash.cc:152
152 b = hid->hash(k, hid->size);
Missing separate debuginfos, use: debuginfo-install glibc-2.17-106.el7_2.6.x86_64 libattr-2.4.46-12.el7.x86_64 libcap-2.22-8.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 libtool-ltdl-2.4.2-21.el7_2.x86_64 nss-softokn-freebl-3.16.2.3-13.el7_1.x86_64

(gdb) backtrace
#0 hash_lookup (hid=0x0, k=0xcd4200) at hash.cc:152
#1 0x000000000056059f in idnsCachedLookup (key=***@entry=0xcd4200 "atld-mcafee01.airwatch.dev", callback=***@entry=0x5d96a0 <ipcacheHandleReply(void*, rfc1035_rr const*, int, char const*)>,
data=***@entry=0xcd4608) at dns_internal.cc:1675
#2 0x00000000005667ee in idnsALookup (name=0xcd4200 "atld-mcafee01.airwatch.dev", callback=***@entry=0x5d96a0 <ipcacheHandleReply(void*, rfc1035_rr const*, int, char const*)>, data=***@entry=0xcd4608)
at dns_internal.cc:1742
#3 0x00000000005d9033 in ipcache_nbgethostbyname (name=***@entry=0xcd3db0 "atld-mcafee01.airwatch.dev", handler=***@entry=0x0, handlerData=***@entry=0x0) at ipcache.cc:561
#4 0x00000000005d95cc in ipcache_gethostbyname (name=0xcd3db0 "atld-mcafee01.airwatch.dev", flags=***@entry=1) at ipcache.cc:653
#5 0x00000000007fae8c in Adaptation::ServiceConfig::grokUri (this=***@entry=0xcd3ad0, value=***@entry=0xcd3cf0 "icap://atld-mcafee01.airwatch.dev:1344/") at ServiceConfig.cc:239
#6 0x00000000007fc41f in Adaptation::ServiceConfig::parse (this=0xcd3ad0) at ServiceConfig.cc:122
#7 0x00000000007f2773 in Adaptation::Config::parseService (this=0xcb57a0 <Adaptation::Icap::TheConfig>) at Config.cc:136
#8 0x000000000050737b in parse_icap_service_type (cfg=<optimized out>) at cache_cf.cc:4235
#9 parse_line (buff=<optimized out>) at cf_parser.cci:3185
#10 0x0000000000510e89 in parseOneConfigFile (file_name=***@entry=0xcc9860 "/etc/squid/squid.conf", depth=***@entry=0) at cache_cf.cc:544
#11 0x000000000051190f in parseConfigFile (file_name=0xcc9860 "/etc/squid/squid.conf") at cache_cf.cc:585
#12 0x00000000005ddc97 in SquidMain (argc=<optimized out>, argv=0x7fffffffe478) at main.cc:1523
#13 0x00000000004e77ad in SquidMainSafe (argv=<optimized out>, argc=<optimized out>) at main.cc:1374
#14 main (argc=<optimized out>, argv=<optimized out>) at main.cc:1367

(gdb) frame 5
#5 0x00000000007fae8c in Adaptation::ServiceConfig::grokUri (this=***@entry=0xcd3ad0, value=***@entry=0xcd3cf0 "icap://atld-mcafee01.airwatch.dev:1344/") at ServiceConfig.cc:239
239 (void)ipcache_gethostbyname(host.termedBuf(), IP_LOOKUP_IF_MISS);

(gdb) frame 4
#4 0x00000000005d95cc in ipcache_gethostbyname (name=0xcd3db0 "atld-mcafee01.airwatch.dev", flags=***@entry=1) at ipcache.cc:653
653 ipcache_nbgethostbyname(name, NULL, NULL);

(gdb) frame 3
#3 0x00000000005d9033 in ipcache_nbgethostbyname (name=***@entry=0xcd3db0 "atld-mcafee01.airwatch.dev", handler=***@entry=0x0, handlerData=***@entry=0x0) at ipcache.cc:561
561 idnsALookup(hashKeyStr(&i->hash), ipcacheHandleReply, c);

(gdb) frame 2
#2 0x00000000005667ee in idnsALookup (name=0xcd4200 "atld-mcafee01.airwatch.dev", callback=***@entry=0x5d96a0 <ipcacheHandleReply(void*, rfc1035_rr const*, int, char const*)>, data=***@entry=0xcd4608)
at dns_internal.cc:1742
1742 if (idnsCachedLookup(name, callback, data))

(gdb) frame 1
#1 0x000000000056059f in idnsCachedLookup (key=***@entry=0xcd4200 "atld-mcafee01.airwatch.dev", callback=***@entry=0x5d96a0 <ipcacheHandleReply(void*, rfc1035_rr const*, int, char const*)>,
data=***@entry=0xcd4608) at dns_internal.cc:1675
1675 idns_query *old = (idns_query *) hash_lookup(idns_lookup_hash, key);

(gdb) frame 0
#0 hash_lookup (hid=0x0, k=0xcd4200) at hash.cc:152
152 b = hid->hash(k, hid->size);
(gdb)


Thanks
Aashima

Continue reading on narkive:
Loading...