Add rotated logs support

README.md

@@ -53,8 +53,6 @@ weekday on midnight.
   -r, --resume=                  auto-resume location [$CRONN_RESUME]
   -u, --update                   auto-update mode [$CRONN_UPDATE]
   -j, --jitter                   up to 10s jitter [$CRONN_JITTER]
-      --log                      enable logging [$CRONN_LOG]
-      --dbg                      debug mode [$CRONN_DEBUG]
 
 repeater:
       --repeater.attempts=       how many time repeat failed job (default: 1) [$CRONN_REPEATER_ATTEMPTS]
@@ -76,6 +74,15 @@ notify:
       --notify.max-log=          max number of log lines name (default: 100) [$CRONN_NOTIFY_MAX_LOG]
       --notify.host=             host name running cronn [$CRONN_NOTIFY_HOSTNAME]
 
+log:
+      --log.enabled              enable logging [$CRONN_LOG_ENABLED]
+      --log.debug                debug mode [$CRONN_LOG_DEBUG]
+      --log.filename=            file to write logs to. Log to stdout if not specified [$CRONN_LOG_FILENAME]
+      --log.max-size=            maximum size in megabytes of the log file before it gets rotated (default: 100) [$CRONN_LOG_MAX_SIZE]
+      --log.max-age=             maximum number of days to retain old log files (default: 0) [$CRONN_LOG_MAX_AGE]
+      --log.max-backups=         maximum number of old log files to retain (default: 7) [$CRONN_LOG_MAX_BACKUPS]
+      --log.enabled-compress     determines if the rotated log files should be compressed using gzip [$CRONN_LOG_ENABLED_COMPRESS]
+
 Help Options:
   -h, --help                     Show this help message
 ```

app/main.go

@@ -3,6 +3,7 @@ package main
 import (
 	"context"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"os"
 	"os/signal"
@@ -15,6 +16,7 @@ import (
 	"github.com/go-pkgz/repeater/strategy"
 	"github.com/robfig/cron/v3"
 	"github.com/umputun/go-flags"
+	"gopkg.in/natefinch/lumberjack.v2"
 
 	"github.com/umputun/cronn/app/crontab"
 	"github.com/umputun/cronn/app/notify"
@@ -28,8 +30,6 @@ var opts struct {
 	Resume       string `short:"r" long:"resume" env:"CRONN_RESUME" description:"auto-resume location"`
 	UpdateEnable bool   `short:"u" long:"update" env:"CRONN_UPDATE" description:"auto-update mode"`
 	JitterEnable bool   `short:"j" long:"jitter" env:"CRONN_JITTER" description:"up to 10s jitter"`
-	LogEnabled   bool   `long:"log" env:"CRONN_LOG" description:"enable logging"`
-	Dbg          bool   `long:"dbg" env:"CRONN_DEBUG" description:"debug mode"`
 
 	Repeater struct {
 		Attempts int           `long:"attempts" env:"ATTEMPTS" default:"1" description:"how many time repeat failed job"`
@@ -52,6 +52,16 @@ var opts struct {
 		MaxLogLines       int           `long:"max-log" env:"MAX_LOG" default:"100" description:"max number of log lines name"`
 		HostName          string        `long:"host" env:"HOSTNAME" description:"host name running cronn"`
 	} `group:"notify" namespace:"notify" env-namespace:"CRONN_NOTIFY"`
+
+	Log struct {
+		Enabled         bool   `long:"enabled" env:"ENABLED" description:"enable logging"`
+		Debug           bool   `long:"debug" env:"DEBUG" description:"debug mode"`
+		Filename        string `long:"filename" env:"FILENAME" description:"file to write logs to. Log to stdout if not specified"`
+		MaxSize         int    `long:"max-size" env:"MAX_SIZE" default:"100" description:"maximum size in megabytes of the log file before it gets rotated"`
+		MaxAge          int    `long:"max-age" env:"MAX_AGE" default:"0" description:"maximum number of days to retain old log files"`
+		MaxBackups      int    `long:"max-backups" env:"MAX_BACKUPS" default:"7" description:"maximum number of old log files to retain"`
+		EnabledCompress bool   `long:"enabled-compress" env:"ENABLED_COMPRESS" description:"determines if the rotated log files should be compressed using gzip"`
+	} `group:"log" namespace:"log" env-namespace:"CRONN_LOG"`
 }
 
 var revision = "unknown"
@@ -62,7 +72,7 @@ func main() {
 	if _, err := flags.Parse(&opts); err != nil {
 		os.Exit(2)
 	}
-	setupLogs(opts.LogEnabled, opts.Dbg)
+	stdout := setupLogs()
 
 	defer func() {
 		if x := recover(); x != nil {
@@ -93,6 +103,7 @@ func main() {
 		Notifier:       makeNotifier(),
 		HostName:       makeHostName(),
 		MaxLogLines:    opts.Notify.MaxLogLines,
+		Stdout:         stdout,
 	}
 	signals(cancel) // handle SIGQUIT and SIGTERM
 	cronService.Do(ctx)
@@ -135,17 +146,37 @@ func makeHostName() string {
 	return host
 }
 
-func setupLogs(enabled, dbg bool) {
-	if !enabled {
+func setupLogs() io.Writer {
+	if !opts.Log.Enabled {
 		log.Setup(log.Out(ioutil.Discard), log.Err(ioutil.Discard))
-		return
+		return os.Stdout
 	}
 
-	if dbg {
-		log.Setup(log.Debug, log.Msec, log.CallerFunc, log.CallerPkg, log.CallerFile)
-		return
-	}
 	log.Setup(log.Msec)
+
+	if opts.Log.Debug {
+		log.Setup(log.Debug, log.CallerFunc, log.CallerPkg, log.CallerFile)
+	}
+
+	if opts.Log.Filename != "" {
+		fileLogger := &lumberjack.Logger{
+			Filename:   opts.Log.Filename,
+			MaxSize:    opts.Log.MaxSize,
+			MaxBackups: opts.Log.MaxBackups,
+			MaxAge:     opts.Log.MaxAge,
+			Compress:   opts.Log.EnabledCompress,
+			LocalTime:  true, // as log files have content in local time format
+		}
+
+		log.Setup(
+			log.Out(fileLogger),
+			log.Err(fileLogger),
+		)
+
+		return fileLogger
+	}
+
+	return os.Stdout
 }
 
 func signals(cancel context.CancelFunc) {

app/main_test.go

@@ -1,11 +1,13 @@
 package main
 
 import (
+	"io/ioutil"
 	"os"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"gopkg.in/natefinch/lumberjack.v2"
 )
 
 func Test_makeHostName(t *testing.T) {
@@ -27,3 +29,30 @@ func Test_makeNotifier(t *testing.T) {
 	require.NotNil(t, notif)
 	assert.Equal(t, "cronn@"+makeHostName(), notif.From)
 }
+
+func Test_setupLogsWithLogsDisabled(t *testing.T) {
+	opts.Log.Enabled = false
+	assert.Equal(t, os.Stdout, setupLogs())
+}
+
+func Test_setupLogsToFile(t *testing.T) {
+	tmpfile, err := ioutil.TempFile("", "")
+	require.NoError(t, err)
+
+	opts.Log.Enabled = true
+	opts.Log.Filename = tmpfile.Name()
+	opts.Log.MaxSize = 100
+	opts.Log.MaxBackups = 7
+	opts.Log.MaxAge = 0
+	opts.Log.EnabledCompress = false
+
+	out := setupLogs()
+	assert.IsType(t, &lumberjack.Logger{}, out)
+
+	logger := out.(*lumberjack.Logger)
+	assert.Equal(t, tmpfile.Name(), logger.Filename)
+	assert.Equal(t, 100, logger.MaxSize)
+	assert.Equal(t, 7, logger.MaxBackups)
+	assert.Equal(t, 0, logger.MaxAge)
+	assert.Equal(t, false, logger.Compress)
+}

app/service/log_prefixer.go

@@ -0,0 +1,71 @@
+package service
+
+import (
+	"bufio"
+	"bytes"
+	"fmt"
+	"io"
+)
+
+const prefixCommandMaxlen = 16
+const prefixCutCommandSuffix = "..."
+
+// LogPrefixer implements `io.writer` interface and adds prefix to each output line.
+type LogPrefixer struct {
+	writer io.Writer
+	prefix []byte
+}
+
+// NewLogPrefixer initializes log prefixer.
+func NewLogPrefixer(writer io.Writer, command string) *LogPrefixer {
+	logPrefixer := &LogPrefixer{writer: writer}
+	logPrefixer.prefix = logPrefixer.prefixForCommand(command)
+	return logPrefixer
+}
+
+func (p *LogPrefixer) Write(data []byte) (int, error) {
+	reader := bufio.NewReader(bytes.NewReader(data))
+
+	var line []byte
+	var err error
+	var bytesWritten int = 0
+
+	for {
+		line, err = reader.ReadBytes('\n')
+
+		// There can be data to write in `line` even if `io.EOF` error is returned.
+		// Exit immediately only in case of unexpected error.
+		if err != nil && err != io.EOF {
+			return bytesWritten, err
+		}
+
+		if len(line) > 0 {
+			_, writeErr := p.writer.Write(p.prefix)
+			if writeErr != nil {
+				return bytesWritten, writeErr
+			}
+
+			n, writeErr := p.writer.Write(line)
+			bytesWritten += n
+			if writeErr != nil {
+				return bytesWritten, writeErr
+			}
+		}
+
+		if err == io.EOF {
+			break
+		}
+	}
+
+	return bytesWritten, nil
+}
+
+func (p *LogPrefixer) prefixForCommand(command string) []byte {
+	if len(command) > prefixCommandMaxlen {
+		command = command[:prefixCommandMaxlen]
+		command += prefixCutCommandSuffix
+	}
+
+	prefix := fmt.Sprintf("{%s} ", command)
+	return []byte(prefix)
+}

app/service/log_prefixer_test.go

@@ -0,0 +1,35 @@
+package service
+
+import (
+	"bytes"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestLogPrefixer_Write(t *testing.T) {
+	out := bytes.NewBuffer(nil)
+	prefixer := NewLogPrefixer(out, "du /var/lib/monitoring")
+
+	n, err := prefixer.Write([]byte("first line of the output\n"))
+	require.NoError(t, err)
+	assert.Equal(t, 25, n)
+
+	n, err = prefixer.Write([]byte("second line of the output\n"))
+	require.NoError(t, err)
+	assert.Equal(t, 26, n)
+
+	expectedOutput :=
+		"{du /var/lib/moni...} first line of the output\n" +
+			"{du /var/lib/moni...} second line of the output\n"
+	assert.Equal(t, expectedOutput, out.String())
+}
+
+func TestLogPrefixer_prefixForCommand(t *testing.T) {
+	prefixer := &LogPrefixer{}
+
+	assert.Equal(t, []byte("{ls -la} "), prefixer.prefixForCommand("ls -la"))
+	assert.Equal(t, []byte("{cat /var/lib/pid} "), prefixer.prefixForCommand("cat /var/lib/pid"))
+	assert.Equal(t, []byte("{du /var/lib/moni...} "), prefixer.prefixForCommand("du /var/lib/monitoring"))
+}

app/service/service.go

@@ -37,7 +37,7 @@ type Scheduler struct {
 	HostName       string
 	MaxLogLines    int
 	Repeater       *repeater.Repeater
-	stdout         io.Writer
+	Stdout         io.Writer
 }
 
 // Resumer defines interface for resumer.Resumer providing auto-restart for failed jobs
@@ -73,8 +73,8 @@ type Notifier interface {
 
 // Do runs blocking scheduler
 func (s *Scheduler) Do(ctx context.Context) {
-	if s.stdout == nil {
-		s.stdout = os.Stdout
+	if s.Stdout == nil {
+		s.Stdout = os.Stdout
 	}
 	s.resumeInterrupted()
 
@@ -115,7 +115,7 @@ func (s *Scheduler) jobFunc(r crontab.JobSpec, sched cron.Schedule) cron.FuncJob
 
 		rfile, rerr := s.Resumer.OnStart(cmd)
 
-		if err = s.executeCommand(cmd, s.stdout); err != nil {
+		if err = s.executeCommand(cmd, s.Stdout); err != nil {
 			if e := s.notify(r, err.Error()); e != nil {
 				return errors.Wrap(err, "failed to notify")
 			}
@@ -149,7 +149,10 @@ func (s *Scheduler) executeCommand(command string, logWriter io.Writer) error {
 	err := s.Repeater.Do(context.Background(), func() error {
 		cmd := exec.Command("sh", "-c", command) // nolint gosec
 		serr := NewErrorWriter(s.MaxLogLines)
-		logWithErr := io.MultiWriter(logWriter, serr)
+
+		prefixer := NewLogPrefixer(logWriter, command)
+
+		logWithErr := io.MultiWriter(prefixer, serr)
 		cmd.Stdout = logWithErr
 		cmd.Stderr = logWithErr
 		if e := cmd.Run(); e != nil {
@@ -237,7 +240,7 @@ func (s *Scheduler) resumeInterrupted() {
 
 	go func() {
 		for _, cmd := range cmds {
-			if err := s.executeCommand(cmd.Command, os.Stdout); err != nil {
+			if err := s.executeCommand(cmd.Command, s.Stdout); err != nil {
 				r := crontab.JobSpec{Spec: "auto-resume", Command: cmd.Command}
 				if e := s.notify(r, err.Error()); e != nil {
 					log.Printf("[WARN] failed to notify, %v", e)

app/service/service_test.go

@@ -69,14 +69,14 @@ func TestScheduler_DoIntegration(t *testing.T) {
 		CrontabParser:  parser,
 		UpdatesEnabled: false,
 		Notifier:       notif,
-		stdout:         out,
+		Stdout:         out,
 	}
 	ctx, cancel := context.WithTimeout(context.Background(), 110*time.Second)
 	defer cancel()
 
 	svc.Do(ctx)
 	t.Log(out.String())
-	assert.Contains(t, out.String(), "123\n")
+	assert.Contains(t, out.String(), "{echo 123} 123\n")
 	notif.AssertExpectations(t)
 }
 
@@ -85,7 +85,7 @@ func TestScheduler_execute(t *testing.T) {
 	wr := bytes.NewBuffer(nil)
 	err := svc.executeCommand("echo 123", wr)
 	require.NoError(t, err)
-	assert.Equal(t, "123\n", wr.String())
+	assert.Equal(t, "{echo 123} 123\n", wr.String())
 }
 
 func TestScheduler_executeFailedNotFound(t *testing.T) {
@@ -111,14 +111,14 @@ func TestScheduler_jobFunc(t *testing.T) {
 	resmr := &mocks.Resumer{}
 	scheduleMock := &scheduleMock{next: time.Date(2020, 7, 21, 16, 30, 0, 0, time.UTC)}
 	wr := bytes.NewBuffer(nil)
-	svc := Scheduler{MaxLogLines: 10, stdout: wr, Resumer: resmr, Repeater: repeater.New(&strategy.Once{})}
+	svc := Scheduler{MaxLogLines: 10, Stdout: wr, Resumer: resmr, Repeater: repeater.New(&strategy.Once{})}
 
 	resmr.On("List").Return(nil).Once()
 	resmr.On("OnStart", "echo 123").Return("resume.file", nil).Once()
 	resmr.On("OnFinish", "resume.file").Return(nil).Once()
 
 	svc.jobFunc(crontab.JobSpec{Spec: "@startup", Command: "echo 123"}, scheduleMock).Run()
-	assert.Equal(t, "123\n", wr.String())
+	assert.Equal(t, "{echo 123} 123\n", wr.String())
 }
 
 func TestScheduler_jobFuncFailed(t *testing.T) {
@@ -128,7 +128,7 @@ func TestScheduler_jobFuncFailed(t *testing.T) {
 	notif.On("IsOnError").Return(true)
 	scheduleMock := &scheduleMock{next: time.Date(2020, 7, 21, 16, 30, 0, 0, time.UTC)}
 	wr := bytes.NewBuffer(nil)
-	svc := Scheduler{MaxLogLines: 10, stdout: wr, Resumer: resmr, Notifier: notif, Repeater: repeater.New(&strategy.Once{})}
+	svc := Scheduler{MaxLogLines: 10, Stdout: wr, Resumer: resmr, Notifier: notif, Repeater: repeater.New(&strategy.Once{})}
 
 	resmr.On("List").Return(nil).Once()
 	resmr.On("OnStart", "no-such-thing").Return("resume.file", nil).Once()

go.mod

@@ -9,4 +9,5 @@ require (
 	github.com/robfig/cron/v3 v3.0.1
 	github.com/stretchr/testify v1.4.0
 	github.com/umputun/go-flags v1.5.1
+	gopkg.in/natefinch/lumberjack.v2 v2.0.0
 )

go.sum

@@ -19,5 +19,7 @@ github.com/umputun/go-flags v1.5.1 h1:vRauoXV3Ultt1HrxivSxowbintgZLJE+EcBy5ta3/m
 github.com/umputun/go-flags v1.5.1/go.mod h1:nTbvsO/hKqe7Utri/NoyN18GR3+EWf+9RrmsdwdhrEc=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/natefinch/lumberjack.v2 v2.0.0 h1:1Lc07Kr7qY4U2YPouBjpCLxpiyxIVoxqXgkXLknAOE8=
+gopkg.in/natefinch/lumberjack.v2 v2.0.0/go.mod h1:l0ndWWf7gzL7RNwBG7wST/UCcT4T24xpD6X8LsfU/+k=
 gopkg.in/yaml.v2 v2.2.2 h1:ZCJp+EgiOT7lHqUV2J862kp8Qj64Jo6az82+3Td9dZw=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=