Fix logger not respecting updated level (#2456)

Fix logger not respecting updated level (#2456)

changelog/fragments/1680764383-Respecting-logging.level-settings.yaml

@@ -0,0 +1,31 @@
+# Kind can be one of:
+# - breaking-change: a change to previously-documented behavior
+# - deprecation: functionality that is being removed in a later release
+# - bug-fix: fixes a problem in a previous version
+# - enhancement: extends functionality but does not break or fix existing behavior
+# - feature: new functionality
+# - known-issue: problems that we are aware of in a given version
+# - security: impacts on the security of a product or a user’s deployment.
+# - upgrade: important information for someone upgrading from a prior version
+# - other: does not fit into any of the other categories
+kind: bug-fix
+
+# Change summary; a 80ish characters long description of the change.
+summary: Respecting logging.level settings coming whether from Fleet UI or config file.
+
+# Long description; in case the summary is not enough to describe the change
+# this field accommodate a description without length limits.
+#description:
+
+# Affected component; a word indicating the component this changeset affects.
+component: elastic-agent
+
+# PR number; optional; the PR number that added the changeset.
+# If not present is automatically filled by the tooling finding the PR where this changelog fragment has been added.
+# NOTE: the tooling supports backports, so it's able to fill the original PR number instead of the backport PR number.
+# Please provide it if you are adding a fragment for a different PR.
+pr: 2456
+
+# Issue number; optional; the GitHub issue related to this changeset (either closes or is part of).
+# If not present is automatically filled by the tooling with the issue linked to the PR number.
+issue: 2450

internal/pkg/agent/cmd/run.go

@@ -178,7 +178,7 @@ func run(override cfgOverrider, testingMode bool, modifiers ...component.Platfor
 		return errors.New(err, "error migrating agent state")
 	}
 
-	agentInfo, err := info.NewAgentInfoWithLog(defaultLogLevel(cfg), createAgentID)
+	agentInfo, err := info.NewAgentInfoWithLog(defaultLogLevel(cfg, logLvl.String()), createAgentID)
 	if err != nil {
 		return errors.New(err,
 			"could not load agent info",
@@ -399,10 +399,10 @@ func getOverwrites(rawConfig *config.Config) error {
 	return nil
 }
 
-func defaultLogLevel(cfg *configuration.Configuration) string {
+func defaultLogLevel(cfg *configuration.Configuration, currentLevel string) string {
 	if configuration.IsStandalone(cfg.Fleet) {
 		// for standalone always take the one from config and don't override
-		return ""
+		return currentLevel
 	}
 
 	defaultLogLevel := logger.DefaultLogLevel.String()

internal/pkg/composable/providers/kubernetes/kubernetes.go

@@ -8,7 +8,6 @@ import (
 	"fmt"
 
 	"github.com/elastic/elastic-agent-autodiscover/kubernetes"
-	"github.com/elastic/elastic-agent-libs/logp"
 
 	k8s "k8s.io/client-go/kubernetes"
 
@@ -58,7 +57,7 @@ func DynamicProviderBuilder(logger *logger.Logger, c *config.Config, managed boo
 // Run runs the kubernetes context provider.
 func (p *dynamicProvider) Run(comm composable.DynamicProviderComm) error {
 	if p.config.Hints.Enabled {
-		betalogger := logp.NewLogger("cfgwarn")
+		betalogger := p.logger.Named("cfgwarn")
 		betalogger.Warnf("BETA: Hints' feature is beta.")
 	}
 	eventers := make([]Eventer, 0, 3)

internal/pkg/config/operations/inspector.go

@@ -7,7 +7,6 @@ package operations
 import (
 	"fmt"
 
-	"github.com/elastic/elastic-agent-libs/logp"
 	"github.com/elastic/elastic-agent/internal/pkg/agent/application/info"
 	"github.com/elastic/elastic-agent/internal/pkg/agent/application/paths"
 	"github.com/elastic/elastic-agent/internal/pkg/agent/configuration"
@@ -55,7 +54,7 @@ func LoadFullAgentConfig(logger *logger.Logger, cfgPath string, failOnFleetMissi
 		return c, nil
 	}
 
-	fleetConfig, err := loadFleetConfig()
+	fleetConfig, err := loadFleetConfig(logger)
 	if err != nil {
 		return nil, err
 	} else if fleetConfig == nil {
@@ -104,13 +103,8 @@ func loadConfig(configPath string) (*config.Config, error) {
 	return rawConfig, nil
 }
 
-func loadFleetConfig() (map[string]interface{}, error) {
-	log, err := newErrorLogger()
-	if err != nil {
-		return nil, err
-	}
-
-	stateStore, err := store.NewStateStoreWithMigration(log, paths.AgentActionStoreFile(), paths.AgentStateStoreFile())
+func loadFleetConfig(l *logger.Logger) (map[string]interface{}, error) {
+	stateStore, err := store.NewStateStoreWithMigration(l, paths.AgentActionStoreFile(), paths.AgentStateStoreFile())
 	if err != nil {
 		return nil, err
 	}
@@ -125,7 +119,3 @@ func loadFleetConfig() (map[string]interface{}, error) {
 	}
 	return nil, nil
 }
-
-func newErrorLogger() (*logger.Logger, error) {
-	return logger.NewWithLogpLevel("", logp.ErrorLevel, false)
-}

pkg/component/runtime/command.go

@@ -76,7 +76,7 @@ type CommandRuntime struct {
 }
 
 // NewCommandRuntime creates a new command runtime for the provided component.
-func NewCommandRuntime(comp component.Component, monitor MonitoringManager) (ComponentRuntime, error) {
+func NewCommandRuntime(comp component.Component, log *logger.Logger, monitor MonitoringManager) (ComponentRuntime, error) {
 	c := &CommandRuntime{
 		current:     comp,
 		monitor:     monitor,
@@ -92,9 +92,9 @@ func NewCommandRuntime(comp component.Component, monitor MonitoringManager) (Com
 		return nil, errors.New("must have command defined in specification")
 	}
 	ll, unitLevels := getLogLevels(comp)
-	c.logStd = createLogWriter(c.current, c.getCommandSpec(), c.getSpecType(), c.getSpecBinaryName(), ll, unitLevels, logSourceStdout)
+	c.logStd = createLogWriter(c.current, log, c.getCommandSpec(), c.getSpecType(), c.getSpecBinaryName(), ll, unitLevels, logSourceStdout)
 	ll, unitLevels = getLogLevels(comp) // don't want to share mapping of units (so new map is generated)
-	c.logErr = createLogWriter(c.current, c.getCommandSpec(), c.getSpecType(), c.getSpecBinaryName(), ll, unitLevels, logSourceStderr)
+	c.logErr = createLogWriter(c.current, log, c.getCommandSpec(), c.getSpecType(), c.getSpecBinaryName(), ll, unitLevels, logSourceStderr)
 
 	c.restartBucket = newRateLimiter(cmdSpec.RestartMonitoringPeriod, cmdSpec.MaxRestartsPerPeriod)
 
@@ -494,20 +494,19 @@ func attachOutErr(stdOut *logWriter, stdErr *logWriter) process.CmdOption {
 	}
 }
 
-func createLogWriter(comp component.Component, cmdSpec *component.CommandSpec, typeStr string, binaryName string, ll zapcore.Level, unitLevels map[string]zapcore.Level, src logSource) *logWriter {
+func createLogWriter(comp component.Component, baseLog *logger.Logger, cmdSpec *component.CommandSpec, typeStr string, binaryName string, ll zapcore.Level, unitLevels map[string]zapcore.Level, src logSource) *logWriter {
 	dataset := fmt.Sprintf("elastic_agent.%s", strings.ReplaceAll(strings.ReplaceAll(binaryName, "-", "_"), "/", "_"))
-	logger := logger.NewWithoutConfig("").
-		With(
-			"component", map[string]interface{}{
-				"id":      comp.ID,
-				"type":    typeStr,
-				"binary":  binaryName,
-				"dataset": dataset,
-			},
-			"log", map[string]interface{}{
-				"source": comp.ID,
-			},
-		)
+	logger := baseLog.With(
+		"component", map[string]interface{}{
+			"id":      comp.ID,
+			"type":    typeStr,
+			"binary":  binaryName,
+			"dataset": dataset,
+		},
+		"log", map[string]interface{}{
+			"source": comp.ID,
+		},
+	)
 	return newLogWriter(logger.Core(), cmdSpec.Log, ll, unitLevels, src)
 }
 

pkg/component/runtime/runtime.go

@@ -64,7 +64,7 @@ func NewComponentRuntime(
 	}
 	if comp.InputSpec != nil {
 		if comp.InputSpec.Spec.Command != nil {
-			return NewCommandRuntime(comp, monitor)
+			return NewCommandRuntime(comp, logger, monitor)
 		}
 		if comp.InputSpec.Spec.Service != nil {
 			return NewServiceRuntime(comp, logger)
@@ -73,7 +73,7 @@ func NewComponentRuntime(
 	}
 	if comp.ShipperSpec != nil {
 		if comp.ShipperSpec.Spec.Command != nil {
-			return NewCommandRuntime(comp, monitor)
+			return NewCommandRuntime(comp, logger, monitor)
 		}
 		return nil, errors.New("components for shippers can only support command runtime")
 	}

pkg/core/logger/logger.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"go.elastic.co/ecszap"
+	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 	"gopkg.in/yaml.v2"
 
@@ -41,6 +42,8 @@ type Logger = logp.Logger
 // Config is a logging config.
 type Config = logp.Config
 
+var internalLevelEnabler *zap.AtomicLevel
+
 // New returns a configured ECS Logger
 func New(name string, logInternal bool) (*Logger, error) {
 	defaultCfg := DefaultLoggingConfig()
@@ -110,7 +113,11 @@ func toCommonConfig(cfg *Config) (*config.C, error) {
 
 // SetLevel changes the overall log level of the global logger.
 func SetLevel(lvl logp.Level) {
-	logp.SetLevel(lvl.ZapLevel())
+	zapLevel := lvl.ZapLevel()
+	logp.SetLevel(zapLevel)
+	if internalLevelEnabler != nil {
+		internalLevelEnabler.SetLevel(zapLevel)
+	}
 }
 
 // DefaultLoggingConfig returns default configuration for agent logging.
@@ -119,7 +126,7 @@ func DefaultLoggingConfig() *Config {
 	cfg.Beat = agentName
 	cfg.Level = DefaultLogLevel
 	cfg.ToFiles = true
-	cfg.Files.Path = paths.Logs()
+	cfg.Files.Path = filepath.Join(paths.Home(), DefaultLogDirectory)
 	cfg.Files.Name = agentName
 	cfg.Files.MaxSize = 20 * 1024 * 1024
 
@@ -133,8 +140,9 @@ func makeInternalFileOutput(cfg *Config) (zapcore.Core, error) {
 	// defaultCfg is used to set the defaults for the file rotation of the internal logging
 	// these settings cannot be changed by a user configuration
 	defaultCfg := logp.DefaultConfig(logp.DefaultEnvironment)
-	filename := filepath.Join(paths.Home(), DefaultLogDirectory, cfg.Beat)
-
+	filename := filepath.Join(paths.Logs(), cfg.Beat)
+	al := zap.NewAtomicLevelAt(cfg.Level.ZapLevel())
+	internalLevelEnabler = &al // directly persisting struct will panic on accessing unitialized backing pointer
 	rotator, err := file.NewFileRotator(filename,
 		file.MaxSizeBytes(defaultCfg.Files.MaxSize),
 		file.MaxBackups(defaultCfg.Files.MaxBackups),
@@ -150,7 +158,7 @@ func makeInternalFileOutput(cfg *Config) (zapcore.Core, error) {
 	encoderConfig := ecszap.ECSCompatibleEncoderConfig(logp.JSONEncoderConfig())
 	encoderConfig.EncodeTime = utcTimestampEncode
 	encoder := zapcore.NewJSONEncoder(encoderConfig)
-	return ecszap.WrapCore(zapcore.NewCore(encoder, rotator, cfg.Level.ZapLevel())), nil
+	return ecszap.WrapCore(zapcore.NewCore(encoder, rotator, internalLevelEnabler)), nil
 }
 
 // utcTimestampEncode is a zapcore.TimeEncoder that formats time.Time in ISO-8601 in UTC.

pkg/core/logger/logger_test.go

@@ -0,0 +1,58 @@
+// Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+// or more contributor license agreements. Licensed under the Elastic License;
+// you may not use this file except in compliance with the Elastic License.
+
+package logger
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/elastic/elastic-agent-libs/logp"
+)
+
+func Test_SetLevel(t *testing.T) {
+	l, err := NewWithLogpLevel("", logp.ErrorLevel, true)
+	require.NoError(t, err)
+
+	// core logger works
+	require.Equal(t, false, l.Core().Enabled(zapcore.DebugLevel))
+	require.Equal(t, false, l.Core().Enabled(zapcore.InfoLevel))
+	require.Equal(t, false, l.Core().Enabled(zapcore.WarnLevel))
+	require.Equal(t, true, l.Core().Enabled(zapcore.ErrorLevel))
+	// enabler updated
+	require.Equal(t, false, internalLevelEnabler.Enabled(zapcore.DebugLevel))
+	require.Equal(t, false, internalLevelEnabler.Enabled(zapcore.InfoLevel))
+	require.Equal(t, false, internalLevelEnabler.Enabled(zapcore.WarnLevel))
+	require.Equal(t, true, internalLevelEnabler.Enabled(zapcore.ErrorLevel))
+
+	tests := []struct {
+		SetLogLevel  logp.Level
+		DebugEnabled bool
+		InfoEnabled  bool
+		WarnEnabled  bool
+		ErrEnabled   bool
+	}{
+		{logp.DebugLevel, true, true, true, true},
+		{logp.InfoLevel, false, true, true, true},
+		{logp.WarnLevel, false, false, true, true},
+		{logp.ErrorLevel, false, false, false, true},
+	}
+
+	for _, tc := range tests {
+		SetLevel(tc.SetLogLevel)
+
+		// core logger works
+		require.Equal(t, tc.DebugEnabled, l.Core().Enabled(zapcore.DebugLevel))
+		require.Equal(t, tc.InfoEnabled, l.Core().Enabled(zapcore.InfoLevel))
+		require.Equal(t, tc.WarnEnabled, l.Core().Enabled(zapcore.WarnLevel))
+		require.Equal(t, tc.ErrEnabled, l.Core().Enabled(zapcore.ErrorLevel))
+		// enabler updated
+		require.Equal(t, tc.DebugEnabled, internalLevelEnabler.Enabled(zapcore.DebugLevel))
+		require.Equal(t, tc.InfoEnabled, internalLevelEnabler.Enabled(zapcore.InfoLevel))
+		require.Equal(t, tc.WarnEnabled, internalLevelEnabler.Enabled(zapcore.WarnLevel))
+		require.Equal(t, tc.ErrEnabled, internalLevelEnabler.Enabled(zapcore.ErrorLevel))
+	}
+}