Squid 3.5 ICAP Problems

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Squid 3.5 ICAP Problems

Stephen Stark
Hello everyone,

I am having problems using Squid with ICAP (C-ICAP and clamd). The thing that is bugging me is I had this was working fine and now it cannot connect to the local ICAP service.

Below is the debug section 93,3 to see what was going on when I restarted Squid:

2017/11/02 12:06:34.546 kid1| 93,3| ServiceRep.cc(712) detach: detaching ICAP service: icap://127.0.0.1:1344/virus_scan [down,!opt]
2017/11/02 12:06:34.546 kid1| 93,3| ServiceRep.cc(712) detach: detaching ICAP service: icap://127.0.0.1:1344/srv_content_filtering [down,!opt]
2017/11/02 12:06:34.548 kid1| 93,3| Service.cc(19) Service: creating adaptation service service_cfi_resp
2017/11/02 12:06:34.548 kid1| 93,3| Service.cc(19) Service: creating adaptation service service_avi_resp
2017/11/02 12:06:34.548 kid1| 93,3| Config.cc(195) finalize: Created 2 adaptation services
2017/11/02 12:06:34.548 kid1| Adaptation support is on
2017/11/02 12:06:34.548 kid1| 93,2| Config.cc(211) FinalizeEach: Initialized 2 message adaptation services
2017/11/02 12:06:34.548 kid1| 93,2| Config.cc(211) FinalizeEach: Initialized 1 message adaptation service groups
2017/11/02 12:06:34.548 kid1| 93,2| Config.cc(211) FinalizeEach: Initialized 3 message adaptation access rules
2017/11/02 12:06:51.415 kid1| 93,3| AccessCheck.cc(196) callBack: NULL
2017/11/02 12:06:51.415 kid1| 93,3| client_side_request.cc(1074) noteAdaptationAclCheckDone: 0x10dd728 adaptationAclCheckDone called
2017/11/02 12:06:51.454 kid1| 93,3| AccessCheck.cc(196) callBack: 0xd45b80*2
2017/11/02 12:06:51.454 kid1| 93,3| Xaction.cc(60) Xaction: Adaptation::Icap::ModXact constructed, this=0x124c4b8 [icapxjob146537]
2017/11/02 12:06:51.454 kid1| 93,3| Xaction.cc(60) Xaction: Adaptation::Icap::OptXact constructed, this=0x120c818 [icapxjob146539]
2017/11/02 12:06:51.454 kid1| 93,3| ServiceRep.cc(122) getConnection: got connection:
2017/11/02 12:06:51.454 kid1| 93,3| Xaction.cc(145) openConnection: Adaptation::Icap::OptXact opens connection to 127.0.0.1:1344
2017/11/02 12:06:51.454 kid1| 93,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommConnected constructed, this=0x10a1ed0 [call901778]
2017/11/02 12:06:51.454 kid1| 93,3| AsyncCall.cc(93) ScheduleCall: ConnOpener.cc(137) will call Adaptation::Icap::Xaction::noteCommConnected(local=[::] remote=127.0.0.1:1344 flags=1, errno=101, flag=-8, data=0x120c818) [call901778]
2017/11/02 12:06:51.454 kid1| 93,3| AsyncCallQueue.cc(55) fireNext: entering Adaptation::Icap::Xaction::noteCommConnected(local=[::] remote=127.0.0.1:1344 flags=1, errno=101, flag=-8, data=0x120c818)
2017/11/02 12:06:51.454 kid1| 93,3| AsyncCall.cc(38) make: make call Adaptation::Icap::Xaction::noteCommConnected [call901778]
2017/11/02 12:06:51.454 kid1| 93,3| AsyncJob.cc(123) callStart: Adaptation::Icap::OptXact status in: [/ job146539]
2017/11/02 12:06:51.454 kid1| 93,2| Xaction.cc(272) dieOnConnectionFailure: Adaptation::Icap::OptXact failed to connect to icap://127.0.0.1:1344/virus_scan
2017/11/02 12:06:51.454 kid1| 93,3| ServiceRep.cc(161) noteConnectionFailed: Connection failed: failure
2017/11/02 12:06:51.454 kid1| 93,3| ../../../src/base/AsyncJobCalls.h(177) dial: Adaptation::Icap::Xaction::noteCommConnected threw exception: cannot connect to the ICAP service
2017/11/02 12:06:51.454 kid1| 93,3| Xaction.cc(71) ~Xaction: Adaptation::Icap::OptXact destructed, this=0x120c818 [icapxjob146539]
2017/11/02 12:06:51.454 kid1| 93,3| AsyncCallQueue.cc(57) fireNext: leaving Adaptation::Icap::Xaction::noteCommConnected(local=[::] remote=127.0.0.1:1344 flags=1, errno=101, flag=-8, data=0x120c818)
2017/11/02 12:06:51.454 kid1| 93,3| Launcher.cc(95) noteXactAbort: cannot retry or repeat a failed transaction
2017/11/02 12:06:51.454 kid1| 93,3| ServiceRep.cc(534) noteAdaptationAnswer: failed to fetch options [down,!opt,fail1]
2017/11/02 12:06:51.454 kid1| optional ICAP service is down after an options fetch failure: icap://127.0.0.1:1344/virus_scan [down,!opt]

