]> git.ipfire.org Git - thirdparty/squid.git/commit
Log early level-0/1 debugs() messages to cache_log (#950)
authorAlex Rousskov <rousskov@measurement-factory.com>
Thu, 3 Feb 2022 22:04:52 +0000 (22:04 +0000)
committerSquid Anubis <squid-anubis@squid-cache.org>
Fri, 4 Feb 2022 10:32:13 +0000 (10:32 +0000)
commit61be1d8eeb035b2ef4c6c78783160a233998c75c
treebc144600a48512a6801b7dc849bad27f09305854
parent2d6a38a5d7812184b8053f01b1fe6cdda6223a4c
Log early level-0/1 debugs() messages to cache_log (#950)

Commit d7ca82e dropped cache.log-recording of debugs() messages produced
by `finalizeConfig` runners (e.g., `WARNING: mem-cache size is...`).
This change restores that functionality (by buffering early messages
until the cache.log file is opened) and improves early debugs() handling
as detailed below.

## Squid has three channels for debugs() messages:

* cache.log (`cache_log`): Settles as squid.conf settings take effect.
* stderr (mostly `-d`): Settles when command line options take effect.
* syslog (mostly `-s`): Settles when command line options take effect.

Squid always ignores debugging messages with section/level mismatching
Debug::Levels configuration (driven by a combination of the `-k debug`,
`-X`, and `debug_options` directives). _Beyond_ that ever-present
top-level filter, each debugging channel has its own set of rules that
determine which filtered debugs() messages the channel accepts; the
following approximate summary is based on the changes in this commit:

* cache.log: all messages;
* stderr: either messages satisfying explicit `-d` level restrictions or
  messages that Squid failed to write to cache.log (if no `-d`);
* syslog: level-0/1 messages and `ForceAllert` messages.

This change encapsulates channel-specific logic in dedicated classes.

## Guiding design principles

* **no repetition**: A channel must record each message at most once.
* **no reordering**: Each channel must preserve same-process debugs()
  call order across all recorded messages.
* **no loss**: Each channel must log all messages matching the channel
  configuration/filters.
* **no delay**: Each channel must record each message ASAP.
* **cache.log primacy**: Admins want messages logged to cache.log if
  possible and to stderr/syslog only if necessary or explicitly
  requested.
* **cache.log locking**: No cache.log updates without a PID lock.

## The fix

Commit d7ca82e dropped level-0/1 messages produced by `finalizeConfig`
runners because, since that commit, the cache.log channel was opened
_after_ the `finalizeConfig` event. Official code also dropped other,
even earlier level-0/1 messages, violating the "cache.log primacy"
principle. We now save early level-0/1 messages into a buffer. This
buffering can be misinterpreted as violating the "no [artificial] delay"
principle, but the messages are actually written to cache.log ASAP;
without the buffer the messages would be missing from the "primary"
cache.log and, in many use cases without stderr capturing, completely.

If Squid fails to open cache.log, early messages saved for the cache.log
channel are given to the stderr channel (following the "no loss"
principle). The stderr channel logs those messages that obey explicit
`-d` restrictions and do not violate the "no reordering" and "no
repetition" principles. Violations are tracked by assigning each message
its debugs() call sequence number.

The early messages buffer is currently dedicated to level-0/1 messages
because we were worried that level-2+ messages (if enabled via `-X`)
would overflow any reasonably-sized buffer[^1]. Correctly handling such
overflows is very difficult (we tried), so we avoid them instead.

## Side effects and surprises

To allow admins to see early level-1 cache.log messages (without adding
an `if early` check to the debugs() macro[^2]), we changed the _initial_
Debug::Levels value from `ALL,0` to `ALL,1`, matching the debug_options
default set later. This fix uncovered a few early level-1 messages that
were previously hidden[^3]:

    09:46:36| Startup: Initializing Authentication Schemes ...
    09:46:36| Startup: Initialized Authentication Scheme 'basic'
    09:46:36| Startup: Initialized Authentication Scheme 'digest'
    09:46:36| Startup: Initialized Authentication Scheme 'negotiate'
    09:46:36| Startup: Initialized Authentication Scheme 'ntlm'
    09:46:36| Startup: Initialized Authentication.
    09:46:36| Processing Configuration File: .../squid.conf ...
    09:46:36| Initializing https:// proxy context
    09:46:36| Set Current Directory to /usr/local/squid/var

The fact that many debugs() messages happen before cache_log can be
opened is fairly obvious, but it is also true that stderr and syslog
channels cannot write messages immediately. Both channels need to wait
for the command line options to be parsed. Even the global `stderr`
variable may not be available during very early debugs() calls! Each
channel now buffers level-0/1 messages until it settles.

Since the early message buffers are limited to level-0/1 messages,
initial cache.log records logged by `squid -X` are level-0/1 messages,
followed by true ALL,9 debugging. The admins can get early ALL,9
messages via stderr, of course.

The `-z` command-line option no longer overrides `-d` settings.

Squid no longer writes to cache_log after removing the PID file.

fatal() text and the `Squid Cache...: Terminated abnormally.` message
are no longer dropped during certain early process terminations.

`squid -k ...` logs some new level-0/1 messages to stderr.

Improved support for assert()/debugs() triggered from within the Debug
module: Besides crashes, such "internal" debugs() could be logged before
earlier "external" messages and some assert() messages could be lost.

[^1]: The restriction to only buffer level-0/1 messages can be easily
removed (after research and discussion) if there is consensus that the
actual memory required to accumulate all typical level-2+ early messages
is worth spending on making `squid -X` write all messages to cache.log.

[^2]: Squid has thousands of debugs() calls (and counting), including
many calls on performance-sensitive paths. Most debugs() calls should do
nothing by default. Thus, the speed at which the debugs() macro can skip
logging is an important common case on the performance sensitive path.
Similarly, disruption to CPU processing pipeline due to top-level
debugs() checks may be important. Actually writing the message to the
cache.log may not be that important -- at that time, the performance
battle can be considered lost -- but the initial rejection is.

[^3]: This change is not about the levels of any specific messages.
Wrong message levels (if any) should be fixed separately. This change
does not imply that the newly discovered messages have wrong levels.
12 files changed:
src/Debug.h
src/Instance.cc
src/base/Optional.h
src/debug.cc
src/fatal.cc
src/icmp/IcmpPinger.cc
src/icmp/pinger.cc
src/main.cc
src/mem/old_api.cc
src/tests/stub_debug.cc
src/tests/test_http_range.cc
src/tools.cc