Automatically track subloggers in allLoggers

changelog/22038.txt

@@ -0,0 +1,3 @@
+```release-note:bug
+core: All subloggers now reflect configured log level on reload.
+```

command/server.go

@@ -40,6 +40,7 @@ import (
 	"github.com/hashicorp/vault/helper/builtinplugins"
 	"github.com/hashicorp/vault/helper/constants"
 	"github.com/hashicorp/vault/helper/experiments"
+	"github.com/hashicorp/vault/helper/logging"
 	loghelper "github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/helper/metricsutil"
 	"github.com/hashicorp/vault/helper/namespace"
@@ -120,6 +121,7 @@ type ServerCommand struct {
 	licenseReloadedCh chan (error)    // for tests
 
 	allLoggers []hclog.Logger
+	logging.SubloggerAdder
 
 	flagConfigs            []string
 	flagRecovery           bool
@@ -441,6 +443,26 @@ func (c *ServerCommand) parseConfig() (*server.Config, []configutil.ConfigError,
 	return config, configErrors, nil
 }
 
+// AppendToAllLoggers is registered with the base logger to handle creation of
+// new subloggers through the phases of server startup. There are three phases
+// we need to handle: (1) Before CoreConfig is created, new subloggers are added
+// to c.allLoggers; (2) After CoreConfig is created, new subloggers are added to
+// CoreConfig.AllLoggers; (3) After Core instantiation, new subloggers are
+// appended to Core.allLoggers. This logic is managed by the SubloggerAdder
+// interface.
+//
+// NOTE: Core.allLoggers must be set to CoreConfig.allLoggers after NewCore to
+// keep track of new subloggers added before c.SubloggerAdder gets reassigned to
+// the Core implementation.
+func (c *ServerCommand) AppendToAllLoggers(sub hclog.Logger) hclog.Logger {
+	if c.SubloggerAdder == nil {
+		c.allLoggers = append(c.allLoggers, sub)
+		return sub
+	}
+
+	return c.SubloggerHook(sub)
+}
+
 func (c *ServerCommand) runRecoveryMode() int {
 	config, configErrors, err := c.parseConfig()
 	if err != nil {
@@ -586,6 +608,7 @@ func (c *ServerCommand) runRecoveryMode() int {
 		DisableMlock: config.DisableMlock,
 		RecoveryMode: c.flagRecovery,
 		ClusterAddr:  config.ClusterAddr,
+		AllLoggers:   c.allLoggers,
 	}
 
 	core, newCoreError := vault.NewCore(coreConfig)
@@ -809,7 +832,6 @@ func (c *ServerCommand) setupStorage(config *server.Config) (physical.Backend, e
 	}
 
 	namedStorageLogger := c.logger.Named("storage." + config.Storage.Type)
-	c.allLoggers = append(c.allLoggers, namedStorageLogger)
 	backend, err := factory(config.Storage.Config, namedStorageLogger)
 	if err != nil {
 		return nil, fmt.Errorf("Error initializing storage of type %s: %w", config.Storage.Type, err)
@@ -825,7 +847,6 @@ func beginServiceRegistration(c *ServerCommand, config *server.Config) (sr.Servi
 	}
 
 	namedSDLogger := c.logger.Named("service_registration." + config.ServiceRegistration.Type)
-	c.allLoggers = append(c.allLoggers, namedSDLogger)
 
 	// Since we haven't even begun starting Vault's core yet,
 	// we know that Vault is in its pre-running state.
@@ -1104,7 +1125,6 @@ func (c *ServerCommand) Run(args []string) int {
 
 	// create GRPC logger
 	namedGRPCLogFaker := c.logger.Named("grpclogfaker")
-	c.allLoggers = append(c.allLoggers, namedGRPCLogFaker)
 	grpclog.SetLogger(&grpclogFaker{
 		logger: namedGRPCLogFaker,
 		log:    os.Getenv("VAULT_GRPC_LOGGING") != "",
@@ -1257,6 +1277,10 @@ func (c *ServerCommand) Run(args []string) int {
 		return c.enableThreeNodeDevCluster(&coreConfig, info, infoKeys, c.flagDevListenAddr, os.Getenv("VAULT_DEV_TEMP_DIR"))
 	}
 
+	// Keep track of new subloggers in coreConfig.AllLoggers until we hand it
+	// off to core
+	c.SubloggerAdder = &coreConfig
+
 	if c.flagDevFourCluster {
 		return enableFourClusterDev(c, &coreConfig, info, infoKeys, c.flagDevListenAddr, os.Getenv("VAULT_DEV_TEMP_DIR"))
 	}
@@ -1344,6 +1368,10 @@ func (c *ServerCommand) Run(args []string) int {
 
 	}
 
+	// Now we can use the core SubloggerHook to add any new subloggers to
+	// core.allLoggers
+	c.SubloggerAdder = core
+
 	// Copy the reload funcs pointers back
 	c.reloadFuncs = coreConfig.ReloadFuncs
 	c.reloadFuncsLock = coreConfig.ReloadFuncsLock
@@ -1820,6 +1848,7 @@ func (c *ServerCommand) configureLogging(config *server.Config) (hclog.Intercept
 		LogRotateDuration: logRotateDuration,
 		LogRotateBytes:    config.LogRotateBytes,
 		LogRotateMaxFiles: config.LogRotateMaxFiles,
+		SubloggerHook:     c.AppendToAllLoggers,
 	}
 
 	return loghelper.Setup(logCfg, c.logWriter)
@@ -2527,7 +2556,6 @@ func setSeal(c *ServerCommand, config *server.Config, infoKeys []string, info ma
 
 		var seal vault.Seal
 		sealLogger := c.logger.ResetNamed(fmt.Sprintf("seal.%s", sealType))
-		c.allLoggers = append(c.allLoggers, sealLogger)
 		defaultSeal := vault.NewDefaultSeal(vaultseal.NewAccess(aeadwrapper.NewShamirWrapper()))
 		var sealInfoKeys []string
 		sealInfoMap := map[string]string{}
@@ -2582,7 +2610,6 @@ func initHaBackend(c *ServerCommand, config *server.Config, coreConfig *vault.Co
 		}
 
 		namedHALogger := c.logger.Named("ha." + config.HAStorage.Type)
-		c.allLoggers = append(c.allLoggers, namedHALogger)
 		habackend, err := factory(config.HAStorage.Config, namedHALogger)
 		if err != nil {
 			return false, fmt.Errorf("Error initializing HA storage of type %s: %s", config.HAStorage.Type, err)

helper/logging/logger.go

@@ -48,6 +48,17 @@ type LogConfig struct {
 
 	// LogRotateMaxFiles is the maximum number of past archived log files to keep
 	LogRotateMaxFiles int
+
+	// SubloggerHook handles creation of new subloggers, automatically appending
+	// them to core's running list of allLoggers.
+	// see: server.AppendToAllLoggers for more details.
+	SubloggerHook func(log.Logger) log.Logger
+}
+
+// SubloggerAdder is an interface which facilitates tracking of new subloggers
+// added between phases of server startup.
+type SubloggerAdder interface {
+	SubloggerHook(logger log.Logger) log.Logger
 }
 
 func (c *LogConfig) isLevelInvalid() bool {
@@ -148,6 +159,7 @@ func Setup(config *LogConfig, w io.Writer) (log.InterceptLogger, error) {
 		IndependentLevels: true,
 		Output:            io.MultiWriter(writers...),
 		JSONFormat:        config.isFormatJson(),
+		SubloggerHook:     config.SubloggerHook,
 	})
 
 	return logger, nil

helper/testhelpers/corehelpers/corehelpers.go

@@ -20,6 +20,7 @@ import (
 	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/vault/audit"
 	"github.com/hashicorp/vault/builtin/credential/approle"
+	"github.com/hashicorp/vault/helper/logging"
 	"github.com/hashicorp/vault/plugins/database/mysql"
 	"github.com/hashicorp/vault/sdk/framework"
 	"github.com/hashicorp/vault/sdk/helper/consts"
@@ -418,6 +419,32 @@ type TestLogger struct {
 	Path string
 	File *os.File
 	sink hclog.SinkAdapter
+	// For managing temporary start-up state
+	sync.RWMutex
+	AllLoggers []hclog.Logger
+	logging.SubloggerAdder
+}
+
+// RegisterSubloggerAdder checks to see if the provided logger interface is a
+// TestLogger and re-assigns the SubloggerHook implementation if so.
+func RegisterSubloggerAdder(logger hclog.Logger, adder logging.SubloggerAdder) {
+	if l, ok := logger.(*TestLogger); ok {
+		l.Lock()
+		l.SubloggerAdder = adder
+		l.Unlock()
+	}
+}
+
+// AppendToAllLoggers appends the sub logger to allLoggers, or if the TestLogger
+// is assigned to a SubloggerAdder implementation, it calls the underlying hook.
+func (l *TestLogger) AppendToAllLoggers(sub hclog.Logger) hclog.Logger {
+	l.Lock()
+	defer l.Unlock()
+	if l.SubloggerAdder == nil {
+		l.AllLoggers = append(l.AllLoggers, sub)
+		return sub
+	}
+	return l.SubloggerHook(sub)
 }
 
 func NewTestLogger(t testing.T) *TestLogger {
@@ -441,25 +468,31 @@ func NewTestLogger(t testing.T) *TestLogger {
 		output = logFile
 	}
 
+	sink := hclog.NewSinkAdapter(&hclog.LoggerOptions{
+		Output:            output,
+		Level:             hclog.Trace,
+		IndependentLevels: true,
+	})
+
+	testLogger := &TestLogger{
+		Path: logPath,
+		File: logFile,
+		sink: sink,
+	}
+
 	// We send nothing on the regular logger, that way we can later deregister
 	// the sink to stop logging during cluster cleanup.
 	logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{
 		Output:            io.Discard,
 		IndependentLevels: true,
 		Name:              t.Name(),
+		SubloggerHook:     testLogger.AppendToAllLoggers,
 	})
-	sink := hclog.NewSinkAdapter(&hclog.LoggerOptions{
-		Output:            output,
-		Level:             hclog.Trace,
-		IndependentLevels: true,
-	})
+
 	logger.RegisterSink(sink)
-	return &TestLogger{
-		Path:            logPath,
-		File:            logFile,
-		InterceptLogger: logger,
-		sink:            sink,
-	}
+	testLogger.InterceptLogger = logger
+
+	return testLogger
 }
 
 func (tl *TestLogger) StopLogging() {

vault/activity_log.go

@@ -1104,7 +1104,6 @@ func (c *Core) setupActivityLog(ctx context.Context, wg *sync.WaitGroup) error {
 // this function should be called with activityLogLock.
 func (c *Core) setupActivityLogLocked(ctx context.Context, wg *sync.WaitGroup) error {
 	logger := c.baseLogger.Named("activity")
-	c.AddLogger(logger)
 
 	if os.Getenv("VAULT_DISABLE_ACTIVITY_LOG") != "" {
 		if c.CensusLicensingEnabled() {

vault/audit.go

@@ -383,7 +383,6 @@ func (c *Core) persistAudit(ctx context.Context, table *MountTable, localOnly bo
 // initialize the audit backends
 func (c *Core) setupAudits(ctx context.Context) error {
 	brokerLogger := c.baseLogger.Named("audit")
-	c.AddLogger(brokerLogger)
 	broker, err := NewAuditBroker(brokerLogger, c.IsExperimentEnabled(experiments.VaultExperimentCoreAuditEventsAlpha1))
 	if err != nil {
 		return err
@@ -495,7 +494,6 @@ func (c *Core) newAuditBackend(ctx context.Context, entry *MountEntry, view logi
 	}
 
 	auditLogger := c.baseLogger.Named("audit")
-	c.AddLogger(auditLogger)
 
 	switch entry.Type {
 	case "file":

vault/auth.go

@@ -998,7 +998,6 @@ func (c *Core) newCredentialBackend(ctx context.Context, entry *MountEntry, sysV
 	conf["plugin_version"] = entry.Version
 
 	authLogger := c.baseLogger.Named(fmt.Sprintf("auth.%s.%s", t, entry.Accessor))
-	c.AddLogger(authLogger)
 	pluginEventSender, err := c.events.WithPlugin(entry.namespace, &logical.EventPluginInfo{
 		MountClass:    consts.PluginTypeCredential.String(),
 		MountAccessor: entry.Accessor,

vault/cluster.go

@@ -323,7 +323,6 @@ func (c *Core) startClusterListener(ctx context.Context) error {
 	if networkLayer == nil {
 		tcpLogger := c.logger.Named("cluster-listener.tcp")
 		networkLayer = cluster.NewTCPLayer(c.clusterListenerAddrs, tcpLogger)
-		c.AddLogger(tcpLogger)
 	}
 
 	listenerLogger := c.logger.Named("cluster-listener")
@@ -332,8 +331,6 @@ func (c *Core) startClusterListener(ctx context.Context) error {
 		listenerLogger,
 		5*c.clusterHeartbeatInterval))
 
-	c.AddLogger(listenerLogger)
-
 	err := c.getClusterListener().Run(ctx)
 	if err != nil {
 		return err

vault/core.go

@@ -854,6 +854,13 @@ type CoreConfig struct {
 	AdministrativeNamespacePath string
 }
 
+// SubloggerHook implements the SubloggerAdder interface. This implementation
+// manages CoreConfig.AllLoggers state prior to (and during) NewCore.
+func (c *CoreConfig) SubloggerHook(logger log.Logger) log.Logger {
+	c.AllLoggers = append(c.AllLoggers, logger)
+	return logger
+}
+
 // GetServiceRegistration returns the config's ServiceRegistration, or nil if it does
 // not exist.
 func (c *CoreConfig) GetServiceRegistration() sr.ServiceRegistration {
@@ -1024,10 +1031,7 @@ func CreateCore(conf *CoreConfig) (*Core, error) {
 
 	c.shutdownDoneCh.Store(make(chan struct{}))
 
-	c.allLoggers = append(c.allLoggers, c.logger)
-
 	c.router.logger = c.logger.Named("router")
-	c.allLoggers = append(c.allLoggers, c.router.logger)
 
 	c.inFlightReqData = &InFlightRequests{
 		InFlightReqMap:   &sync.Map{},
@@ -1105,7 +1109,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 	if err != nil {
 		return nil, err
 	}
-
 	if err = coreInit(c, conf); err != nil {
 		return nil, err
 	}
@@ -1176,10 +1179,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 
 	c.loginMFABackend = NewLoginMFABackend(c, conf.Logger)
 
-	if c.loginMFABackend.mfaLogger != nil {
-		c.AddLogger(c.loginMFABackend.mfaLogger)
-	}
-
 	logicalBackends := make(map[string]logical.Factory)
 	for k, f := range conf.LogicalBackends {
 		logicalBackends[k] = f
@@ -1192,7 +1191,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 	logicalBackends["cubbyhole"] = CubbyholeBackendFactory
 	logicalBackends[systemMountType] = func(ctx context.Context, config *logical.BackendConfig) (logical.Backend, error) {
 		sysBackendLogger := conf.Logger.Named("system")
-		c.AddLogger(sysBackendLogger)
 		b := NewSystemBackend(c, sysBackendLogger)
 		if err := b.Setup(ctx, config); err != nil {
 			return nil, err
@@ -1201,7 +1199,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 	}
 	logicalBackends["identity"] = func(ctx context.Context, config *logical.BackendConfig) (logical.Backend, error) {
 		identityLogger := conf.Logger.Named("identity")
-		c.AddLogger(identityLogger)
 		return NewIdentityStore(ctx, c, config, identityLogger)
 	}
 	addExtraLogicalBackends(c, logicalBackends, conf.AdministrativeNamespacePath)
@@ -1213,7 +1210,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 	}
 	credentialBackends["token"] = func(ctx context.Context, config *logical.BackendConfig) (logical.Backend, error) {
 		tsLogger := conf.Logger.Named("token")
-		c.AddLogger(tsLogger)
 		return NewTokenStore(ctx, tsLogger, c, config)
 	}
 	addExtraCredentialBackends(c, credentialBackends)
@@ -1251,7 +1247,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 	}
 
 	quotasLogger := conf.Logger.Named("quotas")
-	c.allLoggers = append(c.allLoggers, quotasLogger)
 	c.quotaManager, err = quotas.NewManager(quotasLogger, c.quotaLeaseWalker, c.metricSink)
 	if err != nil {
 		return nil, err
@@ -1269,7 +1264,6 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 
 	// start the event system
 	eventsLogger := conf.Logger.Named("events")
-	c.allLoggers = append(c.allLoggers, eventsLogger)
 	events, err := eventbus.NewEventBus(eventsLogger)
 	if err != nil {
 		return nil, err
@@ -1279,6 +1273,10 @@ func NewCore(conf *CoreConfig) (*Core, error) {
 		c.events.Start()
 	}
 
+	// Make sure we're keeping track of the subloggers added above. We haven't
+	// yet registered core to the server command's SubloggerAdder, so any new
+	// subloggers will be in conf.AllLoggers.
+	c.allLoggers = conf.AllLoggers
 	return c, nil
 }
 
@@ -3041,6 +3039,14 @@ func (c *Core) AddLogger(logger log.Logger) {
 	c.allLoggers = append(c.allLoggers, logger)
 }
 
+// SubloggerHook implements the SubloggerAdder interface. We add this method to
+// the server command after NewCore returns with a Core object. The hook keeps
+// track of newly added subloggers without manual calls to c.AddLogger.
+func (c *Core) SubloggerHook(logger log.Logger) log.Logger {
+	c.AddLogger(logger)
+	return logger
+}
+
 // SetLogLevel sets logging level for all tracked loggers to the level provided
 func (c *Core) SetLogLevel(level log.Level) {
 	c.allLoggersLock.RLock()