[squid-dev] [RFC] Migrate explicit syslog calls to debugs

[Amos Jeffries]

On 28/07/17 11:12, Alex Rousskov wrote:
> On 07/26/2017 11:04 PM, Amos Jeffries wrote:
>> On 27/07/17 16:06, Alex Rousskov wrote:
>>>       Squid master process uses many explicit syslog() calls like these:
>>>
>>>> syslog(LOG_ALERT, "fork failed: %s", xstrerr(xerrno));
>>>> syslog(LOG_ALERT, "Suspiciously high workers value: %d",
>>>> syslog(LOG_NOTICE, "Squid Parent: will start %d kids", (int)TheKids.count());
>>>> syslog(LOG_ALERT, "execvp failed: %s", xstrerr(xerrno));
>>>> syslog(LOG_NOTICE, "Squid Parent: %s process %d started",
>>>> syslog(LOG_NOTICE, "Squid Parent: %s process %d exited with status %d",
>>>> syslog(LOG_NOTICE, "Squid Parent: %s process %d exited due to signal %d with status %d",
>>>> syslog(LOG_NOTICE, "Squid Parent: %s process %d exited",
>>>> syslog(LOG_NOTICE, "Squid Parent: %s process %d will not"
>>>> syslog(LOG_NOTICE, "Squid Parent: unknown child process %d exited", pid);
>>>> syslog(LOG_ALERT, "Exiting due to unexpected forced shutdown");
>>>> syslog(LOG_ALERT, "Exiting due to repeated, frequent failures");
>>>
>>>
>>> I propose to replace explicit syslog() calls with DBG_CRITICAL and
>>> DBG_IMPORTANT debugs() calls _and_ automatically enable syslog-logging
>>> of levels 0-1 debugs() calls made by the master process.
> 
> 
>> It can easily result in log lines too long for syslog to record easily
>> (IIRC some do brain-dead line wrapping at inconvenient lengths). So that
>> will need to be accounted for in the design.
> 
> AFAICT[1], "too long" here means "more than 400 characters" in extreme
> cases and "more than 2000 characters" in most environments, so any
> reasonable DBG_CRITICAL and DBG_IMPORTANT messages should be safe. Such
> messages ought to be brief anyway. And if some overly detailed messages
> are truncated or wrapped awkwardly, it is not a big deal IMHO.

Any log message that mentions a URL (eg a security alert, or a critical 
warning about some transaction-specific thing) may be upwards of 8000 
characters long.

Some of the most important (and correspondingly rare) log messages 
contain URL to assist tracking down the exact problematic transaction 
which is breaking things without assertion or fatal termination of Squid.

The common case short messages are not the one we have to care about, 
they should work whatever is implemented.  It is the rare cases that 
cause mess we have to take care to design around.

In case you missed it, I was not objecting. My point was that you will 
have to review all those 0/1 level outputs to ensure that the maximum 
useful info is output before the truncation point.

FWIW: I have vague recollections of encountering bug reports about one 
syslog implementation causing somebody problems by NOT doing that 
documented truncation, but by slicing the line into multiple parts 
indiscriminantly and prefixing each with the syslog timestamp etc info. 
Words or key=value wrapping at weird places.

That one may come up for us, but I'm okay as long as the truncation is 
coped with.


> 
> [1]
> https://stackoverflow.com/questions/3310875/find-syslog-max-message-length
> 
> Do you think that declaring a "keep level-0/1 messages brief" policy
> would be sufficient here, killing two logging birds with one stone?
> 

Not really. The most successful critical messages contain extra text 
telling the admin what they can do. Even the most dumb admin can easily 
get help from more observant people that way.


> 
>> I wonder if the use of clog you suggested years ago to resolve the early
>> startup messages problems should be fixed first.
> 
> I am afraid that fix is currently blocked on your response:
> 
> http://lists.squid-cache.org/pipermail/squid-dev/2017-June/008792.html
> 

Oh? <http://www.squid-cache.org/Versions/v5/changesets/squid-5-15171.patch>

That thread has nothing to do with the clog idea I was referring to. 
IIRC you wanted debugs() to use std::clog instead of std::cerr so that 
the things done before main(), and also the bits before squid.conf 
loading completed could just be buffered then dumped through the 
expected cache.log channel when it became known.


> 
>> +1 on having this happen though, whenever it happens.
> 
> 
> Thank you,
> 
> Alex.
> 


Cheers
Amos