Looks like it load my rules and then tries to connect and fails. I read almost every post I could find but do not seem to have the same problem.

I can use the c-icap-client and test each service. It looks fine.

># ./c-icap-client -s virus_scan
ICAP server:localhost, ip:127.0.0.1, port:1344

OPTIONS:
        Allow 204: Yes
        Preview: 1024
        Keep alive: Yes

ICAP HEADERS:
        ICAP/1.0 200 OK
        Methods: RESPMOD, REQMOD
        Service: C-ICAP/0.4.3 server - Antivirus service
        ISTag: CI0001-J8gT2j9ufFux2fjZGxq1qAAA
        Transfer-Preview: *
        Options-TTL: 3600
        Date: Thu, 02 Nov 2017 16:17:15 GMT
        Preview: 1024
        Allow: 204
        Encapsulated: null-body=0

># ./c-icap-client -s virus_scan -f /bin/ls
ICAP server:localhost, ip:127.0.0.1, port:1344

No modification needed (Allow 204 response)

I can post some of my squid.conf file below for icap options:

icap_enable on
adaptation_send_client_ip on
icap_persistent_connections on
icap_service_failure_limit -1

icap_send_client_ip on
icap_send_client_username on
icap_client_username_header X-Authenticated-User
icap_preview_enable on
icap_preview_size 1024


icap_service service_cfi_resp respmod_precache icap://127.0.0.1:1344/srv_content_filtering routing=on bypass=on

icap_service service_avi_resp respmod_precache icap://127.0.0.1:1344/virus_scan routing=on bypass=on

adaptation_service_chain check_services service_avi_resp service_cfi_resp

adaptation_access check_services allow Antivirus_users

adaptation_access service_avi_resp deny all
adaptation_access service_cfi_resp deny all



If you need more information I can provide it. I am stuck at why this does not work anymore.

Note: this is basic linux box running Squid 3.5.22 with C-ICAP 0.4.3 and ClamAV 0.99.2 also i am not using caching with squid.

Thanks

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Alex Rousskov
On 11/02/2017 10:29 AM, Stephen Stark wrote:
> Adaptation::Icap::Xaction::noteCommConnected(local=[::]
> remote=127.0.0.1:1344 flags=1, errno=101, ...

The logs you have provided do not show where/why exactly the TCP
connection to the ICAP service fails, but error number 101 is probably
"network unreachable". This is unusual but not impossible for localhost
traffic. The next step depends on the failure cause. There are at least
two major cases to consider:

A) If Squid sends packets to 127.0.0.1:1344, then you can easily
reproduce the problem using something like "telnet" or "nc" on the Squid
box command line. Just make sure you use the right _source_ IP address
for the connection! It has to be the same source IP address that Squid
is using. It might not be 127.0.0.1. Running that command as Squid user
might also be important if the Squid box have some fancy user-specific
networking restrictions.

B) If Squid does not send packets to 127.0.0.1:1344, then one can figure
out what goes wrong by studying relevant ALL,9 logs. You may also want
to address other errors or warnings Squid logs to cache.log (if any).

You can determine whether Squid sends packets to 127.0.0.1:1344 by
collecting a packet trace (for all Squid box interfaces!) and/or running
strace (for the Squid worker process).


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Eliezer Croitoru
I'm not sure but after testing with telnet  or\and nc you can try to verify the open files limits on the system which might cause this issue.
To identify how many connections are opened to the service you can use netstat or ss tools.
netstat -ntp

and a similar on ss.

Also it's a good practice to put an ICAP periodic(2-20 seconds apparat) with an OPTIONS request to make sure that the service is alive.
If you want my testing script let me know.

Eliezer

