logger: write internal / outlet errors to an error outlet

refs #28

cmd/config_logging.go

@@ -13,7 +13,7 @@ import (
 )
 
 type LoggingConfig struct {
-	Outlets logger.Outlets
+	Outlets *logger.Outlets
 }
 
 type MetadataFlags int64
@@ -26,10 +26,21 @@ const (
 	MetadataAll  MetadataFlags = ^0
 )
 
+func LoggerErrorOutlet() logger.Outlet {
+
+	formatter := &HumanFormatter{}
+	writer := os.Stderr
+	formatter.SetMetadataFlags(MetadataAll)
+	return WriterOutlet{
+		formatter, writer,
+	}
+}
+
 func parseLogging(i interface{}) (c *LoggingConfig, err error) {
 
 	c = &LoggingConfig{}
-	c.Outlets = logger.NewOutlets()
+
+	c.Outlets = logger.NewOutlets(LoggerErrorOutlet())
 
 	var asList []interface{}
 	if err = mapstructure.Decode(i, &asList); err != nil {

cmd/test.go

@@ -65,7 +65,7 @@ func init() {
 
 func testCmdGlobalInit(cmd *cobra.Command, args []string) {
 
-	out := logger.NewOutlets()
+	out := logger.NewOutlets(WriterOutlet{&NoFormatter{}, os.Stderr})
 	out.Add(WriterOutlet{&NoFormatter{}, os.Stdout}, logger.Info)
 	log := logger.NewLogger(out, 1*time.Second)
 	testCmdGlobal.log = log

logger/datastructures.go

@@ -78,14 +78,28 @@ type Outlet interface {
 	WriteEntry(ctx context.Context, entry Entry) error
 }
 
-type Outlets map[Level][]Outlet
+type Outlets struct {
-
+	reg map[Level][]Outlet
-func NewOutlets() Outlets {
+	e   Outlet
-	return make(Outlets, len(AllLevels))
 }
 
-func (os Outlets) Add(outlet Outlet, minLevel Level) {
+func NewOutlets(loggerErrorOutlet Outlet) *Outlets {
-	for _, l := range AllLevels[minLevel:] {
+	return &Outlets{
-		os[l] = append(os[l], outlet)
+		make(map[Level][]Outlet, len(AllLevels)),
+		loggerErrorOutlet,
 	}
 }
+
+func (os *Outlets) Add(outlet Outlet, minLevel Level) {
+	for _, l := range AllLevels[minLevel:] {
+		os.reg[l] = append(os.reg[l], outlet)
+	}
+}
+
+func (os *Outlets) Get(level Level) []Outlet {
+	return os.reg[level]
+}
+
+func (os *Outlets) GetLoggerErrorOutlet() Outlet {
+	return os.e
+}

logger/logger.go

@@ -3,7 +3,6 @@ package logger
 import (
 	"context"
 	"fmt"
-	"os"
 	"runtime/debug"
 	"sync"
 	"time"
@@ -15,17 +14,16 @@ const (
 )
 
 const DefaultUserFieldCapacity = 5
-const InternalErrorPrefix = "github.com/zrepl/zrepl/logger: "
 
 type Logger struct {
 	fields        Fields
-	outlets       Outlets
+	outlets       *Outlets
 	outletTimeout time.Duration
 
 	mtx *sync.Mutex
 }
 
-func NewLogger(outlets Outlets, outletTimeout time.Duration) *Logger {
+func NewLogger(outlets *Outlets, outletTimeout time.Duration) *Logger {
 	return &Logger{
 		make(Fields, DefaultUserFieldCapacity),
 		outlets,
@@ -34,6 +32,29 @@ func NewLogger(outlets Outlets, outletTimeout time.Duration) *Logger {
 	}
 }
 
+type outletResult struct {
+	Outlet Outlet
+	Error  error
+}
+
+func (l *Logger) logInternalError(outlet Outlet, err string) {
+	fields := Fields{}
+	if outlet != nil {
+		if _, ok := outlet.(fmt.Stringer); ok {
+			fields["outlet"] = fmt.Sprintf("%s", outlet)
+		}
+		fields["outlet_type"] = fmt.Sprintf("%T", outlet)
+	}
+	fields[FieldError] = err
+	entry := Entry{
+		Error,
+		"outlet error",
+		time.Now(),
+		fields,
+	}
+	l.outlets.GetLoggerErrorOutlet().WriteEntry(context.Background(), entry)
+}
+
 func (l *Logger) log(level Level, msg string) {
 
 	l.mtx.Lock()
@@ -42,24 +63,24 @@ func (l *Logger) log(level Level, msg string) {
 	entry := Entry{level, msg, time.Now(), l.fields}
 
 	ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(l.outletTimeout))
-	ech := make(chan error)
+	ech := make(chan outletResult)
 
-	louts := l.outlets[level]
+	louts := l.outlets.Get(level)
 	for i := range louts {
 		go func(ctx context.Context, outlet Outlet, entry Entry) {
-			ech <- outlet.WriteEntry(ctx, entry)
+			ech <- outletResult{outlet, outlet.WriteEntry(ctx, entry)}
 		}(ctx, louts[i], entry)
 	}
 
 	for fin := 0; fin < len(louts); fin++ {
 		select {
-		case err := <-ech:
+		case res := <-ech:
-			if err != nil {
+			if res.Error != nil {
-				fmt.Fprintf(os.Stderr, "%s outlet error: %s\n", InternalErrorPrefix, err)
+				l.logInternalError(res.Outlet, res.Error.Error())
 			}
 		case <-ctx.Done():
 			if ctx.Err() == context.DeadlineExceeded {
-				fmt.Fprintf(os.Stderr, "%s outlets exceeded deadline, keep waiting anyways", InternalErrorPrefix)
+				l.logInternalError(nil, "one or more outlets exceeded timeout but will keep waiting anyways")
 			}
 		}
 	}
@@ -74,7 +95,8 @@ func (l *Logger) WithField(field string, val interface{}) *Logger {
 	defer l.mtx.Unlock()
 
 	if _, ok := l.fields[field]; ok {
-		fmt.Fprintf(os.Stderr, "%s caller overwrites field '%s'. Stack:\n%s\n", InternalErrorPrefix, field, string(debug.Stack()))
+		l.logInternalError(nil,
+			fmt.Sprintf("caller overwrites field '%s'. Stack: %s", field, string(debug.Stack())))
 	}
 
 	child := &Logger{