cron/logger: update Logger to comply with logr

this makes it possible to use cron with key/value logging systems.

BREAKING: WithVerboseLogger was changed to WithLogger.
Callers should update by invoking:

    WithLogger(VerbosePrintfLogger(logger))

WithVerboseLogger was introduced in the most recent commit, so it's unlikely to
affect many users.

Fixes #202

Author: Rob Figueiredo

README.md

@@ -16,6 +16,11 @@ It is currently IN DEVELOPMENT and will be considered released once a 3.0
 version is tagged. It is backwards INCOMPATIBLE with both the v1 and v2
 branches.
 
+New features:
+
+- Extensible, key/value logging via an interface that complies with
+  the github.com/go-logr/logr project.
+
 Updates required:
 
 - The v1 branch accepted an optional seconds field at the beginning of the cron

cron.go

@@ -1,6 +1,7 @@
 package cron
 
 import (
+	"fmt"
 	"runtime"
 	"sort"
 	"time"
@@ -17,7 +18,6 @@ type Cron struct {
 	snapshot chan chan []Entry
 	running  bool
 	logger   Logger
-	vlogger  Logger
 	location *time.Location
 	parser   Parser
 	nextID   EntryID
@@ -106,7 +106,6 @@ func New(opts ...Option) *Cron {
 		remove:   make(chan EntryID),
 		running:  false,
 		logger:   DefaultLogger,
-		vlogger:  nil,
 		location: time.Local,
 		parser:   standardParser,
 	}
@@ -213,7 +212,12 @@ func (c *Cron) runWithRecovery(j Job) {
 			const size = 64 << 10
 			buf := make([]byte, size)
 			buf = buf[:runtime.Stack(buf, false)]
-			c.logger.Printf("panic running job: %v\n%s", r, buf)
+			var err error
+			err, ok := r.(error)
+			if !ok {
+				err = fmt.Errorf("%v", r)
+			}
+			c.logger.Error(err, "panic running job", "stack", "...\n"+string(buf))
 		}
 	}()
 	j.Run()
@@ -222,13 +226,13 @@ func (c *Cron) runWithRecovery(j Job) {
 // run the scheduler.. this is private just due to the need to synchronize
 // access to the 'running' state variable.
 func (c *Cron) run() {
-	c.logVerbosef("cron is starting")
+	c.logger.Info("start")
 
 	// Figure out the next activation times for each entry.
 	now := c.now()
 	for _, entry := range c.entries {
 		entry.Next = entry.Schedule.Next(now)
-		c.logVerbosef("(%s) scheduled entry %d for %s", now, entry.ID, entry.Next)
+		c.logger.Info("schedule", "now", now, "entry", entry.ID, "next", entry.Next)
 	}
 
 	for {
@@ -248,7 +252,7 @@ func (c *Cron) run() {
 			select {
 			case now = <-timer.C:
 				now = now.In(c.location)
-				c.logVerbosef("(%s) woke up", now)
+				c.logger.Info("wake", "now", now)
 
 				// Run every entry whose next time was less than now
 				for _, e := range c.entries {
@@ -258,52 +262,37 @@ func (c *Cron) run() {
 					go c.runWithRecovery(e.Job)
 					e.Prev = e.Next
 					e.Next = e.Schedule.Next(now)
-					c.logVerbosef("(%s) started entry %d, next scheduled for %s", now, e.ID, e.Next)
+					c.logger.Info("run", "now", now, "entry", e.ID, "next", e.Next)
 				}
 
 			case newEntry := <-c.add:
 				timer.Stop()
 				now = c.now()
 				newEntry.Next = newEntry.Schedule.Next(now)
 				c.entries = append(c.entries, newEntry)
-				c.logVerbosef("(%s) added new entry %d, scheduled for", now, newEntry.ID, newEntry.Next)
+				c.logger.Info("added", "now", now, "entry", newEntry.ID, "next", newEntry.Next)
 
 			case replyChan := <-c.snapshot:
 				replyChan <- c.entrySnapshot()
 				continue
 
 			case <-c.stop:
 				timer.Stop()
-				c.logVerbosef("cron is stopping")
+				c.logger.Info("stop")
 				return
 
 			case id := <-c.remove:
 				timer.Stop()
 				now = c.now()
 				c.removeEntry(id)
-				c.logVerbosef("removed entry %d", id)
+				c.logger.Info("removed", "entry", id)
 			}
 
 			break
 		}
 	}
 }
 
-// logVerbosef logs a verbose message, if such a logger is configured.
-func (c *Cron) logVerbosef(format string, args ...interface{}) {
-	if c.vlogger != nil {
-		// Format any times provided as RFC3339, easier to read than default.
-		var formattedArgs []interface{}
-		for _, arg := range args {
-			if t, ok := arg.(time.Time); ok {
-				arg = t.Format(time.RFC3339)
-			}
-			formattedArgs = append(formattedArgs, arg)
-		}
-		c.vlogger.Printf(format, formattedArgs...)
-	}
-}
-
 // now returns current time in c location
 func (c *Cron) now() time.Time {
 	return time.Now().In(c.location)

doc.go

@@ -158,6 +158,14 @@ care must be taken to ensure proper synchronization.
 All cron methods are designed to be correctly synchronized as long as the caller
 ensures that invocations have a clear happens-before ordering between them.
 
+Logging
+
+Cron defines a Logger interface that is a subset of the one defined in
+github.com/go-logr/logr. It has two logging levels (Info and Error), and
+parameters are key/value pairs. This makes it possible for cron logging to plug
+into structured logging systems. An adapter, [Verbose]PrintfLogger, is provided
+to wrap the standard library *log.Logger.
+
 Implementation
 
 Cron entries are stored in an array, sorted by their next activation time.  Cron

logger.go

@@ -3,12 +3,80 @@ package cron
 import (
 	"log"
 	"os"
+	"strings"
+	"time"
 )
 
-var DefaultLogger = log.New(os.Stderr, "cron: ", log.LstdFlags)
+// DefaultLogger is used by Cron if none is specified.
+var DefaultLogger Logger = PrintfLogger(log.New(os.Stdout, "cron: ", log.LstdFlags))
 
 // Logger is the interface used in this package for logging, so that any backend
-// can be easily plugged in. It's implemented directly by "log" and logrus.
+// can be plugged in. It is a subset of the github.com/go-logr/logr interface.
 type Logger interface {
-	Printf(string, ...interface{})
+	// Info logs routine messages about cron's operation.
+	Info(msg string, keysAndValues ...interface{})
+	// Error logs an error condition.
+	Error(err error, msg string, keysAndValues ...interface{})
+}
+
+// PrintfLogger wraps a Printf-based logger (such as the standard library "log")
+// into an implementation of the Logger interface which logs errors only.
+func PrintfLogger(l interface{ Printf(string, ...interface{}) }) Logger {
+	return printfLogger{l, false}
+}
+
+// VerbosePrintfLogger wraps a Printf-based logger (such as the standard library
+// "log") into an implementation of the Logger interface which logs everything.
+func VerbosePrintfLogger(l interface{ Printf(string, ...interface{}) }) Logger {
+	return printfLogger{l, true}
+}
+
+type printfLogger struct {
+	logger  interface{ Printf(string, ...interface{}) }
+	logInfo bool
+}
+
+func (pl printfLogger) Info(msg string, keysAndValues ...interface{}) {
+	if pl.logInfo {
+		keysAndValues = formatTimes(keysAndValues)
+		pl.logger.Printf(
+			formatString(len(keysAndValues)),
+			append([]interface{}{msg}, keysAndValues...)...)
+	}
+}
+
+func (pl printfLogger) Error(err error, msg string, keysAndValues ...interface{}) {
+	keysAndValues = formatTimes(keysAndValues)
+	pl.logger.Printf(
+		formatString(len(keysAndValues)+2),
+		append([]interface{}{msg, "error", err}, keysAndValues...)...)
+}
+
+// formatString returns a logfmt-like format string for the number of
+// key/values.
+func formatString(numKeysAndValues int) string {
+	var sb strings.Builder
+	sb.WriteString("%s")
+	if numKeysAndValues > 0 {
+		sb.WriteString(", ")
+	}
+	for i := 0; i < numKeysAndValues/2; i++ {
+		if i > 0 {
+			sb.WriteString(", ")
+		}
+		sb.WriteString("%v=%v")
+	}
+	return sb.String()
+}
+
+// formatTimes formats any time.Time values as RFC3339.
+func formatTimes(keysAndValues []interface{}) []interface{} {
+	var formattedArgs []interface{}
+	for _, arg := range keysAndValues {
+		if t, ok := arg.(time.Time); ok {
+			arg = t.Format(time.RFC3339)
+		}
+		formattedArgs = append(formattedArgs, arg)
+	}
+	return formattedArgs
 }

option.go

@@ -33,13 +33,13 @@ func WithParser(p Parser) Option {
 // WithPanicLogger overrides the logger used for logging job panics.
 func WithPanicLogger(l *log.Logger) Option {
 	return func(c *Cron) {
-		c.logger = l
+		c.logger = PrintfLogger(l)
 	}
 }
 
-// WithVerboseLogger enables verbose logging of events that occur in cron.
-func WithVerboseLogger(logger Logger) Option {
+// WithLogger uses the provided logger.
+func WithLogger(logger Logger) Option {
 	return func(c *Cron) {
-		c.vlogger = logger
+		c.logger = logger
 	}
 }

option_test.go

@@ -27,16 +27,16 @@ func TestWithPanicLogger(t *testing.T) {
 	var b bytes.Buffer
 	var logger = log.New(&b, "", log.LstdFlags)
 	c := New(WithPanicLogger(logger))
-	if c.logger != logger {
+	if c.logger.(printfLogger).logger != logger {
 		t.Error("expected provided logger")
 	}
 }
 
 func TestWithVerboseLogger(t *testing.T) {
 	var buf syncWriter
 	var logger = log.New(&buf, "", log.LstdFlags)
-	c := New(WithVerboseLogger(logger))
-	if c.vlogger != logger {
+	c := New(WithLogger(VerbosePrintfLogger(logger)))
+	if c.logger.(printfLogger).logger != logger {
 		t.Error("expected provided logger")
 	}
 
@@ -45,8 +45,8 @@ func TestWithVerboseLogger(t *testing.T) {
 	time.Sleep(OneSecond)
 	c.Stop()
 	out := buf.String()
-	if !strings.Contains(out, "scheduled entry") ||
-		!strings.Contains(out, "started entry") {
+	if !strings.Contains(out, "schedule,") ||
+		!strings.Contains(out, "run,") {
 		t.Error("expected to see some actions, got:", out)
 	}
 }