From e0185c96f31587bc37250f363e8955fb26ace6cb Mon Sep 17 00:00:00 2001 From: Dave Date: Fri, 5 Feb 2021 15:31:03 -0700 Subject: [PATCH] add support for uber-go/zap development mode logs Zap's development-mode logs prefix the structured k/v pairs with timestamps, log levels, caller-location, and the main message before the JSON object followed by some optional context lines in the case of WARN/ERROR/FATAL level logs. The handler added here captures those prefixed fields, parses them as appropriate, and puts them into a JSONHandler. --- scanner.go | 4 + zap_development_handler.go | 39 ++++++ zap_development_handler_test.go | 221 ++++++++++++++++++++++++++++++++ 3 files changed, 264 insertions(+) create mode 100644 zap_development_handler.go create mode 100644 zap_development_handler_test.go diff --git a/scanner.go b/scanner.go index c296486..2b26c33 100644 --- a/scanner.go +++ b/scanner.go @@ -50,6 +50,10 @@ func Scanner(src io.Reader, dst io.Writer, opts *HandlerOptions) error { dst.Write(logfmtEntry.Prettify(opts.SkipUnchanged && lastLogfmt)) lastLogfmt = true + case tryZapDevPrefix(lineData, &jsonEntry): + dst.Write(jsonEntry.Prettify(opts.SkipUnchanged && lastJSON)) + lastJSON = true + default: lastLogfmt = false lastJSON = false diff --git a/zap_development_handler.go b/zap_development_handler.go new file mode 100644 index 0000000..4a38961 --- /dev/null +++ b/zap_development_handler.go @@ -0,0 +1,39 @@ +package humanlog + +import ( + "regexp" + "strings" + "time" +) + +// Zap Development logs are made up of the following separated by whitespace +// 1. timestamp in ISO-8601 (??) +// 2. Log Level (one of DEBUG ERROR INFO WARN FATAL) +// 3. Caller Location in the source +// 4. The main logged message +// 5. a JSON object containing the structured k/v pairs +// 6. optional context lines - but since they are on a separate line the main +// scanner loop will never capture them +var zapDevLogsPrefixRe = regexp.MustCompile("^(?P\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}-\\d{4})\\s+(?P\\w{4,5})\\s+(?P\\S+)\\s+(?P[^{]+?)\\s+(?P{.+})$") + +// This is not obviously an RFC-compliant format and is not a constant in the +// time package which is worrisome but this pattern does work. +const someRFC = "2006-01-02T15:04:05.000-0700" + +func tryZapDevPrefix(d []byte, handler *JSONHandler) bool { + if matches := zapDevLogsPrefixRe.FindSubmatch(d); matches != nil { + if handler.TryHandle(matches[5]) { + t, err := time.Parse(someRFC, string(matches[1])) + if err != nil { + return false + } + handler.Time = t + + handler.Level = strings.ToLower(string(matches[2])) + handler.setField([]byte("caller"), matches[3]) + handler.Message = string(matches[4]) + return true + } + } + return false +} diff --git a/zap_development_handler_test.go b/zap_development_handler_test.go new file mode 100644 index 0000000..307fe92 --- /dev/null +++ b/zap_development_handler_test.go @@ -0,0 +1,221 @@ +package humanlog + +import ( + "reflect" + "testing" + "time" +) + +var logLinesByLevel = map[string][]byte{ + "DEBUG": []byte(`2021-02-05T12:41:48.053-0700 DEBUG zapper/zapper.go:18 some message 1 {"rand_index": 1}`), + "ERROR": []byte(`2021-02-05T12:41:49.059-0700 ERROR zapper/zapper.go:18 some message 2 {"rand_index": 3}`), + "FATAL": []byte(`2021-02-05T15:45:04.425-0700 FATAL zapper/zapper.go:18 some message 5 {"rand_index": 11}`), + "INFO": []byte(`2021-02-05T12:41:50.064-0700 INFO zapper/zapper.go:18 some message 3 {"rand_index": 5}`), + "WARN": []byte(`2021-02-05T12:41:51.069-0700 WARN zapper/zapper.go:18 some message 4 {"rand_index": 7}`), +} + +func Test_zapDevLogsPrefixRe(t *testing.T) { + tests := []struct { + name string + logLine []byte + wantTS string + wantLevel string + wantLocation string + wantMessage string + wantJSON string + }{ + { + name: "debug message", + + logLine: logLinesByLevel["DEBUG"], + + wantTS: "2021-02-05T12:41:48.053-0700", + wantLevel: "DEBUG", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 1", + wantJSON: `{"rand_index": 1}`, + }, + { + name: "error message with caller info", + + logLine: logLinesByLevel["ERROR"], + + wantTS: "2021-02-05T12:41:49.059-0700", + wantLevel: "ERROR", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 2", + wantJSON: `{"rand_index": 3}`, + }, + { + name: "fatal message with caller info and exit status", + logLine: logLinesByLevel["FATAL"], + wantTS: "2021-02-05T15:45:04.425-0700", + wantLevel: "FATAL", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 5", + wantJSON: `{"rand_index": 11}`, + }, + { + name: "info message", + + logLine: logLinesByLevel["INFO"], + + wantTS: "2021-02-05T12:41:50.064-0700", + wantLevel: "INFO", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 3", + wantJSON: `{"rand_index": 5}`, + }, + { + + name: "warning message with caller info", + + logLine: logLinesByLevel["WARN"], + + wantTS: "2021-02-05T12:41:51.069-0700", + wantLevel: "WARN", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 4", + wantJSON: `{"rand_index": 7}`, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + matches := zapDevLogsPrefixRe.FindSubmatch(test.logLine) + if matches != nil { + result := make(map[string]string) + for i, name := range zapDevLogsPrefixRe.SubexpNames() { + if i != 0 && name != "" { + result[name] = string(matches[i]) + } + } + + if result["timestamp"] != test.wantTS { + t.Errorf("want %q, got %q, want != got", test.wantTS, result["timestamp"]) + } + + if result["level"] != test.wantLevel { + t.Errorf("want %q, got %q, want != got", test.wantLevel, result["level"]) + } + + if result["location"] != test.wantLocation { + t.Errorf("want %q, got %q, want != got", test.wantLocation, result["location"]) + } + + if result["message"] != test.wantMessage { + t.Errorf("want %q, got %q, want != got", test.wantMessage, result["message"]) + } + + if result["jsonbody"] != test.wantJSON { + t.Errorf("want %q, got %q, want != got", test.wantJSON, result["jsonbody"]) + } + } else { + t.Errorf("regular expression did not match log line") + } + }) + } +} + +func Test_tryZapDevPrefix(t *testing.T) { + tests := []struct { + name string + logLine []byte + wantMatch bool + + wantLevel string + wantLocation string + wantMessage string + + wantExtraContext string + }{ + { + name: "no match", + + logLine: []byte("that's no good"), + + wantMatch: false, + }, + { + name: "debug message", + + logLine: logLinesByLevel["DEBUG"], + + wantMatch: true, + wantLevel: "debug", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 1", + }, + { + name: "error message with caller info", + + logLine: logLinesByLevel["ERROR"], + + wantMatch: true, + wantLevel: "error", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 2", + }, + { + name: "fatal message with caller info and exit status", + + logLine: logLinesByLevel["FATAL"], + + wantMatch: true, + + wantLevel: "fatal", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 5", + }, + { + name: "info message", + + logLine: logLinesByLevel["INFO"], + + wantMatch: true, + wantLevel: "info", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 3", + }, + { + + name: "warning message with caller info", + + logLine: logLinesByLevel["WARN"], + + wantMatch: true, + wantLevel: "warn", + wantLocation: "zapper/zapper.go:18", + wantMessage: "some message 4", + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + h := &JSONHandler{} + m := tryZapDevPrefix(test.logLine, h) + + if m != test.wantMatch { + t.Error("expected the prefix to match, it did not") + } + // Short circuit - if we want failure don't assert against the handler + if !test.wantMatch { + return + } + + if reflect.DeepEqual(time.Time{}, h.Time) { + t.Errorf("want a parsed time, got empty time; want != got") + } + if h.Level != test.wantLevel { + t.Errorf("want %q, got %q; want != got", test.wantLevel, h.Level) + } + if h.Message != test.wantMessage { + t.Errorf("want %q, got %q; want != got", test.wantMessage, h.Message) + } + if h.Fields["caller"] != test.wantLocation { + t.Errorf("want %q, got %q; want != got", test.wantLocation, h.Fields["caller"]) + } + }) + } + +}