From 7ed8fe33a58988b6d2abd9d40b10e5b5609b25dc Mon Sep 17 00:00:00 2001 From: Jonathan Rockway <2367+jrockway@users.noreply.github.com> Date: Thu, 23 Jun 2022 10:23:34 -0400 Subject: [PATCH] parse: test all filtering scenarios, with and without context --- cmd/jlog/main.go | 22 +- pkg/parse/context.go | 3 +- pkg/parse/context_test.go | 4 +- pkg/parse/default_parsers_test.go | 1 + pkg/parse/filter.go | 64 +++- pkg/parse/filter_test.go | 221 ++++++++++++++ pkg/parse/parse.go | 25 +- pkg/parse/parse_test.go | 492 ++++++++++++++++++++++-------- 8 files changed, 675 insertions(+), 157 deletions(-) create mode 100644 pkg/parse/filter_test.go diff --git a/cmd/jlog/main.go b/cmd/jlog/main.go index 1b17075..86019f8 100644 --- a/cmd/jlog/main.go +++ b/cmd/jlog/main.go @@ -6,7 +6,6 @@ import ( "io" "os" "os/signal" - "regexp" "runtime/debug" "runtime/pprof" "strings" @@ -172,23 +171,14 @@ func main() { fmt.Fprintf(os.Stderr, "cannot have both a non-empty MatchRegex and a non-empty NoMatchRegex\n") os.Exit(1) } - if rx := gen.MatchRegex; rx != "" { - regex, err := regexp.Compile(rx) - if err != nil { - fmt.Fprintf(os.Stderr, "problem compiling MatchRegex: %v\n", err) - os.Exit(1) - } - fsch.MatchRegex = regex + if err := fsch.AddMatchRegex(gen.MatchRegex); err != nil { + fmt.Fprintf(os.Stderr, "problem compiling MatchRegex: %v\n", err) + os.Exit(1) } - if rx := gen.NoMatchRegex; rx != "" { - regex, err := regexp.Compile(rx) - if err != nil { - fmt.Fprintf(os.Stderr, "problem compiling NoMatchRegex: %v\n", err) - os.Exit(1) - } - fsch.NoMatchRegex = regex + if err := fsch.AddNoMatchRegex(gen.NoMatchRegex); err != nil { + fmt.Fprintf(os.Stderr, "problem compiling NoMatchRegex: %v\n", err) + os.Exit(1) } - if err := fsch.AddJQ(gen.JQ); err != nil { fmt.Fprintf(os.Stderr, "problem %v\n", err) os.Exit(1) diff --git a/pkg/parse/context.go b/pkg/parse/context.go index 1113d45..cbdd5df 100644 --- a/pkg/parse/context.go +++ b/pkg/parse/context.go @@ -22,9 +22,8 @@ func (c *context) Print(msg *line, selected bool) []*line { c.lastPrint != 0 && // suppress separator if we are no-op context (c.After != 0 || c.Before != 0) && - // suppress separator if end of after is contigious with the start of before + // suppress separator if end of after is contiguous with the start of before c.line-len(c.lines)-c.lastPrint > 1 { - result = append(result, &line{isSeparator: true}) } for _, l := range c.lines { diff --git a/pkg/parse/context_test.go b/pkg/parse/context_test.go index aca7d7a..bad8a48 100644 --- a/pkg/parse/context_test.go +++ b/pkg/parse/context_test.go @@ -144,8 +144,8 @@ func TestContext(t *testing.T) { l.reset() l.msg = msg selected := test.match.MatchString(msg) - print := ctx.Print(&l, selected) - for _, x := range print { + toEmit := ctx.Print(&l, selected) + for _, x := range toEmit { if x.isSeparator { out.WriteString("---") } else { diff --git a/pkg/parse/default_parsers_test.go b/pkg/parse/default_parsers_test.go index 644e28d..1ad33b5 100644 --- a/pkg/parse/default_parsers_test.go +++ b/pkg/parse/default_parsers_test.go @@ -103,6 +103,7 @@ func TestLevelParsers(t *testing.T) { } func TestNoopParsers(t *testing.T) { + // nolint: errcheck testData := []func(){func() { NoopTimeParser(1) }, func() { NoopLevelParser("info") }} for _, test := range testData { ok := func() (ok bool) { diff --git a/pkg/parse/filter.go b/pkg/parse/filter.go index 97f9e22..58b2e66 100644 --- a/pkg/parse/filter.go +++ b/pkg/parse/filter.go @@ -98,7 +98,6 @@ func (f *FilterScheme) runJQ(l *line) (bool, error) { } } else { filtered = true - l.fields = make(map[string]interface{}) } return filtered, nil } @@ -120,6 +119,7 @@ func runRegexp(rx *regexp.Regexp, l *line, scope regexpScope) bool { case regexpScopeMessage: input = l.msg } + fields := rx.FindStringSubmatch(input) if len(fields) == 0 { return false @@ -139,21 +139,67 @@ func runRegexp(rx *regexp.Regexp, l *line, scope regexpScope) bool { // Run runs all the filters defined in this FilterScheme against the provided line. The return // value is true if the line should be removed from the output ("filtered"). func (f *FilterScheme) Run(l *line) (bool, error) { + rxFiltered := false if rx := f.NoMatchRegex; rx != nil { - found := runRegexp(rx, l, regexpScopeMessage) - if found { - return true, nil + if found := runRegexp(rx, l, regexpScopeMessage); found { + rxFiltered = true } } if rx := f.MatchRegex; rx != nil { - found := runRegexp(rx, l, regexpScopeMessage) - if !found { - return true, nil + if found := runRegexp(rx, l, regexpScopeMessage); !found { + rxFiltered = true } } - filtered, err := f.runJQ(l) + jqFiltered, err := f.runJQ(l) if err != nil { return false, fmt.Errorf("jq: %w", err) } - return filtered, nil + return rxFiltered || jqFiltered, nil +} + +var ( + ErrAlreadyAdded = errors.New("regex already added") + ErrConflict = errors.New("attempt to add regex when a conflicting regex has already been added") +) + +// Add a MatchRegex to this filter scheme. A MatchRegex filters out all lines that do not match it. +// An empty string is a no-op. This method may only be called with a non-empty string once, and +// returns an ErrConflict if a NoMatchRegex is set. +func (f *FilterScheme) AddMatchRegex(rx string) error { + if rx == "" { + return nil + } + if f.MatchRegex != nil { + return ErrAlreadyAdded + } + if f.NoMatchRegex != nil { + return ErrConflict + } + var err error + f.MatchRegex, err = regexp.Compile(rx) + if err != nil { + return fmt.Errorf("compile regex: %w", err) + } + return nil +} + +// Add a NoMatchRegex to this filter scheme. A NoMatchRegex filters out all lines that match it. +// An empty string is a no-op. This method may only be called with a non-empty string once, and +// returns an ErrConflict if a MatchRegex is set. +func (f *FilterScheme) AddNoMatchRegex(rx string) error { + if rx == "" { + return nil + } + if f.NoMatchRegex != nil { + return ErrAlreadyAdded + } + if f.MatchRegex != nil { + return ErrConflict + } + var err error + f.NoMatchRegex, err = regexp.Compile(rx) + if err != nil { + return fmt.Errorf("compile: %w", err) + } + return nil } diff --git a/pkg/parse/filter_test.go b/pkg/parse/filter_test.go new file mode 100644 index 0000000..0084114 --- /dev/null +++ b/pkg/parse/filter_test.go @@ -0,0 +1,221 @@ +package parse + +import ( + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/google/go-cmp/cmp/cmpopts" +) + +func TestJQ(t *testing.T) { + referenceLine := func() *line { return &line{msg: "foo", fields: map[string]interface{}{"foo": 42, "bar": "hi"}} } + testData := []struct { + jq string + l *line + wantLine *line + wantFiltered bool + wantErr error + }{ + { + jq: ".", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: nil, + }, + { + jq: "", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: nil, + }, + { + jq: `error("goodbye")`, + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: Match("goodbye"), + }, + { + jq: "null", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: Match("unexpected nil result"), + }, + { + jq: "3.141592", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: Match("unexpected result type float64\\(3.1"), + }, + { + jq: "1 > 2", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: false, + wantErr: Match("unexpected boolean output"), + }, + { + jq: "{}", + l: referenceLine(), + wantLine: &line{msg: "foo"}, + wantFiltered: false, + wantErr: nil, + }, + { + jq: "{}, {}", + l: referenceLine(), + wantLine: &line{msg: "foo"}, + wantFiltered: false, + wantErr: Match("unexpectedly produced more than 1 output"), + }, + { + jq: "empty", + l: referenceLine(), + wantLine: referenceLine(), + wantFiltered: true, + wantErr: nil, + }, + } + for _, test := range testData { + fs := new(FilterScheme) + if err := fs.AddJQ(test.jq); err != nil { + t.Fatal(err) + } + gotFiltered, gotErr := fs.runJQ(test.l) + if diff := cmp.Diff(test.l, test.wantLine, cmp.AllowUnexported(line{}), cmpopts.EquateEmpty()); diff != "" { + t.Errorf("line: %s", diff) + } + if got, want := gotFiltered, test.wantFiltered; got != want { + t.Errorf("filtered:\n got: %v\n want: %v", got, want) + } + if got, want := gotErr, test.wantErr; !comperror(got, want) { + t.Errorf("error:\n got: %v\n want: %v", got, want) + } + } +} + +func TestAdds(t *testing.T) { + testData := []struct { + name string + match, matchagain, nomatch, jq []string + want []error + }{ + { + name: "empty", + }, + { + name: "valid match", + match: []string{"foo"}, + }, + { + name: "valid nomatch", + nomatch: []string{"foo"}, + }, + { + name: "valid jq", + jq: []string{"{}"}, + }, + { + name: "valid match and jq", + match: []string{"foo"}, + jq: []string{"{}"}, + }, + { + name: "valid nomatch and jq", + nomatch: []string{"foo"}, + jq: []string{"{}"}, + }, + { + name: "unparseable jq", + jq: []string{"{"}, + want: []error{Match("EOF")}, + }, + { + name: "uncompilable jq", + jq: []string{"$INVALID"}, + want: []error{Match("variable not defined")}, + }, + { + name: "double jq", + jq: []string{".", "."}, + want: []error{Match("already added")}, + }, + { + name: "invalid match", + match: []string{"["}, + want: []error{Match("missing closing ]")}, + }, + { + name: "invalid nomatch", + nomatch: []string{"["}, + want: []error{Match("missing closing ]")}, + }, + { + name: "invalid regexes", + match: []string{"["}, + nomatch: []string{"["}, + want: []error{Match("missing closing ]"), Match("missing closing ]")}, + }, + { + name: "match and nomatch", + match: []string{".*"}, + nomatch: []string{".*"}, + want: []error{ErrConflict}, + }, + { + name: "nomatch and match", + nomatch: []string{".*"}, + matchagain: []string{".*"}, + want: []error{ErrConflict}, + }, + { + name: "double match", + match: []string{"a", "b"}, + want: []error{ErrAlreadyAdded}, + }, + { + name: "double nomatch", + nomatch: []string{"a", "b"}, + want: []error{ErrAlreadyAdded}, + }, + } + + for _, test := range testData { + t.Run(test.name, func(t *testing.T) { + f := new(FilterScheme) + var errs []error + for _, jq := range test.jq { + if err := f.AddJQ(jq); err != nil { + errs = append(errs, err) + } + } + for _, rx := range test.match { + if err := f.AddMatchRegex(rx); err != nil { + errs = append(errs, err) + } + } + for _, rx := range test.nomatch { + if err := f.AddNoMatchRegex(rx); err != nil { + errs = append(errs, err) + } + } + for _, rx := range test.matchagain { + if err := f.AddMatchRegex(rx); err != nil { + errs = append(errs, err) + } + } + if diff := cmp.Diff(errs, test.want, cmp.Comparer(comperror)); diff != "" { + t.Errorf("error:\n%s", diff) + } + if len(errs) > 0 { + if _, err := f.Run(&line{}); err != nil { + t.Errorf("run: %v", err) + } + } + }) + } +} diff --git a/pkg/parse/parse.go b/pkg/parse/parse.go index 4fd3ea8..4fcbdf4 100644 --- a/pkg/parse/parse.go +++ b/pkg/parse/parse.go @@ -9,6 +9,7 @@ import ( "io" "os" "runtime" + "sort" "time" "github.com/logrusorgru/aurora/v3" @@ -84,11 +85,16 @@ type OutputFormatter interface { // State keeps state between log lines. type State struct { - // seenFields maintains an ordering of all fields, so that they are consistent between log lines. - seenFields []string + // seenFields maintains an ordering of all fields, so that they are consistent between log + // lines. + seenFields []string + // timePadding is the width of the time field, so that the next field in the output lines up + // with the line above it. timePadding int - lastFields map[string][]byte - lastTime time.Time + // lastFields is the value of each field that was most recently seen. + lastFields map[string][]byte + // lastTime is the time of the last log line. + lastTime time.Time } // OutputSchema controls how output lines are formatted. @@ -519,12 +525,19 @@ func (s *OutputSchema) Emit(l line, w *bytes.Buffer) { } } - // Any new fields. - for k, v := range l.fields { + // Any new fields (in a deterministic order, mostly for tests). + newFields := make([]string, 0, len(l.fields)) + for k := range l.fields { + newFields = append(newFields, k) + } + sort.Strings(newFields) + for _, k := range newFields { + v := l.fields[k] write(k, v) s.state.seenFields = append(s.state.seenFields, k) } + // Keep state for field eliding. for k := range s.state.lastFields { if _, ok := seenFieldsThisIteration[k]; !ok { delete(s.state.lastFields, k) diff --git a/pkg/parse/parse_test.go b/pkg/parse/parse_test.go index 6a1764e..cd1ebaf 100644 --- a/pkg/parse/parse_test.go +++ b/pkg/parse/parse_test.go @@ -2,6 +2,7 @@ package parse import ( "bytes" + "encoding/json" "errors" "fmt" "io" @@ -13,7 +14,7 @@ import ( "github.com/google/go-cmp/cmp" "github.com/google/go-cmp/cmp/cmpopts" - "github.com/itchyny/gojq" + "github.com/logrusorgru/aurora/v3" ) var ( @@ -661,15 +662,15 @@ var goodLine = `{"t":1,"l":"info","m":"hi","a":42}` + "\n" func TestReadLog(t *testing.T) { testData := []struct { - name string - r io.Reader - w rw - is *InputSchema - jq *gojq.Code - wantOutput string - wantSummary Summary - wantErrs []error - wantFinalErr error + name string + r io.Reader + w rw + is *InputSchema + jq, matchrx, nomatchrx string + wantOutput string + wantSummary Summary + wantErrs []error + wantFinalErr error }{ { name: "empty input", @@ -716,7 +717,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ(".a |= . + $LVL"), + jq: ".a |= . + $LVL", wantOutput: "{LVL:I} {TS:1} {MSG:hi} {F:A:45}\n", wantSummary: Summary{Lines: 1}, wantErrs: nil, @@ -747,7 +748,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(`{"a":42}` + "\n"), w: new(bytes.Buffer), is: laxSchema, - jq: mustJQ("select(.a!=42)"), + jq: "select(.a!=42)", wantOutput: "", wantSummary: Summary{Lines: 1, Filtered: 1, Errors: 1}, wantErrs: nil, @@ -758,7 +759,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(`{"a":42}` + "\n"), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("select(.a!=42)"), + jq: "select(.a!=42)", wantOutput: `{"a":42}` + "\n", wantSummary: Summary{Lines: 1, Errors: 1}, wantErrs: []error{Match("no time key")}, @@ -809,7 +810,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine + goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("select($TS<0)"), + jq: "select($TS<0)", wantOutput: "", wantSummary: Summary{Lines: 2, Errors: 0, Filtered: 2}, wantErrs: nil, @@ -820,7 +821,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("{}"), + jq: "{}", wantOutput: "{LVL:I} {TS:1} {MSG:hi}\n", wantSummary: Summary{Lines: 1, Errors: 0, Filtered: 0}, wantErrs: nil, @@ -866,6 +867,35 @@ func TestReadLog(t *testing.T) { wantErrs: nil, wantFinalErr: Match("panic"), }, + { + name: "log without time, level, and message", + r: strings.NewReader(`{"t":1,"l":"info","m":"hi","a":"value"}` + "\n" + `{"a":"value","t":1}` + "\n{}\n"), + w: new(bytes.Buffer), + is: modifyBasicSchema(func(s *InputSchema) { + s.TimeFormat = NoopTimeParser + s.LevelFormat = NoopLevelParser + s.NoTimeKey = true + s.NoLevelKey = true + s.NoMessageKey = true + }), + wantSummary: Summary{Lines: 3, Errors: 0}, + wantOutput: "{F:A:value} {F:T:1} {F:L:info} {F:M:hi}\n{F:A:} {F:T:}\n\n", + wantErrs: nil, + wantFinalErr: nil, + }, + { + name: "log without level", + r: strings.NewReader(`{"t":1,"l":"info","m":"line 1","a":"value"}` + "\n" + `{"a":"value","t":2,"m":"line 2"}` + "\n" + `{"t":3,"m":"line 3"}` + "\n"), + w: new(bytes.Buffer), + is: modifyBasicSchema(func(s *InputSchema) { + s.LevelFormat = NoopLevelParser + s.NoLevelKey = true + }), + wantSummary: Summary{Lines: 3, Errors: 0}, + wantOutput: "{TS:1} {MSG:line 1} {F:A:value} {F:L:info}\n{TS:2} {MSG:line 2} {F:A:}\n{TS:3} {MSG:line 3}\n", + wantErrs: nil, + wantFinalErr: nil, + }, // These jq tests are here because I am not sure that I want to make a single jq // error abort processing entirely yet. { @@ -873,7 +903,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("null"), + jq: "null", wantOutput: goodLine, wantSummary: Summary{Lines: 1, Errors: 1, Filtered: 0}, wantErrs: nil, @@ -884,7 +914,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("error(\"goodbye\")"), + jq: `error("goodbye")`, wantOutput: goodLine, wantSummary: Summary{Lines: 1, Errors: 1, Filtered: 0}, wantErrs: nil, @@ -895,7 +925,7 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(goodLine), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ("{},{}"), + jq: "{},{}", wantOutput: goodLine, wantSummary: Summary{Lines: 1, Errors: 1, Filtered: 0}, wantErrs: nil, @@ -906,41 +936,12 @@ func TestReadLog(t *testing.T) { r: strings.NewReader(`{"t":1,"l":"info","m":"hi","a":42}` + "\n" + `{"t":1,"l":"warn","m":"hi","a":42}` + "\n"), w: new(bytes.Buffer), is: basicSchema, - jq: mustJQ(`highlight($LVL==$WARN)`), + jq: `highlight($LVL==$WARN)`, wantOutput: "{LVL:I} {TS:1} {MSG:hi} {F:A:42}\n{LVL:W} {TS:1} {MSG:[hi]} {F:A:}\n", wantSummary: Summary{Lines: 2}, wantErrs: nil, wantFinalErr: nil, }, - { - name: "log without time, level, and message", - r: strings.NewReader(`{"t":1,"l":"info","m":"hi","a":"value"}` + "\n" + `{"a":"value","t":1}` + "\n{}\n"), - w: new(bytes.Buffer), - is: modifyBasicSchema(func(s *InputSchema) { - s.TimeFormat = NoopTimeParser - s.LevelFormat = NoopLevelParser - s.NoTimeKey = true - s.NoLevelKey = true - s.NoMessageKey = true - }), - wantSummary: Summary{Lines: 3, Errors: 0}, - wantOutput: "{F:A:value} {F:T:1} {F:L:info} {F:M:hi}\n{F:A:} {F:T:}\n\n", - wantErrs: nil, - wantFinalErr: nil, - }, - { - name: "log without level", - r: strings.NewReader(`{"t":1,"l":"info","m":"line 1","a":"value"}` + "\n" + `{"a":"value","t":2,"m":"line 2"}` + "\n" + `{"t":3,"m":"line 3"}` + "\n"), - w: new(bytes.Buffer), - is: modifyBasicSchema(func(s *InputSchema) { - s.LevelFormat = NoopLevelParser - s.NoLevelKey = true - }), - wantSummary: Summary{Lines: 3, Errors: 0}, - wantOutput: "{TS:1} {MSG:line 1} {F:A:value} {F:L:info}\n{TS:2} {MSG:line 2} {F:A:}\n{TS:3} {MSG:line 3}\n", - wantErrs: nil, - wantFinalErr: nil, - }, } for _, test := range testData { var gotErrs []error @@ -952,8 +953,15 @@ func TestReadLog(t *testing.T) { } t.Run(test.name, func(t *testing.T) { - fs := &FilterScheme{ - JQ: test.jq, + fs := new(FilterScheme) + if err := fs.AddJQ(test.jq); err != nil { + t.Fatalf("add jq: %v", err) + } + if err := fs.AddMatchRegex(test.matchrx); err != nil { + t.Fatalf("add matchregex: %v", err) + } + if err := fs.AddNoMatchRegex(test.nomatchrx); err != nil { + t.Fatalf("add nomatchregex: %v", err) } summary, err := ReadLog(test.r, test.w, test.is, os, fs) if diff := cmp.Diff(test.w.String(), test.wantOutput); diff != "" { @@ -972,109 +980,349 @@ func TestReadLog(t *testing.T) { } } -func mustJQ(prog string) *gojq.Code { - jq, err := compileJQ(prog) - if err != nil { - panic(err) - } - return jq -} - func TestReadLogWithNullFormatter(t *testing.T) { r := strings.NewReader(`{"level":"info","ts":12345,"msg":"foo"}` + "\n") w := io.Discard is := &InputSchema{Strict: false} os := &OutputSchema{} - fs := &FilterScheme{JQ: mustJQ(".")} + fs := new(FilterScheme) if _, err := ReadLog(r, w, is, os, fs); err != nil { t.Fatal(err) } } -func TestJQ(t *testing.T) { - referenceLine := func() *line { return &line{msg: "foo", fields: map[string]interface{}{"foo": 42, "bar": "hi"}} } +func ts(t float64) time.Time { + fl := math.Floor(t) + sec := int64(fl) + nsec := int64(1e3 * math.Round(1e6*(t-fl))) + return time.Unix(sec, nsec) +} + +func makeLog(t time.Time, lvl, message string, fields map[string]any) string { + x := map[string]any{ + "ts": t.In(time.UTC).Format(time.RFC3339Nano), + "level": lvl, + "msg": message, + } + for k, v := range fields { + x[k] = v + } + b, err := json.Marshal(x) + if err != nil { + panic(fmt.Sprintf("make log: marshal: %v", err)) + } + return string(b) +} + +var ( + testLog = []string{ + makeLog(ts(1), "info", "start", nil), + makeLog(ts(1.000001), "debug", "reading config", map[string]any{"file": "/tmp/config.json"}), + makeLog(ts(1.000002), "debug", "reading config", map[string]any{"file": "/tmp/config-overlay.json"}), + makeLog(ts(1.002), "info", "serving", map[string]any{"port": 8080}), + makeLog(ts(10), "debug", "started incoming request", map[string]any{"route": "/example", "request_id": 1234}), + makeLog(ts(10.01), "debug", "started incoming request", map[string]any{"route": "/test", "request_id": 4321}), + makeLog(ts(10.02), "debug", "finished incoming request", map[string]any{"route": "/example", "request_id": 1234, "response_code": 200}), + makeLog(ts(10.0201), "warn", "user not found", map[string]any{"route": "/test", "request_id": 4321}), + makeLog(ts(10.0202), "error", "finished incoming request", map[string]any{"route": "/test", "request_id": 4321, "response_code": 401}), + makeLog(ts(10.03), "debug", "started incoming request", map[string]any{"route": "/example", "request_id": 5432}), + makeLog(ts(10.031), "debug", "finished incoming request", map[string]any{"route": "/example", "request_id": 5432, "response_code": 200}), + makeLog(ts(100), "info", "shutting down server; waiting for connections to drain", map[string]any{"port": 8080}), + makeLog(ts(115), "info", "connections drained", map[string]any{"port": 8080}), + } + + formattedTestLog = []string{ + "INFO Jan 1 00:00:01.000000 start", + "DEBUG .000001 reading config file:/tmp/config.json", + "DEBUG .000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "DEBUG .010000 started incoming request request_id:4321 route:/test", + "DEBUG .020000 finished incoming request request_id:1234 route:/example response_code:200", + "WARN .020100 user not found request_id:4321 route:/test", + "ERROR .020200 finished incoming request request_id:↑ route:↑ response_code:401", + "DEBUG .030000 started incoming request request_id:5432 route:/example", + "DEBUG .031000 finished incoming request request_id:↑ route:↑ response_code:200", + "INFO Jan 1 00:01:40.000000 shutting down server; waiting for connections to drain port:8080", + "INFO Jan 1 00:01:55.000000 connections drained port:↑", + } +) + +func TestFullLog(t *testing.T) { testData := []struct { - jq *gojq.Code - l *line - wantLine *line - wantFiltered bool - wantErr error + name string + jq, matchregex, nomatchregex string + beforecontext, aftercontext int + input []string + wantOutput []string }{ { - jq: mustJQ("."), - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: nil, + name: "no filtering", + input: testLog, + wantOutput: formattedTestLog, + }, + { + name: "no filtering, before context", + input: testLog, + beforecontext: 2, + wantOutput: formattedTestLog, + }, + { + name: "no filtering, after context", + input: testLog, + aftercontext: 2, + wantOutput: formattedTestLog, + }, + { + name: "no filtering, context", + input: testLog, + beforecontext: 2, + aftercontext: 2, + wantOutput: formattedTestLog, + }, + { + name: "jq filter by request id", + input: testLog, + jq: `select(.request_id == 1234)`, + wantOutput: []string{ + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "DEBUG .020000 finished incoming request request_id:↑ route:↑ response_code:200", + }, + }, + { + name: "jq filter by request id, before context", + input: testLog, + jq: `select(.request_id == 1234)`, + beforecontext: 2, + wantOutput: []string{ + "DEBUG Jan 1 00:00:01.000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "DEBUG .010000 started incoming request request_id:4321 route:/test", + "DEBUG .020000 finished incoming request request_id:1234 route:/example response_code:200", + }, + }, + { + name: "jq filter by request id, after context", + input: testLog, + jq: `select(.request_id == 1234)`, + aftercontext: 2, + wantOutput: []string{ + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "DEBUG .010000 started incoming request request_id:4321 route:/test", + "DEBUG .020000 finished incoming request request_id:1234 route:/example response_code:200", + "WARN .020100 user not found request_id:4321 route:/test", + "ERROR .020200 finished incoming request request_id:↑ route:↑ response_code:401", + }, + }, + { + name: "jq filter by request id, both context", + input: testLog, + jq: `select(.request_id == 1234)`, + aftercontext: 2, + beforecontext: 2, + wantOutput: []string{ + "DEBUG Jan 1 00:00:01.000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "DEBUG .010000 started incoming request request_id:4321 route:/test", + "DEBUG .020000 finished incoming request request_id:1234 route:/example response_code:200", + "WARN .020100 user not found request_id:4321 route:/test", + "ERROR .020200 finished incoming request request_id:↑ route:↑ response_code:401", + }, + }, + { + name: "jq filter, non-contiguous", + input: testLog, + jq: `select(.port == 8080)`, + aftercontext: 1, + beforecontext: 1, + wantOutput: []string{ + "DEBUG Jan 1 00:00:01.000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request request_id:1234 route:/example", + "---", + "DEBUG .031000 finished incoming request request_id:5432 route:↑ response_code:200", + "INFO Jan 1 00:01:40.000000 shutting down server; waiting for connections to drain port:8080", + "INFO Jan 1 00:01:55.000000 connections drained port:↑", + }, + }, + { + name: "regex match", + input: testLog, + matchregex: `(?Pstarted|finished) (?Pincoming|outgoing)`, + wantOutput: []string{ + "DEBUG Jan 1 00:00:10.000000 started incoming request dir:incoming request_id:1234 route:/example state:started", + "DEBUG .010000 started incoming request dir:↑ request_id:4321 route:/test state:↑", + "DEBUG .020000 finished incoming request dir:↑ request_id:1234 route:/example state:finished response_code:200", + "ERROR .020200 finished incoming request dir:↑ request_id:4321 route:/test state:↑ response_code:401", + "DEBUG .030000 started incoming request dir:↑ request_id:5432 route:/example state:started", + "DEBUG .031000 finished incoming request dir:↑ request_id:↑ route:↑ state:finished response_code:200", + }, }, { - jq: nil, - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: nil, + name: "regex match, before context", + input: testLog, + beforecontext: 2, + matchregex: `(?Pstarted|finished) (?Pincoming|outgoing)`, + wantOutput: []string{ + "DEBUG Jan 1 00:00:01.000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request dir:incoming request_id:1234 route:/example state:started", + "DEBUG .010000 started incoming request dir:↑ request_id:4321 route:/test state:↑", + "DEBUG .020000 finished incoming request dir:↑ request_id:1234 route:/example state:finished response_code:200", + "WARN .020100 user not found request_id:4321 route:/test", + "ERROR .020200 finished incoming request dir:incoming request_id:↑ route:↑ state:finished response_code:401", + "DEBUG .030000 started incoming request dir:↑ request_id:5432 route:/example state:started", + "DEBUG .031000 finished incoming request dir:↑ request_id:↑ route:↑ state:finished response_code:200", + }, }, { - jq: mustJQ(`error("goodbye")`), - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: Match("goodbye"), + name: "regex match with jq", + input: testLog, + matchregex: `(?Pstarted|finished) (?Pincoming|outgoing)`, + jq: `select(.state == "started") | {state, dir}`, + wantOutput: []string{ + "DEBUG Jan 1 00:00:10.000000 started incoming request dir:incoming state:started", + "DEBUG .010000 started incoming request dir:↑ state:↑", + "DEBUG .030000 started incoming request dir:↑ state:↑", + }, }, { - jq: mustJQ("null"), - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: Match("unexpected nil result"), + name: "regex match with jq, with context", + input: testLog, + matchregex: `(?Pstarted|finished) (?Pincoming|outgoing)`, + jq: `select(.state == "started") | {}`, + beforecontext: 1, + aftercontext: 1, + wantOutput: []string{ + "INFO Jan 1 00:00:01.002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request", + "DEBUG .010000 started incoming request", + "DEBUG .020000 finished incoming request dir:incoming request_id:1234 response_code:200 route:/example state:finished", + "---", + "ERROR .020200 finished incoming request dir:↑ request_id:4321 response_code:401 route:/test state:↑", + "DEBUG .030000 started incoming request", + "DEBUG .031000 finished incoming request dir:incoming request_id:5432 response_code:200 route:/example state:finished", + }, }, { - jq: mustJQ("3.141592"), - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: Match("unexpected result type float64\\(3.1"), + name: "regex nomatch", + input: testLog, + beforecontext: 1, + aftercontext: 1, + nomatchregex: `(started|finished) incoming request`, + wantOutput: []string{ + "INFO Jan 1 00:00:01.000000 start", + "DEBUG .000001 reading config file:/tmp/config.json", + "DEBUG .000002 reading config file:/tmp/config-overlay.json", + "INFO .002000 serving port:8080", + "DEBUG Jan 1 00:00:10.000000 started incoming request $1:started request_id:1234 route:/example", + "---", + "DEBUG .020000 finished incoming request $1:finished request_id:↑ route:↑ response_code:200", + "WARN .020100 user not found request_id:4321 route:/test", + "ERROR .020200 finished incoming request $1:finished request_id:↑ route:↑ response_code:401", + "---", + "DEBUG .031000 finished incoming request $1:↑ request_id:5432 route:/example response_code:200", + "INFO Jan 1 00:01:40.000000 shutting down server; waiting for connections to drain port:8080", + "INFO Jan 1 00:01:55.000000 connections drained port:↑", + }, }, { - jq: mustJQ("1 > 2"), - l: referenceLine(), - wantLine: referenceLine(), - wantFiltered: false, - wantErr: Match("unexpected boolean output"), + name: "regex nomatch with jq", + input: testLog, + beforecontext: 1, + aftercontext: 1, + nomatchregex: `(started|finished) incoming request`, + jq: `if ."$1" != null then {"$1"} else {} end`, + wantOutput: []string{ + "INFO Jan 1 00:00:01.000000 start", + "DEBUG .000001 reading config", + "DEBUG .000002 reading config", + "INFO .002000 serving", + "DEBUG Jan 1 00:00:10.000000 started incoming request $1:started", + "---", + "DEBUG .020000 finished incoming request $1:finished", + "WARN .020100 user not found", + "ERROR .020200 finished incoming request $1:finished", + "---", + "DEBUG .031000 finished incoming request $1:↑", + "INFO Jan 1 00:01:40.000000 shutting down server; waiting for connections to drain", + "INFO Jan 1 00:01:55.000000 connections drained", + }, }, { - jq: mustJQ("{}"), - l: referenceLine(), - wantLine: &line{msg: "foo"}, - wantFiltered: false, - wantErr: nil, + name: "no output, regex", + input: testLog, + beforecontext: 1, + aftercontext: 1, + matchregex: "this matches nothing", }, { - jq: mustJQ("{}, {}"), - l: referenceLine(), - wantLine: &line{msg: "foo"}, - wantFiltered: false, - wantErr: Match("unexpectedly produced more than 1 output"), + name: "no output, regex nomatch", + input: testLog, + beforecontext: 1, + aftercontext: 1, + nomatchregex: ".*", }, { - jq: mustJQ("empty"), - l: referenceLine(), - wantLine: &line{msg: "foo"}, - wantFiltered: true, - wantErr: nil, + name: "jq", + input: testLog, + beforecontext: 1, + aftercontext: 1, + jq: "empty", }, } + for _, test := range testData { - fs := &FilterScheme{JQ: test.jq} - gotFiltered, gotErr := fs.runJQ(test.l) - if diff := cmp.Diff(test.l, test.wantLine, cmp.AllowUnexported(line{}), cmpopts.EquateEmpty()); diff != "" { - t.Errorf("line: %s", diff) - } - if got, want := gotFiltered, test.wantFiltered; got != want { - t.Errorf("filtered:\n got: %v\n want: %v", got, want) - } - if got, want := gotErr, test.wantErr; !comperror(got, want) { - t.Errorf("error:\n got: %v\n want: %v", got, want) - } + t.Run(test.name, func(t *testing.T) { + fs := new(FilterScheme) + if err := fs.AddJQ(test.jq); err != nil { + t.Fatal(err) + } + if err := fs.AddMatchRegex(test.matchregex); err != nil { + t.Fatal(err) + } + if err := fs.AddNoMatchRegex(test.nomatchregex); err != nil { + t.Fatal(err) + } + + r := strings.NewReader(strings.Join(test.input, "\n")) + w := new(bytes.Buffer) + + is := &InputSchema{ + TimeKey: "ts", + TimeFormat: DefaultTimeParser, + LevelKey: "level", + LevelFormat: DefaultLevelParser, + MessageKey: "msg", + Strict: true, + } + + os := &OutputSchema{ + Formatter: &DefaultOutputFormatter{ + Aurora: aurora.NewAurora(false), + ElideDuplicateFields: true, + AbsoluteTimeFormat: time.StampMicro, + SubSecondsOnlyFormat: " .000000", + Zone: time.UTC, + }, + BeforeContext: test.beforecontext, + AfterContext: test.aftercontext, + } + + if _, err := ReadLog(r, w, is, os, fs); err != nil { + t.Errorf("read log: unexpected error: %v", err) + } + + out := strings.Split(w.String(), "\n") + if len(out) > 0 && out[len(out)-1] == "" { + out = out[:len(out)-1] + } + if diff := cmp.Diff(out, test.wantOutput, cmpopts.EquateEmpty()); diff != "" { + t.Errorf("output:\ngot:<\n%s\n>\nwant:<\n%s\n>", strings.Join(out, "\n"), strings.Join(test.wantOutput, "\n")) + t.Logf("diff: (-clean +maybe with bugs)\n %v", diff) + } + }) } }