util/log,cli: channel abstraction; new configuration system #57134

knz · 2020-11-25T17:33:51Z

(This PR chips away at #51987 to make it smaller. Still, it's a large-ish change. To ease the review, I added an "incremental changes" summary below which the reviewer can use as reading guide.)

tldr: this patch refactors the logging code to use channels instead of
secondary loggers, and applies a new YAML-based configuration system.

Background

Previously, log channels were defined via secondary loggers: there
were separate secondary loggers for audit logs, for
Pebble, etc. This infrastructure was unsatisfactory:

certain users have expressed the desire to refine logging streams,
by splitting e.g. configuration changes and monitoring data
into their dedicated logging outputs.

As we foresee that the number of distinct streams may increase over
time, the requirement to define a secondary logger object for each
stream becomes cumbersome: we then need to hold into each logger's
state (multiple *SecondaryLogger pointers stored at every
component that logs multiple streams) and for each make separate
choices wrt logging directory, etc.
the secondary logger abstraction excessively conflates logical event
channels, which correspond to different “categories” of events,
together with the separation of logging outputs.

In practice, we find that some users want multiple event categories go
to e.g. the same file. Later, as we introduce more various sinks,
we want to offer the option to redirect multiple event categories
to the same sink.
it was possible to define multiple loggers using the same filenames
and the same directory destination, but with competing GC and
rotation parameters.

Channels

To address these shortcomings, this patch de-publicizes the secondary
logger abstraction and supersedes it with the notion of
logging channel, which is a logical/virtual log stream. Each event
in a given logger (logging output) belongs to exactly one
channel. There can be events from multiple channels emitted to one
logger.

In accordance with expressed user requirements, the following streams
are defined here:

DEV (current “default” log): development logging.
STORAGE (current RocksDB/pebble log): low-level storage events.
This will include events currently sent to the current "pebble"
and "rocksdb" secondary logger.
SESSIONS: client connections and session/query cancellation.
This will include events currently sent to the current "auth"
secondary logger.
SENSITIVE_ACCESS: operations that access sensitive data (when enabled).
This will include events currently sent to the current "sql audit"
secondary logger.
SQL_EXEC: SQL execution logging (when enabled).
This will include events currently sent to the current "sql exec"
secondary logger.
SQL_PERF: SQL performance events (when enabled)
This will include events currently sent to the current "sql slow"
secondary logger ("Slow query log").
SQL_INTERNAL_PERF: ditto SQL_PERF, for internal queries.

File output

The file logging format now embeds the channel ID numerically as a
prefix to the filename.

The location of the prefix on the log line is chosen to be
backward-compatible with log parsers built for previous versions of
CockroachDB, which would be unable to handle additional fields on the
line.

For example:

E200727 11:57:22.907515 1392 1@sql/conn_executor.go:492  [n1] panic: woo
                             ^^ channel ID 1 = OPS

This prefix is omitted if the ID is 0 (DEV). Conversely, when parsing
an existing log file, a missing ID is considered to be an event on the
DEV channel. This makes the parser in the new version able to parse
entries emitted by previous versions.

Configuration format

The configuration can now be specified via YAML,
using a new command line flag --log.

The format works as follows:

file-defaults: #optional
  dir: <path>          # output directory, defaults to first store dir
  filter: <severity>   # min severity level for file output, default INFO
  redact: <bool>       # whether to remove sensitive info, default false
  redactable: <bool>   # whether to strip redaction markers, default false
  max-file-size: <sz>  # max log file size, default 10MB
  max-group-size: <sz> # max log file group size, default 100MB

sinks: #optional
 stderr: #optional
  filter: <severity>   # min severity level for stderr output, default NONE
  channels: <chans>    # channel selection for stderr output, default ALL
  redact: <bool>       # whether to remove sensitive info, default false
  redactable: <bool>   # whether to strip redaction markers, default false
  nocolor: <bool>      # disable VT color codes, default is to enable color

 file-groups: #optional
   <filename>:
     channels: <chans>    # channel selection for this file output, mandatory
     filter: <severity>   # defaults to file-defaults.filter
     dir: <path>          # defaults to file-defaults.dir
     redact: <bool>       # defaults to file-defaults.redact
     redactable: <bool>   # defaults to file-defaults.redactable
     max-file-size: <sz>  # defaults to file-defaults.max-file-size
     max-group-size: <sz> # defaults to file-defaults.max-group-size

   ... repeat ...

capture-stray-errors: #optional
  enable: <bool>   # whether to enable internal fd2 capture
  dir: <path>      # output directory, defaults to file-defaults.dir

The channel selection (channels in each sink) can be:

ALL for all channels;
a comma-delimited list of specific channels;
ALL EXCEPT <list> for all channels except the provided
channel names.

A CLI utility to validate the configuration is also provided:
cockroach debug check-log-config.

Incremental changes

The change was carried out as follows (this may guide the review):

logpb/log.proto: introduce a new protobuf enum Channels
log/gen.sh: auto-generate channel aliases in new sub-package channel
log/gen.sh: auto-generate per-channel APIs in log_channels.go
log: rework clog.go and other files to pass the channel as argument
log/logconfig: new package for log config data structures + parser + tests
log/flags.go: apply the configuration
cli/{context,flags}.go: read log config via --log, mark other flags deprecated
cli/logconfig.go: new command cockroach check-log-config for demos & checks

Release note (cli change): The logging configuration can now be
specified via the --log parameter. See the documentation for
details. The flags --log-dir, --log-file-max-size,
--log-file-verbosity, --log-group-max-size are now deprecated.

Release note (cli change): A new command cockroch debug check-log-config prints out the logging configuration that results
from the provided combination of --store, --log and other
logging-related flags on the command line.

Release note (doc change): A report of the possible logging severities
and channels is now automatically generated in
docs/generated/logging.md.

cockroach-teamcity · 2020-11-25T17:34:04Z

This change is

A linter change in cockroachdb#57134 made me discover this bug. Release note: None

itsbilal

This is a massive overhaul and my experience with a lot of this code isn't all that deep, but overall it looks great save for some minor comments.

Reviewed 79 of 85 files at r1, 13 of 13 files at r2, 9 of 9 files at r3.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @adityamaru, @itsbilal, and @knz)

