add option to merge a field into the main set of fields; make lager u…

…se this; un-skip all integration tests; make integration tests emit ERROR type messages; wire in key deletion and upgrading; update docs

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 <key>`. 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 <key>`. 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"`.

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 {

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,44 +132,48 @@ 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",
 				TimeKey:     "timestamp",
 				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",
 				TimeKey:     "timestamp",
 				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())

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)
 	}

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