ICAP protocol error / timeout

[markus....@gmail.com]

hi

yet another problem. Squid configured with SSL bumping + E2G as ICAP. after a few minutes from starting browsing the internet Squid slows down and finally there is a message 

------------------------------------------

    ICAP protocol error.

The system returned: [No Error]

This means that some aspect of the ICAP communication failed.

------------------

There is no specific message in E2g log or squid log, but ussualy there is a lot (over 50) conections in TIME_WAIT state in netstat -an|grep 1344.

I wrote a shell script for checking the connectivity (runining every one minute) . I'm using squidclient (squidclient -T 5 -p 8080 -T 5 -p 8080 $TestURL) , and what interesting - squidclient itself cannot clog the ICAP Server . But whenever I start browsing the internet from normal browser, after a few minutes there is the ICAP problem (and then, even the commandlne script don't get the response). Maybe a normal browser initiate too many connections to remote servers.

Is there any parameter i E2G/ICAP, which defines the  connections limit? Did somebody have a simmilar problem?

thx

Mark

[markus....@gmail.com]

I increased httpworkers parameter from default 500 to 4000 and now it's much better. I'm worried because I was the only one person who tested it and 500 wasn't enough. We'll see what happens when more people gonna use it.

[Philip Pearce]

Check your dstats log (enable it if not already on) to monitor how many httpworkers are busy.

With ICAP squid uses the same connection for multiple clients, so there should not a be a large number of busy workers.

If there are lots, in comparison to the number of clients, then there is a problem at the squid end.  However, I'm not a squid expert and so if this is the case maybe other ICAP users on the list will be able to help.

Philip

---

--
E2guardian:
https://groups.google.com/d/forum/e2guardian
Github:
https://github.com/e2guardian/e2guardian
Follow us on twitter:
https://twitter.com/e2guardian
---
You received this message because you are subscribed to the Google Groups "e2guardian" group.
To unsubscribe from this group and stop receiving emails from it, send an email to e2guardian+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/e2guardian/08a3ac91-b54a-4b67-bd2d-1292fa950d13n%40googlegroups.com.

[FredB]

Could I see your squid.conf ? At least the icap part

Something in cache.log ?

--
Envoyé de mon appareil Android avec Courriel K-9 Mail. Veuillez excuser ma brièveté.

[markus....@gmail.com]

Hi, of course:

https://marek.helion.pl/tmp/squid.conf.txt

https://marek.helion.pl/tmp/e2guardian.conf.txt

if you have any hints,  let me know please

thx

[FredB]

Which versions are you using ? Nothing in cache.log ? Compiled ? Package ?

I personally used e2/squid with a lot of simultaneous users (thousands in big server)

I will try to find my squid config this week

[markus....@gmail.com]

even 4000 isn't enough, I just noticed  "ICAP protocol error" , after browsing for 20 minutes (only one person!)

Squid 4.12 - self compiled:

root@Guardian:/home/mserafin# /usr/local/squid4/sbin/squid -v

Squid Cache: Version 4.12

Service Name: squid

This binary uses OpenSSL 1.1.1g  21 Apr 2020. For legal restrictions on distribution see https://www.openssl.org/source/license.html

configure options:  '--prefix=/usr/local/squid4' '--sysconfdir=/etc/squid' '--mandir=/usr/share/man' '--enable-ssl' '--enable-ssl-crtd' '--enable-delay-pools' '--enable-linux-netfilter' '--enable-underscores' '--enable-icap-client' '--enable-inline' '--enable-async-io=8' '--enable-removal-policies=lru,heap' '--enable-auth-digest=file' '--enable-external-acl-helpers=unix_group' '--with-logdir=/var/log/squid' '--enable-err-language=Polish' '--enable-default-err-language=Polish' '--with-default-user=proxy' '--with-pidfile=/var/run/squid.pid' '--with-openssl'

-------------------

cache.log:

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 43: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 45: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 46: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 47: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

[...]

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 43: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

2020/08/26 15:37:47 kid1| ERROR: negotiating TLS on FD 13: error:00000000:lib(0):func(0):reason(0) (5/-1/104)

środa, 26 sierpnia 2020 o 15:32:26 UTC+2 FredB napisał(a):

[markus....@gmail.com]

there're also in cache.log

 

2020/08/24 13:47:57 kid1| suspending ICAP service for too many failures

2020/08/24 13:47:57 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/request [down,susp,fail6]

2020/08/24 13:48:27 kid1| suspending ICAP service for too many failures

2020/08/24 13:48:27 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/response [down,susp,fail6]

2020/08/24 13:50:57 kid1| optional ICAP service is up: icap://127.0.0.1:1344/request [up]

