Merge pull request #9012 from hashicorp/dnephin/log-fix-rotation

logging: prune logs on startup

logging/logfile.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
+	"sort"
 	"strconv"
 	"strings"
 	"sync"
@@ -93,23 +94,28 @@ func (l *LogFile) pruneFiles() error {
 	if l.MaxFiles == 0 {
 		return nil
 	}
-	pattern := l.fileNamePattern()
+
-	//get all the files that match the log file pattern
+	pattern := filepath.Join(l.logPath, fmt.Sprintf(l.fileNamePattern(), "*"))
-	globExpression := filepath.Join(l.logPath, fmt.Sprintf(pattern, "*"))
+	matches, err := filepath.Glob(pattern)
-	matches, err := filepath.Glob(globExpression)
 	if err != nil {
 		return err
 	}
-	var stale int
+
-	if l.MaxFiles <= -1 {
+	switch {
-		// Prune everything
+	case l.MaxFiles < 0:
-		stale = len(matches)
+		return removeFiles(matches)
-	} else {
+	case len(matches) < l.MaxFiles:
-		// Prune if there are more files stored than the configured max
+		return nil
-		stale = len(matches) - l.MaxFiles
 	}
-	for i := 0; i < stale; i++ {
+
-		if err := os.Remove(matches[i]); err != nil {
+	sort.Strings(matches)
+	last := len(matches) - l.MaxFiles
+	return removeFiles(matches[:last])
+}
+
+func removeFiles(files []string) error {
+	for _, file := range files {
+		if err := os.Remove(file); err != nil {
 			return err
 		}
 	}

logging/logfile_test.go

@@ -2,135 +2,122 @@ package logging
 
 import (
 	"io/ioutil"
+	"os"
 	"path/filepath"
+	"sort"
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/require"
+
 	"github.com/hashicorp/consul/sdk/testutil"
 )
 
-const (
+func TestLogFile_Rotation_MaxDuration(t *testing.T) {
-	testFileName = "Consul.log"
+	tempDir := testutil.TempDir(t, "")
-	testDuration = 50 * time.Millisecond
-	testBytes    = 10
-)
-
-func TestLogFile_timeRotation(t *testing.T) {
-	tempDir := testutil.TempDir(t, "LogWriterTime")
 	logFile := LogFile{
-		fileName: testFileName,
+		fileName: "consul.log",
 		logPath:  tempDir,
-		duration: testDuration,
+		duration: 50 * time.Millisecond,
 	}
+
 	logFile.Write([]byte("Hello World"))
-	time.Sleep(3 * testDuration)
+	time.Sleep(3 * logFile.duration)
 	logFile.Write([]byte("Second File"))
-	want := 2
+	require.Len(t, listDir(t, tempDir), 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) {
-	tempDir := testutil.TempDir(t, "LogWriterOpen")
+	logFile := LogFile{
-	logFile := LogFile{fileName: testFileName, logPath: tempDir, duration: testDuration}
+		fileName: "consul.log",
-	if err := logFile.openNew(); err != nil {
+		logPath:  testutil.TempDir(t, ""),
-		t.Errorf("Expected open file %s, got an error (%s)", testFileName, err)
+		duration: defaultRotateDuration,
 	}
+	err := logFile.openNew()
+	require.NoError(t, err)
 
-	if _, err := ioutil.ReadFile(logFile.FileInfo.Name()); err != nil {
+	msg := "[INFO] Something"
-		t.Errorf("Expected readable file %s, got an error (%s)", logFile.FileInfo.Name(), err)
+	_, err = logFile.Write([]byte(msg))
-	}
+	require.NoError(t, err)
+
+	content, err := ioutil.ReadFile(logFile.FileInfo.Name())
+	require.NoError(t, err)
+	require.Contains(t, string(content), msg)
 }
 
-func TestLogFile_byteRotation(t *testing.T) {
+func TestLogFile_Rotation_MaxBytes(t *testing.T) {
 	tempDir := testutil.TempDir(t, "LogWriterBytes")
 	logFile := LogFile{
-		fileName: testFileName,
+		fileName: "somefile.log",
 		logPath:  tempDir,
-		MaxBytes: testBytes,
+		MaxBytes: 10,
-		duration: 24 * time.Hour,
+		duration: defaultRotateDuration,
 	}
 	logFile.Write([]byte("Hello World"))
 	logFile.Write([]byte("Second File"))
-	want := 2
+	require.Len(t, listDir(t, tempDir), 2)
-	tempFiles, _ := ioutil.ReadDir(tempDir)
-	if got := tempFiles; len(got) != want {
-		t.Errorf("Expected %d files, got %v file(s)", want, len(got))
-	}
 }
 
-func TestLogFile_deleteArchives(t *testing.T) {
+func TestLogFile_PruneFiles(t *testing.T) {
-	tempDir := testutil.TempDir(t, "LogWriteDeleteArchives")
+	tempDir := testutil.TempDir(t, t.Name())
 	logFile := LogFile{
-		fileName: testFileName,
+		fileName: "consul.log",
 		logPath:  tempDir,
-		MaxBytes: testBytes,
+		MaxBytes: 10,
-		duration: 24 * time.Hour,
+		duration: defaultRotateDuration,
 		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)
-	if got := tempFiles; len(got) != want {
-		t.Errorf("Expected %d files, got %v file(s)", want, len(got))
-		return
-	}
-	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)
 
-		if contents == "[INFO] Hello World" {
+	logFiles := listDir(t, tempDir)
-			t.Errorf("Should have deleted the eldest log file")
+	sort.Strings(logFiles)
-			return
+	require.Len(t, logFiles, 2)
-		}
+
-	}
+	content, err := ioutil.ReadFile(filepath.Join(tempDir, logFiles[0]))
+	require.NoError(t, err)
+	require.Contains(t, string(content), "Second File")
+
+	content, err = ioutil.ReadFile(filepath.Join(tempDir, logFiles[1]))
+	require.NoError(t, err)
+	require.Contains(t, string(content), "Third File")
 }
 
-func TestLogFile_deleteArchivesDisabled(t *testing.T) {
+func TestLogFile_PruneFiles_Disabled(t *testing.T) {
 	tempDir := testutil.TempDir(t, t.Name())
 	logFile := LogFile{
-		fileName: testFileName,
+		fileName: "somename.log",
 		logPath:  tempDir,
-		MaxBytes: testBytes,
+		MaxBytes: 10,
-		duration: 24 * time.Hour,
+		duration: defaultRotateDuration,
 		MaxFiles: 0,
 	}
 	logFile.Write([]byte("[INFO] Hello World"))
 	logFile.Write([]byte("[INFO] Second File"))
 	logFile.Write([]byte("[INFO] Third File"))
-	want := 3
+	require.Len(t, listDir(t, tempDir), 3)
-	tempFiles, _ := ioutil.ReadDir(tempDir)
-	if got := tempFiles; len(got) != want {
-		t.Errorf("Expected %d files, got %v file(s)", want, len(got))
-		return
-	}
 }
 
-func TestLogFile_rotationDisabled(t *testing.T) {
+func TestLogFile_FileRotation_Disabled(t *testing.T) {
 	tempDir := testutil.TempDir(t, t.Name())
 	logFile := LogFile{
-		fileName: testFileName,
+		fileName: "consul.log",
 		logPath:  tempDir,
-		MaxBytes: testBytes,
+		MaxBytes: 10,
-		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 := 1
+	require.Len(t, listDir(t, tempDir), 1)
-	tempFiles, _ := ioutil.ReadDir(tempDir)
+}
-	if got := tempFiles; len(got) != want {
+
-		t.Errorf("Expected %d files, got %v file(s)", want, len(got))
+func listDir(t *testing.T, name string) []string {
-		return
+	t.Helper()
-	}
+	fh, err := os.Open(name)
+	require.NoError(t, err)
+	files, err := fh.Readdirnames(100)
+	require.NoError(t, err)
+	return files
 }

logging/logger.go

@@ -40,15 +40,8 @@ type Config struct {
 	LogRotateMaxFiles int
 }
 
-const (
+// defaultRotateDuration is the default time taken by the agent to rotate logs
-	// defaultRotateDuration is the default time taken by the agent to rotate logs
+const defaultRotateDuration = 24 * time.Hour
-	defaultRotateDuration = 24 * time.Hour
-)
-
-var (
-	logRotateDuration time.Duration
-	logRotateBytes    int
-)
 
 type LogSetupErrorFn func(string)
 
@@ -86,28 +79,22 @@ func Setup(config Config, out io.Writer) (hclog.InterceptLogger, error) {
 	// Create a file logger if the user has specified the path to the log file
 	if config.LogFilePath != "" {
 		dir, fileName := filepath.Split(config.LogFilePath)
-		// If a path is provided but has no fileName a default is provided.
 		if fileName == "" {
 			fileName = "consul.log"
 		}
-		// Try to enter the user specified log rotation duration first
+		if config.LogRotateDuration == 0 {
-		if config.LogRotateDuration != 0 {
+			config.LogRotateDuration = defaultRotateDuration
-			logRotateDuration = config.LogRotateDuration
-		} else {
-			// Default to 24 hrs if no rotation period is specified
-			logRotateDuration = defaultRotateDuration
-		}
-		// User specified byte limit for log rotation if one is provided
-		if config.LogRotateBytes != 0 {
-			logRotateBytes = config.LogRotateBytes
 		}
 		logFile := &LogFile{
 			fileName: fileName,
 			logPath:  dir,
-			duration: logRotateDuration,
+			duration: config.LogRotateDuration,
-			MaxBytes: logRotateBytes,
+			MaxBytes: config.LogRotateBytes,
 			MaxFiles: config.LogRotateMaxFiles,
 		}
+		if err := logFile.pruneFiles(); err != nil {
+			return nil, fmt.Errorf("Failed to prune log files: %w", err)
+		}
 		if err := logFile.openNew(); err != nil {
 			return nil, fmt.Errorf("Failed to setup logging: %w", err)
 		}