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 f23e1792..b4a3d480 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 { @@ -75,6 +79,39 @@ func LoggingWithOutputs(beatName string, cfg *config.C, outputs ...zapcore.Core) return logp.ConfigureWithOutputs(config, outputs...) } +// LoggingWithTypedOutputs applies some defaults then calls ConfigureWithTypedOutputs +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 { + if err := cfg.Unpack(&config); err != nil { + return err + } + } + + applyFlags(&config) + + 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 typed output config: %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...) +} + func applyFlags(cfg *logp.Config) { if toStderr { cfg.ToStderr = true diff --git a/logp/core.go b/logp/core.go index 321a20d4..5ad47db5 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" @@ -68,10 +68,7 @@ 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 { +func createSink(defaultLoggerCfg Config, outputs ...zapcore.Core) (zapcore.Core, zap.AtomicLevel, *observer.ObservedLogs, map[string]struct{}, error) { var ( sink zapcore.Core observedLogs *observer.ObservedLogs @@ -79,25 +76,25 @@ func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { level zap.AtomicLevel ) - level = zap.NewAtomicLevelAt(cfg.Level.ZapLevel()) + level = zap.NewAtomicLevelAt(defaultLoggerCfg.Level.ZapLevel()) // Build a single output (stderr has priority if more than one are enabled). - if cfg.toObserver { + if defaultLoggerCfg.toObserver { sink, observedLogs = observer.New(level) } else { - sink, err = createLogOutput(cfg, level) + 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 // 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)) - if cfg.Level.Enabled(DebugLevel) && len(cfg.Selectors) > 0 { - for _, sel := range cfg.Selectors { + 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{}{} } @@ -118,7 +115,73 @@ func ConfigureWithOutputs(cfg Config, outputs ...zapcore.Core) error { } sink = newMultiCore(append(outputs, sink)...) - root := zap.New(sink, makeOptions(cfg)...) + + 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, + rootLogger: root, + globalLogger: root.WithOptions(zap.AddCallerSkip(1)), + logger: newLogger(root, ""), + level: level, + observedLogs: observedLogs, + }) + return nil +} + +// 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 +// 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 +// - `typedLoggerCfg` is used to create a new output that will only be used +// when the log entry matches `entry[logKey] = kind` +// - `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. +// +// 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 + } + + 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) + } + + sink = &typedLoggerCore{ + defaultCore: sink, + typedCore: typedCore, + key: key, + value: value, + } + + sink = selectiveWrapper(sink, selectors) + + root := zap.New(sink, makeOptions(defaultLoggerCfg)...) storeLogger(&coreLogger{ selectors: selectors, rootLogger: root, @@ -215,7 +278,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 } 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 a881200b..d3d22d40 100644 --- a/logp/core_test.go +++ b/logp/core_test.go @@ -18,13 +18,21 @@ package logp import ( - "io/ioutil" + "bufio" + "encoding/json" + "errors" + "io" golog "log" + "os" + "path/filepath" + "runtime" + "strings" "testing" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) func TestLogger(t *testing.T) { @@ -167,25 +175,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) { @@ -212,3 +220,402 @@ func TestLoggingECSFields(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 + // 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 + // 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() + } + + 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 + // 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) + } + + // Create a log entry just to "test" the logger + 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) + } + + // 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 + + // 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(secondLoggerName) + secondLogger = secondLogger.WithOptions(zap.WrapCore(outCore)) + secondLogger.Info(secondLoggerMessage) + if err := secondLogger.Sync(); err != nil { + t.Fatalf("could not sync log file from second logger: %s", err) + } + + // Write again with the first logger to ensure it has not been affected + // by the new configuration on the second logger. + 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(dir) + if err != nil { + 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), dir) + t.Errorf("Files in '%s':", dir) + for _, f := range files { + t.Error(f.Name()) + } + t.FailNow() + } + + fullPath := filepath.Join(dir, files[0].Name()) + f, err := os.Open(fullPath) + if err != nil { + 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)) + } + + if logEntry[key] == value { + return + } + lines = append(lines, string(logData)) + } + + t.Errorf("could not find [%s]='%s' in any log line.", key, value) + t.Log("Log lines:") + for _, l := range lines { + t.Log(l) + } +} + +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() + + //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()) + 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) { + 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", + } + + 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"}`, + + // One last message with the default logger + `{"level":"info","msg":"another message without any extra fields"}`, + } + + // 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++ + } +} + +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} +} diff --git a/logp/selective_test.go b/logp/selective_test.go index e03d5bd5..16c07d87 100644 --- a/logp/selective_test.go +++ b/logp/selective_test.go @@ -54,3 +54,68 @@ 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 + + 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") + + 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) + } + } + } +} diff --git a/logp/typedloggercore.go b/logp/typedloggercore.go new file mode 100644 index 00000000..83da18a0 --- /dev/null +++ b/logp/typedloggercore.go @@ -0,0 +1,85 @@ +// 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 ( + "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 { + 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 { + 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) + } + } + + return t.defaultCore.Write(e, fields) +}