----
Eliezer Croitoru
Linux System Administrator
Mobile: +972-5-28704261
Email: [hidden email]



-----Original Message-----
From: squid-users [mailto:[hidden email]] On Behalf Of Alex Rousskov
Sent: Thursday, November 2, 2017 19:22
To: Stephen Stark <[hidden email]>; [hidden email]
Subject: Re: [squid-users] Squid 3.5 ICAP Problems

On 11/02/2017 10:29 AM, Stephen Stark wrote:
> Adaptation::Icap::Xaction::noteCommConnected(local=[::]
> remote=127.0.0.1:1344 flags=1, errno=101, ...

The logs you have provided do not show where/why exactly the TCP connection to the ICAP service fails, but error number 101 is probably "network unreachable". This is unusual but not impossible for localhost traffic. The next step depends on the failure cause. There are at least two major cases to consider:

A) If Squid sends packets to 127.0.0.1:1344, then you can easily reproduce the problem using something like "telnet" or "nc" on the Squid box command line. Just make sure you use the right _source_ IP address for the connection! It has to be the same source IP address that Squid is using. It might not be 127.0.0.1. Running that command as Squid user might also be important if the Squid box have some fancy user-specific networking restrictions.

B) If Squid does not send packets to 127.0.0.1:1344, then one can figure out what goes wrong by studying relevant ALL,9 logs. You may also want to address other errors or warnings Squid logs to cache.log (if any).

You can determine whether Squid sends packets to 127.0.0.1:1344 by collecting a packet trace (for all Squid box interfaces!) and/or running strace (for the Squid worker process).


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Enrico Heine
Hey Guys,

I also have a long term issue with C-ICAP on many servers in different
countries.

It looks like an ICAP Queue overload happening within squid. Since after
taking a lot time in order to fine tune and debug the C-ICAP Service and
the clamav-daemon in order to ensure that it can handle the high load
and is configured properly, the ICAP suspended, down and UP messages
dissappeared entirely in the cache.log, which I had after some days,
then some weeks (after tuning the ICAP Server even more) occuring and
after some messages the performance become steady slow until squid
service is restarted. So now I have fixed the C-ICAP Server that is
using squidclamav as C-ICAP Module for in-stream scanning.
http://squidclamav.darold.net/, So I no longer can see any C-ICAP DOWN
and UP Messages anymore. Which tells me that C-ICAP seems to always have
enough workers to take the load.

So as I said now after finalizing my C-ICAP Server fine tuning,
reconfiguration and debugging. I have no more ICAP Up and down messages
and now after some weeks squid became slow again. When restarting the
squid service all works fine again until some day in some weeks where it
becomes slow again until service restart.

So I guess I need to set the right debug options for you guys, but that
would create a very big log file since it takes days or weeks until this
issue is happening. Any suggestions on what you think how I can do
debugging in the best way?


BTW: I hope I do not mix up issues here, but it seems to be related to
my issue that I am face since I was moving to a newer Version back in
the old days then squid 3.5.12 <- somewhere there this story started for
me. Unsure if it was exactliy starting with this version, some versions
later or some earlier. But well it definitely was not happening on
3.5.10 or earlier, so here I can cut it a  bit. So the issue was
definitely introduced somewhere between 3.5.11 until 3.5.18. But as I
said now I can at least fully outline the C-ICAP Server, which the cache
log confirms by not showing any down, suspended and up messages any
more.

I believe when I enforce a service restart once in the night, I will
never see this issue of slow performance caused by the C-ICAP Module
within squid anymore.

Best regards,
Enrico/Flashdown



Am 2017-11-03 12:54, schrieb Eliezer Croitoru:

