log rotation: addressing PR feedback

Author: javicrespo

cmd/telegraf/telegraf.go

@@ -114,7 +114,7 @@ func runAgent(ctx context.Context,
 ) error {
 	// Setup default logging. This may need to change after reading the config
 	// file, but we can configure it to use our logger implementation now.
-	logger.SetupLogging(false, false, "", internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	logger.SetupLogging(LogConfig{})
 	log.Printf("I! Starting Telegraf %s", version)
 
 	// If no other options are specified, load the config file and run.
@@ -155,13 +155,16 @@ func runAgent(ctx context.Context,
 	}
 
 	// Setup logging as configured.
-	logger.SetupLogging(
-		ag.Config.Agent.Debug || *fDebug,
-		ag.Config.Agent.Quiet || *fQuiet,
-		ag.Config.Agent.Logfile,
-		ag.Config.Agent.LogfileRotationInterval,
-		ag.Config.Agent.LogfileRotationMaxSize,
-		ag.Config.Agent.LogfileRotationMaxArchives)
+	logConfig := LogConfig{
+		Debug:               ag.Config.Agent.Debug || *fDebug,
+		Quiet:               ag.Config.Agent.Quiet || *fQuiet,
+		Logfile:             ag.Config.Agent.Logfile,
+		RotationInterval:    ag.Config.Agent.LogfileRotationInterval,
+		RotationMaxSize:     ag.Config.Agent.LogfileRotationMaxSize,
+		RotationMaxArchives: ag.Config.Agent.LogfileRotationMaxArchives,
+	}
+
+	logger.SetupLogging(logConfig)
 
 	if *fTest {
 		return ag.Test(ctx)

docs/CONFIGURATION.md

@@ -147,7 +147,7 @@ The agent table configures Telegraf and the defaults used across all plugins.
   The log file max [size][]. Log files will be rotated when they exceed this size. Default is 0 => no rotation based on file size.
 - **logfile_rotation_max_archives**:
   Maximum number of archives (rotated) files to keep. Older log files are deleted first.
-  This setting is only applicable if MaxAge and/or MaxSize settings have been specified (otherwise there is no rotation)
+  This setting is only applicable if `logfile_rotation_interval` and/or `logfile_rotation_max_size` settings have been specified (otherwise there is no rotation)
   Default is 0 => all rotated files are deleted. Use -1 to keep all archives.
 
 - **hostname**:

internal/config/config.go

@@ -288,7 +288,7 @@ var agentConfig = `
   ## The log file max size. Log files will be rotated when they exceed this size. Default is 0 => no rotation based on file size.
   # logfile_rotation_max_size = "10 MB"
   ## Maximum number of archives (rotated) files to keep. Older log files are deleted first.
-  ## This setting is only applicable if MaxAge and/or MaxSize settings have been specified (otherwise there is no rotation)
+  ## This setting is only applicable if logfile_rotation_interval and/or logfile_rotation_max_size settings have been specified (otherwise there is no rotation)
   ## Default is 0 => all rotated files are deleted. 
   ## Use -1 to keep all archives.
   ## Analogous to logrotate "rotate" setting http://man7.org/linux/man-pages/man8/logrotate.8.html

internal/rotate/file_writer.go

@@ -7,7 +7,6 @@ import (
 	"os"
 	"path/filepath"
 	"sort"
-	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -17,7 +16,7 @@ import (
 // the files it creates.
 const (
 	FilePerm   = os.FileMode(0644)
-	DateFormat = "2006-01-02"
+	DateFormat = "2006-01-02T150405"
 )
 
 // FileWriter implements the io.Writer interface and writes to the
@@ -44,10 +43,15 @@ func NewFileWriter(filename string, interval time.Duration, maxSizeInBytes int64
 		return openFile(filename)
 	}
 
-	w := &FileWriter{filename: filename, interval: interval, maxSizeInBytes: maxSizeInBytes,
-		maxArchives: maxArchives, filenameRotationTemplate: getFilenameRotationTemplate(filename)}
+	w := &FileWriter{
+		filename:                 filename,
+		interval:                 interval,
+		maxSizeInBytes:           maxSizeInBytes,
+		maxArchives:              maxArchives,
+		filenameRotationTemplate: getFilenameRotationTemplate(filename),
+	}
 
-	if err := w.openCurrent(true); err != nil {
+	if err := w.openCurrent(); err != nil {
 		return nil, err
 	}
 
@@ -62,8 +66,8 @@ func getFilenameRotationTemplate(filename string) string {
 	// Extract the file extension
 	fileExt := filepath.Ext(filename)
 	// Remove the file extension from the filename (if any)
-	filenameWithoutExtension := strings.TrimSuffix(filename, fileExt)
-	return filenameWithoutExtension + "-%s-%s" + fileExt
+	stem := strings.TrimSuffix(filename, fileExt)
+	return stem + ".%s" + fileExt
 }
 
 // Write writes p to the current file, then checks to see if
@@ -90,7 +94,7 @@ func (w *FileWriter) Close() (err error) {
 	defer w.Unlock()
 
 	// Rotate before closing
-	if err = w.rotate(false); err != nil {
+	if err = w.rotate(); err != nil {
 		return err
 	}
 
@@ -101,21 +105,21 @@ func (w *FileWriter) Close() (err error) {
 	return nil
 }
 
-func (w *FileWriter) openCurrent(firstRun bool) (err error) {
-	w.current, err = openFile(w.filename)
+func (w *FileWriter) openCurrent() (err error) {
+	// In case ModTime() fails, we use time.Now()
 	w.expireTime = time.Now().Add(w.interval)
 	w.bytesWritten = 0
+	w.current, err = openFile(w.filename)
 
 	if err != nil {
 		return err
 	}
-	if !firstRun {
-		return nil
-	}
 
-	// Goal here is to rotate old pre-existing files. For that we use fileInfo.ModTime, instead of time.Now(), only when the FileWriter is created (firstRun)
-	// Example: telegraf is restarted every 23 hours and the rotation interval is set to 24 hours. With time.now() as a reference we'd never rotate the file.
-	// It's only necessary to use modtime when the filewriter is created, otherwise we assume that we've been continuously running, so time.now is fine.
+	// Goal here is to rotate old pre-existing files.
+	// For that we use fileInfo.ModTime, instead of time.Now().
+	// Example: telegraf is restarted every 23 hours and
+	// the rotation interval is set to 24 hours.
+	// With time.now() as a reference we'd never rotate the file.
 	if fileInfo, err := w.current.Stat(); err == nil {
 		w.expireTime = fileInfo.ModTime().Add(w.interval)
 	}
@@ -125,18 +129,20 @@ func (w *FileWriter) openCurrent(firstRun bool) (err error) {
 func (w *FileWriter) rotateIfNeeded() error {
 	if (w.interval > 0 && time.Now().After(w.expireTime)) ||
 		(w.maxSizeInBytes > 0 && w.bytesWritten >= w.maxSizeInBytes) {
-		return w.rotate(true)
+		if err := w.rotate(); err != nil {
+			//Ignore rotation errors and keep the log open
+			fmt.Printf("unable to rotate the file '%s', %s", w.filename, err.Error())
+		}
+		return w.openCurrent()
 	}
 	return nil
 }
 
-func (w *FileWriter) rotate(createNewFile bool) (err error) {
+func (w *FileWriter) rotate() (err error) {
 	if err = w.current.Close(); err != nil {
 		return err
 	}
-	now := time.Now()
-	// Use year-month-date for readability, unix time to make archive names unique
-	rotatedFilename := fmt.Sprintf(w.filenameRotationTemplate, now.Format(DateFormat), strconv.FormatInt(now.UnixNano(), 10))
+	rotatedFilename := fmt.Sprintf(w.filenameRotationTemplate, time.Now().Format(DateFormat))
 	if err = os.Rename(w.filename, rotatedFilename); err != nil {
 		return err
 	}
@@ -145,9 +151,6 @@ func (w *FileWriter) rotate(createNewFile bool) (err error) {
 		return err
 	}
 
-	if createNewFile {
-		return w.openCurrent(false)
-	}
 	return nil
 }
 
@@ -158,7 +161,7 @@ func (w *FileWriter) purgeArchivesIfNeeded() (err error) {
 	}
 
 	var matches []string
-	if matches, err = filepath.Glob(fmt.Sprintf(w.filenameRotationTemplate, "*", "*")); err != nil {
+	if matches, err = filepath.Glob(fmt.Sprintf(w.filenameRotationTemplate, "*")); err != nil {
 		return err
 	}
 

internal/rotate/file_writer_test.go

@@ -59,7 +59,7 @@ func TestFileWriter_SizeRotation(t *testing.T) {
 	assert.Equal(t, 2, len(files))
 }
 
-func TestFileWriter_deleteArchives(t *testing.T) {
+func TestFileWriter_DeleteArchives(t *testing.T) {
 	tempDir, err := ioutil.TempDir("", "RotationDeleteArchives")
 	require.NoError(t, err)
 	maxSize := int64(5)
@@ -69,8 +69,13 @@ func TestFileWriter_deleteArchives(t *testing.T) {
 
 	_, err = writer.Write([]byte("First file"))
 	require.NoError(t, err)
+	// File names include the date with second precision
+	// So, to force rotation with different file names
+	// we need to wait
+	time.Sleep(1 * time.Second)
 	_, err = writer.Write([]byte("Second file"))
 	require.NoError(t, err)
+	time.Sleep(1 * time.Second)
 	_, err = writer.Write([]byte("Third file"))
 	require.NoError(t, err)
 
@@ -106,5 +111,5 @@ func TestFileWriter_CloseRotates(t *testing.T) {
 
 	files, _ := ioutil.ReadDir(tempDir)
 	assert.Equal(t, 1, len(files))
-	assert.Regexp(t, "^test-[^\\.]+\\.log$", files[0].Name())
+	assert.Regexp(t, "^test\\.[^\\.]+\\.log$", files[0].Name())
 }

logger/logger.go

@@ -18,12 +18,32 @@ var prefixRegex = regexp.MustCompile("^[DIWE]!")
 // newTelegrafWriter returns a logging-wrapped writer.
 func newTelegrafWriter(w io.Writer) io.Writer {
 	return &telegrafLog{
-		writer: wlog.NewWriter(w),
+		writer:         wlog.NewWriter(w),
+		internalWriter: w,
 	}
 }
 
+// LogConfig contains the log configuration settings
+type LogConfig struct {
+	// will set the log level to DEBUG
+	Debug bool
+	//will set the log level to ERROR
+	Quiet bool
+	// will direct the logging output to a file. Empty string is
+	// interpreted as stderr. If there is an error opening the file the
+	// logger will fallback to stderr
+	Logfile string
+	// will rotate when current file at the specified time interval
+	RotationInterval internal.Duration
+	// will rotate when current file size exceeds this parameter.
+	RotationMaxSize internal.Size
+	// maximum rotated files to keep (older ones will be deleted)
+	RotationMaxArchives int
+}
+
 type telegrafLog struct {
-	writer io.Writer
+	writer         io.Writer
+	internalWriter io.Writer
 }
 
 func (t *telegrafLog) Write(b []byte) (n int, err error) {
@@ -37,41 +57,32 @@ func (t *telegrafLog) Write(b []byte) (n int, err error) {
 }
 
 func (t *telegrafLog) Close() error {
-	closer, isCloser := t.writer.(io.Closer)
+	closer, isCloser := t.internalWriter.(io.Closer)
 	if !isCloser {
 		return errors.New("the underlying writer cannot be closed")
 	}
 	return closer.Close()
 }
 
 // SetupLogging configures the logging output.
-//   debug                  will set the log level to DEBUG
-//   quiet                  will set the log level to ERROR
-//   logfile                will direct the logging output to a file. Empty string is
-//                          interpreted as stderr. If there is an error opening the file the
-//                          logger will fallback to stderr.
-//   logRotationInterval    will rotate when current file at the specified time interval.
-//   logRotationMaxSize     will rotate when current file size exceeds this parameter.
-//   logRotationMaxArchives maximum rotated files to keep (older ones will be deleted)
-func SetupLogging(debug, quiet bool, logfile string, logRotationInterval internal.Duration, logRotationMaxSize internal.Size, logRotationMaxArchives int) {
-	setupLoggingAndReturnWriter(debug, quiet, logfile, logRotationInterval, logRotationMaxSize, logRotationMaxArchives)
+func SetupLogging(config LogConfig) {
+	setupLoggingAndReturnWriter(config)
 }
 
-func setupLoggingAndReturnWriter(debug, quiet bool, logfile string, logRotationInterval internal.Duration, logRotationMaxSize internal.Size,
-	logRotationMaxArchives int) io.Writer {
+func setupLoggingAndReturnWriter(config LogConfig) io.Writer {
 	log.SetFlags(0)
-	if debug {
+	if config.Debug {
 		wlog.SetLevel(wlog.DEBUG)
 	}
-	if quiet {
+	if config.Quiet {
 		wlog.SetLevel(wlog.ERROR)
 	}
 
 	var writer io.Writer
-	if logfile != "" {
+	if config.Logfile != "" {
 		var err error
-		if writer, err = rotate.NewFileWriter(logfile, logRotationInterval.Duration, logRotationMaxSize.Size, logRotationMaxArchives); err != nil {
-			log.Printf("E! Unable to open %s (%s), using stderr", logfile, err)
+		if writer, err = rotate.NewFileWriter(config.Logfile, config.RotationInterval.Duration, config.RotationMaxSize.Size, config.RotationMaxArchives); err != nil {
+			log.Printf("E! Unable to open %s (%s), using stderr", config.Logfile, err)
 			writer = os.Stderr
 		}
 	} else {

logger/logger_test.go

@@ -19,7 +19,8 @@ func TestWriteLogToFile(t *testing.T) {
 	assert.NoError(t, err)
 	defer func() { os.Remove(tmpfile.Name()) }()
 
-	SetupLogging(false, false, tmpfile.Name(), internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	config := createBasicLogConfig(tmpfile.Name())
+	SetupLogging(config)
 	log.Printf("I! TEST")
 	log.Printf("D! TEST") // <- should be ignored
 
@@ -32,8 +33,9 @@ func TestDebugWriteLogToFile(t *testing.T) {
 	tmpfile, err := ioutil.TempFile("", "")
 	assert.NoError(t, err)
 	defer func() { os.Remove(tmpfile.Name()) }()
-
-	SetupLogging(true, false, tmpfile.Name(), internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	config := createBasicLogConfig(tmpfile.Name())
+	config.Debug = true
+	SetupLogging(config)
 	log.Printf("D! TEST")
 
 	f, err := ioutil.ReadFile(tmpfile.Name())
@@ -45,8 +47,9 @@ func TestErrorWriteLogToFile(t *testing.T) {
 	tmpfile, err := ioutil.TempFile("", "")
 	assert.NoError(t, err)
 	defer func() { os.Remove(tmpfile.Name()) }()
-
-	SetupLogging(false, true, tmpfile.Name(), internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	config := createBasicLogConfig(tmpfile.Name())
+	config.Quiet = true
+	SetupLogging(config)
 	log.Printf("E! TEST")
 	log.Printf("I! TEST") // <- should be ignored
 
@@ -59,8 +62,9 @@ func TestAddDefaultLogLevel(t *testing.T) {
 	tmpfile, err := ioutil.TempFile("", "")
 	assert.NoError(t, err)
 	defer func() { os.Remove(tmpfile.Name()) }()
-
-	SetupLogging(true, false, tmpfile.Name(), internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	config := createBasicLogConfig(tmpfile.Name())
+	config.Debug = true
+	SetupLogging(config)
 	log.Printf("TEST")
 
 	f, err := ioutil.ReadFile(tmpfile.Name())
@@ -72,8 +76,9 @@ func TestWriteToTruncatedFile(t *testing.T) {
 	tmpfile, err := ioutil.TempFile("", "")
 	assert.NoError(t, err)
 	defer func() { os.Remove(tmpfile.Name()) }()
-
-	SetupLogging(true, false, tmpfile.Name(), internal.Duration{Duration: 0}, internal.Size{Size: int64(0)}, 0)
+	config := createBasicLogConfig(tmpfile.Name())
+	config.Debug = true
+	SetupLogging(config)
 	log.Printf("TEST")
 
 	f, err := ioutil.ReadFile(tmpfile.Name())
@@ -94,8 +99,9 @@ func TestWriteToTruncatedFile(t *testing.T) {
 func TestWriteToFileInRotation(t *testing.T) {
 	tempDir, err := ioutil.TempDir("", "LogRotation")
 	require.NoError(t, err)
-	writer := setupLoggingAndReturnWriter(false, false, filepath.Join(tempDir, "test.log"),
-		internal.Duration{Duration: 0}, internal.Size{Size: int64(30)}, -1)
+	config := createBasicLogConfig(filepath.Join(tempDir, "test.log"))
+	config.RotationMaxSize = internal.Size{Size: int64(30)}
+	writer := setupLoggingAndReturnWriter(config)
 	// Close the writer here, otherwise the temp folder cannot be deleted because the current log file is in use.
 	closer, isCloser := writer.(io.Closer)
 	assert.True(t, isCloser)
@@ -116,3 +122,10 @@ func BenchmarkTelegrafLogWrite(b *testing.B) {
 		w.Write(msg)
 	}
 }
+
+func createBasicLogConfig(filename string) LogConfig {
+	return LogConfig{
+		Logfile:             filename,
+		RotationMaxArchives: -1,
+	}
+}