Merge pull request #262 from bobheadxi/master

Add pluggable Logger for pipeline

Author: vmarkovtsev

Gopkg.lock

@@ -34,6 +34,8 @@ type {{.name}} struct {
   hercules.NoopMerger
   // Process each merge commit only once
   hercules.OneShotMergeProcessor
+  // Logger for consistent output
+  l hercules.Logger
 }
 
 // {{.name}}Result is returned by Finalize() and represents the analysis result.
@@ -81,11 +83,15 @@ func ({{.varname}} *{{.name}}) Description() string {
 
 // Configure applies the parameters specified in the command line. Map keys correspond to "Name".
 func ({{.varname}} *{{.name}}) Configure(facts map[string]interface{}) error {
+  if l, exists := facts[hercules.ConfigLogger].(hercules.Logger); exists {
+    {{.varname}}.l = l
+  }
   return nil
 }
 
 // Initialize resets the internal temporary data structures and prepares the object for Consume().
 func ({{.varname}} *{{.name}}) Initialize(repository *git.Repository) error {
+  {{.varname}}.l = hercules.NewLogger()
   {{.varname}}.OneShotMergeProcessor.Initialize()
   return nil
 }

cmd/hercules/plugin.template

@@ -30,6 +30,8 @@ type ChurnAnalysis struct {
 
 	// references IdentityDetector.ReversedPeopleDict
 	reversedPeopleDict []string
+
+	l hercules.Logger
 }
 
 type editInfo struct {
@@ -105,6 +107,9 @@ func (churn *ChurnAnalysis) Description() string {
 
 // Configure applies the parameters specified in the command line. Map keys correspond to "Name".
 func (churn *ChurnAnalysis) Configure(facts map[string]interface{}) error {
+	if l, exists := facts[hercules.ConfigLogger].(hercules.Logger); exists {
+		churn.l = l
+	}
 	if val, exists := facts[ConfigChurnTrackPeople].(bool); exists {
 		churn.TrackPeople = val
 	}
@@ -116,6 +121,7 @@ func (churn *ChurnAnalysis) Configure(facts map[string]interface{}) error {
 
 // Initialize resets the internal temporary data structures and prepares the object for Consume().
 func (churn *ChurnAnalysis) Initialize(repository *git.Repository) error {
+	churn.l = hercules.NewLogger()
 	churn.global = []editInfo{}
 	churn.people = map[int][]editInfo{}
 	churn.OneShotMergeProcessor.Initialize()

contrib/_plugin_example/churn_analysis.go

@@ -81,6 +81,8 @@ const (
 	ConfigPipelineCommits = core.ConfigPipelineCommits
 	// ConfigTickSize is the number of hours per 'tick'
 	ConfigTickSize = plumbing.ConfigTicksSinceStartTickSize
+	// ConfigLogger is used to set the logger in all pipeline items.
+	ConfigLogger = core.ConfigLogger
 )
 
 // NewPipeline initializes a new instance of Pipeline struct.
@@ -174,3 +176,9 @@ func PathifyFlagValue(flag *pflag.Flag) {
 func EnablePathFlagTypeMasquerade() {
 	core.EnablePathFlagTypeMasquerade()
 }
+
+// Logger is the Hercules logging interface
+type Logger core.Logger
+
+// NewLogger returns an instance of the default Hercules logger
+func NewLogger() core.Logger { return core.NewLogger() }

core.go

@@ -37,6 +37,15 @@ Finally extract the result:
 
 The actual usage example is cmd/hercules/root.go - the command line tool's code.
 
+You can provide additional options via `facts` on initialization. For example,
+to provide your own logger, enable people-tracking, and set a custom tick size:
+
+  pipe.Initialize(map[string]interface{}{
+    hercules.ConfigLogger:            zap.NewExample().Sugar(),
+    hercules.ConfigTickSize:          12,
+    leaves.ConfigBurndownTrackPeople: true,
+  })
+
 Hercules depends heavily on https://github.com/src-d/go-git and leverages the
 diff algorithm through https://github.com/sergi/go-diff.
 

doc.go

@@ -0,0 +1,91 @@
+package core
+
+import (
+	"log"
+	"os"
+	"runtime/debug"
+	"strings"
+)
+
+// ConfigLogger is the key for the pipeline's logger
+const ConfigLogger = "Core.Logger"
+
+// Logger defines the output interface used by Hercules components.
+type Logger interface {
+	Info(...interface{})
+	Infof(string, ...interface{})
+	Warn(...interface{})
+	Warnf(string, ...interface{})
+	Error(...interface{})
+	Errorf(string, ...interface{})
+	Critical(...interface{})
+	Criticalf(string, ...interface{})
+}
+
+// DefaultLogger is the default logger used by a pipeline, and wraps the standard
+// log library.
+type DefaultLogger struct {
+	I *log.Logger
+	W *log.Logger
+	E *log.Logger
+}
+
+// NewLogger returns a configured default logger.
+func NewLogger() *DefaultLogger {
+	return &DefaultLogger{
+		I: log.New(os.Stderr, "[INFO] ", log.LstdFlags),
+		W: log.New(os.Stderr, "[WARN] ", log.LstdFlags),
+		E: log.New(os.Stderr, "[ERROR] ", log.LstdFlags),
+	}
+}
+
+// Info writes to "info" logger.
+func (d *DefaultLogger) Info(v ...interface{}) { d.I.Println(v...) }
+
+// Infof writes to "info" logger with printf-style formatting.
+func (d *DefaultLogger) Infof(f string, v ...interface{}) { d.I.Printf(f, v...) }
+
+// Warn writes to the "warning" logger.
+func (d *DefaultLogger) Warn(v ...interface{}) { d.W.Println(v...) }
+
+// Warnf writes to the "warning" logger with printf-style formatting.
+func (d *DefaultLogger) Warnf(f string, v ...interface{}) { d.W.Printf(f, v...) }
+
+// Error writes to the "error" logger.
+func (d *DefaultLogger) Error(v ...interface{}) { d.E.Println(v...) }
+
+// Errorf writes to the "error" logger with printf-style formatting.
+func (d *DefaultLogger) Errorf(f string, v ...interface{}) { d.E.Printf(f, v...) }
+
+// Critical writes to the "error" logger and logs the current stacktrace.
+func (d *DefaultLogger) Critical(v ...interface{}) {
+	d.E.Println(v...)
+	d.logStacktraceToErr()
+}
+
+// Criticalf writes to the "error" logger with printf-style formatting and logs the
+// current stacktrace.
+func (d *DefaultLogger) Criticalf(f string, v ...interface{}) {
+	d.E.Printf(f, v...)
+	d.logStacktraceToErr()
+}
+
+// logStacktraceToErr prints a stacktrace to the logger's error output.
+// It skips 4 levels that aren't meaningful to a logged stacktrace:
+// * debug.Stack()
+// * core.captureStacktrace()
+// * DefaultLogger::logStacktraceToErr()
+// * DefaultLogger::Error() or DefaultLogger::Errorf()
+func (d *DefaultLogger) logStacktraceToErr() {
+	d.E.Println("stacktrace:\n" + strings.Join(captureStacktrace(4), "\n"))
+}
+
+func captureStacktrace(skip int) []string {
+	stack := string(debug.Stack())
+	lines := strings.Split(stack, "\n")
+	linesToSkip := 2*skip + 1
+	if linesToSkip > len(lines) {
+		return lines
+	}
+	return lines[linesToSkip:]
+}

internal/core/logger.go

@@ -0,0 +1,66 @@
+package core
+
+import (
+	"bytes"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestLogger(t *testing.T) {
+	var (
+		f = "%s-%s"
+		v = []interface{}{"hello", "world"}
+		l = NewLogger()
+
+		iBuf bytes.Buffer
+		wBuf bytes.Buffer
+		eBuf bytes.Buffer
+	)
+
+	// capture output
+	l.I.SetOutput(&iBuf)
+	l.W.SetOutput(&wBuf)
+	l.E.SetOutput(&eBuf)
+
+	l.Info(v...)
+	assert.Contains(t, iBuf.String(), "[INFO]")
+	iBuf.Reset()
+
+	l.Infof(f, v...)
+	assert.Contains(t, iBuf.String(), "[INFO]")
+	assert.Contains(t, iBuf.String(), "-")
+	iBuf.Reset()
+
+	l.Warn(v...)
+	assert.Contains(t, wBuf.String(), "[WARN]")
+	wBuf.Reset()
+
+	l.Warnf(f, v...)
+	assert.Contains(t, wBuf.String(), "[WARN]")
+	assert.Contains(t, wBuf.String(), "-")
+	wBuf.Reset()
+
+	l.Error(v...)
+	assert.Contains(t, eBuf.String(), "[ERROR]")
+	eBuf.Reset()
+
+	l.Errorf(f, v...)
+	assert.Contains(t, eBuf.String(), "[ERROR]")
+	assert.Contains(t, eBuf.String(), "-")
+	eBuf.Reset()
+
+	l.Critical(v...)
+	assert.Contains(t, eBuf.String(), "[ERROR]")
+	assert.Contains(t, eBuf.String(), "internal/core.TestLogger")
+	assert.Contains(t, eBuf.String(), "internal/core/logger_test.go:53")
+	eBuf.Reset()
+
+	l.Criticalf(f, v...)
+	assert.Contains(t, eBuf.String(), "[ERROR]")
+	assert.Contains(t, eBuf.String(), "-")
+	assert.Contains(t, eBuf.String(), "internal/core.TestLogger")
+	assert.Contains(t, eBuf.String(), "internal/core/logger_test.go:59")
+	println(eBuf.String())
+	eBuf.Reset()
+}