From 53c78d0c20e168c257dc642cd8d34acd09fa4e90 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Tue, 19 Dec 2023 12:14:42 +0100 Subject: [PATCH 01/26] [logp] Allow a logger to change its output This commit enables a logger to change its output after creation and independently from the global logger configuration. --- logp/configure/logging.go | 4 ++++ logp/core.go | 16 ++++++++++++++++ 2 files changed, 20 insertions(+) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index f23e1792..06d006a0 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -45,6 +45,10 @@ func init() { flag.Var((*environmentVar)(&environment), "environment", "set environment being ran in") } +func GetEnvironment() logp.Environment { + return environment +} + // Logging builds a logp.Config based on the given common.Config and the specified // CLI flags. func Logging(beatName string, cfg *config.C) error { diff --git a/logp/core.go b/logp/core.go index 321a20d4..cb6b7e7d 100644 --- a/logp/core.go +++ b/logp/core.go @@ -236,6 +236,22 @@ func makeEventLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, er return wrappedCore(core), nil } +// WithFileOutput creates a new file output based on cfg and +// replaces the previous one. +func WithFileOutput(cfg Config) func(zapcore.Core) zapcore.Core { + out, err := makeFileOutput(cfg, zap.DebugLevel) + if err != nil { + L().Errorf("could not create file output: %s", err) + out = zapcore.NewNopCore() + } + + f := func(zapcore.Core) zapcore.Core { + return out + } + + return f +} + func makeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { filename := paths.Resolve(paths.Logs, filepath.Join(cfg.Files.Path, cfg.LogFilename())) From d6fdd9322339e15fe7a78eaedf2eabba561a47f8 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Tue, 16 Jan 2024 08:33:13 +0100 Subject: [PATCH 02/26] Add tests for WithFileOutput --- logp/core_test.go | 118 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 118 insertions(+) diff --git a/logp/core_test.go b/logp/core_test.go index a881200b..f732333a 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -18,8 +18,12 @@ package logp import ( + "encoding/json" "io/ioutil" golog "log" + "os" + "path/filepath" + "runtime" "testing" "github.com/stretchr/testify/assert" @@ -212,3 +216,117 @@ func TestLoggingECSFields(t *testing.T) { } } } + +func TestWithFileOutput(t *testing.T) { + var tempDir1, tempDir2 string + // Because of the way logp and zap work, when the test finishes, the log + // file is still open, this creates a problem on Windows because the + // temporary directory cannot be removed if a file inside it is still + // open. + // + // To circumvent this problem on Windows we use os.MkdirTemp + // leaving it behind and delegating to the OS the responsibility + // of cleaning it up (usually on restart). + if runtime.GOOS == "windows" { + var err error + tempDir1, err = os.MkdirTemp("", t.Name()+"-*") + if err != nil { + t.Fatalf("could not create temporary directory: %s", err) + } + tempDir2, err = os.MkdirTemp("", t.Name()+"-*") + if err != nil { + t.Fatalf("could not create temporary directory: %s", err) + } + } else { + // We have no problems on Linux and Darwin, so we can rely on t.TempDir + // that will remove the files once the tests finishes. + tempDir1 = t.TempDir() + tempDir2 = t.TempDir() + } + + expectedLogMessage := "this is a log message" + expectedLogLogger := t.Name() + "-second" + + // We follow the same approach as on a Beat, first the logger + // (always global) is configured and used, then we instantiate + // a new one, secondLogger, and perform the tests on it. + loggerCfg := DefaultConfig(DefaultEnvironment) + loggerCfg.Beat = t.Name() + "-first" + loggerCfg.ToFiles = true + loggerCfg.ToStderr = false + loggerCfg.Files.Name = "test-log-file-first" + // We want a separate directory for this logger + // and we don't need to inspect it. + loggerCfg.Files.Path = tempDir1 + + // Configures the global logger with the "default" log configuration. + if err := Configure(loggerCfg); err != nil { + t.Errorf("could not initialise logger: %s", err) + } + logger := L() + + // Create a log entry just to "test" the logger + logger.Info("not the message we want") + if err := logger.Sync(); err != nil { + t.Fatalf("could not sync log file from fist logger: %s", err) + } + + // Actually clones the logger and use the "WithFileOutput" function + secondCfg := DefaultConfig(DefaultEnvironment) + secondCfg.ToFiles = true + secondCfg.ToStderr = false + secondCfg.Files.Name = "test-log-file" + secondCfg.Files.Path = tempDir2 + + // We do not call Configure here as we do not want to affect + // the global logger configuration + secondLogger := NewLogger(t.Name() + "-second") + secondLogger = secondLogger.WithOptions(zap.WrapCore(WithFileOutput(secondCfg))) + secondLogger.Info(expectedLogMessage) + if err := secondLogger.Sync(); err != nil { + t.Fatalf("could not sync log file from second logger: %s", err) + } + + // Writes again with the first logger to ensure it has not been affected + // by the new configuration on the second logger. + logger.Info("not the message we want") + if err := logger.Sync(); err != nil { + t.Fatalf("could not sync log file from fist logger: %s", err) + } + + // Find the log file. The file name gets the date added, so we list the + // directory and ensure there is only one file there. + files, err := os.ReadDir(tempDir2) + if err != nil { + t.Fatalf("could not read temporary directory '%s': %s", tempDir2, err) + } + + // If there is more than one file, list all files + // and fail the test. + if len(files) != 1 { + t.Errorf("found %d files in '%s', there must be only one", len(files), tempDir2) + t.Errorf("Files in '%s':", tempDir2) + for _, f := range files { + t.Error(f.Name()) + } + t.FailNow() + } + + logData, err := os.ReadFile(filepath.Join(tempDir2, files[0].Name())) + if err != nil { + t.Fatalf("could not read log file: %s", err) + } + + logEntry := map[string]any{} + if err := json.Unmarshal(logData, &logEntry); err != nil { + t.Fatalf("could not read log entry as JSON. Log entry: '%s'", string(logData)) + } + + // Ensure a couple of fields exist + if logEntry["log.logger"] != expectedLogLogger { + t.Fatalf("expecting 'log.logger' to be '%s', got '%s' instead", expectedLogLogger, logEntry["log.logger"]) + } + if logEntry["message"] != expectedLogMessage { + t.Fatalf("expecting 'message' to be '%s, got '%s' instead", expectedLogMessage, logEntry["message"]) + } +} From ef009efaf5e5c7bd1861f90092076781a716f931 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 22 Jan 2024 16:05:18 +0100 Subject: [PATCH 03/26] PR improvements --- logp/core.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logp/core.go b/logp/core.go index cb6b7e7d..c06d9a66 100644 --- a/logp/core.go +++ b/logp/core.go @@ -239,7 +239,7 @@ func makeEventLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, er // WithFileOutput creates a new file output based on cfg and // replaces the previous one. func WithFileOutput(cfg Config) func(zapcore.Core) zapcore.Core { - out, err := makeFileOutput(cfg, zap.DebugLevel) + out, err := makeFileOutput(cfg, cfg.Level.ZapLevel()) if err != nil { L().Errorf("could not create file output: %s", err) out = zapcore.NewNopCore() From d2d46228bb18fe2730585e2b42b0cfc8c16a2f75 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 22 Jan 2024 17:30:01 +0100 Subject: [PATCH 04/26] update to use file or stderr output --- logp/core.go | 24 ++++++++++++++++++------ logp/core_test.go | 2 +- 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/logp/core.go b/logp/core.go index c06d9a66..ee58ed06 100644 --- a/logp/core.go +++ b/logp/core.go @@ -236,13 +236,25 @@ func makeEventLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, er return wrappedCore(core), nil } -// WithFileOutput creates a new file output based on cfg and -// replaces the previous one. -func WithFileOutput(cfg Config) func(zapcore.Core) zapcore.Core { - out, err := makeFileOutput(cfg, cfg.Level.ZapLevel()) - if err != nil { - L().Errorf("could not create file output: %s", err) +// WithFileOrStderrOutput configures the logger with an output based on cfg. +// If neither `cfg.ToFiles` nor `cfg.ToSdterr` are true, then a noop output +// is created. If both are true, the file output has preference. +func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { + var out zapcore.Core + var err error + + switch { + case cfg.ToFiles: + out, err = makeFileOutput(cfg, cfg.Level.ZapLevel()) + case cfg.ToStderr: + out, err = makeStderrOutput(cfg, cfg.Level.ZapLevel()) + default: out = zapcore.NewNopCore() + err = errors.New("unexpected output type, only allowed outputs are 'file' and 'stderr'") + } + + if err != nil { + L().Errorf("could not create log output: %s", err) } f := func(zapcore.Core) zapcore.Core { diff --git a/logp/core_test.go b/logp/core_test.go index f732333a..93799363 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -281,7 +281,7 @@ func TestWithFileOutput(t *testing.T) { // We do not call Configure here as we do not want to affect // the global logger configuration secondLogger := NewLogger(t.Name() + "-second") - secondLogger = secondLogger.WithOptions(zap.WrapCore(WithFileOutput(secondCfg))) + secondLogger = secondLogger.WithOptions(zap.WrapCore(WithFileOrStderrOutput(secondCfg))) secondLogger.Info(expectedLogMessage) if err := secondLogger.Sync(); err != nil { t.Fatalf("could not sync log file from second logger: %s", err) From da04db011987371c4e0d3b1f1767a6358dc11209 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Wed, 24 Jan 2024 15:42:47 +0100 Subject: [PATCH 05/26] [WIP] Make MakeFileOutput public --- logp/core.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/logp/core.go b/logp/core.go index ee58ed06..988574d4 100644 --- a/logp/core.go +++ b/logp/core.go @@ -141,7 +141,7 @@ func createLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error case cfg.ToEventLog: return makeEventLogOutput(cfg, enab) case cfg.ToFiles: - return makeFileOutput(cfg, enab) + return MakeFileOutput(cfg, enab) } switch cfg.environment { @@ -150,7 +150,7 @@ func createLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error case MacOSServiceEnvironment, WindowsServiceEnvironment: fallthrough default: - return makeFileOutput(cfg, enab) + return MakeFileOutput(cfg, enab) } } @@ -245,7 +245,7 @@ func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { switch { case cfg.ToFiles: - out, err = makeFileOutput(cfg, cfg.Level.ZapLevel()) + out, err = MakeFileOutput(cfg, cfg.Level.ZapLevel()) case cfg.ToStderr: out, err = makeStderrOutput(cfg, cfg.Level.ZapLevel()) default: @@ -264,7 +264,7 @@ func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { return f } -func makeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { +func MakeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { filename := paths.Resolve(paths.Logs, filepath.Join(cfg.Files.Path, cfg.LogFilename())) rotator, err := file.NewFileRotator(filename, From c5b6944a9013444e59c3c52d1ff90dc31f2709c9 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 25 Jan 2024 13:09:57 +0100 Subject: [PATCH 06/26] [WIP] Implement typed outputs --- logp/configure/logging.go | 24 ++++- logp/core.go | 207 ++++++++++++++++++++++++++++++++++++-- 2 files changed, 219 insertions(+), 12 deletions(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index 06d006a0..43a105a1 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -66,7 +66,7 @@ func Logging(beatName string, cfg *config.C) error { // LoggingWithOutputs builds a logp.Config based on the given common.Config and the specified // CLI flags along with the given outputs. -func LoggingWithOutputs(beatName string, cfg *config.C, outputs ...zapcore.Core) error { +func LoggingWithOutputs(beatName string, cfg, sensitiveCfg *config.C, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName if cfg != nil { @@ -79,6 +79,28 @@ func LoggingWithOutputs(beatName string, cfg *config.C, outputs ...zapcore.Core) return logp.ConfigureWithOutputs(config, outputs...) } +func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { + config := logp.DefaultConfig(environment) + config.Beat = beatName + if cfg != nil { + if err := cfg.Unpack(&config); err != nil { + return err + } + } + + applyFlags(&config) + // HERE logp is called and creates a new output + // it needs to receive the sensitive core and the other cores all at once. + // the sensitive core needs to be its own thing + + sensitiveLogpConfig := logp.Config{} + if err := sensitiveCfg.Unpack(&sensitiveLogpConfig); err != nil { + return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) + } + + return logp.ConfigureWithTypedOutputs(config, sensitiveLogpConfig, "log.type", "sensitive", outputs...) +} + func applyFlags(cfg *logp.Config) { if toStderr { cfg.ToStderr = true diff --git a/logp/core.go b/logp/core.go index 988574d4..9b640ada 100644 --- a/logp/core.go +++ b/logp/core.go @@ -21,7 +21,7 @@ import ( "errors" "flag" "fmt" - "io/ioutil" + "io" golog "log" "os" "path/filepath" @@ -65,13 +65,6 @@ type coreLogger struct { // Configure configures the logp package. func Configure(cfg Config) error { - return ConfigureWithOutputs(cfg) -} - -// ConfigureWithOutputs XXX: is used by elastic-agent only (See file: x-pack/elastic-agent/pkg/core/logger/logger.go). -// The agent requires that the output specified in the config object is configured and merged with the -// logging outputs given. -func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { var ( sink zapcore.Core observedLogs *observer.ObservedLogs @@ -92,7 +85,7 @@ func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { // Default logger is always discard, debug level below will // possibly re-enable it. - golog.SetOutput(ioutil.Discard) + golog.SetOutput(io.Discard) // Enabled selectors when debug is enabled. selectors := make(map[string]struct{}, len(cfg.Selectors)) @@ -117,7 +110,6 @@ func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { sink = selectiveWrapper(sink, selectors) } - sink = newMultiCore(append(outputs, sink)...) root := zap.New(sink, makeOptions(cfg)...) storeLogger(&coreLogger{ selectors: selectors, @@ -130,6 +122,144 @@ func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { return nil } +// ConfigureWithOutputs XXX: is used by elastic-agent only (See file: x-pack/elastic-agent/pkg/core/logger/logger.go). //FIXME +// The agent requires that the output specified in the config object is configured and merged with the +// logging outputs given. +// TODO: Rename to ConfigureWithTypedOutptus +func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) error { + var ( + sink zapcore.Core + observedLogs *observer.ObservedLogs + err error + level zap.AtomicLevel + ) + + level = zap.NewAtomicLevelAt(defaultLoggerCfg.Level.ZapLevel()) + // Build a single output (stderr has priority if more than one are enabled). + if defaultLoggerCfg.toObserver { + sink, observedLogs = observer.New(level) + } else { + sink, err = createLogOutput(defaultLoggerCfg, level) + } + if err != nil { + return fmt.Errorf("failed to build log output: %w", err) + } + + // Default logger is always discard, debug level below will + // possibly re-enable it. + golog.SetOutput(io.Discard) + + // Enabled selectors when debug is enabled. + selectors := make(map[string]struct{}, len(defaultLoggerCfg.Selectors)) + if defaultLoggerCfg.Level.Enabled(DebugLevel) && len(defaultLoggerCfg.Selectors) > 0 { + for _, sel := range defaultLoggerCfg.Selectors { + selectors[strings.TrimSpace(sel)] = struct{}{} + } + + // Default to all enabled if no selectors are specified. + if len(selectors) == 0 { + selectors["*"] = struct{}{} + } + + // Re-enable the default go logger output when either stdlog + // or all selector is enabled. + _, stdlogEnabled := selectors["stdlog"] + _, allEnabled := selectors["*"] + if stdlogEnabled || allEnabled { + golog.SetOutput(_defaultGoLog) + } + + sink = selectiveWrapper(sink, selectors) + } + + outputs = append(outputs, sink) + sink = newMultiCore(outputs...) + + root := zap.New(sink, makeOptions(defaultLoggerCfg)...) + storeLogger(&coreLogger{ + selectors: selectors, + rootLogger: root, + globalLogger: root.WithOptions(zap.AddCallerSkip(1)), + logger: newLogger(root, ""), + level: level, + observedLogs: observedLogs, + }) + return nil +} + +func ConfigureWithTypedOutputs(defaultLoggerCfg, sensitiveLoggerCfg Config, logKey, kind string, outputs ...zapcore.Core) error { + var ( + sink zapcore.Core + observedLogs *observer.ObservedLogs + err error + level zap.AtomicLevel + ) + + level = zap.NewAtomicLevelAt(defaultLoggerCfg.Level.ZapLevel()) + // Build a single output (stderr has priority if more than one are enabled). + if defaultLoggerCfg.toObserver { + sink, observedLogs = observer.New(level) + } else { + sink, err = createLogOutput(defaultLoggerCfg, level) + } + if err != nil { + return fmt.Errorf("failed to build log output: %w", err) + } + + // Default logger is always discard, debug level below will + // possibly re-enable it. + golog.SetOutput(io.Discard) + + // Enabled selectors when debug is enabled. + selectors := make(map[string]struct{}, len(defaultLoggerCfg.Selectors)) + if defaultLoggerCfg.Level.Enabled(DebugLevel) && len(defaultLoggerCfg.Selectors) > 0 { + for _, sel := range defaultLoggerCfg.Selectors { + selectors[strings.TrimSpace(sel)] = struct{}{} + } + + // Default to all enabled if no selectors are specified. + if len(selectors) == 0 { + selectors["*"] = struct{}{} + } + + // Re-enable the default go logger output when either stdlog + // or all selector is enabled. + _, stdlogEnabled := selectors["stdlog"] + _, allEnabled := selectors["*"] + if stdlogEnabled || allEnabled { + golog.SetOutput(_defaultGoLog) + } + + sink = selectiveWrapper(sink, selectors) + } + + outputs = append(outputs, sink) + sink = newMultiCore(outputs...) + + sensitiveCore, err := MakeFileOutput(sensitiveLoggerCfg, sensitiveLoggerCfg.Level.ZapLevel()) + if err != nil { + return fmt.Errorf("could not create sensitive file output: %w", err) + } + + sink = typedLoggerCore{ + defaultCore: sink, + sensitiveCore: sensitiveCore, + logKey: logKey, + kind: kind, + } + + root := zap.New(sink, makeOptions(defaultLoggerCfg)...) + storeLogger(&coreLogger{ + selectors: selectors, + rootLogger: root, + globalLogger: root.WithOptions(zap.AddCallerSkip(1)), + logger: newLogger(root, ""), + level: level, + observedLogs: observedLogs, + }) + return nil +} + func createLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { switch { case cfg.toIODiscard: @@ -215,7 +345,7 @@ func makeStderrOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, erro } func makeDiscardOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { - discard := zapcore.AddSync(ioutil.Discard) + discard := zapcore.AddSync(io.Discard) return newCore(buildEncoder(cfg), discard, enab), nil } @@ -371,3 +501,58 @@ func (m multiCore) Sync() error { } return errors.Join(errs...) } + +// typedLoggerCore warps a zapcore.Core and only logs if the field `log.type` +// matches `kind`. +// +// All other method calls are passed directly to the wrapped core. +type typedLoggerCore struct { + sensitiveCore zapcore.Core + defaultCore zapcore.Core + kind string + logKey string +} + +func (s typedLoggerCore) Enabled(l zapcore.Level) bool { + return s.defaultCore.Enabled(l) || s.sensitiveCore.Enabled(l) +} + +func (s typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { + s.defaultCore = s.defaultCore.With(fields) + s.sensitiveCore = s.sensitiveCore.With(fields) + return s +} + +func (s typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if s.defaultCore.Check(e, ce) != nil { + ce = ce.AddCore(e, s.defaultCore) + } + if s.sensitiveCore.Check(e, ce) != nil { + ce = ce.AddCore(e, s.sensitiveCore) + } + + return ce +} + +func (s typedLoggerCore) Sync() error { + defaultErr := s.defaultCore.Sync() + sensitiveErr := s.sensitiveCore.Sync() + + if defaultErr != nil || sensitiveErr != nil { + return fmt.Errorf("error syncing loggers. DefaultCore: %s, sensitiveCore: %s", defaultErr, sensitiveErr) + } + + return nil +} + +func (s typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { + for _, f := range fields { + if f.Key == s.logKey { + if f.String == s.kind { + return s.sensitiveCore.Write(e, fields) + } + } + } + + return s.defaultCore.Write(e, fields) +} From f9e923b46d78475a98ee1237355baa6acbd57c75 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 25 Jan 2024 15:18:44 +0100 Subject: [PATCH 07/26] Better documentation and cleaning up --- logp/configure/logging.go | 4 +--- logp/core.go | 14 ++++++++++++++ 2 files changed, 15 insertions(+), 3 deletions(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index 43a105a1..c00eccf5 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -79,6 +79,7 @@ func LoggingWithOutputs(beatName string, cfg, sensitiveCfg *config.C, outputs .. return logp.ConfigureWithOutputs(config, outputs...) } +// LoggingWithTypedOutputs applies some defaults then calls ConfigureWithTypedOutputs func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName @@ -89,9 +90,6 @@ func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKe } applyFlags(&config) - // HERE logp is called and creates a new output - // it needs to receive the sensitive core and the other cores all at once. - // the sensitive core needs to be its own thing sensitiveLogpConfig := logp.Config{} if err := sensitiveCfg.Unpack(&sensitiveLogpConfig); err != nil { diff --git a/logp/core.go b/logp/core.go index 9b640ada..86ac8e8a 100644 --- a/logp/core.go +++ b/logp/core.go @@ -187,6 +187,20 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro return nil } +// ConfigureWithTypedOutputs configures the global logger to use typed outputs. +// +// If a log entry matches the defined key/value, this entry is logged using the +// core generated from `sensitiveLoggerCfg`, otherwise it will be logged by all +// cores in `outputs` and the one generated from `defaultLoggerCfg` +// Arguments: +// - `defaultLoggerCfg` is used to create a new core that will be the default +// output from the logger +// - `sensitiveLoggerCfg` is used to create a new output that will only be used +// when the log entry matches `logKey = kind` +// - `logKey` is the key the typed logger will look at +// - `kind` is the value compared against the `logKey` entry +// - `outputs` is a list of cores that will be added together with the core +// generated by `defaultLoggerCfg` as the default output for the loggger. func ConfigureWithTypedOutputs(defaultLoggerCfg, sensitiveLoggerCfg Config, logKey, kind string, outputs ...zapcore.Core) error { var ( sink zapcore.Core From 024f465b29f9f556d52609f32e2e0bbe3d31ed4d Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 25 Jan 2024 17:21:54 +0100 Subject: [PATCH 08/26] Refactoring --- logp/core.go | 141 ++++++++++++++++----------------------------------- 1 file changed, 43 insertions(+), 98 deletions(-) diff --git a/logp/core.go b/logp/core.go index 86ac8e8a..ab7d6b9b 100644 --- a/logp/core.go +++ b/logp/core.go @@ -65,67 +65,13 @@ type coreLogger struct { // Configure configures the logp package. func Configure(cfg Config) error { - var ( - sink zapcore.Core - observedLogs *observer.ObservedLogs - err error - level zap.AtomicLevel - ) - - level = zap.NewAtomicLevelAt(cfg.Level.ZapLevel()) - // Build a single output (stderr has priority if more than one are enabled). - if cfg.toObserver { - sink, observedLogs = observer.New(level) - } else { - sink, err = createLogOutput(cfg, level) - } - if err != nil { - return fmt.Errorf("failed to build log output: %w", err) - } - - // Default logger is always discard, debug level below will - // possibly re-enable it. - golog.SetOutput(io.Discard) - - // Enabled selectors when debug is enabled. - selectors := make(map[string]struct{}, len(cfg.Selectors)) - if cfg.Level.Enabled(DebugLevel) && len(cfg.Selectors) > 0 { - for _, sel := range cfg.Selectors { - selectors[strings.TrimSpace(sel)] = struct{}{} - } - - // Default to all enabled if no selectors are specified. - if len(selectors) == 0 { - selectors["*"] = struct{}{} - } - - // Re-enable the default go logger output when either stdlog - // or all selector is enabled. - _, stdlogEnabled := selectors["stdlog"] - _, allEnabled := selectors["*"] - if stdlogEnabled || allEnabled { - golog.SetOutput(_defaultGoLog) - } - - sink = selectiveWrapper(sink, selectors) - } - - root := zap.New(sink, makeOptions(cfg)...) - storeLogger(&coreLogger{ - selectors: selectors, - rootLogger: root, - globalLogger: root.WithOptions(zap.AddCallerSkip(1)), - logger: newLogger(root, ""), - level: level, - observedLogs: observedLogs, - }) - return nil + return ConfigureWithOutputs(cfg) } // ConfigureWithOutputs XXX: is used by elastic-agent only (See file: x-pack/elastic-agent/pkg/core/logger/logger.go). //FIXME // The agent requires that the output specified in the config object is configured and merged with the // logging outputs given. -// TODO: Rename to ConfigureWithTypedOutptus +// TODO: fix docs func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) error { var ( sink zapcore.Core @@ -172,8 +118,7 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro sink = selectiveWrapper(sink, selectors) } - outputs = append(outputs, sink) - sink = newMultiCore(outputs...) + sink = newMultiCore(append(outputs, sink)...) root := zap.New(sink, makeOptions(defaultLoggerCfg)...) storeLogger(&coreLogger{ @@ -190,18 +135,18 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro // ConfigureWithTypedOutputs configures the global logger to use typed outputs. // // If a log entry matches the defined key/value, this entry is logged using the -// core generated from `sensitiveLoggerCfg`, otherwise it will be logged by all -// cores in `outputs` and the one generated from `defaultLoggerCfg` +// core generated from `typedLoggerCfg`, otherwise it will be logged by all +// cores in `outputs` and the one generated from `defaultLoggerCfg`. // Arguments: // - `defaultLoggerCfg` is used to create a new core that will be the default // output from the logger -// - `sensitiveLoggerCfg` is used to create a new output that will only be used -// when the log entry matches `logKey = kind` +// - `typedLoggerCfg` is used to create a new output that will only be used +// when the log entry matches `entry[logKey] = kind` // - `logKey` is the key the typed logger will look at // - `kind` is the value compared against the `logKey` entry // - `outputs` is a list of cores that will be added together with the core // generated by `defaultLoggerCfg` as the default output for the loggger. -func ConfigureWithTypedOutputs(defaultLoggerCfg, sensitiveLoggerCfg Config, logKey, kind string, outputs ...zapcore.Core) error { +func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { var ( sink zapcore.Core observedLogs *observer.ObservedLogs @@ -247,19 +192,18 @@ func ConfigureWithTypedOutputs(defaultLoggerCfg, sensitiveLoggerCfg Config, logK sink = selectiveWrapper(sink, selectors) } - outputs = append(outputs, sink) - sink = newMultiCore(outputs...) + sink = newMultiCore(append(outputs, sink)...) - sensitiveCore, err := MakeFileOutput(sensitiveLoggerCfg, sensitiveLoggerCfg.Level.ZapLevel()) + typedCore, err := MakeFileOutput(typedLoggerCfg, typedLoggerCfg.Level.ZapLevel()) if err != nil { return fmt.Errorf("could not create sensitive file output: %w", err) } sink = typedLoggerCore{ - defaultCore: sink, - sensitiveCore: sensitiveCore, - logKey: logKey, - kind: kind, + defaultCore: sink, + typedCore: typedCore, + key: key, + value: value, } root := zap.New(sink, makeOptions(defaultLoggerCfg)...) @@ -516,57 +460,58 @@ func (m multiCore) Sync() error { return errors.Join(errs...) } -// typedLoggerCore warps a zapcore.Core and only logs if the field `log.type` -// matches `kind`. +// typedLoggerCore takes two cores and directs logs entries to one of them +// with the value of the field defined by the pair `key` and `value` // -// All other method calls are passed directly to the wrapped core. +// If `entry[key] == value` the typedCore is used, otherwise the +// defaultCore is used. type typedLoggerCore struct { - sensitiveCore zapcore.Core - defaultCore zapcore.Core - kind string - logKey string + typedCore zapcore.Core + defaultCore zapcore.Core + value string + key string } -func (s typedLoggerCore) Enabled(l zapcore.Level) bool { - return s.defaultCore.Enabled(l) || s.sensitiveCore.Enabled(l) +func (t typedLoggerCore) Enabled(l zapcore.Level) bool { + return t.defaultCore.Enabled(l) || t.typedCore.Enabled(l) } -func (s typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { - s.defaultCore = s.defaultCore.With(fields) - s.sensitiveCore = s.sensitiveCore.With(fields) - return s +func (t typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { + t.defaultCore = t.defaultCore.With(fields) + t.typedCore = t.typedCore.With(fields) + return t } -func (s typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { - if s.defaultCore.Check(e, ce) != nil { - ce = ce.AddCore(e, s.defaultCore) +func (t typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if t.defaultCore.Check(e, ce) != nil { + ce = ce.AddCore(e, t.defaultCore) } - if s.sensitiveCore.Check(e, ce) != nil { - ce = ce.AddCore(e, s.sensitiveCore) + if t.typedCore.Check(e, ce) != nil { + ce = ce.AddCore(e, t.typedCore) } return ce } -func (s typedLoggerCore) Sync() error { - defaultErr := s.defaultCore.Sync() - sensitiveErr := s.sensitiveCore.Sync() +func (t typedLoggerCore) Sync() error { + defaultErr := t.defaultCore.Sync() + typedErr := t.typedCore.Sync() - if defaultErr != nil || sensitiveErr != nil { - return fmt.Errorf("error syncing loggers. DefaultCore: %s, sensitiveCore: %s", defaultErr, sensitiveErr) + if defaultErr != nil || typedErr != nil { + return fmt.Errorf("error syncing loggert. DefaultCore: %s, typedCore: %s", defaultErr, typedErr) } return nil } -func (s typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { +func (t typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { for _, f := range fields { - if f.Key == s.logKey { - if f.String == s.kind { - return s.sensitiveCore.Write(e, fields) + if f.Key == t.key { + if f.String == t.value { + return t.typedCore.Write(e, fields) } } } - return s.defaultCore.Write(e, fields) + return t.defaultCore.Write(e, fields) } From f14af858334a295ce0b2f96ea5a8bd1e798d3219 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 25 Jan 2024 18:06:35 +0100 Subject: [PATCH 09/26] Add defaults for LoggingWithTypedOutputs --- logp/configure/logging.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index c00eccf5..b686b29b 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -91,7 +91,9 @@ func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKe applyFlags(&config) - sensitiveLogpConfig := logp.Config{} + sensitiveLogpConfig := logp.DefaultConfig(environment) + sensitiveLogpConfig.ToFiles = true + sensitiveLogpConfig.ToStderr = false if err := sensitiveCfg.Unpack(&sensitiveLogpConfig); err != nil { return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) } From 946ba23e5f65b261ee8f0e561f3d91f3aeeddddb Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 09:26:49 +0100 Subject: [PATCH 10/26] PR improvements --- logp/core_test.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/logp/core_test.go b/logp/core_test.go index 93799363..612a7a74 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -223,6 +223,8 @@ func TestWithFileOutput(t *testing.T) { // file is still open, this creates a problem on Windows because the // temporary directory cannot be removed if a file inside it is still // open. + // See https://github.com/elastic/elastic-agent-libs/issues/179 + // for more details // // To circumvent this problem on Windows we use os.MkdirTemp // leaving it behind and delegating to the OS the responsibility From 1f43dc73a794a4dce77ea8089fafc2a5d23132a1 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 11:55:37 +0100 Subject: [PATCH 11/26] refactoring and improvements --- logp/configure/logging.go | 17 ++++++++++------- logp/core.go | 24 +++++++++++++----------- 2 files changed, 23 insertions(+), 18 deletions(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index b686b29b..3ef17a21 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -66,7 +66,7 @@ func Logging(beatName string, cfg *config.C) error { // LoggingWithOutputs builds a logp.Config based on the given common.Config and the specified // CLI flags along with the given outputs. -func LoggingWithOutputs(beatName string, cfg, sensitiveCfg *config.C, outputs ...zapcore.Core) error { +func LoggingWithOutputs(beatName string, cfg, typedCfg *config.C, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName if cfg != nil { @@ -80,7 +80,10 @@ func LoggingWithOutputs(beatName string, cfg, sensitiveCfg *config.C, outputs .. } // LoggingWithTypedOutputs applies some defaults then calls ConfigureWithTypedOutputs -func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { +// +// At the moment only the sensitive output is supported. It will log any entry that sets +// `log.type: sensitive` to a different file. +func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName if cfg != nil { @@ -91,14 +94,14 @@ func LoggingWithTypedOutputs(beatName string, cfg, sensitiveCfg *config.C, logKe applyFlags(&config) - sensitiveLogpConfig := logp.DefaultConfig(environment) - sensitiveLogpConfig.ToFiles = true - sensitiveLogpConfig.ToStderr = false - if err := sensitiveCfg.Unpack(&sensitiveLogpConfig); err != nil { + typedLogpConfig := logp.DefaultConfig(environment) + typedLogpConfig.ToFiles = true + typedLogpConfig.ToStderr = false + if err := typedCfg.Unpack(&typedLogpConfig); err != nil { return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) } - return logp.ConfigureWithTypedOutputs(config, sensitiveLogpConfig, "log.type", "sensitive", outputs...) + return logp.ConfigureWithTypedOutputs(config, typedLogpConfig, "log.type", "sensitive", outputs...) } func applyFlags(cfg *logp.Config) { diff --git a/logp/core.go b/logp/core.go index ab7d6b9b..025e4452 100644 --- a/logp/core.go +++ b/logp/core.go @@ -68,10 +68,12 @@ func Configure(cfg Config) error { return ConfigureWithOutputs(cfg) } -// ConfigureWithOutputs XXX: is used by elastic-agent only (See file: x-pack/elastic-agent/pkg/core/logger/logger.go). //FIXME -// The agent requires that the output specified in the config object is configured and merged with the -// logging outputs given. -// TODO: fix docs +// ConfigureWithOutputs is required by elastic-agent to create a logger with +// multiple outputs. One is the default configurable output and the other is a +// file output used by the monitoring Beats. +// See: https://github.com/elastic/elastic-agent/blob/main/pkg/core/logger/logger.go +// for more details, look at the `new` and `MakeInternalFileOutput` functions from +// this file. func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) error { var ( sink zapcore.Core @@ -142,8 +144,8 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro // output from the logger // - `typedLoggerCfg` is used to create a new output that will only be used // when the log entry matches `entry[logKey] = kind` -// - `logKey` is the key the typed logger will look at -// - `kind` is the value compared against the `logKey` entry +// - `key` is the key the typed logger will look at +// - `value` is the value compared against the `logKey` entry // - `outputs` is a list of cores that will be added together with the core // generated by `defaultLoggerCfg` as the default output for the loggger. func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { @@ -194,7 +196,7 @@ func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, val sink = newMultiCore(append(outputs, sink)...) - typedCore, err := MakeFileOutput(typedLoggerCfg, typedLoggerCfg.Level.ZapLevel()) + typedCore, err := makeFileOutput(typedLoggerCfg, typedLoggerCfg.Level.ZapLevel()) if err != nil { return fmt.Errorf("could not create sensitive file output: %w", err) } @@ -229,7 +231,7 @@ func createLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error case cfg.ToEventLog: return makeEventLogOutput(cfg, enab) case cfg.ToFiles: - return MakeFileOutput(cfg, enab) + return makeFileOutput(cfg, enab) } switch cfg.environment { @@ -238,7 +240,7 @@ func createLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error case MacOSServiceEnvironment, WindowsServiceEnvironment: fallthrough default: - return MakeFileOutput(cfg, enab) + return makeFileOutput(cfg, enab) } } @@ -333,7 +335,7 @@ func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { switch { case cfg.ToFiles: - out, err = MakeFileOutput(cfg, cfg.Level.ZapLevel()) + out, err = makeFileOutput(cfg, cfg.Level.ZapLevel()) case cfg.ToStderr: out, err = makeStderrOutput(cfg, cfg.Level.ZapLevel()) default: @@ -352,7 +354,7 @@ func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { return f } -func MakeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { +func makeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { filename := paths.Resolve(paths.Logs, filepath.Join(cfg.Files.Path, cfg.LogFilename())) rotator, err := file.NewFileRotator(filename, From e7db2cef9b4f2ca250730853c504276247cf636f Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 12:21:36 +0100 Subject: [PATCH 12/26] add test case --- logp/core_test.go | 49 ++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 48 insertions(+), 1 deletion(-) diff --git a/logp/core_test.go b/logp/core_test.go index 612a7a74..72a89ec3 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -29,6 +29,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) func TestLogger(t *testing.T) { @@ -217,7 +218,7 @@ func TestLoggingECSFields(t *testing.T) { } } -func TestWithFileOutput(t *testing.T) { +func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { var tempDir1, tempDir2 string // Because of the way logp and zap work, when the test finishes, the log // file is still open, this creates a problem on Windows because the @@ -332,3 +333,49 @@ func TestWithFileOutput(t *testing.T) { t.Fatalf("expecting 'message' to be '%s, got '%s' instead", expectedLogMessage, logEntry["message"]) } } + +func TestWithFileOrStderrOutput(t *testing.T) { + testCases := []struct { + name string + toStderr bool + toFile bool + }{ + { + name: "stderr output", + toStderr: true, + toFile: false, + }, + { + name: "file output", + toStderr: false, + toFile: true, + }, + } + + notEnabledLevels := []zapcore.Level{zapcore.InfoLevel, zapcore.DebugLevel} + enabledLevels := []zapcore.Level{zapcore.ErrorLevel, zapcore.PanicLevel} + + for _, tc := range testCases { + cfg := DefaultConfig(DefaultEnvironment) + cfg.ToStderr = tc.toStderr + cfg.ToFiles = tc.toFile + cfg.Level = ErrorLevel + + f := WithFileOrStderrOutput(cfg) + core := f(zapcore.NewNopCore()) + + t.Run(tc.name, func(t *testing.T) { + for _, l := range notEnabledLevels { + if core.Enabled(l) { + t.Errorf("level %s must not be enabled", l.String()) + } + } + + for _, l := range enabledLevels { + if !core.Enabled(l) { + t.Errorf("level %s must Vbe enabled", l.String()) + } + } + }) + } +} From d40968462a01fa5104215989fc041805fe6c23ae Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 13:01:17 +0100 Subject: [PATCH 13/26] reduce code duplication and improve comments --- logp/core.go | 67 ++++++++++++---------------------------------------- 1 file changed, 15 insertions(+), 52 deletions(-) diff --git a/logp/core.go b/logp/core.go index 025e4452..d0eb0b03 100644 --- a/logp/core.go +++ b/logp/core.go @@ -68,13 +68,7 @@ func Configure(cfg Config) error { return ConfigureWithOutputs(cfg) } -// ConfigureWithOutputs is required by elastic-agent to create a logger with -// multiple outputs. One is the default configurable output and the other is a -// file output used by the monitoring Beats. -// See: https://github.com/elastic/elastic-agent/blob/main/pkg/core/logger/logger.go -// for more details, look at the `new` and `MakeInternalFileOutput` functions from -// this file. -func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) error { +func createSink(defaultLoggerCfg Config, outputs ...zapcore.Core) (zapcore.Core, zap.AtomicLevel, *observer.ObservedLogs, map[string]struct{}, error) { var ( sink zapcore.Core observedLogs *observer.ObservedLogs @@ -90,7 +84,7 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro sink, err = createLogOutput(defaultLoggerCfg, level) } if err != nil { - return fmt.Errorf("failed to build log output: %w", err) + return nil, level, nil, nil, fmt.Errorf("failed to build log output: %w", err) } // Default logger is always discard, debug level below will @@ -122,6 +116,17 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro sink = newMultiCore(append(outputs, sink)...) + return sink, level, observedLogs, selectors, err +} + +// ConfigureWithOutputs configures the global logger to use an output created +// from `defaultLoggerCfg` and all the outputs passed by `outputs`. +// This function needs to be exported because it's used by `logp/configure` +func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) error { + sink, level, observedLogs, selectors, err := createSink(defaultLoggerCfg, outputs...) + if err != nil { + return err + } root := zap.New(sink, makeOptions(defaultLoggerCfg)...) storeLogger(&coreLogger{ selectors: selectors, @@ -149,53 +154,11 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro // - `outputs` is a list of cores that will be added together with the core // generated by `defaultLoggerCfg` as the default output for the loggger. func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { - var ( - sink zapcore.Core - observedLogs *observer.ObservedLogs - err error - level zap.AtomicLevel - ) - - level = zap.NewAtomicLevelAt(defaultLoggerCfg.Level.ZapLevel()) - // Build a single output (stderr has priority if more than one are enabled). - if defaultLoggerCfg.toObserver { - sink, observedLogs = observer.New(level) - } else { - sink, err = createLogOutput(defaultLoggerCfg, level) - } + sink, level, observedLogs, selectors, err := createSink(defaultLoggerCfg, outputs...) if err != nil { - return fmt.Errorf("failed to build log output: %w", err) + return err } - // Default logger is always discard, debug level below will - // possibly re-enable it. - golog.SetOutput(io.Discard) - - // Enabled selectors when debug is enabled. - selectors := make(map[string]struct{}, len(defaultLoggerCfg.Selectors)) - if defaultLoggerCfg.Level.Enabled(DebugLevel) && len(defaultLoggerCfg.Selectors) > 0 { - for _, sel := range defaultLoggerCfg.Selectors { - selectors[strings.TrimSpace(sel)] = struct{}{} - } - - // Default to all enabled if no selectors are specified. - if len(selectors) == 0 { - selectors["*"] = struct{}{} - } - - // Re-enable the default go logger output when either stdlog - // or all selector is enabled. - _, stdlogEnabled := selectors["stdlog"] - _, allEnabled := selectors["*"] - if stdlogEnabled || allEnabled { - golog.SetOutput(_defaultGoLog) - } - - sink = selectiveWrapper(sink, selectors) - } - - sink = newMultiCore(append(outputs, sink)...) - typedCore, err := makeFileOutput(typedLoggerCfg, typedLoggerCfg.Level.ZapLevel()) if err != nil { return fmt.Errorf("could not create sensitive file output: %w", err) From 143752dfa0a658dad7f7bc1b091db6b8c42c06ad Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 13:08:50 +0100 Subject: [PATCH 14/26] fix lint errors --- logp/core.go | 2 +- logp/core_test.go | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/logp/core.go b/logp/core.go index d0eb0b03..2eb7edf0 100644 --- a/logp/core.go +++ b/logp/core.go @@ -463,7 +463,7 @@ func (t typedLoggerCore) Sync() error { typedErr := t.typedCore.Sync() if defaultErr != nil || typedErr != nil { - return fmt.Errorf("error syncing loggert. DefaultCore: %s, typedCore: %s", defaultErr, typedErr) + return fmt.Errorf("error syncing loggert. DefaultCore: %w, typedCore: %w", defaultErr, typedErr) } return nil diff --git a/logp/core_test.go b/logp/core_test.go index 72a89ec3..3d80b601 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -19,7 +19,7 @@ package logp import ( "encoding/json" - "io/ioutil" + "io" golog "log" "os" "path/filepath" @@ -172,25 +172,25 @@ func TestDebugAllStdoutEnablesDefaultGoLogger(t *testing.T) { err = DevelopmentSetup(WithSelectors("other")) require.NoError(t, err) - assert.Equal(t, ioutil.Discard, golog.Writer()) + assert.Equal(t, io.Discard, golog.Writer()) } func TestNotDebugAllStdoutDisablesDefaultGoLogger(t *testing.T) { err := DevelopmentSetup(WithSelectors("*"), WithLevel(InfoLevel)) require.NoError(t, err) - assert.Equal(t, ioutil.Discard, golog.Writer()) + assert.Equal(t, io.Discard, golog.Writer()) err = DevelopmentSetup(WithSelectors("stdlog"), WithLevel(InfoLevel)) require.NoError(t, err) - assert.Equal(t, ioutil.Discard, golog.Writer()) + assert.Equal(t, io.Discard, golog.Writer()) err = DevelopmentSetup(WithSelectors("*", "stdlog"), WithLevel(InfoLevel)) require.NoError(t, err) - assert.Equal(t, ioutil.Discard, golog.Writer()) + assert.Equal(t, io.Discard, golog.Writer()) err = DevelopmentSetup(WithSelectors("other"), WithLevel(InfoLevel)) require.NoError(t, err) - assert.Equal(t, ioutil.Discard, golog.Writer()) + assert.Equal(t, io.Discard, golog.Writer()) } func TestLoggingECSFields(t *testing.T) { From 0f96b6bd18ed8b2693f7862a24d4c4a9db37a7d7 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 26 Jan 2024 16:15:55 +0100 Subject: [PATCH 15/26] fix typedLoggerCore Check and Write methods --- logp/core.go | 25 ++++++++++++++++++------- 1 file changed, 18 insertions(+), 7 deletions(-) diff --git a/logp/core.go b/logp/core.go index 2eb7edf0..af833434 100644 --- a/logp/core.go +++ b/logp/core.go @@ -448,11 +448,11 @@ func (t typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { } func (t typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { - if t.defaultCore.Check(e, ce) != nil { - ce = ce.AddCore(e, t.defaultCore) - } - if t.typedCore.Check(e, ce) != nil { - ce = ce.AddCore(e, t.typedCore) + // If either core can write an entry on this level, add the typedLoggerCore + // itself and let the write method decide which core to use and whether to + // write the entry. + if t.defaultCore.Enabled(e.Level) || t.typedCore.Enabled(e.Level) { + return ce.AddCore(e, t) } return ce @@ -473,10 +473,21 @@ func (t typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { for _, f := range fields { if f.Key == t.key { if f.String == t.value { - return t.typedCore.Write(e, fields) + if t.typedCore.Enabled(e.Level) { + return t.typedCore.Write(e, fields) + } + + // We cannot write an entry of this log level, so we return nil + // because it is still a success + return nil } } } - return t.defaultCore.Write(e, fields) + if t.defaultCore.Enabled(e.Level) { + t.defaultCore.Write(e, fields) + } + + // No-Op is still a success + return nil } From 211b1e7cfab6c70cc251bac2e19ebbacf0c6ca72 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 29 Jan 2024 09:35:41 +0100 Subject: [PATCH 16/26] more fixes and tests --- logp/core.go | 41 +++---- logp/core_mock_test.go | 270 +++++++++++++++++++++++++++++++++++++++++ logp/core_test.go | 197 ++++++++++++++++++++++++++++++ 3 files changed, 482 insertions(+), 26 deletions(-) create mode 100644 logp/core_mock_test.go diff --git a/logp/core.go b/logp/core.go index af833434..f44679db 100644 --- a/logp/core.go +++ b/logp/core.go @@ -159,12 +159,12 @@ func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, val return err } - typedCore, err := makeFileOutput(typedLoggerCfg, typedLoggerCfg.Level.ZapLevel()) + typedCore, err := makeFileOutput(typedLoggerCfg, level) if err != nil { return fmt.Errorf("could not create sensitive file output: %w", err) } - sink = typedLoggerCore{ + sink = &typedLoggerCore{ defaultCore: sink, typedCore: typedCore, key: key, @@ -430,6 +430,9 @@ func (m multiCore) Sync() error { // // If `entry[key] == value` the typedCore is used, otherwise the // defaultCore is used. +// WARNING: The level of both cores must always be the same! +// typedLoggerCore will only use the defaultCore level to decide +// whether to log an entry or not type typedLoggerCore struct { typedCore zapcore.Core defaultCore zapcore.Core @@ -437,57 +440,43 @@ type typedLoggerCore struct { key string } -func (t typedLoggerCore) Enabled(l zapcore.Level) bool { - return t.defaultCore.Enabled(l) || t.typedCore.Enabled(l) +func (t *typedLoggerCore) Enabled(l zapcore.Level) bool { + return t.defaultCore.Enabled(l) } -func (t typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { +func (t *typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { t.defaultCore = t.defaultCore.With(fields) t.typedCore = t.typedCore.With(fields) return t } -func (t typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { - // If either core can write an entry on this level, add the typedLoggerCore - // itself and let the write method decide which core to use and whether to - // write the entry. - if t.defaultCore.Enabled(e.Level) || t.typedCore.Enabled(e.Level) { +func (t *typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if t.defaultCore.Enabled(e.Level) { return ce.AddCore(e, t) } return ce } -func (t typedLoggerCore) Sync() error { +func (t *typedLoggerCore) Sync() error { defaultErr := t.defaultCore.Sync() typedErr := t.typedCore.Sync() if defaultErr != nil || typedErr != nil { - return fmt.Errorf("error syncing loggert. DefaultCore: %w, typedCore: %w", defaultErr, typedErr) + return fmt.Errorf("error syncing logger. DefaultCore: '%w', typedCore: '%w'", defaultErr, typedErr) } return nil } -func (t typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { +func (t *typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { for _, f := range fields { if f.Key == t.key { if f.String == t.value { - if t.typedCore.Enabled(e.Level) { - return t.typedCore.Write(e, fields) - } - - // We cannot write an entry of this log level, so we return nil - // because it is still a success - return nil + return t.typedCore.Write(e, fields) } } } - if t.defaultCore.Enabled(e.Level) { - t.defaultCore.Write(e, fields) - } - - // No-Op is still a success - return nil + return t.defaultCore.Write(e, fields) } diff --git a/logp/core_mock_test.go b/logp/core_mock_test.go new file mode 100644 index 00000000..bbfba810 --- /dev/null +++ b/logp/core_mock_test.go @@ -0,0 +1,270 @@ +// Licensed to Elasticsearch B.V. under one or more contributor +// license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright +// ownership. Elasticsearch B.V. licenses this file to you under +// the Apache License, Version 2.0 (the "License"); you may +// not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +// Code generated by moq; DO NOT EDIT. +// github.com/matryer/moq + +package logp + +import ( + "sync" + + "go.uber.org/zap/zapcore" +) + +// ZapCoreMock is a mock implementation of zapcore.Core. +// +// func TestSomethingThatUsesCore(t *testing.T) { +// +// // make and configure a mocked zapcore.Core +// mockedCore := &ZapCoreMock{ +// CheckFunc: func(entry zapcore.Entry, checkedEntry *zapcore.CheckedEntry) *zapcore.CheckedEntry { +// panic("mock out the Check method") +// }, +// EnabledFunc: func(level zapcore.Level) bool { +// panic("mock out the Enabled method") +// }, +// SyncFunc: func() error { +// panic("mock out the Sync method") +// }, +// WithFunc: func(fields []zapcore.Field) zapcore.Core { +// panic("mock out the With method") +// }, +// WriteFunc: func(entry zapcore.Entry, fields []zapcore.Field) error { +// panic("mock out the Write method") +// }, +// } +// +// // use mockedCore in code that requires zapcore.Core +// // and then make assertions. +// +// } +type ZapCoreMock struct { + // CheckFunc mocks the Check method. + CheckFunc func(entry zapcore.Entry, checkedEntry *zapcore.CheckedEntry) *zapcore.CheckedEntry + + // EnabledFunc mocks the Enabled method. + EnabledFunc func(level zapcore.Level) bool + + // SyncFunc mocks the Sync method. + SyncFunc func() error + + // WithFunc mocks the With method. + WithFunc func(fields []zapcore.Field) zapcore.Core + + // WriteFunc mocks the Write method. + WriteFunc func(entry zapcore.Entry, fields []zapcore.Field) error + + // calls tracks calls to the methods. + calls struct { + // Check holds details about calls to the Check method. + Check []struct { + // Entry is the entry argument value. + Entry zapcore.Entry + // CheckedEntry is the checkedEntry argument value. + CheckedEntry *zapcore.CheckedEntry + } + // Enabled holds details about calls to the Enabled method. + Enabled []struct { + // Level is the level argument value. + Level zapcore.Level + } + // Sync holds details about calls to the Sync method. + Sync []struct { + } + // With holds details about calls to the With method. + With []struct { + // Fields is the fields argument value. + Fields []zapcore.Field + } + // Write holds details about calls to the Write method. + Write []struct { + // Entry is the entry argument value. + Entry zapcore.Entry + // Fields is the fields argument value. + Fields []zapcore.Field + } + } + lockCheck sync.RWMutex + lockEnabled sync.RWMutex + lockSync sync.RWMutex + lockWith sync.RWMutex + lockWrite sync.RWMutex +} + +// Check calls CheckFunc. +func (mock *ZapCoreMock) Check(entry zapcore.Entry, checkedEntry *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if mock.CheckFunc == nil { + panic("ZapCoreMock.CheckFunc: method is nil but Core.Check was just called") + } + callInfo := struct { + Entry zapcore.Entry + CheckedEntry *zapcore.CheckedEntry + }{ + Entry: entry, + CheckedEntry: checkedEntry, + } + mock.lockCheck.Lock() + mock.calls.Check = append(mock.calls.Check, callInfo) + mock.lockCheck.Unlock() + return mock.CheckFunc(entry, checkedEntry) +} + +// CheckCalls gets all the calls that were made to Check. +// Check the length with: +// +// len(mockedCore.CheckCalls()) +func (mock *ZapCoreMock) CheckCalls() []struct { + Entry zapcore.Entry + CheckedEntry *zapcore.CheckedEntry +} { + var calls []struct { + Entry zapcore.Entry + CheckedEntry *zapcore.CheckedEntry + } + mock.lockCheck.RLock() + calls = mock.calls.Check + mock.lockCheck.RUnlock() + return calls +} + +// Enabled calls EnabledFunc. +func (mock *ZapCoreMock) Enabled(level zapcore.Level) bool { + if mock.EnabledFunc == nil { + panic("ZapCoreMock.EnabledFunc: method is nil but Core.Enabled was just called") + } + callInfo := struct { + Level zapcore.Level + }{ + Level: level, + } + mock.lockEnabled.Lock() + mock.calls.Enabled = append(mock.calls.Enabled, callInfo) + mock.lockEnabled.Unlock() + return mock.EnabledFunc(level) +} + +// EnabledCalls gets all the calls that were made to Enabled. +// Check the length with: +// +// len(mockedCore.EnabledCalls()) +func (mock *ZapCoreMock) EnabledCalls() []struct { + Level zapcore.Level +} { + var calls []struct { + Level zapcore.Level + } + mock.lockEnabled.RLock() + calls = mock.calls.Enabled + mock.lockEnabled.RUnlock() + return calls +} + +// Sync calls SyncFunc. +func (mock *ZapCoreMock) Sync() error { + if mock.SyncFunc == nil { + panic("ZapCoreMock.SyncFunc: method is nil but Core.Sync was just called") + } + callInfo := struct { + }{} + mock.lockSync.Lock() + mock.calls.Sync = append(mock.calls.Sync, callInfo) + mock.lockSync.Unlock() + return mock.SyncFunc() +} + +// SyncCalls gets all the calls that were made to Sync. +// Check the length with: +// +// len(mockedCore.SyncCalls()) +func (mock *ZapCoreMock) SyncCalls() []struct { +} { + var calls []struct { + } + mock.lockSync.RLock() + calls = mock.calls.Sync + mock.lockSync.RUnlock() + return calls +} + +// With calls WithFunc. +func (mock *ZapCoreMock) With(fields []zapcore.Field) zapcore.Core { + if mock.WithFunc == nil { + panic("ZapCoreMock.WithFunc: method is nil but Core.With was just called") + } + callInfo := struct { + Fields []zapcore.Field + }{ + Fields: fields, + } + mock.lockWith.Lock() + mock.calls.With = append(mock.calls.With, callInfo) + mock.lockWith.Unlock() + return mock.WithFunc(fields) +} + +// WithCalls gets all the calls that were made to With. +// Check the length with: +// +// len(mockedCore.WithCalls()) +func (mock *ZapCoreMock) WithCalls() []struct { + Fields []zapcore.Field +} { + var calls []struct { + Fields []zapcore.Field + } + mock.lockWith.RLock() + calls = mock.calls.With + mock.lockWith.RUnlock() + return calls +} + +// Write calls WriteFunc. +func (mock *ZapCoreMock) Write(entry zapcore.Entry, fields []zapcore.Field) error { + if mock.WriteFunc == nil { + panic("ZapCoreMock.WriteFunc: method is nil but Core.Write was just called") + } + callInfo := struct { + Entry zapcore.Entry + Fields []zapcore.Field + }{ + Entry: entry, + Fields: fields, + } + mock.lockWrite.Lock() + mock.calls.Write = append(mock.calls.Write, callInfo) + mock.lockWrite.Unlock() + return mock.WriteFunc(entry, fields) +} + +// WriteCalls gets all the calls that were made to Write. +// Check the length with: +// +// len(mockedCore.WriteCalls()) +func (mock *ZapCoreMock) WriteCalls() []struct { + Entry zapcore.Entry + Fields []zapcore.Field +} { + var calls []struct { + Entry zapcore.Entry + Fields []zapcore.Field + } + mock.lockWrite.RLock() + calls = mock.calls.Write + mock.lockWrite.RUnlock() + return calls +} diff --git a/logp/core_test.go b/logp/core_test.go index 3d80b601..c6bd929c 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -19,11 +19,13 @@ package logp import ( "encoding/json" + "errors" "io" golog "log" "os" "path/filepath" "runtime" + "strings" "testing" "github.com/stretchr/testify/assert" @@ -379,3 +381,198 @@ func TestWithFileOrStderrOutput(t *testing.T) { }) } } + +type writeSyncer struct { + strings.Builder +} + +// Sync is a no-op +func (w writeSyncer) Sync() error { + return nil +} + +func TestTypedLoggerCore(t *testing.T) { + testCases := []struct { + name string + entry zapcore.Entry + field zapcore.Field + expectedDefaultLog string + expectedTypedLog string + }{ + { + name: "info level default logger", + entry: zapcore.Entry{Level: zapcore.InfoLevel, Message: "msg"}, + field: skipField(), + expectedDefaultLog: `{"level":"info","msg":"msg"}`, + }, + { + name: "info level typed logger", + entry: zapcore.Entry{Level: zapcore.InfoLevel, Message: "msg"}, + field: strField("log.type", "sensitive"), + expectedTypedLog: `{"level":"info","msg":"msg","log.type":"sensitive"}`, + }, + + { + name: "debug level typed logger", + entry: zapcore.Entry{Level: zapcore.DebugLevel, Message: "msg"}, + field: skipField(), + }, + { + name: "debug level typed logger", + entry: zapcore.Entry{Level: zapcore.DebugLevel, Message: "msg"}, + field: strField("log.type", "sensitive"), + }, + } + + defaultWriter := writeSyncer{} + typedWriter := writeSyncer{} + + cfg := zap.NewProductionEncoderConfig() + cfg.TimeKey = "" // remove the time to make the log entry consistent + + defaultCore := zapcore.NewCore( + zapcore.NewJSONEncoder(cfg), + &defaultWriter, + zapcore.InfoLevel, + ) + + typedCore := zapcore.NewCore( + zapcore.NewJSONEncoder(cfg), + &typedWriter, + zapcore.InfoLevel, + ) + + core := typedLoggerCore{ + defaultCore: defaultCore, + typedCore: typedCore, + key: "log.type", + value: "sensitive", + } + + for _, tc := range testCases { + t.Run(tc.name+" Check method", func(t *testing.T) { + defaultWriter.Reset() + typedWriter.Reset() + + if ce := core.Check(tc.entry, nil); ce != nil { + ce.Write(tc.field) + } + defaultLog := strings.TrimSpace(defaultWriter.String()) + typedLog := strings.TrimSpace(typedWriter.String()) + + if tc.expectedDefaultLog != defaultLog { + t.Errorf("expecting default log to be %q, got %q", tc.expectedDefaultLog, defaultLog) + } + if tc.expectedTypedLog != typedLog { + t.Errorf("expecting typed log to be %q, got %q", tc.expectedTypedLog, typedLog) + } + }) + + // The write method does not check the level, so we skip + // this test if the test case is a lower level + if tc.entry.Level < zapcore.InfoLevel { + continue + } + + t.Run(tc.name+" Write method", func(t *testing.T) { + defaultWriter.Reset() + typedWriter.Reset() + + core.Write(tc.entry, []zapcore.Field{tc.field}) + + defaultLog := strings.TrimSpace(defaultWriter.String()) + typedLog := strings.TrimSpace(typedWriter.String()) + + if tc.expectedDefaultLog != defaultLog { + t.Errorf("expecting default log to be %q, got %q", tc.expectedDefaultLog, defaultLog) + } + if tc.expectedTypedLog != typedLog { + t.Errorf("expecting typed log to be %q, got %q", tc.expectedTypedLog, typedLog) + } + + }) + } + + t.Run("method Enabled", func(t *testing.T) { + if !core.Enabled(zapcore.InfoLevel) { + t.Error("core.Enable must return true for level info") + } + + if core.Enabled(zapcore.DebugLevel) { + t.Error("core.Enable must return true for level debug") + } + }) +} + +func TestTypedLoggerCoreSync(t *testing.T) { + t.Run("happy path", func(t *testing.T) { + core := typedLoggerCore{ + defaultCore: &ZapCoreMock{ + SyncFunc: func() error { return nil }, + }, + typedCore: &ZapCoreMock{ + SyncFunc: func() error { return nil }, + }, + } + + if err := core.Sync(); err != nil { + t.Fatalf("Sync must not return an error: %s", err) + } + }) + + t.Run("both cores return error", func(t *testing.T) { + errMsg1 := "some error from defaultCore" + errMsg2 := "some error from typedCore" + core := typedLoggerCore{ + defaultCore: &ZapCoreMock{ + SyncFunc: func() error { return errors.New(errMsg1) }, + }, + typedCore: &ZapCoreMock{ + SyncFunc: func() error { return errors.New(errMsg2) }, + }, + } + + err := core.Sync() + if err == nil { + t.Fatal("Sync must return an error") + } + + gotMsg := err.Error() + if !strings.Contains(gotMsg, errMsg1) { + t.Errorf("expecting %q in the error string: %q", errMsg1, gotMsg) + } + if !strings.Contains(gotMsg, errMsg2) { + t.Errorf("expecting %q in the error string: %q", errMsg2, gotMsg) + } + }) +} + +func TestTypedLoggerCoreWith(t *testing.T) { + defaultCoreMock := &ZapCoreMock{} + typedCoreMock := &ZapCoreMock{} + + defaultCoreMock.WithFunc = func(fields []zapcore.Field) zapcore.Core { return defaultCoreMock } + typedCoreMock.WithFunc = func(fields []zapcore.Field) zapcore.Core { return typedCoreMock } + core := typedLoggerCore{ + defaultCore: defaultCoreMock, + typedCore: typedCoreMock, + } + + field := strField("foo", "bar") + core.With([]zapcore.Field{field}) + + if core.defaultCore != defaultCoreMock { + t.Error("defaultCore must not change after call to With") + } + if core.typedCore != typedCoreMock { + t.Error("typedCore must not change after call to With") + } +} + +func strField(key, val string) zapcore.Field { + return zapcore.Field{Type: zapcore.StringType, Key: key, String: val} +} + +func skipField() zapcore.Field { + return zapcore.Field{Type: zapcore.SkipType} +} From 7fa40e2759d6aaa344fab0c1e9a8cd2d45c9d7e4 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 29 Jan 2024 15:19:49 +0100 Subject: [PATCH 17/26] make lint happy --- logp/core_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/logp/core_test.go b/logp/core_test.go index c6bd929c..8032b732 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -478,6 +478,7 @@ func TestTypedLoggerCore(t *testing.T) { defaultWriter.Reset() typedWriter.Reset() + //nolint:errcheck // It's a test and the underlying writer never fails. core.Write(tc.entry, []zapcore.Field{tc.field}) defaultLog := strings.TrimSpace(defaultWriter.String()) From 8cd2a27798e7e8307d1a11499a4d05801592345a Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 28 Mar 2024 08:53:34 +0100 Subject: [PATCH 18/26] Refactoring - Better name for some functions/variables - Allowing the typedLogger to have any output, its the caller's responsibility to restric output usage - Moved `typedLogger` to its own file - Updated tests accoringly --- logp/configure/logging.go | 5 +-- logp/core.go | 92 ++------------------------------------- logp/core_test.go | 66 +++++++--------------------- logp/typedloggercore.go | 63 +++++++++++++++++++++++++++ 4 files changed, 84 insertions(+), 142 deletions(-) create mode 100644 logp/typedloggercore.go diff --git a/logp/configure/logging.go b/logp/configure/logging.go index 3ef17a21..addff30d 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -81,8 +81,7 @@ func LoggingWithOutputs(beatName string, cfg, typedCfg *config.C, outputs ...zap // LoggingWithTypedOutputs applies some defaults then calls ConfigureWithTypedOutputs // -// At the moment only the sensitive output is supported. It will log any entry that sets -// `log.type: sensitive` to a different file. +// TODO (Tiago): Do we even need this? func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName @@ -101,7 +100,7 @@ func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, k return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) } - return logp.ConfigureWithTypedOutputs(config, typedLogpConfig, "log.type", "sensitive", outputs...) + return logp.ConfigureWithTypedOutput(config, typedLogpConfig, logKey, kind, outputs...) } func applyFlags(cfg *logp.Config) { diff --git a/logp/core.go b/logp/core.go index f44679db..c6240a15 100644 --- a/logp/core.go +++ b/logp/core.go @@ -139,7 +139,7 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro return nil } -// ConfigureWithTypedOutputs configures the global logger to use typed outputs. +// ConfigureWithTypedOutput configures the global logger to use typed outputs. // // If a log entry matches the defined key/value, this entry is logged using the // core generated from `typedLoggerCfg`, otherwise it will be logged by all @@ -153,15 +153,15 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro // - `value` is the value compared against the `logKey` entry // - `outputs` is a list of cores that will be added together with the core // generated by `defaultLoggerCfg` as the default output for the loggger. -func ConfigureWithTypedOutputs(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { +func ConfigureWithTypedOutput(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { sink, level, observedLogs, selectors, err := createSink(defaultLoggerCfg, outputs...) if err != nil { return err } - typedCore, err := makeFileOutput(typedLoggerCfg, level) + typedCore, err := createLogOutput(typedLoggerCfg, level) if err != nil { - return fmt.Errorf("could not create sensitive file output: %w", err) + return fmt.Errorf("could not create typed logger output: %w", err) } sink = &typedLoggerCore{ @@ -289,34 +289,6 @@ func makeEventLogOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, er return wrappedCore(core), nil } -// WithFileOrStderrOutput configures the logger with an output based on cfg. -// If neither `cfg.ToFiles` nor `cfg.ToSdterr` are true, then a noop output -// is created. If both are true, the file output has preference. -func WithFileOrStderrOutput(cfg Config) func(zapcore.Core) zapcore.Core { - var out zapcore.Core - var err error - - switch { - case cfg.ToFiles: - out, err = makeFileOutput(cfg, cfg.Level.ZapLevel()) - case cfg.ToStderr: - out, err = makeStderrOutput(cfg, cfg.Level.ZapLevel()) - default: - out = zapcore.NewNopCore() - err = errors.New("unexpected output type, only allowed outputs are 'file' and 'stderr'") - } - - if err != nil { - L().Errorf("could not create log output: %s", err) - } - - f := func(zapcore.Core) zapcore.Core { - return out - } - - return f -} - func makeFileOutput(cfg Config, enab zapcore.LevelEnabler) (zapcore.Core, error) { filename := paths.Resolve(paths.Logs, filepath.Join(cfg.Files.Path, cfg.LogFilename())) @@ -424,59 +396,3 @@ func (m multiCore) Sync() error { } return errors.Join(errs...) } - -// typedLoggerCore takes two cores and directs logs entries to one of them -// with the value of the field defined by the pair `key` and `value` -// -// If `entry[key] == value` the typedCore is used, otherwise the -// defaultCore is used. -// WARNING: The level of both cores must always be the same! -// typedLoggerCore will only use the defaultCore level to decide -// whether to log an entry or not -type typedLoggerCore struct { - typedCore zapcore.Core - defaultCore zapcore.Core - value string - key string -} - -func (t *typedLoggerCore) Enabled(l zapcore.Level) bool { - return t.defaultCore.Enabled(l) -} - -func (t *typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { - t.defaultCore = t.defaultCore.With(fields) - t.typedCore = t.typedCore.With(fields) - return t -} - -func (t *typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { - if t.defaultCore.Enabled(e.Level) { - return ce.AddCore(e, t) - } - - return ce -} - -func (t *typedLoggerCore) Sync() error { - defaultErr := t.defaultCore.Sync() - typedErr := t.typedCore.Sync() - - if defaultErr != nil || typedErr != nil { - return fmt.Errorf("error syncing logger. DefaultCore: '%w', typedCore: '%w'", defaultErr, typedErr) - } - - return nil -} - -func (t *typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { - for _, f := range fields { - if f.Key == t.key { - if f.String == t.value { - return t.typedCore.Write(e, fields) - } - } - } - - return t.defaultCore.Write(e, fields) -} diff --git a/logp/core_test.go b/logp/core_test.go index 8032b732..ee20216d 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -250,7 +250,7 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { } expectedLogMessage := "this is a log message" - expectedLogLogger := t.Name() + "-second" + expectedLogLoggerName := t.Name() + "-second" // We follow the same approach as on a Beat, first the logger // (always global) is configured and used, then we instantiate @@ -283,16 +283,26 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { secondCfg.Files.Name = "test-log-file" secondCfg.Files.Path = tempDir2 + // Create a new output for the second logger using the same level + // as the global logger + out, err := createLogOutput(secondCfg, loggerCfg.Level.ZapLevel()) + if err != nil { + t.Fatalf("could not create output for second config") + } + outCore := func(zapcore.Core) zapcore.Core { return out } + // We do not call Configure here as we do not want to affect // the global logger configuration secondLogger := NewLogger(t.Name() + "-second") - secondLogger = secondLogger.WithOptions(zap.WrapCore(WithFileOrStderrOutput(secondCfg))) + secondLogger = secondLogger.WithOptions(zap.WrapCore(outCore)) secondLogger.Info(expectedLogMessage) if err := secondLogger.Sync(); err != nil { t.Fatalf("could not sync log file from second logger: %s", err) } - // Writes again with the first logger to ensure it has not been affected + // TODO: Refactor it into a function and use to assert both loggers worked as expected + + // Write again with the first logger to ensure it has not been affected // by the new configuration on the second logger. logger.Info("not the message we want") if err := logger.Sync(); err != nil { @@ -328,60 +338,14 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { } // Ensure a couple of fields exist - if logEntry["log.logger"] != expectedLogLogger { - t.Fatalf("expecting 'log.logger' to be '%s', got '%s' instead", expectedLogLogger, logEntry["log.logger"]) + if logEntry["log.logger"] != expectedLogLoggerName { + t.Fatalf("expecting 'log.logger' to be '%s', got '%s' instead", expectedLogLoggerName, logEntry["log.logger"]) } if logEntry["message"] != expectedLogMessage { t.Fatalf("expecting 'message' to be '%s, got '%s' instead", expectedLogMessage, logEntry["message"]) } } -func TestWithFileOrStderrOutput(t *testing.T) { - testCases := []struct { - name string - toStderr bool - toFile bool - }{ - { - name: "stderr output", - toStderr: true, - toFile: false, - }, - { - name: "file output", - toStderr: false, - toFile: true, - }, - } - - notEnabledLevels := []zapcore.Level{zapcore.InfoLevel, zapcore.DebugLevel} - enabledLevels := []zapcore.Level{zapcore.ErrorLevel, zapcore.PanicLevel} - - for _, tc := range testCases { - cfg := DefaultConfig(DefaultEnvironment) - cfg.ToStderr = tc.toStderr - cfg.ToFiles = tc.toFile - cfg.Level = ErrorLevel - - f := WithFileOrStderrOutput(cfg) - core := f(zapcore.NewNopCore()) - - t.Run(tc.name, func(t *testing.T) { - for _, l := range notEnabledLevels { - if core.Enabled(l) { - t.Errorf("level %s must not be enabled", l.String()) - } - } - - for _, l := range enabledLevels { - if !core.Enabled(l) { - t.Errorf("level %s must Vbe enabled", l.String()) - } - } - }) - } -} - type writeSyncer struct { strings.Builder } diff --git a/logp/typedloggercore.go b/logp/typedloggercore.go new file mode 100644 index 00000000..2ec87f49 --- /dev/null +++ b/logp/typedloggercore.go @@ -0,0 +1,63 @@ +package logp + +import ( + "fmt" + + "go.uber.org/zap/zapcore" +) + +// typedLoggerCore takes two cores and directs logs entries to one of them +// with the value of the field defined by the pair `key` and `value` +// +// If `entry[key] == value` the typedCore is used, otherwise the +// defaultCore is used. +// WARNING: The level of both cores must always be the same! +// typedLoggerCore will only use the defaultCore level to decide +// whether to log an entry or not +type typedLoggerCore struct { + typedCore zapcore.Core + defaultCore zapcore.Core + value string + key string +} + +func (t *typedLoggerCore) Enabled(l zapcore.Level) bool { + return t.defaultCore.Enabled(l) +} + +func (t *typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { + t.defaultCore = t.defaultCore.With(fields) + t.typedCore = t.typedCore.With(fields) + return t +} + +func (t *typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if t.defaultCore.Enabled(e.Level) { + return ce.AddCore(e, t) + } + + return ce +} + +func (t *typedLoggerCore) Sync() error { + defaultErr := t.defaultCore.Sync() + typedErr := t.typedCore.Sync() + + if defaultErr != nil || typedErr != nil { + return fmt.Errorf("error syncing logger. DefaultCore: '%w', typedCore: '%w'", defaultErr, typedErr) + } + + return nil +} + +func (t *typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { + for _, f := range fields { + if f.Key == t.key { + if f.String == t.value { + return t.typedCore.Write(e, fields) + } + } + } + + return t.defaultCore.Write(e, fields) +} From 93843ee8e35be8e66f8653842ddc2353d0eac887 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 8 Apr 2024 15:32:44 +0200 Subject: [PATCH 19/26] Test both logger outputs/files --- logp/core_test.go | 72 +++++++++++++++++++++++++++++++---------------- 1 file changed, 48 insertions(+), 24 deletions(-) diff --git a/logp/core_test.go b/logp/core_test.go index ee20216d..f2ce566d 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -18,6 +18,7 @@ package logp import ( + "bufio" "encoding/json" "errors" "io" @@ -249,8 +250,8 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { tempDir2 = t.TempDir() } - expectedLogMessage := "this is a log message" - expectedLogLoggerName := t.Name() + "-second" + secondLoggerMessage := "this is a log message" + secondLoggerName := t.Name() + "-second" // We follow the same approach as on a Beat, first the logger // (always global) is configured and used, then we instantiate @@ -268,10 +269,13 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { if err := Configure(loggerCfg); err != nil { t.Errorf("could not initialise logger: %s", err) } - logger := L() // Create a log entry just to "test" the logger - logger.Info("not the message we want") + firstLoggerName := "default-beat-logger" + firstLoggerMessage := "not the message we want" + + logger := L().Named(firstLoggerName) + logger.Info(firstLoggerMessage) if err := logger.Sync(); err != nil { t.Fatalf("could not sync log file from fist logger: %s", err) } @@ -293,56 +297,76 @@ func TestCreatingNewLoggerWithDifferentOutput(t *testing.T) { // We do not call Configure here as we do not want to affect // the global logger configuration - secondLogger := NewLogger(t.Name() + "-second") + secondLogger := NewLogger(secondLoggerName) secondLogger = secondLogger.WithOptions(zap.WrapCore(outCore)) - secondLogger.Info(expectedLogMessage) + secondLogger.Info(secondLoggerMessage) if err := secondLogger.Sync(); err != nil { t.Fatalf("could not sync log file from second logger: %s", err) } - // TODO: Refactor it into a function and use to assert both loggers worked as expected - // Write again with the first logger to ensure it has not been affected // by the new configuration on the second logger. - logger.Info("not the message we want") + logger.Info(firstLoggerMessage) if err := logger.Sync(); err != nil { t.Fatalf("could not sync log file from fist logger: %s", err) } + // Ensure the second logger is working as expected + assertKVinLogentry(t, tempDir2, "log.logger", secondLoggerName) + assertKVinLogentry(t, tempDir2, "message", secondLoggerMessage) + + // Ensure the first logger is working as expected + assertKVinLogentry(t, tempDir1, "log.logger", firstLoggerName) + assertKVinLogentry(t, tempDir1, "message", firstLoggerMessage) +} + +func assertKVinLogentry(t *testing.T, dir, key, value string) { + t.Helper() + // Find the log file. The file name gets the date added, so we list the // directory and ensure there is only one file there. - files, err := os.ReadDir(tempDir2) + files, err := os.ReadDir(dir) if err != nil { - t.Fatalf("could not read temporary directory '%s': %s", tempDir2, err) + t.Fatalf("could not read temporary directory '%s': %s", dir, err) } // If there is more than one file, list all files // and fail the test. if len(files) != 1 { - t.Errorf("found %d files in '%s', there must be only one", len(files), tempDir2) - t.Errorf("Files in '%s':", tempDir2) + t.Errorf("found %d files in '%s', there must be only one", len(files), dir) + t.Errorf("Files in '%s':", dir) for _, f := range files { t.Error(f.Name()) } t.FailNow() } - logData, err := os.ReadFile(filepath.Join(tempDir2, files[0].Name())) + fullPath := filepath.Join(dir, files[0].Name()) + f, err := os.Open(fullPath) if err != nil { - t.Fatalf("could not read log file: %s", err) + t.Fatalf("could not open '%s' for reading: %s", fullPath, err) } + defer f.Close() + sc := bufio.NewScanner(f) + lines := []string{} + for sc.Scan() { + logData := sc.Bytes() - logEntry := map[string]any{} - if err := json.Unmarshal(logData, &logEntry); err != nil { - t.Fatalf("could not read log entry as JSON. Log entry: '%s'", string(logData)) - } + logEntry := map[string]any{} + if err := json.Unmarshal(logData, &logEntry); err != nil { + t.Fatalf("could not read log entry as JSON. Log entry: '%s'", string(logData)) + } - // Ensure a couple of fields exist - if logEntry["log.logger"] != expectedLogLoggerName { - t.Fatalf("expecting 'log.logger' to be '%s', got '%s' instead", expectedLogLoggerName, logEntry["log.logger"]) + if logEntry[key] == value { + return + } + lines = append(lines, string(logData)) } - if logEntry["message"] != expectedLogMessage { - t.Fatalf("expecting 'message' to be '%s, got '%s' instead", expectedLogMessage, logEntry["message"]) + + t.Errorf("could not find [%s]='%s' in any log line.", key, value) + t.Log("Log lines:") + for _, l := range lines { + t.Log(l) } } From 9027d035fa818d8deeeb78520a7de1605be15c03 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 8 Apr 2024 15:39:12 +0200 Subject: [PATCH 20/26] Add licence headers --- logp/typedloggercore.go | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/logp/typedloggercore.go b/logp/typedloggercore.go index 2ec87f49..c8829136 100644 --- a/logp/typedloggercore.go +++ b/logp/typedloggercore.go @@ -1,3 +1,20 @@ +// Licensed to Elasticsearch B.V. under one or more contributor +// license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright +// ownership. Elasticsearch B.V. licenses this file to you under +// the Apache License, Version 2.0 (the "License"); you may +// not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + package logp import ( From f58d98e6d8a4f96ae470a2cb2ed2f64bdfe83c52 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 8 Apr 2024 17:22:42 +0200 Subject: [PATCH 21/26] Add default config and values Add DefaultEventConfig function and correctly set some configuraiton options following the default logger configuration --- logp/config.go | 24 ++++++++++++++++++++++++ logp/configure/logging.go | 23 ++++++++++++++++------- 2 files changed, 40 insertions(+), 7 deletions(-) diff --git a/logp/config.go b/logp/config.go index 1e82b6e7..8d890658 100644 --- a/logp/config.go +++ b/logp/config.go @@ -88,6 +88,30 @@ func DefaultConfig(environment Environment) Config { } } +// DefaultEventConfig returns the default config options for the event logger in +// a given environment the Beat is supposed to be run within. +func DefaultEventConfig(environment Environment) Config { + return Config{ + Level: defaultLevel, + ToFiles: true, + ToStderr: false, + Files: FileConfig{ + MaxSize: 5 * 1024 * 1024, // 5Mb + MaxBackups: 2, + Permissions: 0600, + Interval: 0, + RotateOnStartup: false, + RedirectStderr: false, + Name: "event-data", + }, + Metrics: MetricsConfig{ + Enabled: false, + }, + environment: environment, + addCaller: true, + } +} + // LogFilename returns the base filename to which logs will be written for // the "files" log output. If another log output is used, or `logging.files.name` // is unspecified, then the beat name will be returned. diff --git a/logp/configure/logging.go b/logp/configure/logging.go index addff30d..407d7539 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -80,8 +80,6 @@ func LoggingWithOutputs(beatName string, cfg, typedCfg *config.C, outputs ...zap } // LoggingWithTypedOutputs applies some defaults then calls ConfigureWithTypedOutputs -// -// TODO (Tiago): Do we even need this? func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, kind string, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName @@ -93,11 +91,22 @@ func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, k applyFlags(&config) - typedLogpConfig := logp.DefaultConfig(environment) - typedLogpConfig.ToFiles = true - typedLogpConfig.ToStderr = false - if err := typedCfg.Unpack(&typedLogpConfig); err != nil { - return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) + typedLogpConfig := logp.DefaultEventConfig(environment) + defaultName := typedLogpConfig.Files.Name + typedLogpConfig.Beat = beatName + if typedCfg != nil { + if err := typedCfg.Unpack(&typedLogpConfig); err != nil { + return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) + } + } + + // Make sure we're always running on the same log level + typedLogpConfig.Level = config.Level + typedLogpConfig.Selectors = config.Selectors + + // If the name has not been configured, make it {beatName}-events-data + if typedLogpConfig.Files.Name == defaultName { + typedLogpConfig.Files.Name = beatName + "-events-data" } return logp.ConfigureWithTypedOutput(config, typedLogpConfig, logKey, kind, outputs...) From 75c2402c3fa52a47f8c3127ca65204b15ffab612 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Mon, 8 Apr 2024 18:28:30 +0200 Subject: [PATCH 22/26] LoggingWithOutputs does not need typed config --- logp/configure/logging.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index 407d7539..c1d72e86 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -66,7 +66,7 @@ func Logging(beatName string, cfg *config.C) error { // LoggingWithOutputs builds a logp.Config based on the given common.Config and the specified // CLI flags along with the given outputs. -func LoggingWithOutputs(beatName string, cfg, typedCfg *config.C, outputs ...zapcore.Core) error { +func LoggingWithOutputs(beatName string, cfg *config.C, outputs ...zapcore.Core) error { config := logp.DefaultConfig(environment) config.Beat = beatName if cfg != nil { From ba46f6cf2b0fae5bbe55d4abd24a959cb6a09b09 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Tue, 9 Apr 2024 19:13:47 +0200 Subject: [PATCH 23/26] Fix behaviour of typedCore.With --- logp/configure/logging.go | 2 +- logp/core_test.go | 78 +++++++++++++++++++++++++++++++++------ logp/typedloggercore.go | 10 +++-- 3 files changed, 74 insertions(+), 16 deletions(-) diff --git a/logp/configure/logging.go b/logp/configure/logging.go index c1d72e86..b4a3d480 100644 --- a/logp/configure/logging.go +++ b/logp/configure/logging.go @@ -96,7 +96,7 @@ func LoggingWithTypedOutputs(beatName string, cfg, typedCfg *config.C, logKey, k typedLogpConfig.Beat = beatName if typedCfg != nil { if err := typedCfg.Unpack(&typedLogpConfig); err != nil { - return fmt.Errorf("cannot unpack sensitiveCfg: %w", err) + return fmt.Errorf("cannot unpack typed output config: %w", err) } } diff --git a/logp/core_test.go b/logp/core_test.go index f2ce566d..d3d22d40 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -537,24 +537,78 @@ func TestTypedLoggerCoreSync(t *testing.T) { } func TestTypedLoggerCoreWith(t *testing.T) { - defaultCoreMock := &ZapCoreMock{} - typedCoreMock := &ZapCoreMock{} + defaultWriter := writeSyncer{} + typedWriter := writeSyncer{} + + cfg := zap.NewProductionEncoderConfig() + cfg.TimeKey = "" // remove the time to make the log entry consistent + + defaultCore := zapcore.NewCore( + zapcore.NewJSONEncoder(cfg), + &defaultWriter, + zapcore.InfoLevel, + ) + + typedCore := zapcore.NewCore( + zapcore.NewJSONEncoder(cfg), + &typedWriter, + zapcore.InfoLevel, + ) - defaultCoreMock.WithFunc = func(fields []zapcore.Field) zapcore.Core { return defaultCoreMock } - typedCoreMock.WithFunc = func(fields []zapcore.Field) zapcore.Core { return typedCoreMock } core := typedLoggerCore{ - defaultCore: defaultCoreMock, - typedCore: typedCoreMock, + defaultCore: defaultCore, + typedCore: typedCore, + key: "log.type", + value: "sensitive", } - field := strField("foo", "bar") - core.With([]zapcore.Field{field}) + expectedLines := []string{ + // First/Default logger + `{"level":"info","msg":"Very first message"}`, + + // Two messages after calling With + `{"level":"info","msg":"a message with extra fields","foo":"bar"}`, + `{"level":"info","msg":"another message with extra fields","foo":"bar"}`, + + // A message with the default logger + `{"level":"info","msg":"a message without extra fields"}`, + + // Two more messages with a different field + `{"level":"info","msg":"a message with an answer","answer":"42"}`, + `{"level":"info","msg":"another message with an answer","answer":"42"}`, - if core.defaultCore != defaultCoreMock { - t.Error("defaultCore must not change after call to With") + // One last message with the default logger + `{"level":"info","msg":"another message without any extra fields"}`, } - if core.typedCore != typedCoreMock { - t.Error("typedCore must not change after call to With") + + // The default logger, it should not be modified by any call to With. + logger := zap.New(&core) + logger.Info("Very first message") + + // Add a field and write messages + loggerWithFields := logger.With(strField("foo", "bar")) + loggerWithFields.Info("a message with extra fields") + loggerWithFields.Info("another message with extra fields") + + // Use the default logger again + logger.Info("a message without extra fields") + + // New logger with other fields + loggerWithFields = logger.With(strField("answer", "42")) + loggerWithFields.Info("a message with an answer") + loggerWithFields.Info("another message with an answer") + + // One last message with the default logger + logger.Info("another message without any extra fields") + + scanner := bufio.NewScanner(strings.NewReader(defaultWriter.String())) + count := 0 + for scanner.Scan() { + l := scanner.Text() + if l != expectedLines[count] { + t.Error("Expecting:\n", l, "\nGot:\n", expectedLines[count]) + } + count++ } } diff --git a/logp/typedloggercore.go b/logp/typedloggercore.go index c8829136..f4511975 100644 --- a/logp/typedloggercore.go +++ b/logp/typedloggercore.go @@ -43,9 +43,13 @@ func (t *typedLoggerCore) Enabled(l zapcore.Level) bool { } func (t *typedLoggerCore) With(fields []zapcore.Field) zapcore.Core { - t.defaultCore = t.defaultCore.With(fields) - t.typedCore = t.typedCore.With(fields) - return t + newCore := typedLoggerCore{ + defaultCore: t.defaultCore.With(fields), + typedCore: t.typedCore.With(fields), + key: t.key, + value: t.value, + } + return &newCore } func (t *typedLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { From ea0f5c4ae518aba93c38cc23cd8f96414dfdb73b Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Thu, 11 Apr 2024 13:10:18 +0200 Subject: [PATCH 24/26] Correctly handle log selectors when using TypedCore --- logp/core.go | 12 +++++++- logp/selective_test.go | 63 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 74 insertions(+), 1 deletion(-) diff --git a/logp/core.go b/logp/core.go index c6240a15..5ad47db5 100644 --- a/logp/core.go +++ b/logp/core.go @@ -153,13 +153,21 @@ func ConfigureWithOutputs(defaultLoggerCfg Config, outputs ...zapcore.Core) erro // - `value` is the value compared against the `logKey` entry // - `outputs` is a list of cores that will be added together with the core // generated by `defaultLoggerCfg` as the default output for the loggger. +// +// If `defaultLoggerCfg.toObserver` is true, then `typedLoggerCfg` is ignored +// and a single sink is used so all logs can be observed. func ConfigureWithTypedOutput(defaultLoggerCfg, typedLoggerCfg Config, key, value string, outputs ...zapcore.Core) error { sink, level, observedLogs, selectors, err := createSink(defaultLoggerCfg, outputs...) if err != nil { return err } - typedCore, err := createLogOutput(typedLoggerCfg, level) + var typedCore zapcore.Core + if defaultLoggerCfg.toObserver { + typedCore = sink + } else { + typedCore, err = createLogOutput(typedLoggerCfg, level) + } if err != nil { return fmt.Errorf("could not create typed logger output: %w", err) } @@ -171,6 +179,8 @@ func ConfigureWithTypedOutput(defaultLoggerCfg, typedLoggerCfg Config, key, valu value: value, } + sink = selectiveWrapper(sink, selectors) + root := zap.New(sink, makeOptions(defaultLoggerCfg)...) storeLogger(&coreLogger{ selectors: selectors, diff --git a/logp/selective_test.go b/logp/selective_test.go index e03d5bd5..9533e5c1 100644 --- a/logp/selective_test.go +++ b/logp/selective_test.go @@ -54,3 +54,66 @@ func TestLoggerSelectors(t *testing.T) { logs = ObserverLogs().TakeAll() assert.Len(t, logs, 1) } + +func TestTypedCoreSelectors(t *testing.T) { + logSelector := "enabled-log-selector" + expectedMsg := "this should be logged" + + defaultCfg := DefaultConfig(DefaultEnvironment) + eventsCfg := DefaultEventConfig(DefaultEnvironment) + + defaultCfg.Level = DebugLevel + defaultCfg.toObserver = true + defaultCfg.ToStderr = false + defaultCfg.ToFiles = false + defaultCfg.Selectors = []string{logSelector} + + eventsCfg.Level = defaultCfg.Level + eventsCfg.toObserver = defaultCfg.toObserver + eventsCfg.ToStderr = defaultCfg.ToStderr + eventsCfg.ToFiles = defaultCfg.ToFiles + eventsCfg.Selectors = defaultCfg.Selectors + + ConfigureWithTypedOutput(defaultCfg, eventsCfg, "log.type", "event") + + enabledSelector := NewLogger(logSelector) + disabledSelector := NewLogger("foo-selector") + + enabledSelector.Debugw(expectedMsg) + enabledSelector.Debugw(expectedMsg, "log.type", "event") + disabledSelector.Debug("this should not be logged") + + logEntries := ObserverLogs().TakeAll() + if len(logEntries) != 2 { + t.Errorf("expecting 2 log entries, got %d", len(logEntries)) + t.Log("Log entries:") + for _, e := range logEntries { + t.Log("Message:", e.Message, "Fields:", e.Context) + } + t.FailNow() + } + + for i, logEntry := range logEntries { + msg := logEntry.Message + if msg != expectedMsg { + t.Fatalf("[%d] expecting log message '%s', got '%s'", i, expectedMsg, msg) + } + + // The second entry should also contain `log.type: event` + if i == 1 { + fields := logEntry.Context + if len(fields) != 1 { + t.Errorf("expecting one field, got %d", len(fields)) + } + + k := fields[0].Key + v := fields[0].String + if k != "log.type" { + t.Errorf("expecting key 'log.type', got '%s'", k) + } + if v != "event" { + t.Errorf("expecting value 'event', got '%s'", v) + } + } + } +} From d950786f081ce171d4e5001edb6f2d6079565963 Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Fri, 12 Apr 2024 12:55:13 +0200 Subject: [PATCH 25/26] Add error check Add error check in a test to address lint issues. --- logp/selective_test.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/logp/selective_test.go b/logp/selective_test.go index 9533e5c1..16c07d87 100644 --- a/logp/selective_test.go +++ b/logp/selective_test.go @@ -74,7 +74,9 @@ func TestTypedCoreSelectors(t *testing.T) { eventsCfg.ToFiles = defaultCfg.ToFiles eventsCfg.Selectors = defaultCfg.Selectors - ConfigureWithTypedOutput(defaultCfg, eventsCfg, "log.type", "event") + if err := ConfigureWithTypedOutput(defaultCfg, eventsCfg, "log.type", "event"); err != nil { + t.Fatalf("could not configure logger: %s", err) + } enabledSelector := NewLogger(logSelector) disabledSelector := NewLogger("foo-selector") From 8391f6f90ef534f26801fc43023e52fd35120e5d Mon Sep 17 00:00:00 2001 From: Tiago Queiroz Date: Wed, 24 Apr 2024 09:02:03 -0400 Subject: [PATCH 26/26] Break loop early Break loop early whe `f.Key == t.Key` but the values are different. --- logp/typedloggercore.go | 1 + 1 file changed, 1 insertion(+) diff --git a/logp/typedloggercore.go b/logp/typedloggercore.go index f4511975..83da18a0 100644 --- a/logp/typedloggercore.go +++ b/logp/typedloggercore.go @@ -77,6 +77,7 @@ func (t *typedLoggerCore) Write(e zapcore.Entry, fields []zapcore.Field) error { if f.String == t.value { return t.typedCore.Write(e, fields) } + return t.defaultCore.Write(e, fields) } }