2020/08/24 13:51:27 kid1| optional ICAP service is up: icap://127.0.0.1:1344/response [up]

2020/08/24 13:52:03 kid1| suspending ICAP service for too many failures

2020/08/24 13:52:03 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/request [down,susp,fail6]

2020/08/24 13:52:05 kid1| suspending ICAP service for too many failures

2020/08/24 13:52:05 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/response [down,susp,fail6]

root@Guardian:/home/mserafin# tail -f /var/log/squid/cache.log

[FredB]

Nothing about e2guardian in syslog ?
E2guardian is also compiled ?

[FredB]

Why transparenthttpsport is enabled ?

[markus....@gmail.com]

compiled. Now 5.3.4:

e2guardian 5.3.4

Built with:  '--prefix=/usr' '--enable-clamd=yes' '--with-proxyuser=e2guardian' '--with-proxygroup=e2guardian' '--sysconfdir=/etc' '--localstatedir=/var' '--enable-icap=yes' '--enable-commandline=yes' '--enable-email=yes' '--enable-ntlm=no' '--mandir=${prefix}/share/man' '--infodir=${prefix}/share/info' '--enable-pcre=yes' '--enable-sslmitm=yes' 'CPPFLAGS=-mno-sse2 -g -O2'

but the same issue was on 5.5.dev

[markus....@gmail.com]

FredB, what's your httpworkers parameter in e2g config?

środa, 26 sierpnia 2020 o 12:38:23 UTC+2 FredB napisał(a):

[FredB]

Sorry I'm just with my phone right now
I will post my configuration this week.

As far I can remember 5000 but for many users ...

[markus....@gmail.com]

I don't know if that make any sense in this case , but I'm suspecting one thing - DNS server(s) which are used by squid.
I remember 2 years ago when I configured Squid at work (only Squid, without ICAP or any other extensions), it worked fine after start but some time later (20 mins, maybe 1h) it  slowed down dramatically and finally got stuck (no response at all). I was debuging it quite long, because there was no significant info in log files. One day I changed the DNS servers and all problems disappeared.

In this Squid/E2g configuration I've been using OpenDNS with porn  protection but now I'm considering changing it to my local ones.

What do you think?

[markus....@gmail.com]

Hi,

changing dns servers didn't improve anything , problem still exists. Even 4000 workers isn't enough (for 1 person...). Something is terribly wrong here. FredB don't forget to paste your config, if it's no problem for you. thx :)

squid cache.log

2020/08/29 21:41:27 kid1| optional ICAP service is up: icap://127.0.0.1:1344/response [up]

2020/08/29 21:42:41 kid1| suspending ICAP service for too many failures

2020/08/29 21:42:41 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/request [down,susp,fail6]

2020/08/29 21:42:41 kid1| suspending ICAP service for too many failures

2020/08/29 21:42:41 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/response [down,susp,fail6]

2020/08/29 21:42:45 kid1| Error parsing SSL Server Hello Message on FD 59

2020/08/29 21:45:41 kid1| optional ICAP service is up: icap://127.0.0.1:1344/request [up]

2020/08/29 21:45:41 kid1| optional ICAP service is up: icap://127.0.0.1:1344/response [up]

2020/08/29 21:46:16 kid1| suspending ICAP service for too many failures

2020/08/29 21:46:16 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/request [down,susp,fail6]

2020/08/29 21:46:18 kid1| suspending ICAP service for too many failures

2020/08/29 21:46:18 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/response [down,susp,fail6]

-----

E2G dstat log:

root@Guardian:/home/mserafin# tail -f /var/log/e2guardian/dstats.log
1598727314    4000    3    0    0    37    0    143    0    40 1
1598727610    4000    0    0    0    128    0    209    0    40 1
1598727910    4000    0    0    0    98    0    222    0    40 1
1598728210    4000    3    0    0    85    0    128    0    62 1
1598728510    4000    8    0    0    88    0    856    2    62 1
1598728811    4000    0    0    0    124    0    349    1    62 1
1598729111    4000    1    0    0    50    0    89    0    62    1
1598729411    4000    2    0    0    34    0    118    0    62 1
1598729711    4000    3    0    0    77    0    360    1    62 1
1598730012    4000    0    0    0    222    0    485    1    62 1 

[Philip Pearce]

Hi,

The dstats.log shows that the system is using very few httpworkers (max of ~55 at peak) so the number of httpworkers is not the issue here.

Something is dropping the connections early, as in a typical ICAP system, I would expect a low number of connections over 5 mins, but a much higher number of requests. 

