Merge #57134

57134: util/log,cli: channel abstraction; new configuration system r=itsbilal a=knz

(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):

1. `logpb/log.proto`: introduce a new protobuf enum Channels
2. `log/gen.sh`: auto-generate channel aliases in new sub-package `channel`
3. `log/gen.sh`: auto-generate per-channel APIs in `log_channels.go`
4. `log`: rework `clog.go` and other files to pass the channel as argument
5. `log/logconfig`: new package for log config data structures + parser + tests
6. `log/flags.go`: apply the configuration
7. `cli/{context,flags}.go`: read log config via `--log`, mark other flags deprecated
8. `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`.

Co-authored-by: Raphael 'kena' Poss <knz@thaumogen.net>

Makefile

@@ -809,6 +809,7 @@ COCKROACHSHORT := ./cockroachshort$(SUFFIX)
 
 LOG_TARGETS = \
 	pkg/util/log/severity/severity_generated.go \
+	pkg/util/log/channel/channel_generated.go \
 	pkg/util/log/log_channels_generated.go
 
 SQLPARSER_TARGETS = \
@@ -1552,6 +1553,11 @@ pkg/util/log/severity/severity_generated.go: pkg/util/log/gen.sh pkg/util/log/lo
 	mv -f $@.tmp $@
 	gofmt -s -w $@
 
+pkg/util/log/channel/channel_generated.go: pkg/util/log/gen.sh pkg/util/log/logpb/log.proto
+	bash $< channel.go >$@.tmp || { rm -f $@.tmp; exit 1; }
+	mv -f $@.tmp $@
+	gofmt -s -w $@
+
 pkg/util/log/log_channels_generated.go: pkg/util/log/gen.sh pkg/util/log/logpb/log.proto
 	bash $< log_channels.go >$@.tmp || { rm -f $@.tmp; exit 1; }
 	mv -f $@.tmp $@

docs/generated/logging.md

@@ -22,3 +22,73 @@ The FATAL severity is used for situations that require an immedate, hard
 server shutdown. A report is also sent to telemetry if telemetry
 is enabled.
 
+# Logging channels
+
+## DEV
+
+The DEV channel is the channel used during development, to collect log
+details useful for troubleshooting when it is unclear which other
+channel to use. It is also the default logging channel in
+CockroachDB, when the caller does not indicate a channel.
+
+This channel is special in that there are no constraints as to
+what may or may not be logged on it. Conversely, users in
+production deployments are invited to not collect The DEV channel logs in
+centralized logging facilities, because they likely contain
+sensitive operational data.
+
+## STORAGE
+
+The STORAGE channel is the channel used to report low-level storage
+layer events (RocksDB/Pebble).
+
+## SESSIONS
+
+The SESSIONS channel is the channel used to report client network activity:
+
+- connections opened/closed.
+- authentication events: logins, failed attempts.
+- session and query cancellation.
+
+This is typically configured in "audit" mode, with event
+numbering and synchronous writes.
+
+## SENSITIVE_ACCESS
+
+The SENSITIVE_ACCESS channel is the channel used to report SQL
+data access to sensitive data (when enabled):
+
+- data access audit events (when table audit is enabled).
+- SQL statements executed by users with the ADMIN bit.
+- operations that write to `system` tables.
+
+This is typically configured in "audit" mode, with event
+numbering and synchronous writes.
+
+## SQL_EXEC
+
+The SQL_EXEC channel is the channel used to report SQL execution on
+behalf of client connections:
+
+- logical SQL statement executions (if enabled)
+- pgwire events (if enabled)
+
+## SQL_PERF
+
+The SQL_PERF channel is the channel used to report SQL executions
+that are marked to be highlighted as "out of the ordinary"
+to facilitate performance investigations.
+This includes the "SQL slow query log".
+
+Arguably, this channel overlaps with SQL_EXEC defined above.
+However, we keep them separate for backward-compatibility
+with previous versions, where the corresponding events
+were redirected to separate files.
+
+## SQL_INTERNAL_PERF
+
+The SQL_INTERNAL_PERF channel is like the SQL perf channel above but aimed at
+helping developers of CockroachDB itself. It exists as a separate
+channel so as to not pollute the SQL perf logging output with
+internal troubleshooting details.
+

