mlog: complete refactor again, eliminating the go-routine, which allowed a lot of other things to fall into place nicely

This commit is contained in:
Brian Picciano 2018-11-30 16:27:18 -05:00
parent 47061cec4e
commit b5c676b5c8
3 changed files with 82 additions and 196 deletions

View File

@ -75,9 +75,7 @@ func withCtxState(ctx Context, s *ctxState) Context {
// New returns a new context which can be used as the root context for all // New returns a new context which can be used as the root context for all
// purposes in this framework. // purposes in this framework.
func New() Context { func New() Context {
return withCtxState(Context(context.Background()), &ctxState{ return withCtxState(Context(context.Background()), &ctxState{})
//logger: mlog.NewLogger(os.Stderr),
})
} }
// Path returns the sequence of names which were used to produce this context // Path returns the sequence of names which were used to produce this context

View File

@ -15,13 +15,12 @@
package mlog package mlog
import ( import (
"bytes" "bufio"
"fmt" "fmt"
"io" "io"
"os" "os"
"sort" "sort"
"strconv" "strconv"
"strings"
"sync" "sync"
) )
@ -35,6 +34,8 @@ func Truncate(s string, size int) string {
return s[:size] + "..." return s[:size] + "..."
} }
////////////////////////////////////////////////////////////////////////////////
// Level describes the severity of a particular log message, and can be compared // Level describes the severity of a particular log message, and can be compared
// to the severity of any other Level // to the severity of any other Level
type Level interface { type Level interface {
@ -70,31 +71,7 @@ var (
FatalLevel Level = level{s: "FATAL", i: 0} FatalLevel Level = level{s: "FATAL", i: 0}
) )
// LevelFromString parses a string, possibly lowercase, and returns the Level ////////////////////////////////////////////////////////////////////////////////
// identified by it, or an error.
//
// Note that this only works for the Levels pre-defined in this package, if
// you've extended the package to use your own levels you'll have to implement
// your own LevelFromString method.
func LevelFromString(ls string) (Level, error) {
var l Level
switch strings.ToUpper(ls) {
case "DEBUG":
l = DebugLevel
case "INFO":
l = InfoLevel
case "WARN":
l = WarnLevel
case "ERROR":
l = ErrorLevel
case "FATAL":
l = FatalLevel
default:
return nil, fmt.Errorf("unknown log level %q", ls)
}
return l, nil
}
// KVer is used to provide context to a log entry in the form of a dynamic set // KVer is used to provide context to a log entry in the form of a dynamic set
// of key/value pairs which can be different for every entry. // of key/value pairs which can be different for every entry.
@ -190,6 +167,8 @@ func Prefix(kv KVer, prefix string) KVer {
}) })
} }
////////////////////////////////////////////////////////////////////////////////
// Message describes a message to be logged, after having already resolved the // Message describes a message to be logged, after having already resolved the
// KVer // KVer
type Message struct { type Message struct {
@ -198,11 +177,6 @@ type Message struct {
KV KV KV KV
} }
// WriteFn describes a function which formats a single log message and writes it
// to the given io.Writer. If the io.Writer returns an error WriteFn should
// return that error.
type WriteFn func(w io.Writer, msg Message) error
func stringSlice(kv KV) [][2]string { func stringSlice(kv KV) [][2]string {
slice := make([][2]string, 0, len(kv)) slice := make([][2]string, 0, len(kv))
for k, v := range kv { for k, v := range kv {
@ -217,8 +191,15 @@ func stringSlice(kv KV) [][2]string {
return slice return slice
} }
// DefaultWriteFn is the default implementation of WriteFn. // Handler is a function which can process Messages in some way.
func DefaultWriteFn(w io.Writer, msg Message) error { //
// NOTE that Logger does not handle thread-safety, that must be done inside the
// Handler if necessary.
type Handler func(msg Message) error
// DefaultFormat formats and writs the Message to the given Writer using mlog's
// default format.
func DefaultFormat(w io.Writer, msg Message) error {
var err error var err error
write := func(s string, args ...interface{}) { write := func(s string, args ...interface{}) {
if err == nil { if err == nil {
@ -236,172 +217,98 @@ func DefaultWriteFn(w io.Writer, msg Message) error {
return err return err
} }
type msg struct { // DefaultHandler initializes and returns a Handler which will write all
buf *bytes.Buffer // messages to os.Stderr in a thread-safe way. This is the Handler which
msg Message // NewLogger will use automatically.
func DefaultHandler() Handler {
l := new(sync.Mutex)
bw := bufio.NewWriter(os.Stderr)
return func(msg Message) error {
l.Lock()
defer l.Unlock()
err := DefaultFormat(bw, msg)
if err != nil {
err = bw.Flush()
}
return err
}
} }
// Logger wraps a WriteFn and an io.WriteCloser such that logging calls on the // Logger directs Messages to an internal Handler and provides convenient
// Logger will use them (in a thread-safe manner) to write out log messages. // methods for creating and modifying its own behavior.
type Logger struct { type Logger struct {
wc io.WriteCloser w io.Writer
h Handler
l *sync.RWMutex
wfn WriteFn
maxLevel uint maxLevel uint
kv KVer
msgBufPool *sync.Pool
msgCh chan msg
testMsgWrittenCh chan struct{} // only initialized/used in tests testMsgWrittenCh chan struct{} // only initialized/used in tests
stopCh chan struct{}
wg *sync.WaitGroup
} }
// NewLogger initializes and returns a new instance of Logger which will write // NewLogger initializes and returns a new instance of Logger which will write
// to the given WriteCloser. // to the DefaultHandler.
func NewLogger(wc io.WriteCloser) *Logger { func NewLogger() *Logger {
l := &Logger{ return &Logger{
wc: wc, h: DefaultHandler(),
l: new(sync.RWMutex),
wfn: DefaultWriteFn,
maxLevel: InfoLevel.Uint(), maxLevel: InfoLevel.Uint(),
msgBufPool: &sync.Pool{
New: func() interface{} {
return new(bytes.Buffer)
},
},
msgCh: make(chan msg, 1024),
stopCh: make(chan struct{}),
wg: new(sync.WaitGroup),
} }
l.wg.Add(1)
go func() {
defer l.wg.Done()
l.spin()
}()
return l
} }
// Clone returns a usable copy of the *Logger. Changes to the returned Logger // Handler returns the Handler currently in use by the Logger.
// will not effect the original, e.g. if the SetMaxLevel is called on one it func (l *Logger) Handler() Handler {
// will not effect the max level of written logs on the other. If Stop is called return l.h
// on any Logger it effects all parent and child Loggers produced from Clone. }
func (l *Logger) Clone() *Logger {
func (l *Logger) clone() *Logger {
l2 := *l l2 := *l
l2.l = new(sync.RWMutex)
return &l2 return &l2
} }
func (l *Logger) drain() { // WithMaxLevelUint returns a copy of the Logger which will not log any messages
for { // with a higher Level.Uint value than the one given. The returned Logger is
select { // identical in all other aspects.
case m := <-l.msgCh: func (l *Logger) WithMaxLevelUint(i uint) *Logger {
l.writeMsg(m) l = l.clone()
default:
return
}
}
}
func (l *Logger) writeMsg(m msg) {
if _, err := m.buf.WriteTo(l.wc); err != nil {
go l.Error("error writing to Logger's WriteCloser", ErrKV(err))
}
l.msgBufPool.Put(m.buf)
if l.testMsgWrittenCh != nil {
l.testMsgWrittenCh <- struct{}{}
}
if m.msg.Level.Uint() == 0 {
l.wc.Close()
os.Exit(1)
}
}
func (l *Logger) spin() {
defer l.wc.Close()
for {
select {
case m := <-l.msgCh:
l.writeMsg(m)
case <-l.stopCh:
l.drain()
return
}
}
}
// SetMaxLevelUint sets the Logger's max logging level so that it will not log
// any messages with a higher Level.Uint value.
func (l *Logger) SetMaxLevelUint(i uint) {
l.l.Lock()
defer l.l.Unlock()
l.maxLevel = i l.maxLevel = i
return l
} }
// SetMaxLevel sets the Logger's max logging level so that it will not log any // WithMaxLevel returns a copy of the Logger which will not log any messages
// messages with a higher Level.Uint value. // with a higher Level.Uint value than of the Level given. The returned Logger
func (l *Logger) SetMaxLevel(lvl Level) { // is identical in all other aspects.
l.SetMaxLevelUint(lvl.Uint()) func (l *Logger) WithMaxLevel(lvl Level) *Logger {
return l.WithMaxLevelUint(lvl.Uint())
} }
// SetWriteFn sets the Logger to use the given WriteFn to format and write // WithHandler returns a copy of the Logger which will use the given Handler in
// Messages to Logger's WriteCloser. // order to process messages. The returned Logger is identical in all other
func (l *Logger) SetWriteFn(wfn WriteFn) { // aspects.
l.l.Lock() func (l *Logger) WithHandler(h Handler) *Logger {
defer l.l.Unlock() l = l.clone()
l.wfn = wfn l.h = h
} return l
// AddKV sets the Logger to implicitly add the given KVers to all log messages.
// This will not affect KVer data previously added the Logger or its parent (see
// Clone), except to overwrite keys in the case of overlap.
func (l *Logger) AddKV(kvs ...KVer) {
l.l.Lock()
defer l.l.Unlock()
l.kv = MergeInto(l.kv, kvs...)
}
// Stop stops and cleans up any running go-routines and resources held by the
// Logger, allowing it to be garbage-collected. This will flush any remaining
// messages to the io.WriteCloser before returning.
//
// The Logger should not be used after Stop is called
func (l *Logger) Stop() {
close(l.stopCh)
l.wg.Wait()
} }
// Log can be used to manually log a message of some custom defined Level. kvs // Log can be used to manually log a message of some custom defined Level. kvs
// will be Merge'd automatically. If the Level is a fatal (Uint() == 0) then // will be Merge'd automatically. If the Level is a fatal (Uint() == 0) then
// calling this will never return, and the process will have os.Exit(1) called. // calling this will never return, and the process will have os.Exit(1) called.
func (l *Logger) Log(lvl Level, msgStr string, kvs ...KVer) { func (l *Logger) Log(lvl Level, msgStr string, kvs ...KVer) {
l.l.RLock()
defer l.l.RUnlock()
if l.maxLevel < lvl.Uint() { if l.maxLevel < lvl.Uint() {
return return
} }
m := Message{Level: lvl, Msg: msgStr, KV: mergeInto(l.kv, kvs...)} m := Message{Level: lvl, Msg: msgStr, KV: Merge(kvs...).KV()}
buf := l.msgBufPool.Get().(*bytes.Buffer) if err := l.h(m); err != nil {
buf.Reset() go l.Log(ErrorLevel, "Logger.Handler returned error", ErrKV(err))
if err := l.wfn(buf, m); err != nil {
// TODO welp, hopefully this doesn't infinite loop
l.Log(ErrorLevel, "Logger could not write to WriteCloser", ErrKV(err))
return return
} }
select { if l.testMsgWrittenCh != nil {
case l.msgCh <- msg{buf: buf, msg: m}: l.testMsgWrittenCh <- struct{}{}
case <-l.stopCh:
} }
// if a Fatal is logged then we're merely waiting here for spin to call if m.Level.Uint() == 0 {
// os.Exit, and this go-routine shouldn't be allowed to continue os.Exit(1)
if lvl.Uint() == 0 {
select {}
} }
} }
@ -430,17 +337,3 @@ func (l *Logger) Error(msg string, kvs ...KVer) {
func (l *Logger) Fatal(msg string, kvs ...KVer) { func (l *Logger) Fatal(msg string, kvs ...KVer) {
l.Log(FatalLevel, msg, kvs...) l.Log(FatalLevel, msg, kvs...)
} }
// DefaultLogger is a Logger using the default configuration (which will log to
// stderr). The Debug, Info, Warn, etc... methods from DefaultLogger are exposed
// as global functions for convenience. Because Logger is not truly initialized
// till the first time it is called any of DefaultLogger's fields may be
// modified before using one of the Debug, Info, Warn, etc... global functions.
var (
DefaultLogger = NewLogger(os.Stderr)
Debug = DefaultLogger.Debug
Info = DefaultLogger.Info
Warn = DefaultLogger.Warn
Error = DefaultLogger.Error
Fatal = DefaultLogger.Fatal
)

View File

@ -2,8 +2,6 @@ package mlog
import ( import (
"bytes" "bytes"
"io"
"io/ioutil"
"regexp" "regexp"
"strings" "strings"
. "testing" . "testing"
@ -49,13 +47,11 @@ func TestKV(t *T) {
func TestLogger(t *T) { func TestLogger(t *T) {
buf := new(bytes.Buffer) buf := new(bytes.Buffer)
l := NewLogger(struct { h := func(msg Message) error {
io.Writer return DefaultFormat(buf, msg)
io.Closer }
}{
Writer: buf, l := NewLogger().WithHandler(h)
Closer: ioutil.NopCloser(nil),
})
l.testMsgWrittenCh = make(chan struct{}, 10) l.testMsgWrittenCh = make(chan struct{}, 10)
assertOut := func(expected string) massert.Assertion { assertOut := func(expected string) massert.Assertion {
@ -82,7 +78,7 @@ func TestLogger(t *T) {
assertOut("~ ERROR -- buz\n"), assertOut("~ ERROR -- buz\n"),
)) ))
l.SetMaxLevel(WarnLevel) l = l.WithMaxLevel(WarnLevel)
l.Log(DebugLevel, "foo") l.Log(DebugLevel, "foo")
l.Log(InfoLevel, "bar") l.Log(InfoLevel, "bar")
l.Log(WarnLevel, "baz") l.Log(WarnLevel, "baz")
@ -92,11 +88,10 @@ func TestLogger(t *T) {
assertOut("~ ERROR -- buz -- a=\"b\"\n"), assertOut("~ ERROR -- buz -- a=\"b\"\n"),
)) ))
l2 := l.Clone() l2 := l.WithMaxLevel(InfoLevel)
l2.SetMaxLevel(InfoLevel) l2 = l2.WithHandler(func(msg Message) error {
l2.SetWriteFn(func(w io.Writer, msg Message) error {
msg.Msg = strings.ToUpper(msg.Msg) msg.Msg = strings.ToUpper(msg.Msg)
return DefaultWriteFn(w, msg) return h(msg)
}) })
l2.Log(InfoLevel, "bar") l2.Log(InfoLevel, "bar")
l2.Log(WarnLevel, "baz") l2.Log(WarnLevel, "baz")
@ -108,11 +103,11 @@ func TestLogger(t *T) {
)) ))
} }
func TestDefaultWriteFn(t *T) { func TestDefaultFormat(t *T) {
assertFormat := func(postfix string, msg Message) massert.Assertion { assertFormat := func(postfix string, msg Message) massert.Assertion {
expectedRegex := regexp.MustCompile(`^~ ` + postfix + `\n$`) expectedRegex := regexp.MustCompile(`^~ ` + postfix + `\n$`)
buf := bytes.NewBuffer(make([]byte, 0, 128)) buf := bytes.NewBuffer(make([]byte, 0, 128))
writeErr := DefaultWriteFn(buf, msg) writeErr := DefaultFormat(buf, msg)
line, err := buf.ReadString('\n') line, err := buf.ReadString('\n')
return massert.Comment( return massert.Comment(
massert.All( massert.All(