If you switch DEBUG = ICAP and look at the output you should be able to see how the connections are being closed (i.e. by squid or by e2g).  If it is by e2g then please post the debug output and I will check it.

---

From: "markus....@gmail.com" <markus....@gmail.com>
To: "e2guardian" <e2gua...@googlegroups.com>
Sent: Saturday, 29 August, 2020 8:53:51 PM
Subject: Re: ICAP protocol error / timeout

--

E2guardian:
https://groups.google.com/d/forum/e2guardian
Github:
https://github.com/e2guardian/e2guardian
Follow us on twitter:
https://twitter.com/e2guardian
---
You received this message because you are subscribed to the Google Groups "e2guardian" group.
To unsubscribe from this group and stop receiving emails from it, send an email to e2guardian+...@googlegroups.com.

To view this discussion on the web, visit https://groups.google.com/d/msgid/e2guardian/5e6b4936-1e72-4a38-88b7-cf93761398e1n%40googlegroups.com.

[FredB]

Squid.conf

#############ICAP#######
icap_enable on
icap_service service_req reqmod_precache bypass=on
icap://127.0.0.1:1344/request
icap_service service_resp respmod_precache bypass=on
icap://127.0.0.1:1344/response
adaptation_access service_req allow all
adaptation_access service_resp allow all
icap_send_client_ip on
icap_send_client_username on
adaptation_masterx_shared_names X-ICAP-E2G
icap_service_failure_limit 1 in 1 seconds
icap_connect_timeout 10 seconds
icap_io_timeout 15 seconds
icap_service_revival_delay 10

half_closed_clients off
quick_abort_min 0 KB
quick_abort_max 0 KB



E2guardian.conf

languagedir = '/etc/e2guardian/languages'
language = 'french'
loglevel = 2
logexceptionhits = 0
logfileformat = 6
loglocation = '/var/log/e2guardian/access.log'
dstatlocation = '/var/log/e2guardian/dstats.log'
dstatinterval = 20  # = 5 minutes
filterip =
filterports = 8080
icapport = 1344
proxyip = 127.0.0.1
proxyport = 3128
proxytimeout = 50
proxyexchange = 60
pcontimeout = 15
usecustombannedimage = on
custombannedimagefile = '/usr/share/e2guardian/transparent1x1.gif'
usecustombannedflash = on
custombannedflashfile = '/usr/share/e2guardian/blockedflash.swf'
filtergroups = 5
filtergroupslist = '/etc/e2guardian/lists/groupes'
showweightedfound = on
weightedphrasemode = 2
urlcachenumber = 0
urlcacheage = 0
phrasefiltermode = 2
preservecase = 0
hexdecodecontent = off
forcequicksearch = off
reverseaddresslookups = off
reverseclientiplookups = off
logclienthostnames = off
maxcontentfiltersize = 0
maxcontentramcachescansize = 20240
maxcontentfilecachescansize =  512000
filecachedir = '/tmp'
deletedownloadedtempfiles = on
initialtrickledelay = 40
trickledelay = 20
contentscanner = '/etc/e2guardian/contentscanners/icapscan.conf'
contentscannertimeout = 60
contentscanexceptions = off
recheckreplacedurls = off
usexforwardedfor = off
logconnectionhandlingerrors = on
httpworkers = 5000
maxips = 0
nologger = off
logadblocks = off
loguseragent = on
daemonuser = 'e2guardian'
daemongroup = 'e2guardian'
softrestart = off
enablessl = off
preauthstoryboard = '/etc/e2guardian/preauth.story'
storyboardtrace = off
maxheaderlines = 80

[Meridoff]

Hello, Is this problem solved? I have the same problem with e2g 5.5.0 and squid 4.13 (sslbump + interception), both on the same machine.

My log when browsing by Firefox.

2021/04/16 20:36:44 kid1| optional ICAP service is up: icap://127.0.0.1:1344/request [up]
2021/04/16 20:36:44 kid1| optional ICAP service is up: icap://127.0.0.1:1344/response [up]
2021/04/16 20:37:30 kid1| suspending ICAP service for too many failures
2021/04/16 20:37:30 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/request [down,susp,fail2]
2021/04/16 20:37:33 kid1| suspending ICAP service for too many failures
2021/04/16 20:37:33 kid1| optional ICAP service is suspended: icap://127.0.0.1:1344/response [down,susp,fail2]
2021/04/16 20:37:54 kid1| optional ICAP service is up: icap://127.0.0.1:1344/request [up]
2021/04/16 20:37:54 kid1| optional ICAP service is up: icap://127.0.0.1:1344/response [up]

среда, 26 августа 2020 г. в 10:28:33 UTC+3, markus....@gmail.com: