[squid-users] All Adaptation ICAPs go down at the same time

Wed May 19 21:31:44 UTC 2021

Hi,

This are the logs i manage to capture during disconnection (I enabled 93 in
debug_options)

2021/05/12 12:27:24.209| 93,5| ServiceRep.cc(378) noteTimeToUpdate:
performs a regular options update [up]
2021/05/12 12:27:24.209| 93,6| ServiceRep.cc(611) startGettingOptions: will
get new options [up]
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob
constructed, this=0x55a73f3bc468 type=Adaptation::Icap::OptXactLauncher
[job31639]
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall
AsyncJob::start constructed, this=0x55a73ef1ebc0 [call661700]
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(93) ScheduleCall:
AsyncJob.cc(26) will call AsyncJob::start() [call661700]
2021/05/12 12:27:24.209| 93,5| AsyncCallQueue.cc(55) fireNext: entering
AsyncJob::start()
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(38) make: make call
AsyncJob::start [call661700]
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(123) callStart:
Adaptation::Icap::OptXactLauncher status in: [ job31639]
2021/05/12 12:27:24.209| 93,4| Launcher.cc(49) launchXaction: launching
first xaction #1
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob
constructed, this=0x55a73f3bca30 type=Adaptation::Icap::OptXact [job31640]
2021/05/12 12:27:24.209| 93,3| Xaction.cc(101) Xaction:
Adaptation::Icap::OptXact constructed, this=0x55a73f3bc948 [icapxjob31640]
2021/05/12 12:27:24.209| 93,5| Xaction.cc(141) disableRepeats:
Adaptation::Icap::OptXact from now on cannot be repeated because over
icap_retry_limit [/ job31640]
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall
AsyncJob::start constructed, this=0x55a73ef1ecb0 [call661701]
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(93) ScheduleCall:
AsyncJob.cc(26) will call AsyncJob::start() [call661701]
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(154) callEnd:
Adaptation::Icap::OptXactLauncher status out: [ job31639]
2021/05/12 12:27:24.209| 93,5| AsyncCallQueue.cc(57) fireNext: leaving
AsyncJob::start()
2021/05/12 12:27:24.209| 93,5| AsyncCallQueue.cc(55) fireNext: entering
AsyncJob::start()
2021/05/12 12:27:24.209| 93,5| AsyncCall.cc(38) make: make call
AsyncJob::start [call661701]
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(123) callStart:
Adaptation::Icap::OptXact status in: [/ job31640]
2021/05/12 12:27:24.209| 93,3| ServiceRep.cc(142) getConnection: got
connection:
2021/05/12 12:27:24.209| 93,5| Xaction.cc(134) disableRetries:
Adaptation::Icap::OptXact from now on cannot be retried  [/ job31640]
2021/05/12 12:27:24.209| 93,3| Xaction.cc(189) openConnection:
Adaptation::Icap::OptXact opens connection to skipper.proxy:14590
2021/05/12 12:27:24.209| 93,5| AsyncJob.cc(139) callEnd: AsyncJob::start()
ends job [/ job31640]
2021/05/12 12:27:24.210| 93,5| Initiate.cc(64) swanSong: swan sings [/
job31640]
2021/05/12 12:27:24.210| 93,5| Initiate.cc(71) swanSong: swan sang [/
job31640]
2021/05/12 12:27:24.210| 93,3| Xaction.cc(113) ~Xaction:
Adaptation::Icap::OptXact destructed, this=0x55a73f3bc948 [icapxjob31640]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob
destructed, this=0x55a73f3bca30 type=Adaptation::Icap::OptXact [job31640]
2021/05/12 12:27:24.210| 93,6| AsyncJob.cc(149) callEnd: AsyncJob::start()
ended 0x55a73f3bca30
2021/05/12 12:27:24.210| 93,5| AsyncCallQueue.cc(57) fireNext: leaving
AsyncJob::start()
2021/05/12 12:27:24.210| 93,5| Launcher.cc(85) noteXactAbort:
theXaction:0x55a73f3bc948/0x55a73f3bc948 launches: 1
2021/05/12 12:27:24.210| 93,9| Launcher.cc(127) canRepeat: 0
2021/05/12 12:27:24.210| 93,3| Launcher.cc(95) noteXactAbort: cannot retry
or repeat a failed transaction
2021/05/12 12:27:24.210| 93,4| Answer.cc(20) Error: error: 0
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall
Initiator::noteAdaptationAnswer constructed, this=0x55a73f27e950
[call661703]
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(93) ScheduleCall:
Initiate.cc(83) will call Initiator::noteAdaptationAnswer(2) [call661703]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(139) callEnd:
Launcher::noteXactAbort(0,0) ends job [ job31639]
2021/05/12 12:27:24.210| 93,5| Initiate.cc(64) swanSong: swan sings [
job31639]
2021/05/12 12:27:24.210| 93,5| Initiate.cc(71) swanSong: swan sang [
job31639]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(40) ~AsyncJob: AsyncJob
destructed, this=0x55a73f3bc468 type=Adaptation::Icap::OptXactLauncher
[job31639]
2021/05/12 12:27:24.210| 93,6| AsyncJob.cc(149) callEnd:
Launcher::noteXactAbort(0,0) ended 0x55a73f3bc468
2021/05/12 12:27:24.210| 93,7| HttpRequest.cc(63) ~HttpRequest: destructed,
this=0x55a73f3c9580
2021/05/12 12:27:24.210| 93,5| AsyncCallQueue.cc(55) fireNext: entering
Initiator::noteAdaptationAnswer(2)
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(38) make: make call
Initiator::noteAdaptationAnswer [call661703]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(123) callStart:
Adaptation::Icap::ServiceRep status in:[up,fetch]
2021/05/12 12:27:24.210| 93,3| ServiceRep.cc(554) noteAdaptationAnswer:
failed to fetch options [up]
2021/05/12 12:27:24.210| 93,8| ServiceRep.cc(468) changeOptions: changes
options from 0x55a73f3c9470 to 0 [up]
2021/05/12 12:27:24.210| optional ICAP service is down after an options
fetch failure: icap://skipper.proxy:14590/response [down,!opt]
2021/05/12 12:27:24.210| 93,3| ServiceRep.cc(591) handleNewOptions: got new
options and is now [down,!opt]
2021/05/12 12:27:24.210| 93,7| ServiceRep.cc(634) scheduleUpdate: raw
OPTIONS fetch at 1620822474 or in 30 sec
2021/05/12 12:27:24.210| 93,9| ServiceRep.cc(636) scheduleUpdate: last
fetched at 1620822444 or 0 sec ago
2021/05/12 12:27:24.210| 93,5| ServiceRep.cc(649) scheduleUpdate: will
fetch OPTIONS in 30 sec
2021/05/12 12:27:24.210| 93,7| ServiceRep.cc(456) scheduleNotification:
will notify 0 clients
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall
Adaptation::Icap::ServiceRep::noteTimeToNotify constructed,
this=0x55a73ef1ecb0 [call661704]
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(93) ScheduleCall:
ServiceRep.cc(457) will call
Adaptation::Icap::ServiceRep::noteTimeToNotify() [call661704]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(154) callEnd:
Adaptation::Icap::ServiceRep status out:[down,!opt]
2021/05/12 12:27:24.210| 93,5| AsyncCallQueue.cc(57) fireNext: leaving
Initiator::noteAdaptationAnswer(2)
2021/05/12 12:27:24.210| 93,5| AsyncCallQueue.cc(55) fireNext: entering
Adaptation::Icap::ServiceRep::noteTimeToNotify()
2021/05/12 12:27:24.210| 93,5| AsyncCall.cc(38) make: make call
Adaptation::Icap::ServiceRep::noteTimeToNotify [call661704]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(123) callStart:
Adaptation::Icap::ServiceRep status in:[down,!opt]
2021/05/12 12:27:24.210| 93,7| ServiceRep.cc(397) noteTimeToNotify:
notifies 0 clients [down,!opt,notif]
2021/05/12 12:27:24.210| 93,5| AsyncJob.cc(154) callEnd:
Adaptation::Icap::ServiceRep status out:[down,!opt]
2021/05/12 12:27:24.210| 93,5| AsyncCallQueue.cc(57) fireNext: leaving
Adaptation::Icap::ServiceRep::noteTimeToNotify()

