diff --git a/cmd/commandfuncs.go b/cmd/commandfuncs.go index 0718f84a8..5f3a455ca 100644 --- a/cmd/commandfuncs.go +++ b/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 diff --git a/cmd/commands_test.go b/cmd/commands_test.go index f4d215860..b2446a661 100644 --- a/cmd/commands_test.go +++ b/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") + } +} diff --git a/logging.go b/logging.go index 2734b5425..341944947 100644 --- a/logging.go +++ b/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() diff --git a/logging_test.go b/logging_test.go index 293591fbb..960e9131f 100644 --- a/logging_test.go +++ b/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") + } +}