From 871bea3bce2b7db17a57d87573c5601ae131ae1b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Wed, 8 Apr 2020 16:02:00 +0200 Subject: [PATCH 1/6] Do not rotate on startup when interval is configured --- libbeat/common/file/interval_rotator.go | 45 ++++++++++++++++++++++--- libbeat/common/file/rotator.go | 2 +- 2 files changed, 42 insertions(+), 5 deletions(-) diff --git a/libbeat/common/file/interval_rotator.go b/libbeat/common/file/interval_rotator.go index b531acca237..90ef17b2746 100644 --- a/libbeat/common/file/interval_rotator.go +++ b/libbeat/common/file/interval_rotator.go @@ -20,8 +20,11 @@ package file import ( "errors" "fmt" + "io/ioutil" + "path/filepath" "sort" "strconv" + "strings" "time" ) @@ -45,7 +48,7 @@ func (realClock) Now() time.Time { return time.Now() } -func newIntervalRotator(interval time.Duration) (*intervalRotator, error) { +func newIntervalRotator(log Logger, interval time.Duration, rotateOnStartup bool, filename string) (*intervalRotator, error) { if interval == 0 { return nil, nil } @@ -54,11 +57,11 @@ func newIntervalRotator(interval time.Duration) (*intervalRotator, error) { } ir := &intervalRotator{interval: (interval / time.Second) * time.Second} // drop fractional seconds - ir.initialize() + ir.initialize(log, rotateOnStartup, filename) return ir, nil } -func (r *intervalRotator) initialize() error { +func (r *intervalRotator) initialize(log Logger, rotateOnStartup bool, filename string) { r.clock = realClock{} switch r.interval { @@ -93,7 +96,41 @@ func (r *intervalRotator) initialize() error { return lastInterval != currentInterval } } - return nil + + // if rotation is not allowed on startup, find the newest rotated file last modification time + // or that of the unrotated log file + if !rotateOnStartup { + logsDir := filepath.Dir(filename) + logfiles, err := ioutil.ReadDir(logsDir) + if err != nil && log != nil { + log.Debugw("Not attempting to find last rotated time, configured logs dir cannot be opened: %v", err) + return + } + + r.lastRotate = time.Time{} + if len(logfiles) == 1 && logfiles[0].Name() == filename { + if log != nil { + log.Debugw("Setting last rotated time to the last modification time of the log") + } + + r.lastRotate = logfiles[0].ModTime() + return + } + basenamePrefix := filepath.Base(filename) + "-" + for _, fi := range logfiles { + if strings.HasPrefix(fi.Name(), basenamePrefix) { + if fi.ModTime().After(r.lastRotate) { + r.lastRotate = fi.ModTime() + } + } + } + + if log != nil { + log.Debugw("Set last rotated time to", r.lastRotate) + } + } + + return } func (r *intervalRotator) LogPrefix(filename string, modTime time.Time) string { diff --git a/libbeat/common/file/rotator.go b/libbeat/common/file/rotator.go index fa4b5114b2b..0e8e369ff5f 100644 --- a/libbeat/common/file/rotator.go +++ b/libbeat/common/file/rotator.go @@ -166,7 +166,7 @@ func NewFileRotator(filename string, options ...RotatorOption) (*Rotator, error) return nil, errors.Errorf("file rotator permissions mask of %o is invalid", r.permissions) } var err error - r.intervalRotator, err = newIntervalRotator(r.interval) + r.intervalRotator, err = newIntervalRotator(r.log, r.interval, r.rotateOnStartup, r.filename) if err != nil { return nil, err } From 25cdd13fbab97e56a16d0e78a9f741abea3fd673 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Wed, 8 Apr 2020 16:20:48 +0200 Subject: [PATCH 2/6] fix tests --- libbeat/common/file/interval_rotator_test.go | 24 ++++++++++++-------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/libbeat/common/file/interval_rotator_test.go b/libbeat/common/file/interval_rotator_test.go index fda516d8627..b31592677d6 100644 --- a/libbeat/common/file/interval_rotator_test.go +++ b/libbeat/common/file/interval_rotator_test.go @@ -25,7 +25,7 @@ import ( ) func TestSecondRotator(t *testing.T) { - a, err := newIntervalRotator(time.Second) + a, err := newMockIntervalRotator(time.Second) if err != nil { t.Fatal(err) } @@ -51,7 +51,7 @@ func TestSecondRotator(t *testing.T) { } func TestMinuteRotator(t *testing.T) { - a, err := newIntervalRotator(time.Minute) + a, err := newMockIntervalRotator(time.Minute) if err != nil { t.Fatal(err) } @@ -77,7 +77,7 @@ func TestMinuteRotator(t *testing.T) { } func TestHourlyRotator(t *testing.T) { - a, err := newIntervalRotator(time.Hour) + a, err := newMockIntervalRotator(time.Hour) if err != nil { t.Fatal(err) } @@ -103,7 +103,7 @@ func TestHourlyRotator(t *testing.T) { } func TestDailyRotator(t *testing.T) { - a, err := newIntervalRotator(24 * time.Hour) + a, err := newMockIntervalRotator(24 * time.Hour) if err != nil { t.Fatal(err) } @@ -129,7 +129,7 @@ func TestDailyRotator(t *testing.T) { } func TestWeeklyRotator(t *testing.T) { - a, err := newIntervalRotator(7 * 24 * time.Hour) + a, err := newMockIntervalRotator(7 * 24 * time.Hour) if err != nil { t.Fatal(err) } @@ -158,7 +158,7 @@ func TestWeeklyRotator(t *testing.T) { } func TestMonthlyRotator(t *testing.T) { - a, err := newIntervalRotator(30 * 24 * time.Hour) + a, err := newMockIntervalRotator(30 * 24 * time.Hour) if err != nil { t.Fatal(err) } @@ -184,7 +184,7 @@ func TestMonthlyRotator(t *testing.T) { } func TestYearlyRotator(t *testing.T) { - a, err := newIntervalRotator(365 * 24 * time.Hour) + a, err := newMockIntervalRotator(365 * 24 * time.Hour) if err != nil { t.Fatal(err) } @@ -210,7 +210,7 @@ func TestYearlyRotator(t *testing.T) { } func TestArbitraryIntervalRotator(t *testing.T) { - a, err := newIntervalRotator(3 * time.Second) + a, err := newMockIntervalRotator(3 * time.Second) if err != nil { t.Fatal(err) } @@ -253,7 +253,7 @@ func TestArbitraryIntervalRotator(t *testing.T) { } func TestIntervalIsTruncatedToSeconds(t *testing.T) { - a, err := newIntervalRotator(2345 * time.Millisecond) + a, err := newMockIntervalRotator(2345 * time.Millisecond) if err != nil { t.Fatal(err) } @@ -261,7 +261,7 @@ func TestIntervalIsTruncatedToSeconds(t *testing.T) { } func TestZeroIntervalIsNil(t *testing.T) { - a, err := newIntervalRotator(0) + a, err := newMockIntervalRotator(0) if err != nil { t.Fatal(err) } @@ -275,3 +275,7 @@ type testClock struct { func (t testClock) Now() time.Time { return t.time } + +func newMockIntervalRotator(interval time.Duration) (*intervalRotator, error) { + return newIntervalRotator(nil, interval, false, "foo") +} From dacfebdf22048d709bbbafead4c59c165e020d81 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Thu, 9 Apr 2020 13:19:19 +0200 Subject: [PATCH 3/6] add changelog entry --- CHANGELOG.next.asciidoc | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index e3342d740de..046d2060a83 100644 --- a/CHANGELOG.next.asciidoc +++ b/CHANGELOG.next.asciidoc @@ -74,6 +74,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d - Fix concurrency issues in convert processor when used in the global context. {pull}17032[17032] - Fix bug with `monitoring.cluster_uuid` setting not always being exposed via GET /state Beats API. {issue}16732[16732] {pull}17420[17420] - Fix building on FreeBSD by removing build flags from `add_cloudfoundry_metadata` processor. {pull}17486[17486] +- Do not rotate log files on startup when interval is configured and rotateonstartup is disabled. {pull}17613[17613] *Auditbeat* From 5664e54a149fa6e24332abbac64c9d1682a40eae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Thu, 9 Apr 2020 15:02:45 +0200 Subject: [PATCH 4/6] add unit test --- libbeat/common/file/interval_rotator.go | 49 +++++++------ libbeat/common/file/interval_rotator_test.go | 76 ++++++++++++++++++++ 2 files changed, 105 insertions(+), 20 deletions(-) diff --git a/libbeat/common/file/interval_rotator.go b/libbeat/common/file/interval_rotator.go index 90ef17b2746..b35c3750c6a 100644 --- a/libbeat/common/file/interval_rotator.go +++ b/libbeat/common/file/interval_rotator.go @@ -21,6 +21,7 @@ import ( "errors" "fmt" "io/ioutil" + "os" "path/filepath" "sort" "strconv" @@ -102,35 +103,43 @@ func (r *intervalRotator) initialize(log Logger, rotateOnStartup bool, filename if !rotateOnStartup { logsDir := filepath.Dir(filename) logfiles, err := ioutil.ReadDir(logsDir) - if err != nil && log != nil { - log.Debugw("Not attempting to find last rotated time, configured logs dir cannot be opened: %v", err) - return - } - - r.lastRotate = time.Time{} - if len(logfiles) == 1 && logfiles[0].Name() == filename { + if err != nil { if log != nil { - log.Debugw("Setting last rotated time to the last modification time of the log") + log.Debugw("Not attempting to find last rotated time, configured logs dir cannot be opened: %v", err) } - - r.lastRotate = logfiles[0].ModTime() return } - basenamePrefix := filepath.Base(filename) + "-" - for _, fi := range logfiles { - if strings.HasPrefix(fi.Name(), basenamePrefix) { - if fi.ModTime().After(r.lastRotate) { - r.lastRotate = fi.ModTime() - } - } - } + r.lastRotate = determineTimeOfLastRotation(log, filename, logfiles) + } + return +} + +func determineTimeOfLastRotation(log Logger, filename string, logfiles []os.FileInfo) time.Time { + if len(logfiles) == 1 && logfiles[0].Name() == filename { if log != nil { - log.Debugw("Set last rotated time to", r.lastRotate) + log.Debugw("Setting last rotated time to the last modification time of the log") + } + + return logfiles[0].ModTime() + } + lastRotate := time.Time{} + basenamePrefix := filepath.Base(filename) + "-" + for _, fi := range logfiles { + if fi.Name() == filepath.Base(filename) { + return fi.ModTime() + } + if strings.HasPrefix(fi.Name(), basenamePrefix) { + if fi.ModTime().After(lastRotate) { + lastRotate = fi.ModTime() + } } } - return + if log != nil { + log.Debugw("Set last rotated time to", lastRotate) + } + return lastRotate } func (r *intervalRotator) LogPrefix(filename string, modTime time.Time) string { diff --git a/libbeat/common/file/interval_rotator_test.go b/libbeat/common/file/interval_rotator_test.go index b31592677d6..647a54f5654 100644 --- a/libbeat/common/file/interval_rotator_test.go +++ b/libbeat/common/file/interval_rotator_test.go @@ -18,6 +18,7 @@ package file import ( + "os" "testing" "time" @@ -268,6 +269,81 @@ func TestZeroIntervalIsNil(t *testing.T) { assert.True(t, a == nil) } +func TestSelectingLastRotateTime(t *testing.T) { + const oldestTsSec = 1586434581 + cases := map[string]struct { + logfiles []os.FileInfo + expectedRotateTime time.Time + }{ + "one file unrotated file": { + logfiles: []os.FileInfo{ + fileInf{ + name: "foo", + modTime: time.Unix(oldestTsSec, 0), + }, + }, + expectedRotateTime: time.Unix(oldestTsSec, 0), + }, + "one file unrotated file, several rotated files": { + logfiles: []os.FileInfo{ + fileInf{ + name: "foo", + modTime: time.Unix(oldestTsSec+4*60, 0), + }, + fileInf{ + name: "foo-01", + modTime: time.Unix(oldestTsSec+3*60, 0), + }, + fileInf{ + name: "foo-02", + modTime: time.Unix(oldestTsSec+2*60, 0), + }, + fileInf{ + name: "foo-03", + modTime: time.Unix(oldestTsSec+1*60, 0), + }, + }, + expectedRotateTime: time.Unix(oldestTsSec+4*60, 0), + }, + "several rotated files": { + logfiles: []os.FileInfo{ + fileInf{ + name: "foo-01", + modTime: time.Unix(oldestTsSec+3*60, 0), + }, + fileInf{ + name: "foo-02", + modTime: time.Unix(oldestTsSec+2*60, 0), + }, + fileInf{ + name: "foo-03", + modTime: time.Unix(oldestTsSec+1*60, 0), + }, + }, + expectedRotateTime: time.Unix(oldestTsSec+3*60, 0), + }, + } + + for name, test := range cases { + t.Run(name, func(t *testing.T) { + rotatedTime := determineTimeOfLastRotation(nil, "foo", test.logfiles) + assert.Equal(t, rotatedTime.Sub(test.expectedRotateTime), time.Duration(0)) + }) + } +} + +type fileInf struct { + name string + modTime time.Time +} + +func (f fileInf) Name() string { return f.name } +func (f fileInf) ModTime() time.Time { return f.modTime } +func (f fileInf) Size() int64 { return 0 } +func (f fileInf) Mode() os.FileMode { return 0666 } +func (f fileInf) IsDir() bool { return false } +func (f fileInf) Sys() interface{} { return nil } + type testClock struct { time time.Time } From 7bd2debe1b40dc306b246549472089d56238ff4d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Thu, 9 Apr 2020 15:50:21 +0200 Subject: [PATCH 5/6] simplify behaviour --- libbeat/common/file/interval_rotator.go | 37 +--------- libbeat/common/file/interval_rotator_test.go | 76 -------------------- 2 files changed, 2 insertions(+), 111 deletions(-) diff --git a/libbeat/common/file/interval_rotator.go b/libbeat/common/file/interval_rotator.go index b35c3750c6a..432367adc91 100644 --- a/libbeat/common/file/interval_rotator.go +++ b/libbeat/common/file/interval_rotator.go @@ -20,12 +20,9 @@ package file import ( "errors" "fmt" - "io/ioutil" "os" - "path/filepath" "sort" "strconv" - "strings" "time" ) @@ -98,50 +95,20 @@ func (r *intervalRotator) initialize(log Logger, rotateOnStartup bool, filename } } - // if rotation is not allowed on startup, find the newest rotated file last modification time - // or that of the unrotated log file if !rotateOnStartup { - logsDir := filepath.Dir(filename) - logfiles, err := ioutil.ReadDir(logsDir) + fi, err := os.Stat(filename) if err != nil { if log != nil { log.Debugw("Not attempting to find last rotated time, configured logs dir cannot be opened: %v", err) } return } - r.lastRotate = determineTimeOfLastRotation(log, filename, logfiles) + r.lastRotate = fi.ModTime() } return } -func determineTimeOfLastRotation(log Logger, filename string, logfiles []os.FileInfo) time.Time { - if len(logfiles) == 1 && logfiles[0].Name() == filename { - if log != nil { - log.Debugw("Setting last rotated time to the last modification time of the log") - } - - return logfiles[0].ModTime() - } - lastRotate := time.Time{} - basenamePrefix := filepath.Base(filename) + "-" - for _, fi := range logfiles { - if fi.Name() == filepath.Base(filename) { - return fi.ModTime() - } - if strings.HasPrefix(fi.Name(), basenamePrefix) { - if fi.ModTime().After(lastRotate) { - lastRotate = fi.ModTime() - } - } - } - - if log != nil { - log.Debugw("Set last rotated time to", lastRotate) - } - return lastRotate -} - func (r *intervalRotator) LogPrefix(filename string, modTime time.Time) string { var t time.Time if r.lastRotate.IsZero() { diff --git a/libbeat/common/file/interval_rotator_test.go b/libbeat/common/file/interval_rotator_test.go index 647a54f5654..b31592677d6 100644 --- a/libbeat/common/file/interval_rotator_test.go +++ b/libbeat/common/file/interval_rotator_test.go @@ -18,7 +18,6 @@ package file import ( - "os" "testing" "time" @@ -269,81 +268,6 @@ func TestZeroIntervalIsNil(t *testing.T) { assert.True(t, a == nil) } -func TestSelectingLastRotateTime(t *testing.T) { - const oldestTsSec = 1586434581 - cases := map[string]struct { - logfiles []os.FileInfo - expectedRotateTime time.Time - }{ - "one file unrotated file": { - logfiles: []os.FileInfo{ - fileInf{ - name: "foo", - modTime: time.Unix(oldestTsSec, 0), - }, - }, - expectedRotateTime: time.Unix(oldestTsSec, 0), - }, - "one file unrotated file, several rotated files": { - logfiles: []os.FileInfo{ - fileInf{ - name: "foo", - modTime: time.Unix(oldestTsSec+4*60, 0), - }, - fileInf{ - name: "foo-01", - modTime: time.Unix(oldestTsSec+3*60, 0), - }, - fileInf{ - name: "foo-02", - modTime: time.Unix(oldestTsSec+2*60, 0), - }, - fileInf{ - name: "foo-03", - modTime: time.Unix(oldestTsSec+1*60, 0), - }, - }, - expectedRotateTime: time.Unix(oldestTsSec+4*60, 0), - }, - "several rotated files": { - logfiles: []os.FileInfo{ - fileInf{ - name: "foo-01", - modTime: time.Unix(oldestTsSec+3*60, 0), - }, - fileInf{ - name: "foo-02", - modTime: time.Unix(oldestTsSec+2*60, 0), - }, - fileInf{ - name: "foo-03", - modTime: time.Unix(oldestTsSec+1*60, 0), - }, - }, - expectedRotateTime: time.Unix(oldestTsSec+3*60, 0), - }, - } - - for name, test := range cases { - t.Run(name, func(t *testing.T) { - rotatedTime := determineTimeOfLastRotation(nil, "foo", test.logfiles) - assert.Equal(t, rotatedTime.Sub(test.expectedRotateTime), time.Duration(0)) - }) - } -} - -type fileInf struct { - name string - modTime time.Time -} - -func (f fileInf) Name() string { return f.name } -func (f fileInf) ModTime() time.Time { return f.modTime } -func (f fileInf) Size() int64 { return 0 } -func (f fileInf) Mode() os.FileMode { return 0666 } -func (f fileInf) IsDir() bool { return false } -func (f fileInf) Sys() interface{} { return nil } - type testClock struct { time time.Time } From 6603d30ac46a6656e7e80ab96340ba0116efa619 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?No=C3=A9mi=20V=C3=A1nyi?= Date: Thu, 9 Apr 2020 16:32:36 +0200 Subject: [PATCH 6/6] remove unnecessary return --- libbeat/common/file/interval_rotator.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/libbeat/common/file/interval_rotator.go b/libbeat/common/file/interval_rotator.go index 432367adc91..2fb9f89aee8 100644 --- a/libbeat/common/file/interval_rotator.go +++ b/libbeat/common/file/interval_rotator.go @@ -105,8 +105,6 @@ func (r *intervalRotator) initialize(log Logger, rotateOnStartup bool, filename } r.lastRotate = fi.ModTime() } - - return } func (r *intervalRotator) LogPrefix(filename string, modTime time.Time) string {