diff --git a/pkg/cmd/roachtest/BUILD.bazel b/pkg/cmd/roachtest/BUILD.bazel index 14962aad3cbe..44726d39279e 100644 --- a/pkg/cmd/roachtest/BUILD.bazel +++ b/pkg/cmd/roachtest/BUILD.bazel @@ -53,8 +53,6 @@ go_library( "//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/roachtestutil/BUILD.bazel b/pkg/cmd/roachtest/roachtestutil/BUILD.bazel index e18408e19970..971442fc904e 100644 --- a/pkg/cmd/roachtest/roachtestutil/BUILD.bazel +++ b/pkg/cmd/roachtest/roachtestutil/BUILD.bazel @@ -9,6 +9,7 @@ go_library( "health_checker.go", "httpclient.go", "jaeger.go", + "log_redirect.go", "replication.go", "utils.go", "validation_check.go", @@ -28,11 +29,14 @@ go_library( "//pkg/util/httputil", "//pkg/util/humanizeutil", "//pkg/util/log", + "//pkg/util/log/logconfig", + "//pkg/util/log/logpb", "//pkg/util/protoutil", "//pkg/util/retry", "//pkg/util/syncutil", "//pkg/util/timeutil", "@com_github_cockroachdb_errors//:errors", + "@com_github_petermattis_goid//:goid", ], ) diff --git a/pkg/cmd/roachtest/roachtestutil/log_redirect.go b/pkg/cmd/roachtest/roachtestutil/log_redirect.go new file mode 100644 index 000000000000..e04636a34c11 --- /dev/null +++ b/pkg/cmd/roachtest/roachtestutil/log_redirect.go @@ -0,0 +1,122 @@ +// Copyright 2024 The Cockroach Authors. +// +// Use of this software is governed by the Business Source License +// included in the file licenses/BSL.txt. +// +// As of the Change Date specified in that file, in accordance with +// the Business Source License, use of this software will be governed +// by the Apache License, Version 2.0, included in the file +// licenses/APL.txt. + +package roachtestutil + +import ( + "context" + "encoding/json" + "fmt" + "io" + "os" + + "github.com/cockroachdb/cockroach/pkg/roachprod/logger" + "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" + "github.com/petermattis/goid" +) + +type logInterceptor struct{} + +var logRedirect = struct { + mu struct { + syncutil.Mutex + loggers map[int64][]*logger.Logger + } + interceptor logInterceptor +}{ + mu: struct { + syncutil.Mutex + loggers map[int64][]*logger.Logger + }{ + loggers: make(map[int64][]*logger.Logger), + }, +} + +// InitCRDBLogConfig sets up an interceptor for the CockroachDB logger in order to +// redirect logs to the appropriate test log or stderr. This is necessary as the +// CockroachDB logger is used in some test utilities shared between roachtest +// and CockroachDB. Generally, CockroachDB logs should not be used explicitly +// in roachtest. +func InitCRDBLogConfig() { + 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 g, 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, nil /* fileSinkMetricsForDir */, nil /* fatalOnLogStall */); err != nil { + panic(fmt.Errorf("internal error: could not apply CRDB log config: %w", err)) + } + log.InterceptWith(context.Background(), &logRedirect.interceptor) +} + +// Intercept intercepts the CockroachDB log entries and redirects them to the +// appropriate roachtest test logger or stderr. +func (i *logInterceptor) Intercept(logData []byte) { + var entry logpb.Entry + if err := json.Unmarshal(logData, &entry); err != nil { + panic(fmt.Errorf("internal error: could not unmarshal CRDB log entry: %w", err)) + } + l := func() *logger.Logger { + logRedirect.mu.Lock() + defer logRedirect.mu.Unlock() + if loggers, ok := logRedirect.mu.loggers[entry.Goroutine]; ok && len(loggers) > 0 { + return loggers[len(loggers)-1] + } + return nil + }() + if l != nil && !l.Closed() { + if entry.Severity == logpb.Severity_ERROR || entry.Severity == logpb.Severity_FATAL { + writeLog(l.Stderr, entry) + return + } + writeLog(l.Stdout, entry) + return + } + // If no logger is found, dump to OS stderr + writeLog(os.Stderr, entry) +} + +func writeLog(dst io.Writer, entry logpb.Entry) { + if err := log.FormatLegacyEntry(entry, dst); err != nil { + panic(fmt.Errorf("internal error: could not format and write CRDB log entry: %w", err)) + } +} + +// BridgeCRDBLog bridges the CockroachDB logger to the provided test logger. It +// uses the goroutine ID to determine which logger to bridge to. The returned +// function should be called, in order, to remove the bridge. Multiple calls in +// the same goroutine will bridge to the last logger, until the returned +// function is called, which pops the last logger from the stack for that +// goroutine. +func BridgeCRDBLog(l *logger.Logger) func() { + goID := goid.Get() + + logRedirect.mu.Lock() + defer logRedirect.mu.Unlock() + loggers := logRedirect.mu.loggers[goID] + loggers = append(loggers, l) + logRedirect.mu.loggers[goID] = loggers + + return func() { + logRedirect.mu.Lock() + defer logRedirect.mu.Unlock() + loggers = logRedirect.mu.loggers[goID] + if len(loggers) != 0 { + loggers = loggers[:len(loggers)-1] + logRedirect.mu.loggers[goID] = loggers + } + } +} diff --git a/pkg/cmd/roachtest/run.go b/pkg/cmd/roachtest/run.go index e808bb608176..9430598656c7 100644 --- a/pkg/cmd/roachtest/run.go +++ b/pkg/cmd/roachtest/run.go @@ -29,6 +29,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/option" "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/registry" "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/roachtestflags" + "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/roachtestutil" "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/roachtestutil/operations" "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/spec" "github.com/cockroachdb/cockroach/pkg/roachprod" @@ -36,9 +37,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" @@ -117,11 +115,12 @@ func runTests(register func(registry.Registry), filter *registry.TestFilter) err if literalArtifactsDir == "" { literalArtifactsDir = artifactsDir } - setLogConfig(artifactsDir) + roachtestutil.InitCRDBLogConfig() runnerDir := filepath.Join(artifactsDir, runnerLogsDir) runnerLogPath := filepath.Join( runnerDir, fmt.Sprintf("test_runner-%d.log", timeutil.Now().Unix())) l, tee := testRunnerLogger(context.Background(), parallelism, runnerLogPath) + defer roachtestutil.BridgeCRDBLog(l)() roachprod.ClearClusterCache = roachtestflags.ClearClusterCache if runtime.GOOS == "darwin" { @@ -224,20 +223,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, nil /* fileSinkMetricsForDir */, nil /* fatalOnLogStall */); 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 { diff --git a/pkg/cmd/roachtest/test_runner.go b/pkg/cmd/roachtest/test_runner.go index cca8a5a110c6..63e72103ad58 100644 --- a/pkg/cmd/roachtest/test_runner.go +++ b/pkg/cmd/roachtest/test_runner.go @@ -389,6 +389,8 @@ func (r *testRunner) Run( if err != nil { l.ErrorfCtx(ctx, "unable to create logger %s: %s", name, err) childLogger = l + } else { + defer roachtestutil.BridgeCRDBLog(childLogger)() } err = r.runWorker( @@ -1268,7 +1270,7 @@ func (r *testRunner) runTest( testReturnedCh := make(chan struct{}) go func() { defer close(testReturnedCh) // closed only after we've grabbed the debug info below - + defer roachtestutil.BridgeCRDBLog(t.L())() defer func() { // We only have to record panics if the panic'd value is not the sentinel // produced by t.Fatal*(). diff --git a/pkg/cmd/roachtest/tests/BUILD.bazel b/pkg/cmd/roachtest/tests/BUILD.bazel index e00380b34530..90dcdf49c115 100644 --- a/pkg/cmd/roachtest/tests/BUILD.bazel +++ b/pkg/cmd/roachtest/tests/BUILD.bazel @@ -196,6 +196,7 @@ go_library( "util_load_group.go", "validate_system_schema_after_version_upgrade.go", "versionupgrade.go", + "wip.go", "ycsb.go", ], embedsrcs = [ diff --git a/pkg/cmd/roachtest/tests/registry.go b/pkg/cmd/roachtest/tests/registry.go index d9e1383c4bb4..5ee5b141cc6e 100644 --- a/pkg/cmd/roachtest/tests/registry.go +++ b/pkg/cmd/roachtest/tests/registry.go @@ -162,4 +162,5 @@ func RegisterTests(r registry.Registry) { registerMultiRegionMixedVersion(r) registerMultiRegionSystemDatabase(r) registerSqlStatsMixedVersion(r) + registerWIP(r) } diff --git a/pkg/cmd/roachtest/tests/wip.go b/pkg/cmd/roachtest/tests/wip.go new file mode 100644 index 000000000000..e0d84f8ef516 --- /dev/null +++ b/pkg/cmd/roachtest/tests/wip.go @@ -0,0 +1,62 @@ +// Copyright 2024 The Cockroach Authors. +// +// Use of this software is governed by the Business Source License +// included in the file licenses/BSL.txt. +// +// As of the Change Date specified in that file, in accordance with +// the Business Source License, use of this software will be governed +// by the Apache License, Version 2.0, included in the file +// licenses/APL.txt. + +package tests + +import ( + "context" + stdlog "log" + "time" + + "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster" + "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/option" + "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/registry" + "github.com/cockroachdb/cockroach/pkg/cmd/roachtest/test" + "github.com/cockroachdb/cockroach/pkg/roachprod/install" + "github.com/cockroachdb/cockroach/pkg/testutils" + "github.com/cockroachdb/cockroach/pkg/util/log" + "github.com/cockroachdb/errors" +) + +func registerWIP(r registry.Registry) { + r.Add(registry.TestSpec{ + Name: "hbl/wip1", + Owner: registry.OwnerTestEng, + Cluster: r.MakeClusterSpec(1), + CompatibleClouds: registry.CloudsWithServiceRegistration, + Suites: registry.Suites(registry.Nightly), + Leases: registry.MetamorphicLeases, + Run: func(ctx context.Context, t test.Test, c cluster.Cluster) { + c.Start(ctx, t.L(), option.DefaultStartOpts(), install.MakeClusterSettings()) + WaitForReady(ctx, t, c, c.All()) + stdlog.Printf("STDLOG PRINT") + log.Infof(ctx, "CRDB LOG") + //glog.Printf("USUAL PRINT") + tn := time.Now() + testutils.SucceedsSoon(t, func() error { + if time.Since(tn) > 20*time.Second { + return nil + } + return errors.Newf("not yet") + }) + }, + }) + //r.Add(registry.TestSpec{ + // Name: "hbl/wip2", + // Owner: registry.OwnerTestEng, + // Cluster: r.MakeClusterSpec(1), + // CompatibleClouds: registry.CloudsWithServiceRegistration, + // Suites: registry.Suites(registry.Nightly), + // Leases: registry.MetamorphicLeases, + // Run: func(ctx context.Context, t test.Test, c cluster.Cluster) { + // + // }, + //}) +}