Thanks,
Roie

On Mon, Apr 19, 2021 at 12:07 PM Eliezer Croitoru <ngtech1ltd at gmail.com>
wrote:

> Hey Roie,
>
>
>
> From the output I assume it’s a dns resolution issue.
>
> In the past I remember that Docker was updating the hosts file with the
> relevant names but  it’s not working the same way now.
>
> Currently Docker is using a local network dns service which is being
> accessed via 127.0.0.53.
>
> From I remember Squid is resolving the icap service name only at startup
> or reload.
>
> Lately Alex published a testable patch that might fix specific issues with
> icap services which are resolved by dns. ( sorry I don’t remember the bug
> report)
>
> I assume you can try to test this patch first.
>
> If these services are static to some degree you might be able to create a
> script that updates the hosts file and reload squid on each change.
>
> When using the hosts file it’s possible that some issues will disappear.
>
>
> There is also another possibility which is a malformed ICAP response or
> wrong sessions handling which cause this issue.
>
> You might be able to use tcpdump from either the host or the container
> side to capture traffic when these goes down.
>
> Depends on your preference of debug level you might even be able to debug
> specific debug_options like for ICAP services
> and/or requests to the degree you might be able to see what happens on the
> basic level of the ICAP encapsulation.
>
> If you really need help with a diagnosis and a solution you might be able
> to use Alex and the measurement factory.
>
> All The Bests,
>
> Eliezer
>
>
>
> *From:* squid-users <squid-users-bounces at lists.squid-cache.org> *On
> Behalf Of *roie rachamim
> *Sent:* Monday, April 12, 2021 12:54 PM
> *To:* squid-users at lists.squid-cache.org
> *Subject:* [squid-users] All Adaptation ICAPs go down at the same time
>
>
>
> Hi,
>
>
>
> Our setup includes squid that runs in docker container with several ICAP
> servers in additional containers.
>
> From time to time we see in cache.log the following messages:
> 2021/04/12 00:22:39| optional ICAP service is down after an options fetch
> failure: icap://icap1.proxy:14590/censor [down,!opt]
> 2021/04/12 00:22:39| optional ICAP service is down after an options fetch
> failure: icap://icap2.proxy:1344/request [down,!opt]
> 2021/04/12 00:22:39| optional ICAP service is down after an options fetch
> failure: icap://icap3.proxy:14590/response [down,!opt]
>
> 2021/04/12 06:10:45| optional ICAP service is down after an options fetch
> failure: icap://icap1.proxy:14590/censor [down,!opt]
> 2021/04/12 06:10:45| optional ICAP service is down after an options fetch
> failure: icap://icap2.proxy:1344/request [down,!opt]
> 2021/04/12 06:10:45| optional ICAP service is down after an options fetch
> failure: icap://icap3.proxy:14590/response [down,!opt]
>
>
>
> We're trying to understand why it happens to all ICAPs at once. This
> happens in 4.14 and in 5.0.4
>
> Any thoughts about what might cause this ?
>
> Many Thanks,
>
> Roie
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squid-cache.org/pipermail/squid-users/attachments/20210520/d8c46e2e/attachment.htm>