diff --git a/logp/logptest/logger.go b/logp/logptest/logger.go new file mode 100644 index 0000000..8ee002c --- /dev/null +++ b/logp/logptest/logger.go @@ -0,0 +1,203 @@ +// 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 logptest + +import ( + "bufio" + "errors" + "fmt" + "io" + "os" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.elastic.co/ecszap" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + "github.com/elastic/elastic-agent-libs/logp" +) + +// Logger wraps a *logp.Logger and makes it more suitable for tests. +// Key features: +// - All logs are saved on a single temporary log file +// - On failures, the log file is kept and its path printed +// - Methods to search and wait for log entries are provided, +// they keep track of the offset, ensuring ordering when +// when searching for logs +type Logger struct { + *logp.Logger + logFile *os.File + offset int64 +} + +// NewFileLogger returns a logger that logs to a file and has methods +// to search in the logs. +// If dir is not an empty string, the log file will be generated on +// this folder. This is useful to make CI collect the logs in case +// a test fails. If dir is an empty string, the OS temporary folder +// is used. +// +// The *logp.Logger is embedded into it, so [Logger] is a drop-in +// replacement for a *logp.Logger, or the logger can be accessed via +// [Logger.Logger] +func NewFileLogger(t testing.TB, dir string) *Logger { + encoderConfig := ecszap.ECSCompatibleEncoderConfig(zapcore.EncoderConfig{}) + encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + encoder := zapcore.NewJSONEncoder(encoderConfig) + + if dir == "" { + dir = os.TempDir() + } + + if err := os.MkdirAll(dir, 0o750); err != nil { + t.Fatalf("cannot create folder for logs: %s", err) + } + + f, err := os.CreateTemp(dir, "testing-logger-*.log") + if err != nil { + t.Fatalf("cannot create log file: %s", err) + } + + core := zapcore.NewCore(encoder, zapcore.AddSync(f), zap.DebugLevel) + + tl := &Logger{ + logFile: f, + } + + t.Cleanup(func() { + // Sync the core, the file, then close the file + if err := core.Sync(); err != nil { + t.Logf("cannot sync zap core: %s", err) + } + + if err := f.Sync(); err != nil { + t.Logf("cannot sync log file: %s", err) + } + + if err := f.Close(); err != nil { + t.Logf("cannot close log file: %s", err) + } + + // If the test failed, print the log file location, + // otherwise remove it. + if t.Failed() { + t.Logf("Full logs written to %s", f.Name()) + return + } + + if err := os.Remove(f.Name()); err != nil { + t.Logf("could not remove temporary log file: %s", err) + } + }) + + logger := logp.NewLogger( + "", + zap.WrapCore(func(in zapcore.Core) zapcore.Core { + return core + })) + + tl.Logger = logger + + return tl +} + +// WaitLogsContains waits for the specified string s to be present in the logs within +// the given timeout duration and fails the test if s is not found. +// It keeps track of the log file offset, reading only new lines. Each +// subsequent call to WaitLogsContains will only check logs not yet evaluated. +// msgAndArgs should be a format string and arguments that will be printed +// if the logs are not found, providing additional context for debugging. +func (l *Logger) WaitLogsContains(t testing.TB, s string, timeout time.Duration, msgAndArgs ...any) { + t.Helper() + require.EventuallyWithT( + t, + func(c *assert.CollectT) { + found, err := l.FindInLogs(s) + if err != nil { + c.Errorf("cannot check the log file: %s", err) + return + } + + if !found { + c.Errorf("did not find '%s' in the logs", s) + } + }, + timeout, + 100*time.Millisecond, + msgAndArgs...) +} + +// LogContains searches for str in the log file keeping track of the +// offset. If there is any issue reading the log file, then t.Fatalf is called, +// if str is not present in the logs, t.Errorf is called. +func (l *Logger) LogContains(t testing.TB, str string) { + t.Helper() + found, err := l.FindInLogs(str) + if err != nil { + t.Fatalf("cannot read log file: %s", err) + } + + if !found { + t.Errorf("'%s' not found in logs", str) + } +} + +// FindInLogs searches for str in the log file keeping track of the offset. +// It returns true if str is found in the logs. If there are any errors, +// it returns false and the error +func (l *Logger) FindInLogs(str string) (bool, error) { + // Open the file again so we can seek and not interfere with + // the logger writing to it. + f, err := os.Open(l.logFile.Name()) + if err != nil { + return false, fmt.Errorf("cannot open log file for reading: %w", err) + } + + if _, err := f.Seek(l.offset, io.SeekStart); err != nil { + return false, fmt.Errorf("cannot seek log file: %w", err) + } + + r := bufio.NewReader(f) + for { + data, err := r.ReadBytes('\n') + line := string(data) + l.offset += int64(len(data)) + + if err != nil { + if !errors.Is(err, io.EOF) { + return false, fmt.Errorf("error reading log file '%s': %w", l.logFile.Name(), err) + } + break + } + + if strings.Contains(line, str) { + return true, nil + } + } + + return false, nil +} + +// ResetOffset resets the log file offset +func (l *Logger) ResetOffset() { + l.offset = 0 +} diff --git a/logp/logptest/logger_test.go b/logp/logptest/logger_test.go new file mode 100644 index 0000000..321fc19 --- /dev/null +++ b/logp/logptest/logger_test.go @@ -0,0 +1,222 @@ +// 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 logptest + +import ( + "bufio" + "bytes" + "encoding/json" + "errors" + "fmt" + "os" + "os/exec" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestNewFileLogger(t *testing.T) { + logger := NewFileLogger(t, "") + logger.Debug("foo") + + assertLogFormat(t, logger.logFile.Name()) + + t.Run("FindInLogs", func(t *testing.T) { + found, err := logger.FindInLogs("foo") + if err != nil { + t.Fatalf("did not expect an error from 'FindInLogs': %s", err) + } + + if !found { + t.Fatal("expecing 'FindInLogs' to return true") + } + }) + + t.Run("LogContains", func(t *testing.T) { + // Log again, because we track offset + logger.Debug("foo") + // Call it and expect the test not to fail + logger.LogContains(t, "foo") + }) + + t.Run("WaitLogContains", func(t *testing.T) { + // Log again, because we track offset + logger.Debug("foo") + // Call it and expect the test not to fail + logger.WaitLogsContains(t, "foo", 200*time.Millisecond) + }) + + t.Run("ResetOffset", func(t *testing.T) { + logger.ResetOffset() + + // We logged "foo" 3 times, so we should find it 3 times in a row. + for range 3 { + found, err := logger.FindInLogs("foo") + if err != nil { + t.Fatalf("did not expect an error from 'FindInLogs': %s", err) + } + + if !found { + t.Fatal("expecing 'FindInLogs' to return true") + } + } + }) +} + +func assertLogFormat(t *testing.T, path string) { + t.Helper() + + f, err := os.Open(path) + if err != nil { + t.Fatalf("cannot open log file: %s", err) + } + defer f.Close() + + sc := bufio.NewScanner(f) + for sc.Scan() { + entry := struct { + Timestamp string `json:"@timestamp"` + LogLevel string `json:"log.level"` + Message string `json:"message"` + }{} + + if err := json.Unmarshal(sc.Bytes(), &entry); err != nil { + t.Fatalf("%q is not a ndjson file: %s", path, err) + } + + // ensure the basic fileds are populated + if entry.Timestamp == "" { + t.Error("'@timestamp' cannot be empty/zero value") + } + + if entry.LogLevel == "" { + t.Error("'log.level' cannot be empty") + } + + if entry.Message == "" { + t.Error("message cannot be empty") + } + } +} + +func TestLoggerCustomDir(t *testing.T) { + dir := t.TempDir() + logger := NewFileLogger(t, dir) + logger.Info("foo") + + files, err := filepath.Glob(filepath.Join(dir, "testing-logger-*.log")) + if err != nil { + t.Fatalf("cannot resolve glob: %s", err) + } + + if len(files) != 1 { + t.Fatalf("expecting a single log file, got: %d", len(files)) + } +} + +func TestLoggerFileIsRemoved(t *testing.T) { + toBeDeletedLogFile := "" + // Use a subtest so it can finish and succeed before + // we check if the log file has been removed + t.Run("log file is removed", func(t *testing.T) { + logger := NewFileLogger(t, "") + logger.Info("foo") + toBeDeletedLogFile = logger.logFile.Name() + }) + + _, err := os.Stat(toBeDeletedLogFile) + if !errors.Is(err, os.ErrNotExist) { + t.Error("the log file must be removed after a test passes") + } +} + +func TestLoggerFileIsKeptOnTestFailure(t *testing.T) { + if os.Getenv("INNER_TEST") == "1" { + // We're inside the subprocess, use Logger and make it fail the test, + // so the actual test can ensure it is behaving correctly + logger := NewFileLogger(t, "") + logger.Info("foo") + logger.Warn("foo") + logger.Debug("foo") + logger.LogContains(t, "bar") + + return + } + + //nolint:gosec // This is intentionally running a subprocess + cmd := exec.CommandContext( + t.Context(), + os.Args[0], + fmt.Sprintf("-test.run=^%s$", + t.Name()), + "-test.v") + cmd.Env = append(cmd.Env, "INNER_TEST=1") + + out, cmdErr := cmd.CombinedOutput() + if cmdErr != nil { + // The test ran by cmd will fail and retrun 1 as the exit code. So we only + // print the error if the main test fails. + defer func() { + if t.Failed() { + t.Errorf("the test process returned an error (this is expected in on a normal test execution): %s", cmdErr) + } + }() + } + + var path string + sc := bufio.NewScanner(bytes.NewReader(out)) + for sc.Scan() { + txt := sc.Text() + // To extract the log file path we split txt in a way that the path + // is the 2nd element. + // The string we're parsing: + // logger.go:103: Full logs written to /tmp/testing-logger-1901210787.log + if strings.Contains(txt, "Full logs written to") { + split := strings.Split(txt, "Full logs written to ") + if len(split) != 2 { + t.Fatalf("could not parse log file form test output, invalid format %q", txt) + } + path = split[1] + t.Cleanup(func() { + if t.Failed() { + t.Logf("Log file %q", path) + } + }) + } + } + + // Finally ensure the log file was kept and has the correct number of lines + f, err := os.Open(path) + if err != nil { + if errors.Is(err, os.ErrNotExist) { + t.Fatalf("log file %q not found after the test exited", path) + } + t.Fatalf("cannot open log file for reading: %s", err) + } + defer f.Close() + + lineCount := 0 + for sc := bufio.NewScanner(f); sc.Scan(); { + lineCount++ + } + + if got, want := lineCount, 3; got != want { + t.Fatalf("expecting log file to contain %d lines, got %d:", want, got) + } +} diff --git a/logp/logptest/logptest.go b/logp/logptest/logptest.go index 0fe2692..9573b62 100644 --- a/logp/logptest/logptest.go +++ b/logp/logptest/logptest.go @@ -28,7 +28,8 @@ import ( "github.com/elastic/elastic-agent-libs/logp" ) -// NewTestingLogger returns a testing suitable logp.Logger. +// NewTestingLogger returns a testing suitable logp.Logger that uses the +// [testing.T] as the logger output. func NewTestingLogger(t testing.TB, selector string, options ...logp.LogOption) *logp.Logger { log := zaptest.NewLogger(t, zaptest.WrapOptions(options...)) log = log.Named(selector) @@ -40,7 +41,8 @@ func NewTestingLogger(t testing.TB, selector string, options ...logp.LogOption) return logger } -// NewTestingLoggerWithObserver returns a testing suitable logp.Logger and an observer +// NewTestingLoggerWithObserver returns a testing suitable logp.Logger that uses the +// [testing.T] as the logger output and an observer. func NewTestingLoggerWithObserver(t testing.TB, selector string) (*logp.Logger, *observer.ObservedLogs) { observedCore, observedLogs := observer.New(zapcore.DebugLevel) logger := NewTestingLogger(t, selector, zap.WrapCore(func(core zapcore.Core) zapcore.Core {