> I'm not sure but after testing with telnet  or\and nc you can try to
> verify the open files limits on the system which might cause this
> issue.
> To identify how many connections are opened to the service you can use
> netstat or ss tools.
> netstat -ntp
>
> and a similar on ss.
>
> Also it's a good practice to put an ICAP periodic(2-20 seconds
> apparat) with an OPTIONS request to make sure that the service is
> alive.
> If you want my testing script let me know.
>
> Eliezer
>
> ----
> Eliezer Croitoru
> Linux System Administrator
> Mobile: +972-5-28704261
> Email: [hidden email]
>
>
>
> -----Original Message-----
> From: squid-users [mailto:[hidden email]]
> On Behalf Of Alex Rousskov
> Sent: Thursday, November 2, 2017 19:22
> To: Stephen Stark <[hidden email]>;
> [hidden email]
> Subject: Re: [squid-users] Squid 3.5 ICAP Problems
>
> On 11/02/2017 10:29 AM, Stephen Stark wrote:
>> Adaptation::Icap::Xaction::noteCommConnected(local=[::]
>> remote=127.0.0.1:1344 flags=1, errno=101, ...
>
> The logs you have provided do not show where/why exactly the TCP
> connection to the ICAP service fails, but error number 101 is probably
> "network unreachable". This is unusual but not impossible for
> localhost traffic. The next step depends on the failure cause. There
> are at least two major cases to consider:
>
> A) If Squid sends packets to 127.0.0.1:1344, then you can easily
> reproduce the problem using something like "telnet" or "nc" on the
> Squid box command line. Just make sure you use the right _source_ IP
> address for the connection! It has to be the same source IP address
> that Squid is using. It might not be 127.0.0.1. Running that command
> as Squid user might also be important if the Squid box have some fancy
> user-specific networking restrictions.
>
> B) If Squid does not send packets to 127.0.0.1:1344, then one can
> figure out what goes wrong by studying relevant ALL,9 logs. You may
> also want to address other errors or warnings Squid logs to cache.log
> (if any).
>
> You can determine whether Squid sends packets to 127.0.0.1:1344 by
> collecting a packet trace (for all Squid box interfaces!) and/or
> running strace (for the Squid worker process).
>
>
> HTH,
>
> Alex.
> _______________________________________________
> squid-users mailing list
> [hidden email]
> http://lists.squid-cache.org/listinfo/squid-users
>
> _______________________________________________
> squid-users mailing list
> [hidden email]
> http://lists.squid-cache.org/listinfo/squid-users
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Amos Jeffries
Administrator
You seem to be mixing up terminology and software names quite a bit and
its making your post quite confusing even for those of us who know the
subject matter.

"C-ICAP" is the name of a piece of server software. There is no "C-ICAP
module in Squid".

ICAP is a networking protocol. Both C-ICAP and Squid software support
and use the ICAP protocol to exchange messages between each other.

AFAIK, there are no queues in Squid ICAP handling. Messages are
delivered sequentially on ICAP connections with the response waited for
before the next is sent. There _are_ multiple persistent connections
running in parallel, but should not be message pipelining.

The UP/DOWN messages in cache.log occur when the ICAP protocol server
(C-ICAP software) stops responding to the small OPTIONS messages.

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Alex Rousskov
On 11/03/2017 09:17 AM, Amos Jeffries wrote:

> AFAIK, there are no queues in Squid ICAP handling.

ICAP queues do exist. For example, Squid may queue ICAP requests (while
they are waiting for a connection slot) in order to obey Max-Connections
limits imposed by the ICAP service or squid.conf.

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Alex Rousskov
In reply to this post by Enrico Heine
On 11/03/2017 08:16 AM, Flashdown wrote:

> So I guess I need to set the right debug options for you guys, but that
> would create a very big log file since it takes days or weeks until this
> issue is happening. Any suggestions on what you think how I can do
> debugging in the best way?

You can turn detailed debugging on when the problem re-appears. Search
Squid wiki for "-k debug" for a related discussion and advice.

However, for performance issues, it is best to try to isolate the
bottleneck _before_ slowing down Squid with detailed debugging. That is
difficult to do and there are no scripted actions to follow, but you can
start by logging (access.log and icap.log) various response times and
the number of open connections (/proc/ or netstat -n) to narrow down
suspects.


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Squid 3.5 ICAP Problems

Stephen Stark
Hello,
I found put my problem. 

c-icap service was running fine.
I had a modification on FwdState.cc that was not handling any localhost request. So it squid could not resolve host.

Thanks for the help! It helped me find where the problem was using debug options ALL,9.


On Nov 3, 2017 11:41 AM, "Alex Rousskov" <[hidden email]> wrote:
On 11/03/2017 08:16 AM, Flashdown wrote:

> So I guess I need to set the right debug options for you guys, but that
> would create a very big log file since it takes days or weeks until this
> issue is happening. Any suggestions on what you think how I can do
> debugging in the best way?

You can turn detailed debugging on when the problem re-appears. Search
Squid wiki for "-k debug" for a related discussion and advice.

However, for performance issues, it is best to try to isolate the
bottleneck _before_ slowing down Squid with detailed debugging. That is
difficult to do and there are no scripted actions to follow, but you can
start by logging (access.log and icap.log) various response times and
the number of open connections (/proc/ or netstat -n) to narrow down
suspects.


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users