logging: Buffer the logs before config is loaded (#7245)

Author: francislavoie

cmd/commandfuncs.go

@@ -172,7 +172,14 @@ func cmdStart(fl Flags) (int, error) {
 func cmdRun(fl Flags) (int, error) {
 	caddy.TrapSignals()
 
-	logger := caddy.Log()
+	// set up buffered logging for early startup
+	// so that we can hold onto logs until after
+	// the config is loaded (or fails to load)
+	// so that we can write the logs to the user's
+	// configured output. we must be sure to flush
+	// on any error before the config is loaded.
+	logger, defaultLogger, logBuffer := caddy.BufferedLog()
+
 	undoMaxProcs := setResourceLimits(logger)
 	defer undoMaxProcs()
 
@@ -187,6 +194,7 @@ func cmdRun(fl Flags) (int, error) {
 	// load all additional envs as soon as possible
 	err := handleEnvFileFlag(fl)
 	if err != nil {
+		logBuffer.FlushTo(defaultLogger)
 		return caddy.ExitCodeFailedStartup, err
 	}
 
@@ -204,6 +212,7 @@ func cmdRun(fl Flags) (int, error) {
 			logger.Info("no autosave file exists", zap.String("autosave_file", caddy.ConfigAutosavePath))
 			resumeFlag = false
 		} else if err != nil {
+			logBuffer.FlushTo(defaultLogger)
 			return caddy.ExitCodeFailedStartup, err
 		} else {
 			if configFlag == "" {
@@ -222,6 +231,7 @@ func cmdRun(fl Flags) (int, error) {
 	if !resumeFlag {
 		config, configFile, err = LoadConfig(configFlag, configAdapterFlag)
 		if err != nil {
+			logBuffer.FlushTo(defaultLogger)
 			return caddy.ExitCodeFailedStartup, err
 		}
 	}
@@ -239,8 +249,15 @@ func cmdRun(fl Flags) (int, error) {
 	// run the initial config
 	err = caddy.Load(config, true)
 	if err != nil {
+		logBuffer.FlushTo(defaultLogger)
 		return caddy.ExitCodeFailedStartup, fmt.Errorf("loading initial config: %v", err)
 	}
+
+	// at this stage the config will have replaced
+	// the default logger to the configured one, so
+	// we can now flush the buffered logs, then log
+	// that the config is running.
+	logBuffer.FlushTo(caddy.Log())
 	logger.Info("serving initial configuration")
 
 	// if we are to report to another process the successful start

internal/logbuffer.go

@@ -0,0 +1,72 @@
+// Copyright 2015 Matthew Holt and The Caddy Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package internal
+
+import (
+	"sync"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+// LogBufferCore is a zapcore.Core that buffers log entries in memory.
+type LogBufferCore struct {
+	mu      sync.Mutex
+	entries []zapcore.Entry
+	fields  [][]zapcore.Field
+	level   zapcore.LevelEnabler
+}
+
+func NewLogBufferCore(level zapcore.LevelEnabler) *LogBufferCore {
+	return &LogBufferCore{
+		level: level,
+	}
+}
+
+func (c *LogBufferCore) Enabled(lvl zapcore.Level) bool {
+	return c.level.Enabled(lvl)
+}
+
+func (c *LogBufferCore) With(fields []zapcore.Field) zapcore.Core {
+	return c
+}
+
+func (c *LogBufferCore) Check(entry zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
+	if c.Enabled(entry.Level) {
+		return ce.AddCore(entry, c)
+	}
+	return ce
+}
+
+func (c *LogBufferCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	c.entries = append(c.entries, entry)
+	c.fields = append(c.fields, fields)
+	return nil
+}
+
+func (c *LogBufferCore) Sync() error { return nil }
+
+// FlushTo flushes buffered logs to the given zap.Logger.
+func (c *LogBufferCore) FlushTo(logger *zap.Logger) {
+	c.mu.Lock()
+	defer c.mu.Unlock()
+	for idx, entry := range c.entries {
+		logger.WithOptions().Check(entry.Level, entry.Message).Write(c.fields[idx]...)
+	}
+	c.entries = nil
+	c.fields = nil
+}

logging.go

@@ -28,6 +28,8 @@ import (
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 	"golang.org/x/term"
+
+	"github.com/caddyserver/caddy/v2/internal"
 )
 
 func init() {
@@ -773,6 +775,21 @@ func Log() *zap.Logger {
 	return defaultLogger.logger
 }
 
+// BufferedLog sets the default logger to one that buffers
+// logs before a config is loaded.
+// Returns the buffered logger, the original default logger
+// (for flushing on errors), and the buffer core so that the
+// caller can flush the logs after the config is loaded or
+// fails to load.
+func BufferedLog() (*zap.Logger, *zap.Logger, *internal.LogBufferCore) {
+	defaultLoggerMu.Lock()
+	defer defaultLoggerMu.Unlock()
+	origLogger := defaultLogger.logger
+	bufferCore := internal.NewLogBufferCore(zap.InfoLevel)
+	defaultLogger.logger = zap.New(bufferCore)
+	return defaultLogger.logger, origLogger, bufferCore
+}
+
 var (
 	coloringEnabled  = os.Getenv("NO_COLOR") == "" && os.Getenv("TERM") != "xterm-mono"
 	defaultLogger, _ = newDefaultProductionLog()