Fix file audit log rotation, fixes #2388

This commit improves on-disk events log rotation:

* Previously, log rotation was not deterministic,
as logs could be rotated mid-day UTC, and events
from the same day could end up in different files.

This commit makes sure that logs are rotated
on the UTC boundary of the day, and log entries
from this day are located in the appropriate file,
e.g. 2019-02-09.00:00:00.log will contain all
event logs from 2019-02-09 day.

* To improve UX, additional symlink event.log
is located (by default in /var/lib/teleport/events.log)
and is pointing to the latest events log file.

lib/events/auditlog.go

@@ -1,5 +1,5 @@
 /*
-Copyright 2015-2018 Gravitational, Inc.
+Copyright 2015-2019 Gravitational, Inc.
 
 Licensed under the Apache License, Version 2.0 (the "License");
 you may not use this file except in compliance with the License.
@@ -55,6 +55,10 @@ const (
 	// LogfileExt defines the ending of the daily event log file
 	LogfileExt = ".log"
 
+	// SymlinkFilename is a name of the symlink pointing to the last
+	// current log file
+	SymlinkFilename = "events.log"
+
 	// sessionsMigratedEvent is a sessions migration event used internally
 	sessionsMigratedEvent = "sessions.migrated"
 )
@@ -242,6 +246,7 @@ func NewAuditLog(cfg AuditLogConfig) (*AuditLog, error) {
 		al.localLog, err = NewFileLog(FileLogConfig{
 			RotationPeriod: al.RotationPeriod,
 			Dir:            auditDir,
+			SymlinkDir:     cfg.DataDir,
 			Clock:          al.Clock,
 			SearchDirs:     al.auditDirs,
 		})

lib/events/auditlog_test.go

@@ -53,10 +53,17 @@ func (a *AuditTestSuite) TearDownSuite(c *check.C) {
 // creates a file-based audit log and returns a proper *AuditLog pointer
 // instead of the usual IAuditLog interface
 func (a *AuditTestSuite) makeLog(c *check.C, dataDir string, recordSessions bool) (*AuditLog, error) {
+	return a.makeLogWithClock(c, dataDir, recordSessions, nil)
+}
+
+// creates a file-based audit log and returns a proper *AuditLog pointer
+// instead of the usual IAuditLog interface
+func (a *AuditTestSuite) makeLogWithClock(c *check.C, dataDir string, recordSessions bool, clock clockwork.Clock) (*AuditLog, error) {
 	alog, err := NewAuditLog(AuditLogConfig{
 		DataDir:        dataDir,
 		RecordSessions: recordSessions,
 		ServerID:       "server1",
+		Clock:          clock,
 	})
 	if err != nil {
 		return nil, trace.Wrap(err)
@@ -320,6 +327,51 @@ func (a *AuditTestSuite) TestBasicLogging(c *check.C) {
 		fmt.Sprintf("{\"apples?\":\"yes\",\"event\":\"user.joined\",\"time\":\"%s\"}\n", now.Format(time.RFC3339)))
 }
 
+// TestLogRotation makes sure that logs are rotated
+// on the day boundary and symlinks are created and updated
+func (a *AuditTestSuite) TestLogRotation(c *check.C) {
+	start := time.Now().In(time.UTC).Round(time.Second)
+	clock := clockwork.NewFakeClockAt(start)
+
+	// create audit log, write a couple of events into it, close it
+	alog, err := a.makeLogWithClock(c, a.dataDir, true, clock)
+	c.Assert(err, check.IsNil)
+	defer func() {
+		c.Assert(alog.Close(), check.IsNil)
+	}()
+
+	for _, duration := range []time.Duration{0, time.Hour * 24} {
+		// advance time and emit audit event
+		now := start.Add(duration)
+		clock.Advance(duration)
+
+		// emit regular event:
+		err = alog.EmitAuditEvent("user.joined", EventFields{"apples?": "yes"})
+		c.Assert(err, check.IsNil)
+		logfile := alog.localLog.file.Name()
+
+		// make sure that file has the same date as the event
+		dt, err := parseFileTime(filepath.Base(logfile))
+		c.Assert(err, check.IsNil)
+		c.Assert(dt, check.Equals, time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, now.Location()))
+
+		// read back what's been written:
+		bytes, err := ioutil.ReadFile(logfile)
+		c.Assert(err, check.IsNil)
+		contents := fmt.Sprintf("{\"apples?\":\"yes\",\"event\":\"user.joined\",\"time\":\"%s\"}\n", now.Format(time.RFC3339))
+		c.Assert(string(bytes), check.Equals, contents)
+
+		// read back the contents using symlink
+		bytes, err = ioutil.ReadFile(filepath.Join(alog.localLog.SymlinkDir, SymlinkFilename))
+		c.Assert(err, check.IsNil)
+		c.Assert(string(bytes), check.Equals, contents)
+
+		found, err := alog.SearchEvents(now.Add(-time.Hour), now.Add(time.Hour), "", 0)
+		c.Assert(err, check.IsNil)
+		c.Assert(found, check.HasLen, 1)
+	}
+}
+
 // TestForwardAndUpload tests forwarding server and upload
 // server case
 func (a *AuditTestSuite) TestForwardAndUpload(c *check.C) {

lib/events/filelog.go

@@ -1,5 +1,5 @@
 /*
-Copyright 2018 Gravitational, Inc.
+Copyright 2018-2019 Gravitational, Inc.
 
 Licensed under the Apache License, Version 2.0 (the "License");
 you may not use this file except in compliance with the License.
@@ -45,6 +45,8 @@ type FileLogConfig struct {
 	RotationPeriod time.Duration
 	// Dir is a directory where logger puts the files
 	Dir string
+	// SymlinkDir is a directory for symlink pointer to the current log
+	SymlinkDir string
 	// Clock is a clock interface, used in tests
 	Clock clockwork.Clock
 	// SearchDirs is a function that returns
@@ -60,9 +62,18 @@ func (cfg *FileLogConfig) CheckAndSetDefaults() error {
 	if !utils.IsDir(cfg.Dir) {
 		return trace.BadParameter("path %q does not exist or is not a directory", cfg.Dir)
 	}
+	if cfg.SymlinkDir == "" {
+		cfg.SymlinkDir = cfg.Dir
+	}
+	if !utils.IsDir(cfg.SymlinkDir) {
+		return trace.BadParameter("path %q does not exist or is not a directory", cfg.SymlinkDir)
+	}
 	if cfg.RotationPeriod == 0 {
 		cfg.RotationPeriod = defaults.LogRotationPeriod
 	}
+	if cfg.RotationPeriod%(24*time.Hour) != 0 {
+		return trace.BadParameter("rotation period %v is not a multiple of 24 hours, e.g. '24h' or '48h'", cfg.RotationPeriod)
+	}
 	if cfg.Clock == nil {
 		cfg.Clock = clockwork.NewRealClock()
 	}
@@ -279,29 +290,49 @@ func (l *FileLog) rotateLog() (err error) {
 	defer l.Unlock()
 
 	// determine the timestamp for the current log file
-	fileTime := l.Clock.Now().In(time.UTC).Round(l.RotationPeriod)
+	fileTime := l.Clock.Now().In(time.UTC)
+
+	// truncate time to the resolution of one day, cutting at the day end boundary
+	fileTime = time.Date(fileTime.Year(), fileTime.Month(), fileTime.Day(), 0, 0, 0, 0, time.UTC)
+
+	logFilename := filepath.Join(l.Dir,
+		fileTime.Format(defaults.AuditLogTimeFormat)+LogfileExt)
 
 	openLogFile := func() error {
-		logfname := filepath.Join(l.Dir,
-			fileTime.Format(defaults.AuditLogTimeFormat)+LogfileExt)
-		l.file, err = os.OpenFile(logfname, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0640)
+		l.file, err = os.OpenFile(logFilename, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0640)
 		if err != nil {
 			log.Error(err)
 		}
-
 		l.fileTime = fileTime
 		return trace.Wrap(err)
 	}
 
+	linkFilename := filepath.Join(l.SymlinkDir, SymlinkFilename)
+	createSymlink := func() error {
+		err = trace.ConvertSystemError(os.Remove(linkFilename))
+		if err != nil {
+			if !trace.IsNotFound(err) {
+				return trace.Wrap(err)
+			}
+		}
+		return trace.ConvertSystemError(os.Symlink(logFilename, linkFilename))
+	}
+
 	// need to create a log file?
 	if l.file == nil {
-		return openLogFile()
+		if err := openLogFile(); err != nil {
+			return trace.Wrap(err)
+		}
+		return trace.Wrap(createSymlink())
 	}
 
 	// time to advance the logfile?
 	if l.fileTime.Before(fileTime) {
 		l.file.Close()
-		return openLogFile()
+		if err := openLogFile(); err != nil {
+			return trace.Wrap(err)
+		}
+		return trace.Wrap(createSymlink())
 	}
 	return nil
 }
@@ -337,10 +368,9 @@ func (l *FileLog) matchingFiles(fromUTC, toUTC time.Time) ([]eventFile, error) {
 			if fi.IsDir() || filepath.Ext(fi.Name()) != LogfileExt {
 				continue
 			}
-			base := strings.TrimSuffix(fi.Name(), filepath.Ext(fi.Name()))
-			fd, err := time.Parse(defaults.AuditLogTimeFormat, base)
+			fd, err := parseFileTime(fi.Name())
 			if err != nil {
-				l.Warningf("Failed to parse audit log file %q format: %v", base, err)
+				l.Warningf("Failed to parse audit log file %q format: %v", fi.Name(), err)
 				continue
 			}
 			// File rounding in current logs is non-deterministic,
@@ -363,6 +393,12 @@ func (l *FileLog) matchingFiles(fromUTC, toUTC time.Time) ([]eventFile, error) {
 	return filtered, nil
 }
 
+// parseFileTime parses file's timestamp encoded into filename
+func parseFileTime(filename string) (time.Time, error) {
+	base := strings.TrimSuffix(filename, filepath.Ext(filename))
+	return time.Parse(defaults.AuditLogTimeFormat, base)
+}
+
 // findInFile scans a given log file and returns events that fit the criteria
 // This simplistic implementation ONLY SEARCHES FOR EVENT TYPE(s)
 //