diff --git a/pkg/BUILD.bazel b/pkg/BUILD.bazel index 3d58983729d2..c50e28bee896 100644 --- a/pkg/BUILD.bazel +++ b/pkg/BUILD.bazel @@ -268,6 +268,7 @@ ALL_TESTS = [ "//pkg/roachprod/cloud:cloud_test", "//pkg/roachprod/config:config_test", "//pkg/roachprod/install:install_test", + "//pkg/roachprod/logger:logger_test", "//pkg/roachprod/prometheus:prometheus_test", "//pkg/roachprod/ssh:ssh_test", "//pkg/roachprod/vm/gce:gce_test", @@ -1420,6 +1421,7 @@ GO_TARGETS = [ "//pkg/roachprod/install:install_test", "//pkg/roachprod/lock:lock", "//pkg/roachprod/logger:logger", + "//pkg/roachprod/logger:logger_test", "//pkg/roachprod/prometheus:prometheus", "//pkg/roachprod/prometheus:prometheus_test", "//pkg/roachprod/ssh:ssh", diff --git a/pkg/cmd/roachtest/BUILD.bazel b/pkg/cmd/roachtest/BUILD.bazel index 9f65ae08376e..40e419297bd9 100644 --- a/pkg/cmd/roachtest/BUILD.bazel +++ b/pkg/cmd/roachtest/BUILD.bazel @@ -46,9 +46,6 @@ go_library( "//pkg/util/ctxgroup", "//pkg/util/httputil", "//pkg/util/leaktest", - "//pkg/util/log", - "//pkg/util/log/logconfig", - "//pkg/util/log/logpb", "//pkg/util/quotapool", "//pkg/util/randutil", "//pkg/util/stop", diff --git a/pkg/cmd/roachtest/run.go b/pkg/cmd/roachtest/run.go index d77b922cff64..2daac4fd2804 100644 --- a/pkg/cmd/roachtest/run.go +++ b/pkg/cmd/roachtest/run.go @@ -23,9 +23,6 @@ import ( "github.com/cockroachdb/cockroach/pkg/roachprod/logger" "github.com/cockroachdb/cockroach/pkg/util/allstacks" "github.com/cockroachdb/cockroach/pkg/util/leaktest" - "github.com/cockroachdb/cockroach/pkg/util/log" - "github.com/cockroachdb/cockroach/pkg/util/log/logconfig" - "github.com/cockroachdb/cockroach/pkg/util/log/logpb" "github.com/cockroachdb/cockroach/pkg/util/stop" "github.com/cockroachdb/cockroach/pkg/util/timeutil" "github.com/cockroachdb/errors" @@ -109,7 +106,8 @@ func runTests(register func(registry.Registry), filter *registry.TestFilter) err literalArtifactsDir = artifactsDir } - setLogConfig(artifactsDir) + redirectLogger := redirectCRDBLogger(context.Background(), filepath.Join(artifactsDir, "roachtest.crdb.log")) + logger.InitCRDBLogConfig(redirectLogger) runnerDir := filepath.Join(artifactsDir, runnerLogsDir) runnerLogPath := filepath.Join( runnerDir, fmt.Sprintf("test_runner-%d.log", timeutil.Now().Unix())) @@ -167,20 +165,6 @@ func runTests(register func(registry.Registry), filter *registry.TestFilter) err return err } -// This diverts all the default non fatal logging to a file in `baseDir`. This is particularly -// useful in CI, where without this, stderr/stdout are cluttered with logs from various -// packages used in roachtest like sarama and testutils. -func setLogConfig(baseDir string) { - logConf := logconfig.DefaultStderrConfig() - logConf.Sinks.Stderr.Filter = logpb.Severity_FATAL - if err := logConf.Validate(&baseDir); err != nil { - panic(err) - } - if _, err := log.ApplyConfig(logConf); err != nil { - panic(err) - } -} - // getUser takes the value passed on the command line and comes up with the // username to use. func getUser(userFlag string) string { @@ -322,3 +306,14 @@ func testRunnerLogger( shout(ctx, l, os.Stdout, "test runner logs in: %s", runnerLogPath) return l, teeOpt } + +func redirectCRDBLogger(ctx context.Context, path string) *logger.Logger { + verboseCfg := logger.Config{} + var err error + l, err := verboseCfg.NewLogger(path) + if err != nil { + panic(err) + } + shout(ctx, l, os.Stdout, "fallback runner logs in: %s", path) + return l +} diff --git a/pkg/roachprod/logger/BUILD.bazel b/pkg/roachprod/logger/BUILD.bazel index f9d02e7c92b2..3988b817297e 100644 --- a/pkg/roachprod/logger/BUILD.bazel +++ b/pkg/roachprod/logger/BUILD.bazel @@ -1,13 +1,29 @@ -load("@io_bazel_rules_go//go:def.bzl", "go_library") +load("@io_bazel_rules_go//go:def.bzl", "go_library", "go_test") go_library( name = "logger", - srcs = ["log.go"], + srcs = [ + "log.go", + "log_redirect.go", + ], importpath = "github.com/cockroachdb/cockroach/pkg/roachprod/logger", visibility = ["//visibility:public"], deps = [ "//pkg/cli/exit", "//pkg/util/log", + "//pkg/util/log/logconfig", + "//pkg/util/log/logpb", "//pkg/util/syncutil", ], ) + +go_test( + name = "logger_test", + srcs = ["log_redirect_test.go"], + args = ["-test.timeout=295s"], + embed = [":logger"], + deps = [ + "//pkg/util/log", + "@com_github_stretchr_testify//require", + ], +) diff --git a/pkg/roachprod/logger/log_redirect.go b/pkg/roachprod/logger/log_redirect.go new file mode 100644 index 000000000000..51f39dcedf99 --- /dev/null +++ b/pkg/roachprod/logger/log_redirect.go @@ -0,0 +1,93 @@ +// Copyright 2024 The Cockroach Authors. +// +// Use of this software is governed by the CockroachDB Software License +// included in the /LICENSE file. + +package logger + +import ( + "context" + "encoding/json" + "fmt" + "io" + + "github.com/cockroachdb/cockroach/pkg/util/log" + "github.com/cockroachdb/cockroach/pkg/util/log/logconfig" + "github.com/cockroachdb/cockroach/pkg/util/log/logpb" + "github.com/cockroachdb/cockroach/pkg/util/syncutil" +) + +type logRedirect struct { + syncutil.Mutex + logger *Logger + cancelIntercept func() + configured bool +} + +var logRedirectInst = &logRedirect{} + +// InitCRDBLogConfig sets up an interceptor for the CockroachDB log in order to +// redirect logs to a roachprod logger. This is necessary as the CockroachDB log +// is used in some test utilities shared between roachtest and CockroachDB. +// Generally, CockroachDB logs should not be used explicitly in roachtest. +func InitCRDBLogConfig(logger *Logger) { + logRedirectInst.Lock() + defer logRedirectInst.Unlock() + if logRedirectInst.configured { + panic("internal error: CRDB log interceptor already configured") + } + if logger == nil { + panic("internal error: specified logger is nil") + } + logConf := logconfig.DefaultStderrConfig() + logConf.Sinks.Stderr.Filter = logpb.Severity_FATAL + // Disable logging to a file. File sinks write the application arguments to + // the log by default (see: log_entry.go), and it is best to avoid logging + // the roachtest arguments as it may contain sensitive information. + if err := logConf.Validate(nil); err != nil { + panic(fmt.Errorf("internal error: could not validate CRDB log config: %w", err)) + } + if _, err := log.ApplyConfig(logConf); err != nil { + panic(fmt.Errorf("internal error: could not apply CRDB log config: %w", err)) + } + logRedirectInst.logger = logger + logRedirectInst.cancelIntercept = log.InterceptWith(context.Background(), logRedirectInst) + logRedirectInst.configured = true +} + +// TestingCRDBLogConfig is meant to be used in unit tests to reset the CRDB log, +// it's interceptor, and the redirect log config. This is necessary to avoid +// leaking state between tests, that test the logging. +func TestingCRDBLogConfig(logger *Logger) { + logRedirectInst.Lock() + defer logRedirectInst.Unlock() + if logRedirectInst.cancelIntercept != nil { + logRedirectInst.cancelIntercept() + } + log.TestingResetActive() + logRedirectInst = &logRedirect{} + InitCRDBLogConfig(logger) +} + +// Intercept intercepts CockroachDB log entries and redirects it to the +// appropriate roachtest test logger or stderr. +func (i *logRedirect) Intercept(logData []byte) { + var entry logpb.Entry + if err := json.Unmarshal(logData, &entry); err != nil { + i.logger.Errorf("failed to unmarshal intercepted log entry: %v", err) + } + l := i.logger + if l != nil && !l.Closed() { + if entry.Severity == logpb.Severity_ERROR || entry.Severity == logpb.Severity_FATAL { + i.writeLog(l.Stderr, entry) + return + } + i.writeLog(l.Stdout, entry) + } +} + +func (i *logRedirect) writeLog(dst io.Writer, entry logpb.Entry) { + if err := log.FormatLegacyEntry(entry, dst); err != nil { + i.logger.Errorf("could not format and write CRDB log entry: %v", err) + } +} diff --git a/pkg/roachprod/logger/log_redirect_test.go b/pkg/roachprod/logger/log_redirect_test.go new file mode 100644 index 000000000000..8d8dcf88a850 --- /dev/null +++ b/pkg/roachprod/logger/log_redirect_test.go @@ -0,0 +1,59 @@ +// Copyright 2024 The Cockroach Authors. +// +// Use of this software is governed by the CockroachDB Software License +// included in the /LICENSE file. + +package logger + +import ( + "context" + "strings" + "testing" + + "github.com/cockroachdb/cockroach/pkg/util/log" + "github.com/stretchr/testify/require" +) + +type mockLogger struct { + logger *Logger + writer *mockWriter +} + +type mockWriter struct { + lines []string +} + +func (w *mockWriter) Write(p []byte) (n int, err error) { + w.lines = append(w.lines, string(p)) + return len(p), nil +} + +func newMockLogger(t *testing.T) *mockLogger { + writer := &mockWriter{} + logConf := Config{Stdout: writer, Stderr: writer} + l, err := logConf.NewLogger("" /* path */) + require.NoError(t, err) + return &mockLogger{logger: l, writer: writer} +} + +func requireLine(t *testing.T, l *mockLogger, line string) { + t.Helper() + found := false + for _, logLine := range l.writer.lines { + if strings.Contains(logLine, line) { + found = true + break + } + } + require.True(t, found, "expected line not found: %s", line) +} + +func TestLogRedirect(t *testing.T) { + l := newMockLogger(t) + TestingCRDBLogConfig(l.logger) + ctx := context.Background() + + log.Infof(ctx, "[simple test]") + requireLine(t, l, "[simple test]") + require.Equal(t, 1, len(l.writer.lines)) +}