lib/log: internalize logger flushing (#34323)

This PR removes Sync() from the logger interface and adds a callback returned by log.Init which should be called before application exit. The removal of Sync() from the Logger interface helps indicate that not every logger from log.Scoped needs a call to Sync(). For logtest, we add a t.Cleanup func to sync the global logger.

Additionally, I've noticed that log.Fatal is used quite liberally. Even if we switch to error propagation, there's still the issue that os.Exit will bypass any defer calls and hence potentially miss Sync(). To accommodate this pattern, I've decided to add back Fatal to Logger, which internally calls Sync() before os.Exit(1). Also see uber-go/zap#207 for more rationale for supporting Fatal.

Background: All loggers are children of the root global logger that is instantiated once. As such, it is sufficient to just call Sync() on the root logger - all child loggers just write to underlying loggers until they reach the root, which as far as I can tell is an os.File that has Sync(), which gets called by Zap, so it's not a no-op even if Zap itself does not do any buffering (at the moment, the global logger is not configured to do so)

Aside: in practice, it's honestly probably not a huge deal to never call Sync(), but we should anyway just in case, so hopefully this balances the probable need to call Sync() with ergonomics.

doc/dev/how-to/add_and_use_logging.md

@@ -41,14 +41,16 @@ import (
 
 func main() {
   // If unintialized, calls to `log.Scoped` will return a no-op logger in production, or
-  // panic in development.
+  // panic in development. It returns a callback to flush the logger buffer, if any, that
+  // you should make sure to call before application exit (namely via `defer`)
   //
   // Repeated calls to `log.Init` will panic. Make sure to call this exactly once in `main`!
-  log.Init(log.Resource{
+  syncLogs := log.Init(log.Resource{
     Name: env.MyName,
     /* ... optional fields */
     Version: version.Version(),
   })
+  defer syncLogs()
 
   service.Start(/* ... */)
 }

lib/log/init.go

@@ -22,18 +22,19 @@ type Resource = otfields.Resource
 
 // Init initializes the log package's global logger as a logger of the given resource.
 // It must be called on service startup, i.e. 'main()', NOT on an 'init()' function.
-//
 // Subsequent calls will panic, so do not call this within a non-service context.
 //
+// Init returns a callback, sync, that should be called before application exit.
+//
 // For testing, you can use 'logtest.Init' to initialize the logging library.
 //
 // If Init is not called, Get will panic.
-func Init(r Resource) {
+func Init(r Resource) (sync func() error) {
 	if globallogger.IsInitialized() {
 		panic("log.Init initialized multiple times")
 	}
 
 	level := zap.NewAtomicLevelAt(Level(os.Getenv(envSrcLogLevel)).Parse())
 	format := encoders.ParseOutputFormat(os.Getenv(envSrcLogFormat))
-	globallogger.Init(r, level, format, development)
+	return globallogger.Init(r, level, format, development)
 }

lib/log/internal/globallogger/globallogger.go

@@ -28,11 +28,13 @@ func Get(safe bool) *zap.Logger {
 	return globalLogger
 }
 
-// Init initializes the global logger once. Subsequent calls are no-op.
-func Init(r otfields.Resource, level zap.AtomicLevel, format encoders.OutputFormat, development bool) {
+// Init initializes the global logger once. Subsequent calls are no-op. Returns the
+// callback to sync the root core.
+func Init(r otfields.Resource, level zap.AtomicLevel, format encoders.OutputFormat, development bool) func() error {
 	globalLoggerInit.Do(func() {
 		globalLogger = initLogger(r, level, format, development)
 	})
+	return globalLogger.Sync
 }
 
 // IsInitialized indicates if the global logger is initialized.

lib/log/logger.go

@@ -51,10 +51,9 @@ type Logger interface {
 	// Error logs are high-priority. If an application is running smoothly, it shouldn't
 	// generate any error-level logs.
 	Error(string, ...Field)
-
-	// Sync flushes any buffered log entries. Applications should take care to call Sync
-	// before exiting.
-	Sync() error
+	// Fatal logs a fatal error message, including any fields accumulated on the Logger.
+	// The logger then calls os.Exit(1), flushing the logger before doing so. Use sparingly.
+	Fatal(string, ...Field)
 }
 
 // Scoped returns the global logger and sets it up with the given scope and OpenTelemetry

lib/log/logtest/logtest.go

@@ -68,6 +68,9 @@ func Scoped(t testing.TB) log.Logger {
 	// already been done. We allow this in testing for convenience.
 	Init(nil)
 
+	// On cleanup, flush the global logger.
+	t.Cleanup(func() { globallogger.Get(true).Sync() })
+
 	return log.Scoped(t.Name(), "")
 }
 
@@ -88,7 +91,6 @@ func Captured(t testing.TB) (logger log.Logger, exportLogs func() []CapturedLog)
 	}))
 
 	return logger, func() []CapturedLog {
-		logger.Sync()
 		entries := entries.TakeAll()
 		logs := make([]CapturedLog, len(entries))
 		for i, e := range entries {