diff --git a/pkg/cli/mt_start_sql.go b/pkg/cli/mt_start_sql.go index 60a89e6ae176..bdf1ab202797 100644 --- a/pkg/cli/mt_start_sql.go +++ b/pkg/cli/mt_start_sql.go @@ -75,7 +75,16 @@ func runStartSQL(cmd *cobra.Command, args []string) error { return err } - ctx := context.Background() + // Set up a cancellable context for the entire start command. + // The context will be canceled at the end. + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + // The context annotation ensures that server identifiers show up + // in the logging metadata as soon as they are known. + ambientCtx := serverCfg.AmbientCtx + ctx = ambientCtx.AnnotateCtx(ctx) + const clusterName = "" stopper, err := setupAndInitializeLoggingAndProfiling(ctx, cmd, false /* isServerCmd */) diff --git a/pkg/cli/start.go b/pkg/cli/start.go index efe9579259d8..231d7b28a35a 100644 --- a/pkg/cli/start.go +++ b/pkg/cli/start.go @@ -59,6 +59,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/util/tracing" "github.com/cockroachdb/errors" "github.com/cockroachdb/errors/oserror" + "github.com/cockroachdb/logtags" "github.com/cockroachdb/pebble/vfs" "github.com/cockroachdb/redact" "github.com/spf13/cobra" @@ -407,16 +408,21 @@ func runStart(cmd *cobra.Command, args []string, startSingleNode bool) (returnEr ctx, cancel := context.WithCancel(context.Background()) defer cancel() - // Set up a tracing span for the start process. We want any logging - // happening beyond this point to be accounted to this start - // context, including logging related to the initialization of - // the logging infrastructure below. - // This span concludes when the startup goroutine started below - // has completed. - // TODO(andrei): we don't close the span on the early returns below. - tracer := serverCfg.Tracer - startupSpan := tracer.StartSpan("server start") - ctx = tracing.ContextWithSpan(ctx, startupSpan) + ambientCtx := serverCfg.AmbientCtx + + // Annotate the context, and set up a tracing span for the start process. + // + // The context annotation ensures that server identifiers show up + // in the logging metadata as soon as they are known. + // + // The tracing span is because we want any logging happening beyond + // this point to be accounted to this start context, including + // logging related to the initialization of the logging + // infrastructure below. This span concludes when the startup + // goroutine started below has completed. TODO(andrei): we don't + // close the span on the early returns below. + var startupSpan *tracing.Span + ctx, startupSpan = ambientCtx.AnnotateCtxWithSpan(ctx, "server start") // Set up the logging and profiling output. // @@ -568,7 +574,7 @@ func runStart(cmd *cobra.Command, args []string, startSingleNode bool) (returnEr If problems persist, please see %s.` docLink := docs.URL("cluster-setup-troubleshooting.html") if !startCtx.inBackground { - log.Ops.Shoutf(context.Background(), severity.WARNING, msg, docLink) + log.Ops.Shoutf(ctx, severity.WARNING, msg, docLink) } else { // Don't shout to stderr since the server will have detached by // the time this function gets called. @@ -699,9 +705,8 @@ If problems persist, please see %s.` // decommission`, or a signal. // We'll want to log any shutdown activity against a separate span. - shutdownSpan := tracer.StartSpan("server shutdown") + shutdownCtx, shutdownSpan := ambientCtx.AnnotateCtxWithSpan(context.Background(), "server shutdown") defer shutdownSpan.Finish() - shutdownCtx := tracing.ContextWithSpan(context.Background(), shutdownSpan) stopWithoutDrain := make(chan struct{}) // closed if interrupted very early @@ -764,9 +769,8 @@ If problems persist, please see %s.` } // Don't use shutdownCtx because this is in a goroutine that may // still be running after shutdownCtx's span has been finished. - ac := log.AmbientContext{} - ac.AddLogTag("server drain process", nil) - drainCtx := ac.AnnotateCtx(context.Background()) + drainCtx := ambientCtx.AnnotateCtx(context.Background()) + drainCtx = logtags.AddTag(drainCtx, "server drain process", nil) // Perform a graceful drain. We keep retrying forever, in // case there are many range leases or some unavailability @@ -824,7 +828,7 @@ If problems persist, please see %s.` for { select { case <-ticker.C: - log.Ops.Infof(context.Background(), "%d running tasks", stopper.NumTasks()) + log.Ops.Infof(shutdownCtx, "%d running tasks", stopper.NumTasks()) case <-stopper.IsStopped(): return case <-stopWithoutDrain: @@ -1063,7 +1067,7 @@ func maybeWarnMemorySizes(ctx context.Context) { var buf bytes.Buffer fmt.Fprintf(&buf, "Using the default setting for --cache (%s).\n", cacheSizeValue) fmt.Fprintf(&buf, " A significantly larger value is usually needed for good performance.\n") - if size, err := status.GetTotalMemory(context.Background()); err == nil { + if size, err := status.GetTotalMemory(ctx); err == nil { fmt.Fprintf(&buf, " If you have a dedicated server a reasonable setting is --cache=.25 (%s).", humanizeutil.IBytes(size/4)) } else { @@ -1143,7 +1147,7 @@ func setupAndInitializeLoggingAndProfiling( if addr == "" { addr = "any of your IP addresses" } - log.Ops.Shoutf(context.Background(), severity.WARNING, + log.Ops.Shoutf(ctx, severity.WARNING, "ALL SECURITY CONTROLS HAVE BEEN DISABLED!\n\n"+ "This mode is intended for non-production testing only.\n"+ "\n"+ @@ -1153,7 +1157,7 @@ func setupAndInitializeLoggingAndProfiling( "- Intruders can log in without password and read or write any data in the cluster.\n"+ "- Intruders can consume all your server's resources and cause unavailability.", addr) - log.Ops.Shoutf(context.Background(), severity.INFO, + log.Ops.Shoutf(ctx, severity.INFO, "To start a secure server without mandating TLS for clients,\n"+ "consider --accept-sql-without-tls instead. For other options, see:\n\n"+ "- %s\n"+ @@ -1172,7 +1176,7 @@ func setupAndInitializeLoggingAndProfiling( "to databases, the --locality flag must contain a \"region\" tier.\n" + "For more information, see:\n\n" + "- %s" - log.Shoutf(context.Background(), severity.WARNING, warningString, + log.Shoutf(ctx, severity.WARNING, warningString, log.Safe(docs.URL("cockroach-start.html#locality"))) } } diff --git a/pkg/testutils/lint/passes/fmtsafe/functions.go b/pkg/testutils/lint/passes/fmtsafe/functions.go index 8dd98a64aa47..8b1869a81017 100644 --- a/pkg/testutils/lint/passes/fmtsafe/functions.go +++ b/pkg/testutils/lint/passes/fmtsafe/functions.go @@ -79,6 +79,7 @@ var requireConstFmt = map[string]bool{ "github.com/cockroachdb/cockroach/pkg/util/log.MakeLegacyEntry": true, "github.com/cockroachdb/cockroach/pkg/util/log.makeUnstructuredEntry": true, "github.com/cockroachdb/cockroach/pkg/util/log.FormatWithContextTags": true, + "github.com/cockroachdb/cockroach/pkg/util/log.formatOnlyArgs": true, "github.com/cockroachdb/cockroach/pkg/util/log.renderArgsAsRedactable": true, "github.com/cockroachdb/cockroach/pkg/util/log.formatArgs": true, "github.com/cockroachdb/cockroach/pkg/util/log.logfDepth": true, diff --git a/pkg/util/log/channels.go b/pkg/util/log/channels.go index 37f68e0acfab..eab4830979f8 100644 --- a/pkg/util/log/channels.go +++ b/pkg/util/log/channels.go @@ -78,7 +78,7 @@ func shoutfDepth( // it here. fmt.Fprintf(OrigStderr, "*\n* %s: %s\n*\n", sev.String(), strings.Replace( - FormatWithContextTags(ctx, format, args...), + formatOnlyArgs(format, args...), "\n", "\n* ", -1)) } logfDepth(ctx, depth+1, sev, ch, format, args...) diff --git a/pkg/util/log/structured.go b/pkg/util/log/structured.go index fc54821cb5b9..73f48e2e6acc 100644 --- a/pkg/util/log/structured.go +++ b/pkg/util/log/structured.go @@ -28,6 +28,12 @@ func FormatWithContextTags(ctx context.Context, format string, args ...interface return buf.String() } +func formatOnlyArgs(format string, args ...interface{}) string { + var buf strings.Builder + formatArgs(&buf, format, args...) + return buf.String() +} + func formatArgs(buf *strings.Builder, format string, args ...interface{}) { if len(args) == 0 { buf.WriteString(format)