[squid-users] Many new ERROR lines in cache.log after upgrade

[Amos Jeffries]

On 22/12/21 00:42, Truniger Othmar wrote:
> Hi
> we have been successfully running Squid for authentication and authorization for almost two decades. We don't cache and no SSL-bumping, just many access rules.
> 
> Last weekend I migrated from self-compiled 3.5.x on RHEL7 to RHEL8 with official RPM squid-4.11-4 using the same configuration file. We want to get advantage from official RPMs.
> 
> Now we get many log entries in cache.log like this (a few hundred pairs a day):
> 2021/12/21 11:52:24 kid3| ERROR: helper: {result=BH, notes={message: Success; }}, attempt #1 of 2
> 2021/12/21 11:52:24 kid3| ERROR: helper: {result=BH, notes={message: Success; message: Success; }}, attempt #2 of 2
> 
> Because nothing in the environment changed I must assume that it's only a matter of more intensive logging. But I'm not sure if I have to worry about.
> 

Or an old helper that has been producing garbage output that v3.5 
ignored and v4 rejects.


> I understand it's related to basic helpers. Since ever we use the original basic_ldap_auth and ext_ldap_group_acl and never experienced any problems with them. Also cachemgr now reports 100% successful requests/replies for the helpers and I see not any indication for any problem.
> It just looks a little awkward to see ERROR in these lines but Success for everything at the same time.
> I have set "debug_options ALL,1 rotate=2"
> The helpers don't use persistent connections.
> 

The lines shown do not indicate which type of helper is involved.

Squid is receiving one of the following lines from the helper:

   BH message="Success;"
   BH Success;


You will have to track down which helper is actually producing the BH 
output. Each helper API has its own debug section, so you need to know 
which one to enable debugging for first.

Once you know that debug_options will show you the Squid side of the API 
communication. Most helpers support "-d" parameter to debug their 
internal operations for the other side of the picture.


> Maybe this point could be significant: I used "--disable-ipv6" when self-compiling while the RHEL8 RPM probably has full IPv6 support included. Our servers have all IPv6 support disabled though.
> 

AFAIK only the external ACL helper is affected by that issue. You can 
use the 'ipv4' option on the external_acl_type directive to fix it.



> I could not find much about this topic. It was once said that one should check for strange behaviour of the basic helpers if these messages occur.
> 
> Should I worry about it?

Maybe, a little bit anyway. It will be affecting some transactions at 
least and should be fixed.


> Is it just an artefact for logging in this redhat RPM version?
> Could it be related with the way squid helpers deals with IPv6 on systems without IPv6?
> How could I specifically debug the helpers without flooding the cache.log (what section)?

The "ERROR" logs you see are from section 84 which is the logic shared 
used by all helper APIs. That covers the I/O channel and splitting the 
helper response line into concurrency-id, code and kv-pairs. You also 
need the section for whichever helper is actually producing that output 
to see how those details are being treated.


Amos