pkg/base/constants.go

@@ -42,6 +42,10 @@ const (
 	// stores dump when one of the dump heuristics is triggered.
 	GoroutineDumpDir = "goroutine_dump"
 
+	// CPUProfileDir is the directory name where the CPU profile dumper
+	// stores profiles when the periodic CPU profile dump is enabled.
+	CPUProfileDir = "pprof_dump"
+
 	// MinRangeMaxBytes is the minimum value for range max bytes.
 	MinRangeMaxBytes = 64 << 10 // 64 KB
 )

pkg/cli/BUILD.bazel

@@ -11,6 +11,7 @@ go_library(
         "cpuprofile.go",
         "debug.go",
         "debug_check_store.go",
+        "debug_logconfig.go",
         "debug_merge_logs.go",
         "debug_synctest.go",
         "decode.go",
@@ -29,6 +30,7 @@ go_library(
         "init.go",
         "initial_sql.go",
         "keytype_string.go",
+        "log_flags.go",
         "mt.go",
         "mt_cert.go",
         "mt_start_sql.go",
@@ -144,6 +146,8 @@ go_library(
         "//pkg/util/iterutil",
         "//pkg/util/keysutil",
         "//pkg/util/log",
+        "//pkg/util/log/channel",
+        "//pkg/util/log/logconfig",
         "//pkg/util/log/logcrash",
         "//pkg/util/log/logflags",
         "//pkg/util/log/logpb",
@@ -198,6 +202,7 @@ go_library(
         "//vendor/google.golang.org/grpc",
         "//vendor/google.golang.org/grpc/codes",
         "//vendor/google.golang.org/grpc/status",
+        "//vendor/gopkg.in/yaml.v2:yaml_v2",
     ] + select({
         "@io_bazel_rules_go//go/platform:aix": [
             "//vendor/golang.org/x/sys/unix",
@@ -261,6 +266,7 @@ go_test(
         "flags_test.go",
         "haproxy_test.go",
         "import_test.go",
+        "log_flags_test.go",
         "main_test.go",
         "nodelocal_test.go",
         "sql_test.go",
@@ -311,7 +317,8 @@ go_test(
         "//pkg/util",
         "//pkg/util/leaktest",
         "//pkg/util/log",
-        "//pkg/util/log/logflags",
+        "//pkg/util/log/channel",
+        "//pkg/util/log/logconfig",
         "//pkg/util/log/severity",
         "//pkg/util/protoutil",
         "//pkg/util/stop",

pkg/cli/cli.go

@@ -12,7 +12,6 @@ package cli
 
 import (
 	"context"
-	"flag"
 	"fmt"
 	"math/rand"
 	"os"
@@ -24,7 +23,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/cli/exit"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/log/logcrash"
-	"github.com/cockroachdb/cockroach/pkg/util/log/logflags"
 	"github.com/cockroachdb/cockroach/pkg/util/randutil"
 	// intentionally not all the workloads in pkg/ccl/workloadccl/allccl
 	_ "github.com/cockroachdb/cockroach/pkg/workload/bank"       // registers workloads
@@ -51,23 +49,14 @@ func Main() {
 		os.Args = append(os.Args, "help")
 	}
 
-	// Change the logging defaults for the main cockroach binary.
-	// The value is overridden after command-line parsing.
-	if err := flag.Lookup(logflags.LogToStderrName).Value.Set("NONE"); err != nil {
-		panic(err)
-	}
-
-	cmdName := commandName(os.Args[1:])
-
-	logcrash.SetupCrashReporter(
-		context.Background(),
-		cmdName,
-	)
+	// We ignore the error in this lookup, because
+	// we want cobra to handle lookup errors with a verbose
+	// help message in Run() below.
+	cmd, _, _ := cockroachCmd.Find(os.Args[1:])
 
-	defer logcrash.RecoverAndReportPanic(context.Background(), &serverCfg.Settings.SV)
-
-	err := Run(os.Args[1:])
+	cmdName := commandName(cmd)
 
+	err := doMain(cmd, cmdName)
 	errCode := exit.Success()
 	if err != nil {
 		// Display the error and its details/hints.
@@ -88,15 +77,51 @@ func Main() {
 	exit.WithCode(errCode)
 }
 
+func doMain(cmd *cobra.Command, cmdName string) error {
+	if cmd != nil && !cmdHasCustomLoggingSetup(cmd) {
+		// the customLoggingSetupCmds do their own calls to setupLogging().
+		if err := setupLogging(context.Background(), cmd,
+			false /* isServerCmd */, true /* applyConfig */); err != nil {
+			return err
+		}
+	}
+
+	logcrash.SetupCrashReporter(
+		context.Background(),
+		cmdName,
+	)
+
+	defer logcrash.RecoverAndReportPanic(context.Background(), &serverCfg.Settings.SV)
+
+	return Run(os.Args[1:])
+}
+
+func cmdHasCustomLoggingSetup(thisCmd *cobra.Command) bool {
+	if thisCmd == nil {
+		return false
+	}
+	for _, cmd := range customLoggingSetupCmds {
+		if cmd == thisCmd {
+			return true
+		}
+	}
+	hasCustomLogging := false
+	thisCmd.VisitParents(func(parent *cobra.Command) {
+		for _, cmd := range customLoggingSetupCmds {
+			if cmd == parent {
+				hasCustomLogging = true
+			}
+		}
+	})
+	return hasCustomLogging
+}
+
 // commandName computes the name of the command that args would invoke. For
 // example, the full name of "cockroach debug zip" is "debug zip". If args
 // specify a nonexistent command, commandName returns "cockroach".
-func commandName(args []string) string {
+func commandName(cmd *cobra.Command) string {
 	rootName := cockroachCmd.CommandPath()
-	// Ask Cobra to find the command so that flags and their arguments are
-	// ignored. The name of "cockroach --log-dir foo start" is "start", not
-	// "--log-dir" or "foo".
-	if cmd, _, _ := cockroachCmd.Find(os.Args[1:]); cmd != nil {
+	if cmd != nil {
 		return strings.TrimPrefix(cmd.CommandPath(), rootName+" ")
 	}
 	return rootName
@@ -173,6 +198,8 @@ var cockroachCmd = &cobra.Command{
 	SilenceErrors: true,
 }
 
+var workloadCmd = workloadcli.WorkloadCmd(true /* userFacing */)
+
 func init() {
 	cobra.EnableCommandSorting = false
 
@@ -210,11 +237,35 @@ func init() {
 		versionCmd,
 		DebugCmd,
 		sqlfmtCmd,
-		workloadcli.WorkloadCmd(true /* userFacing */),
+		workloadCmd,
 		systemBenchCmd,
 	)
 }
 
+// isWorkloadCmd returns true iff cmd is a sub-command of 'workload'.
+func isWorkloadCmd(cmd *cobra.Command) bool {
+	return hasParentCmd(cmd, workloadCmd)
+}
+
+// isDemoCmd returns true iff cmd is a sub-command of `demo`.
+func isDemoCmd(cmd *cobra.Command) bool {
+	return hasParentCmd(cmd, demoCmd)
+}
+
+// hasParentCmd returns true iff cmd is a sub-command of refParent.
+func hasParentCmd(cmd, refParent *cobra.Command) bool {
+	if cmd == refParent {
+		return true
+	}
+	hasParent := false
+	cmd.VisitParents(func(thisParent *cobra.Command) {
+		if thisParent == refParent {
+			hasParent = true
+		}
+	})
+	return hasParent
+}
+
 // AddCmd adds a command to the cli.
 func AddCmd(c *cobra.Command) {
 	cockroachCmd.AddCommand(c)

pkg/cli/cli_test.go

@@ -1432,9 +1432,10 @@ Available Commands:
   help              Help about any command
 
 Flags:
-  -h, --help                             help for cockroach
-      --logtostderr Severity[=DEFAULT]   logs at or above this threshold go to stderr (default NONE)
-      --no-color                         disable standard error log colorization
+  -h, --help                 help for cockroach
+      --log <string>         
+                                     Logging configuration. See the documentation for details.
+                                    
 
 Use "cockroach [command] --help" for more information about a command.
 `