From fff69a50e339bda7257af61ee11caa795f73f6ac Mon Sep 17 00:00:00 2001 From: Danielle Lancashire Date: Mon, 7 Oct 2019 14:37:31 +0200 Subject: [PATCH] agent: Introduce File Logger This commit introduces a rotating file logger for Nomad Agent Logs. The logger implementation itself is a lift and shift from Consul, with tests updated to fit with the Nomad pattern of using require, and not having a testutil for creating tempdirs cleanly. --- command/agent/log_file.go | 138 ++++++++++++++++++++++++++ command/agent/log_file_test.go | 171 +++++++++++++++++++++++++++++++++ 2 files changed, 309 insertions(+) create mode 100644 command/agent/log_file.go create mode 100644 command/agent/log_file_test.go diff --git a/command/agent/log_file.go b/command/agent/log_file.go new file mode 100644 index 000000000..4e0833df9 --- /dev/null +++ b/command/agent/log_file.go @@ -0,0 +1,138 @@ +package agent + +import ( + "fmt" + "os" + "path/filepath" + "strconv" + "strings" + "sync" + "time" + + "github.com/hashicorp/logutils" +) + +var ( + now = time.Now +) + +// logFile is used to setup a file based logger that also performs log rotation +type logFile struct { + // Log level Filter to filter out logs that do not matcch LogLevel criteria + logFilter *logutils.LevelFilter + + //Name of the log file + fileName string + + //Path to the log file + logPath string + + //Duration between each file rotation operation + duration time.Duration + + //LastCreated represents the creation time of the latest log + LastCreated time.Time + + //FileInfo is the pointer to the current file being written to + FileInfo *os.File + + //MaxBytes is the maximum number of desired bytes for a log file + MaxBytes int + + //BytesWritten is the number of bytes written in the current log file + BytesWritten int64 + + // Max rotated files to keep before removing them. + MaxFiles int + + //acquire is the mutex utilized to ensure we have no concurrency issues + acquire sync.Mutex +} + +func (l *logFile) fileNamePattern() string { + // Extract the file extension + fileExt := filepath.Ext(l.fileName) + // If we have no file extension we append .log + if fileExt == "" { + fileExt = ".log" + } + // Remove the file extension from the filename + return strings.TrimSuffix(l.fileName, fileExt) + "-%s" + fileExt +} + +func (l *logFile) openNew() error { + fileNamePattern := l.fileNamePattern() + // New file name has the format : filename-timestamp.extension + createTime := now() + newfileName := fmt.Sprintf(fileNamePattern, strconv.FormatInt(createTime.UnixNano(), 10)) + newfilePath := filepath.Join(l.logPath, newfileName) + // Try creating a file. We truncate the file because we are the only authority to write the logs + filePointer, err := os.OpenFile(newfilePath, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0640) + if err != nil { + return err + } + + l.FileInfo = filePointer + // New file, new bytes tracker, new creation time :) + l.LastCreated = createTime + l.BytesWritten = 0 + return nil +} + +func (l *logFile) rotate() error { + // Get the time from the last point of contact + timeElapsed := time.Since(l.LastCreated) + // Rotate if we hit the byte file limit or the time limit + if (l.BytesWritten >= int64(l.MaxBytes) && (l.MaxBytes > 0)) || timeElapsed >= l.duration { + l.FileInfo.Close() + if err := l.pruneFiles(); err != nil { + return err + } + return l.openNew() + } + return nil +} + +func (l *logFile) pruneFiles() error { + if l.MaxFiles == 0 { + return nil + } + pattern := l.fileNamePattern() + //get all the files that match the log file pattern + globExpression := filepath.Join(l.logPath, fmt.Sprintf(pattern, "*")) + matches, err := filepath.Glob(globExpression) + if err != nil { + return err + } + // Prune if there are more files stored than the configured max + stale := len(matches) - l.MaxFiles + for i := 0; i < stale; i++ { + if err := os.Remove(matches[i]); err != nil { + return err + } + } + return nil +} + +// Write is used to implement io.Writer +func (l *logFile) Write(b []byte) (n int, err error) { + // Filter out log entries that do not match log level criteria + if !l.logFilter.Check(b) { + return 0, nil + } + + l.acquire.Lock() + defer l.acquire.Unlock() + //Create a new file if we have no file to write to + if l.FileInfo == nil { + if err := l.openNew(); err != nil { + return 0, err + } + } + // Check for the last contact and rotate if necessary + if err := l.rotate(); err != nil { + return 0, err + } + l.BytesWritten += int64(len(b)) + return l.FileInfo.Write(b) +} diff --git a/command/agent/log_file_test.go b/command/agent/log_file_test.go new file mode 100644 index 000000000..dde394276 --- /dev/null +++ b/command/agent/log_file_test.go @@ -0,0 +1,171 @@ +package agent + +import ( + "io/ioutil" + "os" + "path/filepath" + "testing" + "time" + + "github.com/hashicorp/logutils" + "github.com/stretchr/testify/require" +) + +const ( + testFileName = "Nomad.log" + testDuration = 2 * time.Second + testBytes = 10 +) + +func TestLogFile_timeRotation(t *testing.T) { + t.Parallel() + require := require.New(t) + + tempDir, err := ioutil.TempDir("", "LogWriterTimeTest") + require.NoError(err) + + defer os.Remove(tempDir) + + filt := LevelFilter() + logFile := logFile{ + logFilter: filt, + fileName: testFileName, + logPath: tempDir, + duration: testDuration, + } + logFile.Write([]byte("Hello World")) + time.Sleep(2 * time.Second) + logFile.Write([]byte("Second File")) + want := 2 + if got, _ := ioutil.ReadDir(tempDir); len(got) != want { + t.Errorf("Expected %d files, got %v file(s)", want, len(got)) + } +} + +func TestLogFile_openNew(t *testing.T) { + t.Parallel() + require := require.New(t) + + tempDir, err := ioutil.TempDir("", "LogWriterOpenTest") + require.NoError(err) + defer os.Remove(tempDir) + + logFile := logFile{fileName: testFileName, logPath: tempDir, duration: testDuration} + require.NoError(logFile.openNew()) + + _, err = ioutil.ReadFile(logFile.FileInfo.Name()) + require.NoError(err) +} + +func TestLogFile_byteRotation(t *testing.T) { + t.Parallel() + require := require.New(t) + + tempDir, err := ioutil.TempDir("", "LogWriterByteTest") + require.NoError(err) + defer os.Remove(tempDir) + + filt := LevelFilter() + filt.MinLevel = logutils.LogLevel("INFO") + logFile := logFile{ + logFilter: filt, + fileName: testFileName, + logPath: tempDir, + MaxBytes: testBytes, + duration: 24 * time.Hour, + } + logFile.Write([]byte("Hello World")) + logFile.Write([]byte("Second File")) + want := 2 + tempFiles, _ := ioutil.ReadDir(tempDir) + require.Equal(want, len(tempFiles)) +} + +func TestLogFile_logLevelFiltering(t *testing.T) { + t.Parallel() + require := require.New(t) + + tempDir, err := ioutil.TempDir("", "LogWriterFilterTest") + require.NoError(err) + defer os.Remove(tempDir) + filt := LevelFilter() + logFile := logFile{ + logFilter: filt, + fileName: testFileName, + logPath: tempDir, + MaxBytes: testBytes, + duration: testDuration, + } + logFile.Write([]byte("[INFO] This is an info message")) + logFile.Write([]byte("[DEBUG] This is a debug message")) + logFile.Write([]byte("[ERR] This is an error message")) + want := 2 + tempFiles, _ := ioutil.ReadDir(tempDir) + require.Equal(want, len(tempFiles)) +} + +func TestLogFile_deleteArchives(t *testing.T) { + t.Parallel() + require := require.New(t) + + tempDir, err := ioutil.TempDir("", "LogWriterDeleteArchivesTest") + require.NoError(err) + defer os.Remove(tempDir) + + filt := LevelFilter() + filt.MinLevel = logutils.LogLevel("INFO") + logFile := logFile{ + logFilter: filt, + fileName: testFileName, + logPath: tempDir, + MaxBytes: testBytes, + duration: 24 * time.Hour, + MaxFiles: 1, + } + logFile.Write([]byte("[INFO] Hello World")) + logFile.Write([]byte("[INFO] Second File")) + logFile.Write([]byte("[INFO] Third File")) + want := 2 + tempFiles, _ := ioutil.ReadDir(tempDir) + + require.Equal(want, len(tempFiles)) + + for _, tempFile := range tempFiles { + var bytes []byte + var err error + path := filepath.Join(tempDir, tempFile.Name()) + if bytes, err = ioutil.ReadFile(path); err != nil { + t.Errorf(err.Error()) + return + } + contents := string(bytes) + + require.NotEqual("[INFO] Hellow World", contents, "oldest log should have been deleted") + } +} + +func TestLogFile_deleteArchivesDisabled(t *testing.T) { + t.Parallel() + + require := require.New(t) + tempDir, err := ioutil.TempDir("", "LogWriterDeleteArchivesDisabledTest") + require.NoError(err) + defer os.Remove(tempDir) + + filt := LevelFilter() + filt.MinLevel = logutils.LogLevel("INFO") + logFile := logFile{ + logFilter: filt, + fileName: testFileName, + logPath: tempDir, + MaxBytes: testBytes, + duration: 24 * time.Hour, + MaxFiles: 0, + } + logFile.Write([]byte("[INFO] Hello World")) + logFile.Write([]byte("[INFO] Second File")) + logFile.Write([]byte("[INFO] Third File")) + want := 3 + tempFiles, _ := ioutil.ReadDir(tempDir) + require.Equal(want, len(tempFiles)) +}