diff --git a/README.md b/README.md index b2e1d37..45e0b5a 100644 --- a/README.md +++ b/README.md @@ -39,6 +39,9 @@ Here's the `--help` message: --levelkey= JSON key that holds the log level. [$JLOG_LEVEL_KEY] --timekey= JSON key that holds the log timestamp. [$JLOG_TIMESTAMP_KEY] --messagekey= JSON key that holds the log message. [$JLOG_MESSAGE_KEY] + --delete= JSON keys to be deleted before JQ processing and output; repeatable. [$JLOG_DELETE_KEYS] + --upgrade= JSON key (of type object) whose fields should be merged with any other fields; good for loggers that always put structed data in a separate key; repeatable. + --upgrade b would transform as follows: {a:'a', b:{'c':'c'}} -> {a:'a', c:'c'} [$JLOG_UPGRADE_KEYS] Output Format: --no-elide Disable eliding repeated fields. By default, fields that have the same value as the line above them have their values replaced with '↑'. [$JLOG_NO_ELIDE_DUPLICATES] @@ -71,10 +74,23 @@ taught to recognize. If your JSON log uses `foo` as the level, `bar` as the time message, like: `{"foo":"info", "bar":"2022-01-01T00:00:00.123", "baz":"information!"}`, then `jlog --levelkey=foo --timekey=bar --messagekey=baz` will allow jlog to properly format those logs. +There is some logic to guess the log format based on the first line. If this yields incorrect +results, file a bug, but setting any of `--levelkey`, `--timekey`, or `--messagekey` will completely +disable auto-guessing. + +Some loggers put all structured data into one key; you can merge that key's values into the main set +of fields with `--upgrade `. This makes eliding of repeated fields work for that log format. +Logs that look like they were produced by a known library that does this are automatically upgraded. + +Some loggers output schema format information with each log message. You can delete keys like this +with `--delete `. Logs that look that look like they were produced by a known library that does +this automatically have that key deleted. (You can do this with `del(.key)` in a JQ program, as +well.) + ## Output -There are many options to control the output format. You can output times in your favorite format -with `-t XXX`, where XXX is one of the options listed above or any +There are many options to control the output format. You can output timestamps in your favorite +format with `-t XXX`, where XXX is one of the options listed above or any [go time format string](https://pkg.go.dev/time#pkg-constants). If you want to distinguish events that happened in the same second as the previous line, use `-s`. @@ -92,8 +108,8 @@ Into: This can sometimes make spammy logs a little easier on the eyes. -You can pass `-r` to see the time difference between when the program started, and the log line. -This is good if you don't want to do any mental math. +You can pass `-r` to see the time difference between when the program started and the log line. This +is good if you don't want to do any mental math. You can adjust the output timezone with the `TZ` environment variable. `TZ=America/Los_Angeles jlog` will print times in Pacific, for example. @@ -110,3 +126,11 @@ You can pass a [jq](https://stedolan.github.io/jq/) program to process the input `jlog -e 'select($MSG | test("foo"))'` will only show messages that contain "foo" (even if a field contains foo). You can of course access any field in the parsed JSON log line and make selection decisions on that, or delete fields, or add new fields. + +The JQ program is run after schema detection and validation. + +## Highlighting + +The built-in jq function `highlight` will caused matched messages to display in inverse-video +`jlog -e 'highlight(.foo == 42)'` would highlight any message where the `foo` key equals 42. +`jlog -e 'highlight($MSG|test("abc"))'` would highlight any message that contains `"abc"`. diff --git a/cmd/jlog/main.go b/cmd/jlog/main.go index b14fb51..73e5580 100644 --- a/cmd/jlog/main.go +++ b/cmd/jlog/main.go @@ -48,10 +48,12 @@ type general struct { } type input struct { - Lax bool `short:"l" long:"lax" description:"If true, suppress any validation errors including non-JSON log lines and missing timestamps, levels, and message. We extract as many of those as we can, but if something is missing, the errors will be silently discarded." env:"JLOG_LAX"` - LevelKey string `long:"levelkey" description:"JSON key that holds the log level." env:"JLOG_LEVEL_KEY"` - TimestampKey string `long:"timekey" description:"JSON key that holds the log timestamp." env:"JLOG_TIMESTAMP_KEY"` - MessageKey string `long:"messagekey" description:"JSON key that holds the log message." env:"JLOG_MESSAGE_KEY"` + Lax bool `short:"l" long:"lax" description:"If true, suppress any validation errors including non-JSON log lines and missing timestamps, levels, and message. We extract as many of those as we can, but if something is missing, the errors will be silently discarded." env:"JLOG_LAX"` + LevelKey string `long:"levelkey" description:"JSON key that holds the log level." env:"JLOG_LEVEL_KEY"` + TimestampKey string `long:"timekey" description:"JSON key that holds the log timestamp." env:"JLOG_TIMESTAMP_KEY"` + MessageKey string `long:"messagekey" description:"JSON key that holds the log message." env:"JLOG_MESSAGE_KEY"` + DeleteKeys []string `long:"delete" description:"JSON keys to be deleted before JQ processing and output; repeatable." env:"JLOG_DELETE_KEYS"` + UpgradeKeys []string `long:"upgrade" description:"JSON key (of type object) whose fields should be merged with any other fields; good for loggers that always put structed data in a separate key; repeatable.\n--upgrade b would transform as follows: {a:'a', b:{'c':'c'}} -> {a:'a', c:'c'}" env:"JLOG_UPGRADE_KEYS"` } func printVersion(w io.Writer) { @@ -175,6 +177,9 @@ func main() { ins.TimeKey = k ins.TimeFormat = parse.DefaultTimeParser } + if u := in.UpgradeKeys; len(u) > 0 { + ins.UpgradeKeys = append(ins.UpgradeKeys, u...) + } var wantColor = isatty.IsTerminal(os.Stdout.Fd()) switch { diff --git a/integration-tests/loggers_test.go b/integration-tests/loggers_test.go index bef9363..20c3634 100644 --- a/integration-tests/loggers_test.go +++ b/integration-tests/loggers_test.go @@ -4,6 +4,7 @@ import ( "bytes" "errors" "strconv" + "strings" "testing" "time" @@ -38,10 +39,12 @@ func TestLoggers(t *testing.T) { exampleObject := map[string]interface{}{"foo": "bar"} exampleError := errors.New("whoa") testData := []struct { - name string - skip string - ins *parse.InputSchema - f func(buf *bytes.Buffer) + name string + skip string + wantMessagePrefix string + wantLineSuffix string + ins *parse.InputSchema + f func(buf *bytes.Buffer) }{ { name: "zap", @@ -59,7 +62,7 @@ func TestLoggers(t *testing.T) { l := zap.New(core) l.Info("line 1") l.Info("line 2", zap.String("string", "value"), zap.Int("int", 42), zap.Any("object", exampleObject)) - l.Info("line 3", zap.Error(exampleError)) + l.Error("line 3", zap.Error(exampleError)) }, }, { @@ -80,7 +83,7 @@ func TestLoggers(t *testing.T) { } l.Info("line 1") l.WithField("string", "value").WithField("int", 42).WithField("object", exampleObject).Info("line 2") - l.WithError(exampleError).Info("line 3") + l.WithError(exampleError).Error("line 3") }, }, { @@ -101,7 +104,7 @@ func TestLoggers(t *testing.T) { } l.Info("line 1") l.WithField("string", "value").WithField("int", 42).WithField("object", exampleObject).Info("line 2") - l.WithError(exampleError).Info("line 3") + l.WithError(exampleError).Error("line 3") }, }, { @@ -129,12 +132,11 @@ func TestLoggers(t *testing.T) { } l.Info("line 1") l.WithField("string", "value").WithField("int", 42).WithField("object", exampleObject).Info("line 2") - l.WithError(exampleError).Info("line 3") + l.WithError(exampleError).Error("line 3") }, }, { name: "lager/pretty", - skip: "we can't handle the extra 'test.' appended to each message", ins: &parse.InputSchema{ LevelKey: "level", MessageKey: "message", @@ -142,18 +144,20 @@ func TestLoggers(t *testing.T) { LevelFormat: parse.DefaultLevelParser, TimeFormat: parse.DefaultTimeParser, Strict: true, + UpgradeKeys: []string{"data"}, }, + wantMessagePrefix: "test.", + wantLineSuffix: " source:test", f: func(buf *bytes.Buffer) { l := lager.NewLogger("test") l.RegisterSink(lager.NewPrettySink(buf, lager.DEBUG)) l.Info("line 1") - l.Info("line 2", lager.Data{"int": 42, "object": exampleObject}) + l.Info("line 2", lager.Data{"string": "value", "int": 42, "object": exampleObject}) l.Error("line 3", exampleError) }, }, { name: "lager", - skip: "we can't handle the extra 'test.' appended to each message", ins: &parse.InputSchema{ LevelKey: "log_level", MessageKey: "message", @@ -161,12 +165,15 @@ func TestLoggers(t *testing.T) { LevelFormat: parse.LagerLevelParser, TimeFormat: parse.StrictUnixTimeParser, Strict: true, + UpgradeKeys: []string{"data"}, }, + wantMessagePrefix: "test.", + wantLineSuffix: " source:test", f: func(buf *bytes.Buffer) { l := lager.NewLogger("test") l.RegisterSink(lager.NewWriterSink(buf, lager.DEBUG)) l.Info("line 1") - l.Info("line 2", lager.Data{"int": 42, "object": exampleObject}) + l.Info("line 2", lager.Data{"string": "value", "int": 42, "object": exampleObject}) l.Error("line 3", exampleError) }, }, @@ -190,10 +197,10 @@ func TestLoggers(t *testing.T) { // var log = bunyan.createLogger({ name: "test" }); // log.info("line 1"); // log.info({ string: "value", int: 42, object: { foo: "bar" } }, "line 2"); - // log.info({ error: "whoa" }, "line 3"); + // log.error({ error: "whoa" }, "line 3"); buf.WriteString(`{"level":30,"msg":"line 1","time":"2021-03-09T17:44:26.203Z","v":0} {"level":30,"string":"value","int":42,"object":{"foo":"bar"},"msg":"line 2","time":"2021-03-09T17:44:26.204Z","v":0} -{"level":30,"error":"whoa","msg":"line 3","time":"2021-03-09T17:44:26.204Z","v":0} +{"level":50,"error":"whoa","msg":"line 3","time":"2021-03-09T17:44:26.204Z","v":0} `) }, }, @@ -203,17 +210,17 @@ func TestLoggers(t *testing.T) { DefaultOutputFormatter: &parse.DefaultOutputFormatter{ Aurora: aurora.NewAurora(false), AbsoluteTimeFormat: "", - ElideDuplicateFields: true, + ElideDuplicateFields: false, }, } outs := &parse.OutputSchema{ - PriorityFields: []string{"error", "string", "int", "object"}, + PriorityFields: []string{"error", "string", "int", "object", "source"}, Formatter: f, } - want := ` + golden := ` INFO 1 ok line 1 INFO 2 ok line 2 string:value int:42 object:{"foo":"bar"} -INFO 3 ok line 3 error:whoa +ERROR 3 ok line 3 error:whoa `[1:] for _, test := range testData { subTests := map[string]*parse.InputSchema{ @@ -231,6 +238,15 @@ INFO 3 ok line 3 error:whoa if _, err := parse.ReadLog(input, output, ins, outs, nil); err != nil { t.Fatalf("readlog: %v", err) } + want := golden + if p := test.wantMessagePrefix; p != "" { + for _, msg := range []string{"line 1", "line 2", "line 3"} { + want = strings.Replace(want, msg, p+msg, 1) + } + } + if s := test.wantLineSuffix; s != "" { + want = strings.ReplaceAll(want, "\n", s+"\n") + } if test.skip != "" { t.Logf("skipped test:\noutput:\n%s", output.String()) t.Logf("skipped test:\ninput:\n---\n%s\n---\n", inputCopy.String()) diff --git a/pkg/parse/parse.go b/pkg/parse/parse.go index 05e0b50..f6afe97 100644 --- a/pkg/parse/parse.go +++ b/pkg/parse/parse.go @@ -53,9 +53,13 @@ type InputSchema struct { // as normal messages with as much information extracted as possible. Strict bool - // DeleteKeys contains a list of keys to delete; used when the log lines contain version + // DeleteKeys is a list of keys to delete; used when the log lines contain version // information that is used for guessing the schema. DeleteKeys []string + + // UpgradeKeys is a list of keys to merge into the raw data. For example, lager puts + // everything in the "data" key. + UpgradeKeys []string } // OutputFormatter describes an object that actually does the output formatting. Methods take a @@ -393,6 +397,7 @@ func (s *InputSchema) guessSchema(l *line) { s.LevelKey = "level" s.LevelFormat = DefaultLevelParser s.MessageKey = "message" + s.UpgradeKeys = append(s.UpgradeKeys, "data") return } if len(l.fields) == 5 && has("timestamp") && has("log_level") && has("message") && has("data") && has("source") { @@ -402,6 +407,7 @@ func (s *InputSchema) guessSchema(l *line) { s.LevelKey = "log_level" s.LevelFormat = LagerLevelParser s.MessageKey = "message" + s.UpgradeKeys = append(s.UpgradeKeys, "data") return } } @@ -462,6 +468,24 @@ func (s *InputSchema) ReadLine(l *line) error { } else { pushError(fmt.Errorf("no level key %q in incoming log", s.LevelKey)) } + for _, name := range s.UpgradeKeys { + raw, ok := l.fields[name] + if !ok { + // Skip upgrade if the key is absent. + continue + } + toMerge, ok := raw.(map[string]interface{}) + if ok { + // Delete original first, so that foo:{foo:42} will overwrite to foo:42, + // rather than {}. + delete(l.fields, name) + for k, v := range toMerge { + l.fields[k] = v + } + } else if s.Strict { + pushError(fmt.Errorf("upgrade key %q: invalid data type: want map[string]interface{}, got %T", name, raw)) + } + } for _, k := range s.DeleteKeys { delete(l.fields, k) } diff --git a/pkg/parse/parse_fuzz_test.go b/pkg/parse/parse_fuzz_test.go index aec0b82..4d66783 100644 --- a/pkg/parse/parse_fuzz_test.go +++ b/pkg/parse/parse_fuzz_test.go @@ -142,7 +142,7 @@ func FuzzEmit(f *testing.F) { if byts[len(byts)-1] != '\n' { t.Fatal("no trailing newline") } - wantMsg := strings.Replace(msg, "\n", "↩", -1) + wantMsg := cleanupNewlines(msg) if !bytes.Contains(byts, []byte(wantMsg)) { t.Fatal("message not in output") } diff --git a/pkg/parse/parse_test.go b/pkg/parse/parse_test.go index 7dc087e..b9e532f 100644 --- a/pkg/parse/parse_test.go +++ b/pkg/parse/parse_test.go @@ -42,6 +42,12 @@ var ( } ) +func modifyBasicSchema(f func(s *InputSchema)) *InputSchema { + basic := *basicSchema + f(&basic) + return &basic +} + type matchingError struct{ re *regexp.Regexp } func (e *matchingError) Error() string { return "match /" + e.re.String() + "/" } @@ -228,6 +234,83 @@ func TestRead(t *testing.T) { }, err: Match("invalid float64\\(42\\) for log level"), }, + { + name: "valid upgrade", + s: modifyBasicSchema(func(s *InputSchema) { s.UpgradeKeys = []string{"upgrade"} }), + input: `{"t":1,"l":"info","m":"test","existed":true,"overwritten":"nope","upgrade":{"key":"value","num":42.1,"overwritten":true}}`, + want: &line{ + time: time.Unix(1, 0), + lvl: LevelInfo, + msg: "test", + fields: map[string]interface{}{ + "existed": true, + "key": "value", + "num": float64(42.1), + "overwritten": true, + }, + }, + }, + { + name: "valid upgrade, overwrite self", + s: modifyBasicSchema(func(s *InputSchema) { s.UpgradeKeys = []string{"upgrade"} }), + input: `{"t":1,"l":"info","m":"test","existed":true,"upgrade":{"upgrade":"hello"}}`, + want: &line{ + time: time.Unix(1, 0), + lvl: LevelInfo, + msg: "test", + fields: map[string]interface{}{ + "existed": true, + "upgrade": "hello", + }, + }, + }, + { + name: "valid upgrade, but nothing to upgrade", + s: modifyBasicSchema(func(s *InputSchema) { s.UpgradeKeys = []string{"upgrade"} }), + input: `{"t":1,"l":"info","m":"test","existed":true,"overwritten":"nope"}`, + want: &line{ + time: time.Unix(1, 0), + lvl: LevelInfo, + msg: "test", + fields: map[string]interface{}{ + "existed": true, + "overwritten": "nope", + }, + }, + }, + { + name: "invalid upgrade", + s: modifyBasicSchema(func(s *InputSchema) { s.UpgradeKeys = []string{"upgrade"} }), + input: `{"t":1,"l":"info","m":"test","existed":true,"overwritten":"nope","upgrade":["foo"]}`, + want: &line{ + time: time.Unix(1, 0), + lvl: LevelInfo, + msg: "test", + fields: map[string]interface{}{ + "existed": true, + "overwritten": "nope", + "upgrade": []interface{}{"foo"}, + }, + }, + err: Match(`upgrade key "upgrade": invalid data type.*got \[\]`), + }, + { + name: "invalid upgrade, lax", + s: modifyBasicSchema(func(s *InputSchema) { s.Strict = false; s.UpgradeKeys = []string{"upgrade"} }), + input: `{"t":1,"l":"info","m":"test","existed":true,"overwritten":"nope","upgrade":["foo"]}`, + want: &line{ + time: time.Unix(1, 0), + lvl: LevelInfo, + msg: "test", + fields: map[string]interface{}{ + "existed": true, + "overwritten": "nope", + "upgrade": []interface{}{"foo"}, + }, + }, + }, + + // Auto-guess tests { name: "auto-guess zap", s: &InputSchema{Strict: true}, @@ -284,7 +367,7 @@ func TestRead(t *testing.T) { time: time.Unix(1, 1e6), lvl: LevelInfo, msg: `hi`, - fields: map[string]interface{}{"source": "test", "data": map[string]interface{}{"extra": "is here"}}, + fields: map[string]interface{}{"source": "test", "extra": "is here"}, }, err: nil, }, @@ -296,7 +379,7 @@ func TestRead(t *testing.T) { time: time.Unix(1, 1e8), lvl: LevelInfo, msg: `hi`, - fields: map[string]interface{}{"source": "test", "data": map[string]interface{}{"extra": "is here"}}, + fields: map[string]interface{}{"source": "test", "extra": "is here"}, }, err: nil, },