cmd: unbuffer default logger on startup failure (#8180)

* cmd: unbuffer default logger on startup failure

Restore default logger to unbuffered console logger on cmdRun error so WrapCommandFuncForCobra can output the error.

* add regression tests

cmd/commandfuncs.go

@@ -193,9 +193,9 @@ func cmdRun(fl Flags) (int, error) {
 	// 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()
+	// configured output.
+	logger, defaultLogger, _ := caddy.BufferedLog()
+	defer caddy.UnbufferDefaultLogger(defaultLogger)
 
 	undoMaxProcs := setResourceLimits(logger)
 	defer undoMaxProcs()
@@ -214,7 +214,6 @@ 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
 	}
 
@@ -232,7 +231,6 @@ 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 == "" {
@@ -252,7 +250,6 @@ func cmdRun(fl Flags) (int, error) {
 	if !resumeFlag {
 		config, configFile, adapterUsed, err = LoadConfig(configFlag, configAdapterFlag)
 		if err != nil {
-			logBuffer.FlushTo(defaultLogger)
 			return caddy.ExitCodeFailedStartup, err
 		}
 	}
@@ -283,7 +280,6 @@ 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)
 	}
 	// release the reference to the config so it can be GC'd
@@ -295,7 +291,6 @@ func cmdRun(fl Flags) (int, error) {
 	// also clear our ref to the buffer so it can get GC'd
 	logger = caddy.Log()
 	defaultLogger = nil //nolint:ineffassign,wastedassign
-	logBuffer = nil     //nolint:wastedassign,ineffassign
 	logger.Info("serving initial configuration")
 
 	// if we are to report to another process the successful start

cmd/commands_test.go

@@ -11,10 +11,12 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/spf13/cobra"
 	"github.com/spf13/pflag"
 
 	"github.com/caddyserver/caddy/v2"
 	"github.com/caddyserver/caddy/v2/caddyconfig/caddyfile"
+	"github.com/caddyserver/caddy/v2/internal"
 )
 
 // newFmtFlags builds a Flags value wired up the same way the fmt cobra command does.
@@ -309,3 +311,56 @@ func TestCommandsAreAvailable(t *testing.T) {
 		t.Errorf("expected %v, got %v", expectedCommandNames, commandNames)
 	}
 }
+
+func TestCmdRun_UnbufferOnFailure(t *testing.T) {
+	fs := pflag.NewFlagSet("run", pflag.ContinueOnError)
+	fs.StringP("config", "c", "", "")
+	fs.StringP("adapter", "a", "", "")
+	fs.BoolP("resume", "r", false, "")
+	fs.BoolP("environ", "e", false, "")
+	fs.BoolP("watch", "w", false, "")
+	fs.String("pidfile", "", "")
+	fs.String("pingback", "", "")
+	fs.StringSlice("envfile", nil, "")
+	_ = fs.Set("config", filepath.Join(t.TempDir(), "nonexistent"))
+
+	code, err := cmdRun(Flags{fs})
+	if err == nil {
+		t.Fatal("expected error from cmdRun with nonexistent config, got nil")
+	}
+	if code != caddy.ExitCodeFailedStartup {
+		t.Errorf("expected exit code %d, got %d", caddy.ExitCodeFailedStartup, code)
+	}
+
+	// Regression test for #8180: caddy.Log() must not remain buffered after cmdRun failure
+	if _, ok := caddy.Log().Core().(internal.LogBufferCoreInterface); ok {
+		t.Error("caddy.Log() was left in a buffered state after cmdRun failed; should be unbuffered")
+	}
+}
+
+func TestWrapCommandFuncForCobra_RunFailure(t *testing.T) {
+	fs := pflag.NewFlagSet("run", pflag.ContinueOnError)
+	fs.StringP("config", "c", "", "")
+	fs.StringP("adapter", "a", "", "")
+	fs.BoolP("resume", "r", false, "")
+	fs.BoolP("environ", "e", false, "")
+	fs.BoolP("watch", "w", false, "")
+	fs.String("pidfile", "", "")
+	fs.String("pingback", "", "")
+	fs.StringSlice("envfile", nil, "")
+	_ = fs.Set("config", filepath.Join(t.TempDir(), "nonexistent"))
+
+	cmd := &cobra.Command{Use: "run"}
+	cmd.Flags().AddFlagSet(fs)
+
+	runE := WrapCommandFuncForCobra(cmdRun)
+	err := runE(cmd, nil)
+	if err == nil {
+		t.Fatal("expected error from wrapped cmdRun, got nil")
+	}
+
+	// Regression test for #8180: caddy.Log() must not remain buffered after WrapCommandFuncForCobra
+	if _, ok := caddy.Log().Core().(internal.LogBufferCoreInterface); ok {
+		t.Error("caddy.Log() was left in a buffered state after WrapCommandFuncForCobra; should be unbuffered")
+	}
+}

