diff --git a/README.md b/README.md index 06c29d9..b0232da 100644 --- a/README.md +++ b/README.md @@ -3,3 +3,12 @@ This is a collection of packages which I use across many of my personal projects. All packages intended to be used start with an `m`, packages not starting with `m` are for internal use within this set of packages. + +Other third-party packages which integrate into these: + +* [merry](github.com/ansel1/merry): used by `mlog` to embed KV logging + information into `error` instances, it should be assumed that all errors + returned from these packages are `merry.Error` instances. In cases where a + package has a specific error it might return and which might be checked for a + function to perform that equality check will be supplied as part of the + package. diff --git a/mlog/errctx.go b/mlog/errctx.go new file mode 100644 index 0000000..8364cea --- /dev/null +++ b/mlog/errctx.go @@ -0,0 +1,67 @@ +package mlog + +import ( + "context" + "fmt" + "path/filepath" + + "github.com/ansel1/merry" +) + +type kvKey int + +// ErrWithKV embeds the merging of a set of KVs into an error, returning a new +// error instance. If the error already has a KV embedded in it then the +// returned error will have the merging of them all. +func ErrWithKV(err error, kvs ...KVer) merry.Error { + if err == nil { + return nil + } + merr := merry.WrapSkipping(err, 1) + kv := merge(kvs...) + if exKV := merry.Value(merr, kvKey(0)); exKV != nil { + kv = merge(exKV.(KV), kv) + } + return merr.WithValue(kvKey(0), kv) +} + +// ErrKV returns a KV which includes the KV embedded in the error by ErrWithKV, +// if any. The KV will also include an "err" field containing the output of +// err.Error(), and an "errSrc" field if the given error is a merry error which +// contains an embedded stacktrace. +func ErrKV(err error) KVer { + var kv KV + if kvi := merry.Value(err, kvKey(0)); kvi != nil { + kv = kvi.(KV) + } else { + kv = KV{} + } + kv["err"] = err.Error() + if fileFull, line := merry.Location(err); fileFull != "" { + file, dir := filepath.Base(fileFull), filepath.Dir(fileFull) + dir = filepath.Base(dir) // only want the first dirname, ie the pkg name + kv["errSrc"] = fmt.Sprintf("%s/%s:%d", dir, file, line) + } + return kv +} + +// CtxWithKV embeds a KV into a Context, returning a new Context instance. If +// the Context already has a KV embedded in it then the returned error will have +// the merging of the two. +func CtxWithKV(ctx context.Context, kvs ...KVer) context.Context { + kv := merge(kvs...) + existingKV := ctx.Value(kvKey(0)) + if existingKV != nil { + kv = merge(existingKV.(KV), kv) + } + return context.WithValue(ctx, kvKey(0), kv) +} + +// CtxKV returns a copy of the KV embedded in the Context by CtxWithKV +func CtxKV(ctx context.Context) KVer { + kv := ctx.Value(kvKey(0)) + if kv == nil { + return KV{} + } + return kv.(KV) +} diff --git a/mlog/errctx_test.go b/mlog/errctx_test.go new file mode 100644 index 0000000..72ce0da --- /dev/null +++ b/mlog/errctx_test.go @@ -0,0 +1,75 @@ +package mlog + +import ( + "context" + "strings" + . "testing" + + "github.com/ansel1/merry" + "github.com/stretchr/testify/assert" +) + +func TestErrKV(t *T) { + assertErrKV := func(err error, exp KV) { + got := KV(ErrKV(err).KV()) + errSrc := got["errSrc"] + assert.NotEmpty(t, errSrc) + assert.True(t, strings.HasPrefix(errSrc.(string), "mlog/errctx_test.go")) + delete(got, "errSrc") + assert.Equal(t, exp, got) + } + + err := merry.New("foo") + assertErrKV(err, KV{"err": err.Error()}) + + kv := KV{"a": "a"} + err2 := ErrWithKV(err, kv) + assertErrKV(err, KV{"err": err.Error()}) + assertErrKV(err2, KV{"err": err.Error(), "a": "a"}) + + // changing the kv now shouldn't do anything + kv["a"] = "b" + assertErrKV(err, KV{"err": err.Error()}) + assertErrKV(err2, KV{"err": err.Error(), "a": "a"}) + + // a new ErrWithKV shouldn't affect the previous one + err3 := ErrWithKV(err2, KV{"b": "b"}) + assertErrKV(err, KV{"err": err.Error()}) + assertErrKV(err2, KV{"err": err2.Error(), "a": "a"}) + assertErrKV(err3, KV{"err": err3.Error(), "a": "a", "b": "b"}) + + // make sure precedence works + err4 := ErrWithKV(err3, KV{"b": "bb"}) + assertErrKV(err, KV{"err": err.Error()}) + assertErrKV(err2, KV{"err": err2.Error(), "a": "a"}) + assertErrKV(err3, KV{"err": err3.Error(), "a": "a", "b": "b"}) + assertErrKV(err4, KV{"err": err4.Error(), "a": "a", "b": "bb"}) +} + +func TestCtxKV(t *T) { + ctx := context.Background() + assert.Equal(t, KV{}, CtxKV(ctx)) + + kv := KV{"a": "a"} + ctx2 := CtxWithKV(ctx, kv) + assert.Equal(t, KV{}, CtxKV(ctx)) + assert.Equal(t, KV{"a": "a"}, CtxKV(ctx2)) + + // changing the kv now shouldn't do anything + kv["a"] = "b" + assert.Equal(t, KV{}, CtxKV(ctx)) + assert.Equal(t, KV{"a": "a"}, CtxKV(ctx2)) + + // a new CtxWithKV shouldn't affect the previous one + ctx3 := CtxWithKV(ctx2, KV{"b": "b"}) + assert.Equal(t, KV{}, CtxKV(ctx)) + assert.Equal(t, KV{"a": "a"}, CtxKV(ctx2)) + assert.Equal(t, KV{"a": "a", "b": "b"}, CtxKV(ctx3)) + + // make sure precedence works + ctx4 := CtxWithKV(ctx3, KV{"b": "bb"}) + assert.Equal(t, KV{}, CtxKV(ctx)) + assert.Equal(t, KV{"a": "a"}, CtxKV(ctx2)) + assert.Equal(t, KV{"a": "a", "b": "b"}, CtxKV(ctx3)) + assert.Equal(t, KV{"a": "a", "b": "bb"}, CtxKV(ctx4)) +} diff --git a/mlog/llog.go b/mlog/llog.go new file mode 100644 index 0000000..188f96c --- /dev/null +++ b/mlog/llog.go @@ -0,0 +1,334 @@ +// Package mlog is a generic logging library. The log methods come in different +// severities: Debug, Info, Warn, Error, and Fatal. +// +// The log methods take in a string describing the error, and a set of key/value +// pairs giving the specific context around the error. The string is intended to +// always be the same no matter what, while the key/value pairs give information +// like which userID the error happened to, or any other relevant contextual +// information. +// +// Examples: +// +// Info("Something important has occurred") +// Error("Could not open file", llog.KV{"filename": filename}, llog.ErrKV(err)) +// +package mlog + +import ( + "fmt" + "io" + "os" + "sort" + "strconv" + "strings" + "sync" +) + +// Truncate is a helper function to truncate a string to a given size. It will +// add 3 trailing elipses, so the returned string will be at most size+3 +// characters long +func Truncate(s string, size int) string { + if len(s) <= size { + return s + } + return s[:size] + "..." +} + +// Level describes the severity of a particular log message, and can be compared +// to the severity of any other Level +type Level interface { + // String gives the string form of the level, e.g. "INFO" or "ERROR" + String() string + + // Uint gives an integer indicator of the severity of the level, with zero + // being most severe. If a Level with Uint of zero is logged then the Logger + // implementation provided by this package will exit the process (i.e. zero + // is used as Fatal). + Uint() uint +} + +type level struct { + s string + i uint +} + +func (l level) String() string { + return l.s +} + +func (l level) Uint() uint { + return l.i +} + +// All pre-defined log levels +var ( + DebugLevel Level = level{s: "DEBUG", i: 40} + InfoLevel Level = level{s: "INFO", i: 30} + WarnLevel Level = level{s: "WARN", i: 20} + ErrorLevel Level = level{s: "ERROR", i: 10} + 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 +// of key/value pairs which can be different for every entry. +// +// Each returned map should be modifiable. +type KVer interface { + KV() map[string]interface{} +} + +// KV is a simple and convenient implementation of KVer +type KV map[string]interface{} + +// KV implements the KVer method by returning a copy of the casted KV +func (kv KV) KV() map[string]interface{} { + nkv := make(map[string]interface{}, len(kv)) + for k, v := range kv { + nkv[k] = v + } + return nkv +} + +// Set returns a copy of the KV being called on with the given key/val set on +// it. The original KV is unaffected +func (kv KV) Set(k string, v interface{}) KV { + nkv := kv.KV() + nkv[k] = v + return nkv +} + +// separate from Merge because it's convenient to not return a KVer if that KVer +// is going to immediately have KV called on it (and thereby create a copy for +// no reason). +func merge(kvs ...KVer) KV { + kvm := kvs[0].KV() + for _, kv := range kvs[1:] { + for k, v := range kv.KV() { + kvm[k] = v + } + } + return KV(kvm) +} + +// Merge takes in multiple KVers and returns a single KVer which is the union of +// all the passed in ones. Key/vals on the rightmost of the set take precedence +// over conflicting ones to the left. +func Merge(kvs ...KVer) KVer { + return merge(kvs...) +} + +// Message describes a message to be logged, after having already resolved the +// KVer +type Message struct { + Level + Msg string + 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 this should return +// that error. +type WriteFn func(w io.Writer, msg Message) error + +func stringSlice(kv KV) [][2]string { + slice := make([][2]string, 0, len(kv)) + for k, v := range kv { + slice = append(slice, [2]string{ + k, + strconv.QuoteToGraphic(fmt.Sprint(v)), + }) + } + sort.Slice(slice, func(i, j int) bool { + return slice[i][0] < slice[j][0] + }) + return slice +} + +// DefaultWriteFn is the default implementation of WriteFn. +func DefaultWriteFn(w io.Writer, msg Message) error { + var err error + write := func(s string, args ...interface{}) { + if err == nil { + _, err = fmt.Fprintf(w, s, args...) + } + } + write("~ %s -- %s", msg.Level.String(), msg.Msg) + if len(msg.KV) > 0 { + write(" --") + for _, kve := range stringSlice(msg.KV) { + write(" %s=%s", kve[0], kve[1]) + } + } + write("\n") + return err +} + +// Logger wraps a WriteFn and an io.WriteCloser such that logging calls on the +// Logger will use them (in a thread-safe manner) to write out log messages. +// +// Logger will auto-initialize itself on the first method call. +type Logger struct { + WriteFn // Defaults to DefaultWriteFn + io.WriteCloser // Defaults to os.Stderr + + levelL sync.RWMutex + maxLevel uint + maxLevelSet bool + + init sync.Once + msgCh chan Message + testMsgWrittenCh chan struct{} // only initialized/used in tests +} + +func (l *Logger) getMaxLevel() uint { + l.levelL.RLock() + defer l.levelL.RUnlock() + if !l.maxLevelSet { + return InfoLevel.Uint() + } + return l.maxLevel +} + +// SetMaxLevelUint sets the maximum (up-to-and-including) level priority which +// the Logger will output a log for. Any Levels with an Uint value higher than +// this will not be logged. This may be called at any time. +func (l *Logger) SetMaxLevelUint(i uint) { + l.levelL.Lock() + l.maxLevel = i + l.maxLevelSet = true + l.levelL.Unlock() +} + +// SetMaxLevel sets the maximum (up-to-and-including) Level which the Logger +// will output a log for. Any Levels whose Uint value is higher than this one's +// will not be logged. This may be called at any time. +func (l *Logger) SetMaxLevel(lvl Level) { + l.SetMaxLevelUint(lvl.Uint()) +} + +func (l *Logger) spin() { + for msg := range l.msgCh { + if err := l.WriteFn(l.WriteCloser, msg); err != nil { + go l.Error("could not write to Logger.WriteCloser", ErrKV(err)) + } + if l.testMsgWrittenCh != nil { + l.testMsgWrittenCh <- struct{}{} + } + if msg.Level.Uint() == 0 { + l.WriteCloser.Close() + os.Exit(1) + } + } + l.WriteCloser.Close() +} + +func (l *Logger) initDo() { + l.init.Do(func() { + if l.WriteFn == nil { + l.WriteFn = DefaultWriteFn + } + if l.WriteCloser == nil { + l.WriteCloser = os.Stderr + } + // maxLevel's default is implicitly handled by getMaxLevel + l.msgCh = make(chan Message, 1000) + go l.spin() + }) +} + +// Stop stops and cleans up any running go-routines and resources held by the +// Logger, allowing it to be garbage-collected. The Logger should not be used +// after Stop is called +func (l *Logger) Stop() { + l.initDo() + close(l.msgCh) +} + +// 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 +// calling this will never return, and the process will have os.Exit(1) called. +func (l *Logger) Log(lvl Level, msg string, kvs ...KVer) { + if maxLevel := l.getMaxLevel(); maxLevel < lvl.Uint() { + return + } + + var kv KV + if len(kvs) > 0 { + kv = merge(kvs...) + } + + l.initDo() + l.msgCh <- Message{Level: lvl, Msg: msg, KV: kv} + + // if a Fatal is logged then we're merely waiting here for spin to call + // os.Exit, and this go-routine shouldn't be allowed to continue + if lvl.Uint() == 0 { + select {} + } +} + +// Debug logs a DebugLevel message, merging the KVers together first +func (l *Logger) Debug(msg string, kvs ...KVer) { + l.Log(DebugLevel, msg, kvs...) +} + +// Info logs a InfoLevel message, merging the KVers together first +func (l *Logger) Info(msg string, kvs ...KVer) { + l.Log(InfoLevel, msg, kvs...) +} + +// Warn logs a WarnLevel message, merging the KVers together first +func (l *Logger) Warn(msg string, kvs ...KVer) { + l.Log(WarnLevel, msg, kvs...) +} + +// Error logs a ErrorLevel message, merging the KVers together first +func (l *Logger) Error(msg string, kvs ...KVer) { + l.Log(ErrorLevel, msg, kvs...) +} + +// Fatal logs a FatalLevel message, merging the KVers together first. A Fatal +// message automatically stops the process with an os.Exit(1) +func (l *Logger) Fatal(msg string, kvs ...KVer) { + 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 = new(Logger) + Debug = DefaultLogger.Debug + Info = DefaultLogger.Info + Warn = DefaultLogger.Warn + Error = DefaultLogger.Error + Fatal = DefaultLogger.Fatal +) diff --git a/mlog/llog_test.go b/mlog/llog_test.go new file mode 100644 index 0000000..cd5b92d --- /dev/null +++ b/mlog/llog_test.go @@ -0,0 +1,108 @@ +package mlog + +import ( + "bytes" + "io" + "io/ioutil" + "regexp" + . "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestTruncate(t *T) { + assert.Equal(t, "abc", Truncate("abc", 4)) + assert.Equal(t, "abc", Truncate("abc", 3)) + assert.Equal(t, "ab...", Truncate("abc", 2)) +} + +func TestKV(t *T) { + var kv KV + assert.NotNil(t, kv.KV()) + assert.Empty(t, kv.KV()) + + kv = KV{"foo": "a"} + kv2 := KV(kv.KV()) + kv["bar"] = "b" + kv2["bar"] = "bb" + assert.Equal(t, KV{"foo": "a", "bar": "b"}, kv) + assert.Equal(t, KV{"foo": "a", "bar": "bb"}, kv2) + + kv = KV{"foo": "a"} + kv2 = kv.Set("bar", "wat") + assert.Equal(t, KV{"foo": "a"}, kv) + assert.Equal(t, KV{"foo": "a", "bar": "wat"}, kv2) + + assert.Equal(t, KV{"foo": "a", "bar": "b"}, Merge( + KV{"foo": "aaaaa"}, + KV{"foo": "a", "bar": "bbbbb"}, + KV{"bar": "b"}, + )) +} + +func TestLLog(t *T) { + buf := new(bytes.Buffer) + l := &Logger{ + WriteCloser: struct { + io.Writer + io.Closer + }{ + Writer: buf, + Closer: ioutil.NopCloser(nil), + }, + testMsgWrittenCh: make(chan struct{}, 10), + } + + assertOut := func(expected string) { + select { + case <-l.testMsgWrittenCh: + case <-time.After(1 * time.Second): + t.Fatal("waited too long for msg to write") + } + out, err := buf.ReadString('\n') + require.NoError(t, err) + assert.Equal(t, expected, out) + } + + // Default max level should be INFO + l.Log(DebugLevel, "foo") + l.Log(InfoLevel, "bar") + l.Log(WarnLevel, "baz") + l.Log(ErrorLevel, "buz") + assertOut("~ INFO -- bar\n") + assertOut("~ WARN -- baz\n") + assertOut("~ ERROR -- buz\n") + + l.SetMaxLevel(WarnLevel) + l.Log(DebugLevel, "foo") + l.Log(InfoLevel, "bar") + l.Log(WarnLevel, "baz") + l.Log(ErrorLevel, "buz", KV{"a": "b"}) + assertOut("~ WARN -- baz\n") + assertOut("~ ERROR -- buz -- a=\"b\"\n") +} + +func TestDefaultWriteFn(t *T) { + assertFormat := func(postfix string, msg Message) { + expectedRegex := regexp.MustCompile(`^~ ` + postfix + `\n$`) + buf := bytes.NewBuffer(make([]byte, 0, 128)) + assert.NoError(t, DefaultWriteFn(buf, msg)) + line, err := buf.ReadString('\n') + require.NoError(t, err) + assert.True(t, expectedRegex.MatchString(line), "regex: %q line: %q", expectedRegex.String(), line) + } + + msg := Message{Level: InfoLevel, Msg: "this is a test"} + assertFormat("INFO -- this is a test", msg) + + msg.KV = KV{}.KV() + assertFormat("INFO -- this is a test", msg) + + msg.KV = KV{"foo": "a"}.KV() + assertFormat("INFO -- this is a test -- foo=\"a\"", msg) + + msg.KV = KV{"foo": "a", "bar": "b"}.KV() + assertFormat("INFO -- this is a test -- bar=\"b\" foo=\"a\"", msg) +}