pkg/cli/log_flags.go, line 45 at r1 (raw file):

	if cliCtx.deprecatedLogOverrides.anySet() &&
		cliCtx.logConfigInput.isSet {
		return errors.New("--" + cliflags.Log.Name + " is incompatible with legacy discrete logging flags")

Nit: Can use Newf here.

pkg/cli/log_flags_test.go, line 89 at r1 (raw file):

	const defaultLogDir = `PWD/cockroach-data/logs`

	testData := []struct {

Did you consider doing these (and the string generation methods above) as datadriven tests? They might be slightly easier to understand and extend that way. I'm fine with them this way too, just wondering if you thought about it.

pkg/util/log/test_log_scope.go, line 92 at r2 (raw file):

// not just debugLog. This would be necessary because loggers don't
// necessarily have the same config. Until that is implemented,
// we prevent the use case altogether.

Nice

pkg/util/log/logconfig/config.go, line 135 at r2 (raw file):

	NoColor bool `yaml:"no-color,omitempty"`

	CommonSinkConfig `yaml:",inline"`

Shouldn't this be at the top by convention?

pkg/util/log/logconfig/config.go, line 203 at r2 (raw file):

	// MaxFileSize indicates the approximate maximum size of
	// individual files generated by this sinks.

s/sinks/sink/

pkg/util/log/logconfig/validate.go, line 198 at r2 (raw file):

	c.Sinks.sortedFileGroupNames = fileGroupNames

	return nil

You'd have to do return resErr here for the defer-time set to work, right?

itsbilal · 2020-11-30T19:42:19Z

Looks like you did a rebase push right as I submitted my review. Let me know if parts of the old review aren't valid anymore / there are large parts still left to review after the force-push.

itsbilal

Now with the post-rebase review.

Reviewed 16 of 91 files at r4, 85 of 89 files at r5, 9 of 9 files at r6.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @adityamaru and @knz)

knz

Reviewed 1 of 13 files at r2.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @adityamaru and @itsbilal)

pkg/cli/log_flags.go, line 45 at r1 (raw file):