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

[Alex Rousskov]

On 07/31/2017 03:04 AM, Amos Jeffries wrote:
> On 28/07/17 11:12, Alex Rousskov wrote:
>> 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.

An even bigger question is whether it is a good idea to log URLs and
similar transaction details at critical/important levels (by default). I
suspect the correct answer is "no, by default, such messages should cite
access.log record IDs and/or internal incident reports instead", but I
realize that we are a very long way from reaching that ideal, and that
others will probably disagree that it is an "ideal" state, so we will
never reach it anyway.


> 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.

Yes, I gladly noticed that it was not an objection but a design concern.
I agree that it is a valid concern, but I am not yet sure whether it
should be addressed by API or policy. I suspect it is both.

Fortunately, the daemon process where most syslog() messages are written
today does not deal with URLs and similar transaction details, and I am
_not_ proposing that other processes start logging to syslog
automatically (squid -s already gives the admin some control over syslog
logging for other processes). However, I do agree that the change will
make more future debugs() lines suspect. This is why I started asking
questions about addressing that problem.


> 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.

FWIW, I do not think we should invest a lot into improving support for
broken syslog implementations.


>> 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.

The error message may give the admin access to ten pages of information
but remain 200 characters short. Explanations belong to documentation,
and error-specific details can be cached by Squid and then provided via
the cache manager interface (that the error message can link to).


>>> 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>

Nope, that is a very different patch:

* Blocked: [squid-dev] [PATCH] Do not die silently when dying early
* Committed r15171: Do not die silently when dying via std::terminate()


> 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.

That idea does not compute for me: The only difference between clog and
cerr is that clog buffers until EOL while cerr does not buffer at all,
but that difference does not allow us to accumulate complete messages.

We could add code to accumulate (while dumping to clog/cerr) and then
log messages (to cache.log), but I see no connection to removing
explicit syslog() calls. Please clarify what that connection is.


Thank you,

Alex.