diff --git a/README.md b/README.md index 0dcda67..eb849ec 100644 --- a/README.md +++ b/README.md @@ -25,20 +25,30 @@ A field is a `Pair` consisting of a key, `string` and value, `interface{}`. You can choose to instantiate a logger. Doing this will allow you to set a name as well as to add some fields to the logger. #### without a logger instance. -```go - chainsaw.Infof("Application %f starting up", version) - if err!= nil { - chainsaw.Fatal("Out of gloop") - } - // with fields: - chainsaw.Infow("Can't open file",chainsaw.P{"file", file}, chainsaw.P{"err", err}) +``` + package main + import "github.com/celerway/chainsaw" + + func main() { + chainsaw.Infof("Application %f starting up", version) + err := checkGloop() + if err != nil { + chainsaw.Fatal("Out of gloop") + } + // with fields: + chainsaw.Infow("Can't open file", chainsaw.P{"file", file}, chainsaw.P{"err", err}) + } ``` #### with a logger instance. -```go +``` + package main + import "github.com/celerway/chainsaw" - logger := chainsaw.MakeLogger("main") - logger.SetFields(chainsaw.P{"hostname", hostname}) - logger.Error("Error in file:", err) + func main() { + logger := chainsaw.MakeLogger("main") + logger.SetFields(chainsaw.P{"hostname", hostname}) + logger.Error("Error in file:", err) + } } ``` diff --git a/api.go b/api.go index b50adc0..8df6fa7 100644 --- a/api.go +++ b/api.go @@ -41,6 +41,7 @@ func MakeLogger(name string, options ...int) *CircularLogger { chanBufferSize: chanBufferSize, outputWriters: []io.Writer{os.Stdout}, TimeFmt: "2006-01-02T15:04:05-0700", + backTraceLevel: TraceLevel, } go c.channelHandler() runtime.Gosched() @@ -112,12 +113,13 @@ func GetMessages(level LogLevel) []LogMessage { return l.GetMessages(level) } -// BackTrace logs messages from the current buffer to the log file. -// This happens in one single write so it'll be continuous in the logs. -// Todo: finish this. Needs to have formatting stuff done first, which needs the structured bits to work. -func BackTrace() error { +func SetBackTraceLevel(level LogLevel) { + l := defaultLogger + l.SetBackTraceLevel(level) +} - return nil +func (l *CircularLogger) SetBackTraceLevel(level LogLevel) { + l.backTraceLevel = level } // SetLevel sets the log level. This affects if messages are printed to @@ -186,15 +188,15 @@ func GetLevels() []LogLevel { return levels } -func ParseLogLevel(s string) LogLevel { - level := InfoLevel +func ParseLogLevel(s string) (LogLevel, error) { s = strings.ToLower(s) + s = strings.TrimSuffix(s, "level") for l := TraceLevel; l <= FatalLevel; l++ { - cmpLevel := strings.ToLower(l.String()) - if cmpLevel == s { - level = l - break + s2 := strings.ToLower(l.String()) + s2 = strings.TrimSuffix(s2, "level") + if s2 == s { + return l, nil } } - return level + return 0, fmt.Errorf("invalid log level: %s", s) } diff --git a/api_test.go b/api_test.go index 974a7ba..5be4641 100644 --- a/api_test.go +++ b/api_test.go @@ -1,36 +1,89 @@ package chainsaw -import "testing" +import ( + "bytes" + "fmt" + is2 "github.com/matryer/is" + "os" + "testing" + "time" +) func TestParseLogLevel(t *testing.T) { type args struct { s string } tests := []struct { - name string - args args - want LogLevel + name string + args args + want LogLevel + wantErr bool }{ - {"trace", args{"trace"}, TraceLevel}, - {"debug", args{"debug"}, DebugLevel}, - {"info", args{"info"}, InfoLevel}, - {"warn", args{"warn"}, WarnLevel}, - {"error", args{"error"}, ErrorLevel}, - {"fatal", args{"fatal"}, FatalLevel}, - {"traceUpper", args{"TRACE"}, TraceLevel}, - {"debugUpper", args{"DEBUG"}, DebugLevel}, - {"infoUpper", args{"INFO"}, InfoLevel}, - {"warnUpper", args{"WARN"}, WarnLevel}, - {"errorUpper", args{"ERROR"}, ErrorLevel}, - {"fatalUpper", args{"FATAL"}, FatalLevel}, - {"empty", args{""}, InfoLevel}, - {"invalid", args{"blalbla"}, InfoLevel}, + {"trace", args{"trace"}, TraceLevel, false}, + {"debug", args{"debug"}, DebugLevel, false}, + {"info", args{"info"}, InfoLevel, false}, + {"warn", args{"warn"}, WarnLevel, false}, + {"error", args{"error"}, ErrorLevel, false}, + {"fatal", args{"fatal"}, FatalLevel, false}, + {"tracelevel", args{"tracelevel"}, TraceLevel, false}, + {"debuglevel", args{"debuglevel"}, DebugLevel, false}, + {"infolevel", args{"infolevel"}, InfoLevel, false}, + {"warnlevel", args{"warnlevel"}, WarnLevel, false}, + {"errorlevel", args{"errorlevel"}, ErrorLevel, false}, + {"fatallevel", args{"fatallevel"}, FatalLevel, false}, + {"traceUpper", args{"TRACE"}, TraceLevel, false}, + {"debugUpper", args{"DEBUG"}, DebugLevel, false}, + {"infoUpper", args{"INFO"}, InfoLevel, false}, + {"warnUpper", args{"WARN"}, WarnLevel, false}, + {"errorUpper", args{"ERROR"}, ErrorLevel, false}, + {"fatalUpper", args{"FATAL"}, FatalLevel, false}, + {"empty", args{""}, InfoLevel, true}, + {"invalid", args{"blalbla"}, InfoLevel, true}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - if got := ParseLogLevel(tt.args.s); got != tt.want { + got, err := ParseLogLevel(tt.args.s) + if (err != nil) != tt.wantErr { + t.Errorf("ParseLogLevel() error = %v, wantErr %v", err, tt.wantErr) + return + } + if !tt.wantErr && got != tt.want { t.Errorf("ParseLogLevel() = %v, want %v", got, tt.want) } }) } } + +func TestCircularLogger_BackTrace(t *testing.T) { + is := is2.New(t) + + logger := MakeLogger("", 30, 10) + err := logger.RemoveWriter(os.Stdout) + is.NoErr(err) + logger.SetBackTraceLevel(ErrorLevel) + logger.SetLevel(ErrorLevel) + logBuffer := bytes.NewBuffer(make([]byte, 0, 1024)) + err = logger.AddWriter(logBuffer) + is.NoErr(err) + + logger.Trace("trace") + logger.Debug("debug") + logger.Info("info") + logger.Warn("warn") + logger.Error("error") + err = logger.Flush() // trigger a flush, so we know things are flushed out to the buffer + is.NoErr(err) + time.Sleep(time.Millisecond) + lines := bytes.Split(logBuffer.Bytes(), []byte{'\n'}) + for i, line := range lines { + fmt.Printf("line %d: %s\n", i, line) + } + is.True(bytes.Contains(lines[0], []byte("error"))) + is.True(bytes.Contains(lines[1], []byte("backtrace begin"))) + is.True(bytes.Contains(lines[2], []byte("trace"))) + is.True(bytes.Contains(lines[3], []byte("debug"))) + is.True(bytes.Contains(lines[4], []byte("info"))) + is.True(bytes.Contains(lines[5], []byte("warn"))) + is.True(bytes.Contains(lines[6], []byte("error"))) + is.True(bytes.Contains(lines[7], []byte("backtrace end"))) +} diff --git a/controltype_string.go b/controltype_string.go new file mode 100644 index 0000000..23ae968 --- /dev/null +++ b/controltype_string.go @@ -0,0 +1,32 @@ +// Code generated by "stringer -type=controlType"; DO NOT EDIT. + +package chainsaw + +import "strconv" + +func _() { + // An "invalid array index" compiler error signifies that the constant values have changed. + // Re-run the stringer command to generate them again. + var x [1]struct{} + _ = x[ctrlDump-1] + _ = x[ctrlRst-2] + _ = x[ctrlQuit-3] + _ = x[ctrlAddOutputChan-4] + _ = x[ctrlRemoveOutputChan-5] + _ = x[ctrlAddWriter-6] + _ = x[ctrlRemoveWriter-7] + _ = x[ctrlSetLogLevel-8] + _ = x[ctrlFlush-9] +} + +const _controlType_name = "ctrlDumpctrlRstctrlQuitctrlAddOutputChanctrlRemoveOutputChanctrlAddWriterctrlRemoveWriterctrlSetLogLevelctrlFlush" + +var _controlType_index = [...]uint8{0, 8, 15, 23, 40, 60, 73, 89, 104, 113} + +func (i controlType) String() string { + i -= 1 + if i < 0 || i >= controlType(len(_controlType_index)-1) { + return "controlType(" + strconv.FormatInt(int64(i+1), 10) + ")" + } + return _controlType_name[_controlType_index[i]:_controlType_index[i+1]] +} diff --git a/loglevel_string.go b/loglevel_string.go new file mode 100644 index 0000000..0730747 --- /dev/null +++ b/loglevel_string.go @@ -0,0 +1,29 @@ +// Code generated by "stringer -type=LogLevel"; DO NOT EDIT. + +package chainsaw + +import "strconv" + +func _() { + // An "invalid array index" compiler error signifies that the constant values have changed. + // Re-run the stringer command to generate them again. + var x [1]struct{} + _ = x[TraceLevel-1] + _ = x[DebugLevel-2] + _ = x[InfoLevel-3] + _ = x[WarnLevel-4] + _ = x[ErrorLevel-5] + _ = x[FatalLevel-6] +} + +const _LogLevel_name = "TraceLevelDebugLevelInfoLevelWarnLevelErrorLevelFatalLevel" + +var _LogLevel_index = [...]uint8{0, 10, 20, 29, 38, 48, 58} + +func (i LogLevel) String() string { + i -= 1 + if i < 0 || i >= LogLevel(len(_LogLevel_index)-1) { + return "LogLevel(" + strconv.FormatInt(int64(i+1), 10) + ")" + } + return _LogLevel_name[_LogLevel_index[i]:_LogLevel_index[i+1]] +} diff --git a/main.go b/main.go index 7b42319..11e5aa7 100644 --- a/main.go +++ b/main.go @@ -9,6 +9,8 @@ import ( ) //go:generate go run gen/main.go +//go:generate stringer -type=controlType +//go:generate string -type=LogLevel const channelTimeout = time.Second var defaultLogger *CircularLogger @@ -31,24 +33,6 @@ const ( FatalLevel ) -func (level LogLevel) String() string { - switch level { - case TraceLevel: - return "trace" - case DebugLevel: - return "debug" - case InfoLevel: - return "info" - case WarnLevel: - return "warn" - case ErrorLevel: - return "error" - case FatalLevel: - return "fatal" - } - return "unknown" -} - // init() runs when the library is imported. It will start a logger // so the library can be used without initializing a custom logger. func init() { @@ -59,7 +43,7 @@ func init() { type controlType int -// controlMessage struct describes the control message sent to the worker. This is a multi-purpose struct that +// controlMessage struct describes the control message sent to the worker. This is a multipurpose struct that // allows you to do a number of operations. // - Add or remove new output channels // - Dump messages @@ -67,7 +51,7 @@ type controlType int type controlMessage struct { cType controlType returnChan chan []LogMessage // channel for dumps of messages - errChan chan error // Used for acks + errChan chan error // Used for acknowledgements level LogLevel outputCh chan LogMessage newWriter io.Writer @@ -76,14 +60,23 @@ type controlMessage struct { type controlChannel chan controlMessage const ( + // ctrlDump dump messages in the buffer ctrlDump controlType = iota + 1 + // ctrlRst resets the buffer, discarding any messages ctrlRst + // ctrlQuit stops the worker goroutine ctrlQuit + // ctrlAddOutputChan adds a new output channel ctrlAddOutputChan + // ctrlRemoveOutputChan removes an output channel ctrlRemoveOutputChan + // ctrlAddWriter adds a new io.Writer to the list of outputs ctrlAddWriter + // ctrlRemoveWriter removes an io.Writer from the list of outputs ctrlRemoveWriter + // ctrlSetLogLevel sets the log level ctrlSetLogLevel + // ctrlFlush flushes the buffer to the outputs. also used to synchronize. ctrlFlush ) @@ -101,7 +94,7 @@ type LogMessage struct { // CircularLogger is the struct holding a chainsaw instance. // All state within is private and should be access through methods. type CircularLogger struct { - name string // The name gets into all the loglines when printed. + name string // The name gets into all the log-lines when printed. printLevel LogLevel // at what log level should messages be printed to stdout // messages is the internal log buffer keeping the last messages in a circular buffer messages []LogMessage @@ -117,6 +110,7 @@ type CircularLogger struct { chanBufferSize int // how big the channel buffer is. re-used when making streams. TimeFmt string // format string for date. Default is "2006-01-02T15:04:05-0700" fields string // pre-formatted set of fields. this gets included in every line. + backTraceLevel LogLevel // at what level should we trigger a backtrace? Default is TraceLevel, which disables this. } func (l *CircularLogger) log(level LogLevel, message string, fields string) { @@ -128,6 +122,17 @@ func (l *CircularLogger) log(level LogLevel, message string, fields string) { TimeStamp: t, } l.logCh <- logM + // trigger backtrace if level is high enough to triger it. + if l.backTraceLevel > TraceLevel && level >= l.backTraceLevel { + err := l.Flush() + if err != nil { + fmt.Printf("Error flushing: %s", err) + } + err = l.backTrace() + if err != nil { + fmt.Println("Chainsaw internal error getting backtrace: ", err) + } + } } // channelHandler run whenever the logger has been used. @@ -244,6 +249,8 @@ func (l *CircularLogger) addOutputChan(ch logChan) error { return nil } +// removeOutputChan removes a channel from the list of output channels. +// it will also close that channel. func (l *CircularLogger) removeOutputChan(ch logChan) error { found := false for i, outputCh := range l.outputChs { @@ -289,7 +296,7 @@ func (l *CircularLogger) removeWriter(o io.Writer) error { return nil } -// getMessageOverCh is used by the internal goroutine to fetch loglines +// getMessageOverCh is used by the internal goroutine to fetch log-lines // Perhaps it would be more efficient to stream these over a channel instead. // However, in terms of allocation this will do one big allocation and not many smaller ones. func (l *CircularLogger) getMessageOverCh(level LogLevel) []LogMessage { @@ -317,3 +324,39 @@ func (l *CircularLogger) sendCtrlAndWait(ctrlMsg controlMessage) error { l.controlCh <- ctrlMsg return <-errCh // Return the error returned by the logger goroutine. } + +// backTrace logs messages from the current buffer to the log file when a log message has a high enough +// log level. +// This happens in one single write, so it'll be continuous in the logs. +func (l *CircularLogger) backTrace() error { + msgs := l.GetMessages(TraceLevel) + msgStrings := make([]string, len(msgs)) + for _, msg := range msgs { + msgStrings = append(msgStrings, l.formatMessage(msg)) + } + joined := strings.Join(msgStrings, "") + for _, w := range l.outputWriters { + _, _ = w.Write([]byte(l.formatMessage(l.traceMessage(true)))) + _, err := w.Write([]byte(joined)) + if err != nil { + return fmt.Errorf("writing to output writer: %w", err) + } + _, _ = w.Write([]byte(l.formatMessage(l.traceMessage(false)))) + } + l.Reset() // Clear the logs. + return nil +} + +func (l *CircularLogger) traceMessage(begin bool) LogMessage { + var msg string + if begin { + msg = "=== backtrace begins ===" + } else { + msg = "=== backtrace ends ===" + } + return LogMessage{ + LogLevel: l.backTraceLevel, + Message: msg, + TimeStamp: time.Now(), + } +} diff --git a/main_test.go b/main_test.go index cb170b0..79e210e 100644 --- a/main_test.go +++ b/main_test.go @@ -162,33 +162,33 @@ func TestRemoveWriter(t *testing.T) { func TestDumpMessages(t *testing.T) { is := is2.New(t) const logBufferSize = 50 - log := MakeLogger("", logBufferSize, testDefaultChanBufferSize) - err := log.RemoveWriter(os.Stdout) + logger := MakeLogger("", logBufferSize, testDefaultChanBufferSize) + err := logger.RemoveWriter(os.Stdout) is.NoErr(err) - defer log.Stop() + defer logger.Stop() const noOfMessages = 5 var counted = 0 for i := 0; i < noOfMessages; i++ { - log.Tracef("Trace message %d", i) - log.Debugf("Debug message %d", i) - log.Infof("Info message %d", i) - log.Warnf("Warn message %d", i) - log.Errorf("Error message %d", i) + logger.Tracef("Trace message %d", i) + logger.Debugf("Debug message %d", i) + logger.Infof("Info message %d", i) + logger.Warnf("Warn message %d", i) + logger.Errorf("Error message %d", i) counted += 5 } - err = log.Flush() + err = logger.Flush() is.NoErr(err) time.Sleep(defaultSleepTime) // Sleep a few ms while the logs get to the right place. fmt.Printf("Generated %d messages\n", counted) - msgTrace := log.GetMessages(TraceLevel) + msgTrace := logger.GetMessages(TraceLevel) verifyLogLevel(is, msgTrace, TraceLevel) - msgDebug := log.GetMessages(DebugLevel) + msgDebug := logger.GetMessages(DebugLevel) verifyLogLevel(is, msgDebug, DebugLevel) - msgInfo := log.GetMessages(InfoLevel) + msgInfo := logger.GetMessages(InfoLevel) verifyLogLevel(is, msgInfo, InfoLevel) - msgWarn := log.GetMessages(WarnLevel) + msgWarn := logger.GetMessages(WarnLevel) verifyLogLevel(is, msgWarn, WarnLevel) - msgError := log.GetMessages(ErrorLevel) + msgError := logger.GetMessages(ErrorLevel) verifyLogLevel(is, msgWarn, WarnLevel) is.Equal(len(msgTrace), noOfMessages*5) // Trace is.Equal(len(msgDebug), noOfMessages*4) // Debug @@ -211,21 +211,21 @@ func TestDumpLimited(t *testing.T) { is := is2.New(t) const logBufferSize = 10 const logBufferOverrun = logBufferSize * 2 - log := MakeLogger("", logBufferSize, testDefaultChanBufferSize) - err := log.RemoveWriter(os.Stdout) + logger := MakeLogger("", logBufferSize, testDefaultChanBufferSize) + err := logger.RemoveWriter(os.Stdout) is.NoErr(err) - defer log.Stop() + defer logger.Stop() fmt.Printf("Generating %d trace messages...\n", logBufferSize) for i := 0; i < logBufferSize; i++ { - log.Tracef("Trace message %d/%d", i, testDefaultLogBufferSize) + logger.Tracef("Trace message %d/%d", i, testDefaultLogBufferSize) } fmt.Printf("overrunning the buffer with %d more messages\n", logBufferSize) for i := 0; i < logBufferOverrun; i++ { - log.Infof("Info message %d", i) + logger.Infof("Info message %d", i) } - err = log.Flush() + err = logger.Flush() is.NoErr(err) - msgs := log.GetMessages(InfoLevel) + msgs := logger.GetMessages(InfoLevel) fmt.Printf("Got %d messages from the log system\n", len(msgs)) is.Equal(len(msgs), logBufferSize) for i, m := range msgs {