logger, config: setup logging after reading the config file (#856)

Co-authored-by: djshow832 <[email protected]>

Author: dveeden

pkg/manager/config/config.go

@@ -11,7 +11,6 @@ import (
 	"github.com/BurntSushi/toml"
 	"github.com/pingcap/tiproxy/lib/config"
 	"github.com/pingcap/tiproxy/lib/util/errors"
-	"go.uber.org/zap"
 )
 
 func (e *ConfigManager) reloadConfigFile(file string) error {
@@ -68,7 +67,6 @@ func (e *ConfigManager) SetTOMLConfig(data []byte) (err error) {
 	if originalData == nil || !bytes.Equal(originalData, newData) {
 		e.sts.checksum = crc32.ChecksumIEEE(newData)
 		e.sts.data = newData
-		e.logger.Info("current config", zap.Any("cfg", e.sts.current))
 		for _, list := range e.sts.listeners {
 			list <- base.Clone()
 		}

pkg/manager/config/config_test.go

@@ -7,7 +7,6 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
-	"strings"
 	"testing"
 	"time"
 
@@ -299,19 +298,19 @@ func TestFilePath(t *testing.T) {
 }
 
 func TestChecksum(t *testing.T) {
-	cfgmgr, text, _ := testConfigManager(t, "", "")
-	require.Equal(t, 1, strings.Count(text.String(), "current config"))
+	cfgmgr, _, _ := testConfigManager(t, "", "")
+
 	c1 := cfgmgr.GetConfigChecksum()
 	require.NoError(t, cfgmgr.SetTOMLConfig([]byte(`proxy.addr = "gg"`)))
-	require.Equal(t, 2, strings.Count(text.String(), "current config"))
 	// same config, shouldn't log it again
 	require.NoError(t, cfgmgr.SetTOMLConfig([]byte(`proxy.addr = "gg"`)))
-	require.Equal(t, 2, strings.Count(text.String(), "current config"))
+
 	c2 := cfgmgr.GetConfigChecksum()
 	require.NoError(t, cfgmgr.SetTOMLConfig([]byte(`proxy.addr = "vv"`)))
+
 	c3 := cfgmgr.GetConfigChecksum()
 	require.NoError(t, cfgmgr.SetTOMLConfig([]byte(`proxy.addr="gg"`)))
-	require.Equal(t, 4, strings.Count(text.String(), "current config"))
+
 	c4 := cfgmgr.GetConfigChecksum()
 	require.Equal(t, c2, c4)
 	require.NotEqual(t, c1, c2)

pkg/manager/config/manager.go

@@ -5,14 +5,15 @@ package config
 
 import (
 	"context"
+	"fmt"
+	"os"
 	"sync"
 	"time"
 
 	"github.com/pingcap/tiproxy/lib/config"
 	"github.com/pingcap/tiproxy/lib/util/errors"
 	"github.com/pingcap/tiproxy/pkg/util/waitgroup"
 	"github.com/tidwall/btree"
-	"go.uber.org/zap"
 )
 
 const (
@@ -24,9 +25,7 @@ const (
 	checkFileInterval = 2 * time.Second
 )
 
-var (
-	ErrNoResults = errors.Errorf("has no results")
-)
+var ErrNoResults = errors.Errorf("has no results")
 
 type KVValue struct {
 	Key   string
@@ -36,7 +35,6 @@ type KVValue struct {
 type ConfigManager struct {
 	wg            waitgroup.WaitGroup
 	cancel        context.CancelFunc
-	logger        *zap.Logger
 	advertiseAddr string
 
 	kv *btree.BTreeG[KVValue]
@@ -58,11 +56,10 @@ func NewConfigManager() *ConfigManager {
 	}
 }
 
-func (e *ConfigManager) Init(ctx context.Context, logger *zap.Logger, configFile string, advertiseAddr string) error {
+func (e *ConfigManager) Init(ctx context.Context, configFile string, advertiseAddr string) error {
 	var nctx context.Context
 	nctx, e.cancel = context.WithCancel(ctx)
 
-	e.logger = logger
 	e.advertiseAddr = advertiseAddr
 
 	// for namespace persistence
@@ -89,11 +86,11 @@ func (e *ConfigManager) Init(ctx context.Context, logger *zap.Logger, configFile
 					return
 				case <-ticker.C:
 					if err := e.reloadConfigFile(configFile); err != nil {
-						e.logger.Warn("failed to reload file", zap.String("file", configFile), zap.Error(err))
+						fmt.Fprintf(os.Stderr, "failed to reload file %s: %v", configFile, err)
 					}
 				}
 			}
-		}, nil, e.logger)
+		}, nil, nil)
 	} else {
 		if err := e.SetTOMLConfig(nil); err != nil {
 			return err

pkg/manager/config/manager_test.go

@@ -14,7 +14,7 @@ import (
 )
 
 func testConfigManager(t *testing.T, configFile string, advertiseAddr string) (*ConfigManager, fmt.Stringer, context.Context) {
-	logger, text := logger.CreateLoggerForTest(t)
+	_, text := logger.CreateLoggerForTest(t)
 
 	ctx, cancel := context.WithCancel(context.Background())
 	if ddl, ok := t.Deadline(); ok {
@@ -23,7 +23,7 @@ func testConfigManager(t *testing.T, configFile string, advertiseAddr string) (*
 
 	cfgmgr := NewConfigManager()
 	cfgmgr.checkFileInterval = 20 * time.Millisecond
-	require.NoError(t, cfgmgr.Init(ctx, logger, configFile, advertiseAddr))
+	require.NoError(t, cfgmgr.Init(ctx, configFile, advertiseAddr))
 
 	t.Cleanup(func() {
 		require.NoError(t, cfgmgr.Close())

pkg/manager/logger/manager.go

@@ -77,6 +77,7 @@ func (lm *LoggerManager) watchCfg(ctx context.Context, cfgch <-chan *config.Conf
 					zap.NamedError("cfg marshal error", merr),
 				)
 			}
+			lm.logger.Info("current config", zap.Any("cfg", acfg))
 		}
 	}
 }

pkg/manager/logger/manager_test.go

@@ -60,13 +60,15 @@ func TestUpdateCfg(t *testing.T) {
 		},
 		{
 			updateCfg: func(cfg *config.LogOnline) {
+				// Filter the logs in LoggerManager.watchCfg().
+				cfg.Level = "warn"
 				cfg.LogFile.MaxSize = 3
 				cfg.LogFile.MaxBackups = 5
 			},
 			action: func(log *zap.Logger) {
 				for range 5 {
 					msg := strings.Repeat("a", 500*1024)
-					log.Info(msg)
+					log.Warn(msg)
 				}
 			},
 			check: func(files []os.FileInfo) bool {
@@ -103,10 +105,15 @@ func TestUpdateCfg(t *testing.T) {
 		},
 	}
 
-	lg, ch := setupLogManager(t, cfg)
-	// Make sure the latest config also applies to cloned loggers.
-	lg = lg.Named("another").With(zap.String("field", "test_field"))
 	for i, test := range tests {
+		require.NoError(t, os.RemoveAll(dir))
+
+		lm, lg, err := NewLoggerManager(&cfg.Log)
+		require.NoError(t, err)
+		ch := make(chan *config.Config)
+		lm.Init(ch)
+		// Make sure the latest config also applies to cloned loggers.
+		lg = lg.Named("another").With(zap.String("field", "test_field"))
 		require.NoError(t, lg.Sync())
 
 		clonedCfg := cfg.Clone()
@@ -117,10 +124,6 @@ func TestUpdateCfg(t *testing.T) {
 		// this ensured all old data are flushed by closing the older file logger
 		ch <- clonedCfg
 
-		// delete old data after flushed
-		err := os.RemoveAll(dir)
-		require.NoError(t, err)
-
 		// write new data
 		test.action(lg)
 
@@ -148,6 +151,7 @@ func TestUpdateCfg(t *testing.T) {
 			}
 		}
 		timer.Stop()
+		require.NoError(t, lm.Close())
 	}
 }
 

pkg/server/api/server_test.go

@@ -31,7 +31,7 @@ func createServer(t *testing.T) (*Server, doHTTPFunc) {
 	lg, _ := logger.CreateLoggerForTest(t)
 	ready := atomic.NewBool(true)
 	cfgmgr := mgrcfg.NewConfigManager()
-	require.NoError(t, cfgmgr.Init(context.Background(), lg, "", ""))
+	require.NoError(t, cfgmgr.Init(context.Background(), "", ""))
 	crtmgr := mgrcrt.NewCertManager()
 	require.NoError(t, crtmgr.Init(cfgmgr.GetConfig(), lg, cfgmgr.WatchConfig()))
 	nsMgr := newMockNamespaceManager()

pkg/server/server.go

@@ -70,18 +70,18 @@ func NewServer(ctx context.Context, sctx *sctx.Context) (srv *Server, err error)
 	handler := sctx.Handler
 	ready := atomic.NewBool(false)
 
-	// set up logger
-	var lg *zap.Logger
-	if srv.loggerManager, lg, err = logger.NewLoggerManager(nil); err != nil {
+	// setup config manager
+	if err = srv.configManager.Init(ctx, sctx.ConfigFile, sctx.AdvertiseAddr); err != nil {
 		return
 	}
-	srv.loggerManager.Init(srv.configManager.WatchConfig())
+	cfg := srv.configManager.GetConfig()
 
-	// setup config manager
-	if err = srv.configManager.Init(ctx, lg.Named("config"), sctx.ConfigFile, sctx.AdvertiseAddr); err != nil {
+	// set up logger
+	var lg *zap.Logger
+	if srv.loggerManager, lg, err = logger.NewLoggerManager(&cfg.Log); err != nil {
 		return
 	}
-	cfg := srv.configManager.GetConfig()
+	srv.loggerManager.Init(srv.configManager.WatchConfig())
 
 	// welcome messages must be printed after initialization of configmager, because
 	// logfile backended zaplogger is enabled after cfgmgr.Init(..).
@@ -92,7 +92,7 @@ func NewServer(ctx context.Context, sctx *sctx.Context) (srv *Server, err error)
 	// Make sure the TiProxy info is always printed.
 	level := lg.Level()
 	srv.loggerManager.SetLoggerLevel(zap.InfoLevel)
-	printInfo(lg)
+	printInfo(lg, cfg)
 	srv.loggerManager.SetLoggerLevel(level)
 
 	// setup metrics
@@ -224,7 +224,7 @@ func NewServer(ctx context.Context, sctx *sctx.Context) (srv *Server, err error)
 	return
 }
 
-func printInfo(lg *zap.Logger) {
+func printInfo(lg *zap.Logger, cfg *config.Config) {
 	fields := []zap.Field{
 		zap.String("Release Version", versioninfo.TiProxyVersion),
 		zap.String("Git Commit Hash", versioninfo.TiProxyGitHash),
@@ -235,6 +235,7 @@ func printInfo(lg *zap.Logger) {
 		zap.String("Arch", runtime.GOARCH),
 	}
 	lg.Info("Welcome to TiProxy.", fields...)
+	lg.Info("current config", zap.Any("cfg", cfg))
 }
 
 func (s *Server) preClose() {