From 90711333b9d079dbb6bfb793cf1cbd6adebfc1e8 Mon Sep 17 00:00:00 2001 From: Michael Schurter Date: Fri, 17 Sep 2021 10:24:29 -0700 Subject: [PATCH] allow not appending timestamp to current log file (#64) * allow not appending timestamp to current log file Backward compatible version of #62 -- This version does *not* change the default behavior. Users must opt in to new behavior. This patch updates the file sink to allow *not* appending the timestamp on the current log file. In this mode the timestamp is only appended when the file is rotated. This matches the behavior: - Implemented in Nomad v1.1.4 with hashicorp/nomad#11070 - Requested in hashicorp/nomad#11061 > The following example configures a destination called "My Sink" which > stores audit events at the file `/tmp/audit.json`. Nomad's documentation is a little vague but implies the prior behavior of always appending a timestamp. Also fixed one flaky test: * time may be either the same of after While Go compares time using a monotonic clock that only prevents time from moving *backward,* it does *not* guarantee time will move forward between subsequent calls to `time.Now()`. The After assertion failed in a test run on Github because it is missing the `Equal` comparison on the preceeding assertion. --- .github/workflows/go.yml | 2 +- file_sink.go | 38 +++++++++++--- file_sink_test.go | 100 ++++++++++++++++++++++++++++++++++++ filters/gated/gated_test.go | 2 +- 4 files changed, 132 insertions(+), 10 deletions(-) diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index 6f6cfd5..b56312c 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -16,7 +16,7 @@ jobs: - name: Set up Go uses: actions/setup-go@v2 with: - go-version: 1.15 + go-version: 1.16 - name: Build run: go build -v ./... diff --git a/file_sink.go b/file_sink.go index 5ac5f84..70606d8 100644 --- a/file_sink.go +++ b/file_sink.go @@ -46,6 +46,14 @@ type FileSink struct { // Defaults to JSONFormat Format string + // TimestampOnlyOnRotate specifies the file currently being written + // should not contain a timestamp in the name even if rotation is + // enabled. + // + // If false (the default) all files, including the currently written + // one, will contain a timestamp in the filename. + TimestampOnlyOnRotate bool + f *os.File l sync.Mutex } @@ -198,8 +206,20 @@ func (fs *FileSink) rotate() error { ((elapsed > fs.MaxDuration) && (fs.MaxDuration > 0)) { fs.f.Close() + + // Move current log file to a timestamped file. + if fs.TimestampOnlyOnRotate { + rotateTime := time.Now().UnixNano() + rotateFileName := fmt.Sprintf(fs.fileNamePattern(), strconv.FormatInt(rotateTime, 10)) + oldPath := filepath.Join(fs.Path, fs.FileName) + newPath := filepath.Join(fs.Path, rotateFileName) + if err := os.Rename(oldPath, newPath); err != nil { + return fmt.Errorf("failed to rotate log file: %v", err) + } + } + if err := fs.pruneFiles(); err != nil { - return err + return fmt.Errorf("failed to prune log files: %w", err) } return fs.open() } @@ -245,14 +265,16 @@ func (fs *FileSink) fileNamePattern() string { } func (fs *FileSink) newFileName(createTime time.Time) string { - var newFileName string - if fs.rotateEnabled() { - pattern := fs.fileNamePattern() - newFileName = fmt.Sprintf(pattern, strconv.FormatInt(createTime.UnixNano(), 10)) - } else { - newFileName = fs.FileName + if fs.TimestampOnlyOnRotate { + return fs.FileName + } + + if !fs.rotateEnabled() { + return fs.FileName } - return newFileName + + pattern := fs.fileNamePattern() + return fmt.Sprintf(pattern, strconv.FormatInt(createTime.UnixNano(), 10)) } func (fs *FileSink) rotateEnabled() bool { diff --git a/file_sink_test.go b/file_sink_test.go index 3a715dd..98b8525 100644 --- a/file_sink_test.go +++ b/file_sink_test.go @@ -1,6 +1,7 @@ package eventlogger import ( + "bytes" "context" "io/ioutil" "os" @@ -147,6 +148,55 @@ func TestFileSink_TimeRotate(t *testing.T) { } } +func TestFileSink_TimestampOnlyOnRotate_TimeRotate(t *testing.T) { + t.Parallel() + + tmpDir, err := ioutil.TempDir("", t.Name()) + if err != nil { + t.Fatal(err) + } + defer os.RemoveAll(tmpDir) + + fs := FileSink{ + Path: tmpDir, + FileName: "audit.log", + MaxDuration: 2 * time.Second, + TimestampOnlyOnRotate: true, + } + event := &Event{ + Formatted: map[string][]byte{JSONFormat: []byte("First entry")}, + Payload: "First entry", + } + _, err = fs.Process(context.Background(), event) + if err != nil { + t.Fatal(err) + } + + time.Sleep(2 * time.Second) + + event = &Event{ + Formatted: map[string][]byte{JSONFormat: []byte("Last entry")}, + Payload: "Last entry", + } + _, err = fs.Process(context.Background(), event) + if err != nil { + t.Fatal(err) + } + + want := 2 + got, _ := ioutil.ReadDir(tmpDir) + if len(got) != want { + t.Errorf("Expected %d files, got %v file(s)", want, len(got)) + } + if got[1].Name() != "audit.log" { + t.Errorf("Expected audit.log but found: %q", got[1].Name()) + } + contents, _ := os.ReadFile(filepath.Join(tmpDir, "audit.log")) + if expected := []byte("Last entry"); !bytes.Equal(contents, expected) { + t.Errorf("Expected %q but found %q", string(expected), string(contents)) + } +} + func TestFileSink_ByteRotate(t *testing.T) { t.Parallel() @@ -188,6 +238,56 @@ func TestFileSink_ByteRotate(t *testing.T) { } } +func TestFileSink_TimestampOnlyOnRotate_ByteRotate(t *testing.T) { + t.Parallel() + + tmpDir, err := ioutil.TempDir("", t.Name()) + if err != nil { + t.Fatal(err) + } + defer os.RemoveAll(tmpDir) + + fs := FileSink{ + Path: tmpDir, + FileName: "audit.log", + MaxBytes: 5, + MaxDuration: 24 * time.Hour, + TimestampOnlyOnRotate: true, + } + event := &Event{ + Formatted: map[string][]byte{JSONFormat: []byte("first entry")}, + Payload: "first entry", + } + _, err = fs.Process(context.Background(), event) + if err != nil { + t.Fatal(err) + } + + time.Sleep(2 * time.Second) + + event = &Event{ + Formatted: map[string][]byte{JSONFormat: []byte("last entry")}, + Payload: "last entry", + } + _, err = fs.Process(context.Background(), event) + if err != nil { + t.Fatal(err) + } + + want := 2 + got, _ := ioutil.ReadDir(tmpDir) + if len(got) != want { + t.Errorf("Expected %d files, got %v file(s)", want, len(got)) + } + if got[1].Name() != "audit.log" { + t.Errorf("Expected audit.log but found: %q", got[1].Name()) + } + contents, _ := os.ReadFile(filepath.Join(tmpDir, "audit.log")) + if expected := []byte("last entry"); !bytes.Equal(contents, expected) { + t.Errorf("Expected %q but found %q", string(expected), string(contents)) + } +} + func TestFileSink_open(t *testing.T) { t.Parallel() diff --git a/filters/gated/gated_test.go b/filters/gated/gated_test.go index a51e6e1..9f5d269 100644 --- a/filters/gated/gated_test.go +++ b/filters/gated/gated_test.go @@ -451,7 +451,7 @@ func TestGatedFilter_Now(t *testing.T) { n := time.Now() got := gf.Now() assert.True(got.Equal(time.Now()) || got.Before(time.Now())) - assert.True(got.After(n)) + assert.True(got.Equal(n) || got.After(n)) }) t.Run("override-now", func(t *testing.T) { assert := assert.New(t)