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

@@ -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 ./...

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 {

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()
 

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)