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

@@ -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

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<timestamp>\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}-\\d{4})\\s+(?P<level>\\w{4,5})\\s+(?P<location>\\S+)\\s+(?P<message>[^{]+?)\\s+(?P<jsonbody>{.+})$")
+
+// 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
+}

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"])
+			}
+		})
+	}
+
+}