logging.go

@@ -797,6 +797,19 @@ func BufferedLog() (*zap.Logger, *zap.Logger, *internal.LogBufferCore) {
 	return defaultLogger.logger, origLogger, bufferCore
 }
 
+// UnbufferDefaultLogger restores the default logger's underlying zap.Logger to orig
+// if the default logger is still pointing to a buffer core, flushing any remaining buffered logs.
+func UnbufferDefaultLogger(orig *zap.Logger) {
+	defaultLoggerMu.Lock()
+	defer defaultLoggerMu.Unlock()
+	if defaultLogger != nil && defaultLogger.logger != nil {
+		if bufferCore, ok := defaultLogger.logger.Core().(*internal.LogBufferCore); ok {
+			bufferCore.FlushTo(orig)
+			defaultLogger.logger = orig
+		}
+	}
+}
+
 var (
 	coloringEnabled  = os.Getenv("NO_COLOR") == "" && os.Getenv("TERM") != "xterm-mono"
 	defaultLogger, _ = newDefaultProductionLog()

logging_test.go

@@ -14,7 +14,16 @@
 
 package caddy
 
-import "testing"
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/caddyserver/caddy/v2/internal"
+)
 
 func TestCustomLog_loggerAllowed(t *testing.T) {
 	type fields struct {
@@ -104,3 +113,71 @@ func TestCustomLog_loggerAllowed(t *testing.T) {
 		})
 	}
 }
+
+func TestUnbufferDefaultLogger(t *testing.T) {
+	defaultLoggerMu.RLock()
+	origDefault := defaultLogger
+	defaultLoggerMu.RUnlock()
+	t.Cleanup(func() {
+		defaultLoggerMu.Lock()
+		defaultLogger = origDefault
+		defaultLoggerMu.Unlock()
+	})
+
+	// Set up an observing logger to verify buffer flushing and post-unbuffer logging
+	buf := new(bytes.Buffer)
+	destCore := zapcore.NewCore(
+		zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
+		zapcore.AddSync(buf),
+		zapcore.InfoLevel,
+	)
+	destLogger := zap.New(destCore)
+
+	defaultLoggerMu.Lock()
+	defaultLogger = &defaultCustomLog{
+		CustomLog: &CustomLog{},
+		logger:    destLogger,
+	}
+	defaultLoggerMu.Unlock()
+
+	// 1. Engage buffered logging
+	bufferedLogger, origLogger, _ := BufferedLog()
+
+	// Verify default logger is now using the buffer core
+	if _, ok := Log().Core().(*internal.LogBufferCore); !ok {
+		t.Fatal("expected default logger core to be *internal.LogBufferCore")
+	}
+
+	// 2. Log while buffered
+	bufferedLogger.Info("early startup log message")
+
+	// Messages should not be written to destination yet while buffered
+	if buf.Len() > 0 {
+		t.Fatalf("expected destination buffer to be empty while buffered, got: %s", buf.String())
+	}
+
+	// 3. Unbuffer the default logger
+	UnbufferDefaultLogger(origLogger)
+
+	// Verify default logger core is no longer LogBufferCore
+	if _, ok := Log().Core().(*internal.LogBufferCore); ok {
+		t.Fatal("expected default logger core to no longer be *internal.LogBufferCore after UnbufferDefaultLogger")
+	}
+
+	// Verify early buffered logs were flushed to destination logger
+	if !strings.Contains(buf.String(), "early startup log message") {
+		t.Fatalf("expected destination buffer to contain early startup log message, got: %s", buf.String())
+	}
+
+	// 4. Log after unbuffering: should go directly to destination logger, not swallowed
+	Log().Error("startup failed error")
+	if !strings.Contains(buf.String(), "startup failed error") {
+		t.Fatalf("expected destination buffer to contain error message, got: %s", buf.String())
+	}
+
+	// 5. Calling UnbufferDefaultLogger again when not buffered should be a safe no-op
+	UnbufferDefaultLogger(origLogger)
+	if _, ok := Log().Core().(*internal.LogBufferCore); ok {
+		t.Fatal("unexpected buffer core after second unbuffer call")
+	}
+}