diff --git a/cmd/humanlog/main.go b/cmd/humanlog/main.go index f04395c3..8a126365 100644 --- a/cmd/humanlog/main.go +++ b/cmd/humanlog/main.go @@ -7,10 +7,9 @@ import ( "os/signal" "github.com/aybabtme/rgbterm" - "github.com/fatih/color" "github.com/humanlogio/humanlog" "github.com/humanlogio/humanlog/internal/pkg/config" - "github.com/humanlogio/humanlog/internal/pkg/sink" + "github.com/humanlogio/humanlog/internal/pkg/sink/stdiosink" "github.com/mattn/go-colorable" "github.com/urfave/cli" ) @@ -82,7 +81,7 @@ func newApp() *cli.App { colorFlag := cli.StringFlag{ Name: "color", Usage: "specify color mode: auto, on/force, off", - Value: *config.DefaultConfig.ColorFlag, + Value: stdiosink.DefaultStdioOpts.ColorFlag, } lightBg := cli.BoolFlag{ @@ -93,7 +92,7 @@ func newApp() *cli.App { timeFormat := cli.StringFlag{ Name: "time-format", Usage: "output time format, see https://golang.org/pkg/time/ for details", - Value: sink.DefaultStdioOpts.TimeFormat, + Value: stdiosink.DefaultStdioOpts.TimeFormat, } ignoreInterrupts := cli.BoolFlag{ @@ -178,7 +177,7 @@ func newApp() *cli.App { cfg.TimeFormat = ptr(c.String(timeFormat.Name)) } if c.IsSet(colorFlag.Name) { - cfg.ColorFlag = ptr(c.String(colorFlag.Name)) + cfg.ColorMode = ptr(c.String(colorFlag.Name)) } if c.IsSet(skipFlag.Name) { cfg.Skip = ptr([]string(skip)) @@ -207,31 +206,17 @@ func newApp() *cli.App { signal.Ignore(os.Interrupt) } - colorMode, err := config.GrokColorMode(*cfg.ColorFlag) - if err != nil { - return fmt.Errorf("invalid --color=%q: %v", *cfg.ColorFlag, err) - } - switch colorMode { - case config.ColorModeOff: - color.NoColor = true - case config.ColorModeOn: - color.NoColor = false - default: - // 'Auto' default is applied as a global variable initializer function, so nothing - // to do here. - } - if len(*cfg.Skip) > 0 && len(*cfg.Keep) > 0 { fatalf(c, "can only use one of %q and %q", skipFlag.Name, keepFlag.Name) } - sinkOpts, errs := sink.StdioOptsFrom(*cfg) + sinkOpts, errs := stdiosink.StdioOptsFrom(*cfg) if len(errs) > 0 { for _, err := range errs { log.Printf("config error: %v", err) } } - sink := sink.NewStdio(colorable.NewColorableStdout(), sinkOpts) + sink := stdiosink.NewStdio(colorable.NewColorableStdout(), sinkOpts) handlerOpts := humanlog.HandlerOptionsFrom(*cfg) log.Print("reading stdin...") diff --git a/e2e_test.go b/e2e_test.go index 4f9fe8a9..a0ba5182 100644 --- a/e2e_test.go +++ b/e2e_test.go @@ -9,7 +9,7 @@ import ( "testing" "github.com/humanlogio/humanlog/internal/pkg/config" - "github.com/humanlogio/humanlog/internal/pkg/sink" + "github.com/humanlogio/humanlog/internal/pkg/sink/stdiosink" ) func TestHarness(t *testing.T) { @@ -42,11 +42,11 @@ func TestHarness(t *testing.T) { t.Fatalf("unmarshaling config: %v", err) } gotw := bytes.NewBuffer(nil) - sinkOpts, errs := sink.StdioOptsFrom(cfg) + sinkOpts, errs := stdiosink.StdioOptsFrom(cfg) if len(errs) > 1 { t.Fatalf("errs=%v", errs) } - s := sink.NewStdio(gotw, sinkOpts) + s := stdiosink.NewStdio(gotw, sinkOpts) err = Scanner(bytes.NewReader(input), s, HandlerOptionsFrom(cfg)) if err != nil { t.Fatalf("scanning input: %v", err) diff --git a/internal/pkg/config/config.go b/internal/pkg/config/config.go index 2ce50347..cab85d1c 100644 --- a/internal/pkg/config/config.go +++ b/internal/pkg/config/config.go @@ -22,7 +22,7 @@ var DefaultConfig = Config{ SkipUnchanged: ptr(true), Truncates: ptr(true), LightBg: ptr(false), - ColorFlag: ptr("auto"), + ColorMode: ptr("auto"), TruncateLength: ptr(15), TimeFormat: ptr(time.Stamp), Interrupt: ptr(false), @@ -94,7 +94,7 @@ type Config struct { SkipUnchanged *bool `json:"skip-unchanged"` Truncates *bool `json:"truncates"` LightBg *bool `json:"light-bg"` - ColorFlag *string `json:"color-mode"` + ColorMode *string `json:"color-mode"` TruncateLength *int `json:"truncate-length"` TimeFormat *string `json:"time-format"` Palette *TextPalette `json:"palette"` @@ -130,8 +130,8 @@ func (cfg Config) populateEmpty(other *Config) *Config { if out.LightBg == nil && other.LightBg != nil { out.LightBg = other.LightBg } - if out.ColorFlag == nil && other.ColorFlag != nil { - out.ColorFlag = other.ColorFlag + if out.ColorMode == nil && other.ColorMode != nil { + out.ColorMode = other.ColorMode } if out.TruncateLength == nil && other.TruncateLength != nil { out.TruncateLength = other.TruncateLength diff --git a/internal/pkg/sink/stdio.go b/internal/pkg/sink/stdiosink/colors.go similarity index 50% rename from internal/pkg/sink/stdio.go rename to internal/pkg/sink/stdiosink/colors.go index c90c8fc5..0e3ddbc7 100644 --- a/internal/pkg/sink/stdio.go +++ b/internal/pkg/sink/stdiosink/colors.go @@ -1,240 +1,12 @@ -package sink +package stdiosink import ( - "bytes" "fmt" - "io" - "sort" - "strings" - "text/tabwriter" - "time" "github.com/fatih/color" "github.com/humanlogio/humanlog/internal/pkg/config" - "github.com/humanlogio/humanlog/internal/pkg/model" ) -var ( - eol = [...]byte{'\n'} -) - -type Stdio struct { - w io.Writer - opts StdioOpts - - lastEvent *model.Event - lastKVs map[string]string -} - -type StdioOpts struct { - Skip map[string]struct{} - Keep map[string]struct{} - SkipUnchanged bool - SortLongest bool - TimeFormat string - Truncates bool - TruncateLength int - - LightBg bool - Palette Palette -} - -var DefaultStdioOpts = StdioOpts{ - SkipUnchanged: true, - SortLongest: true, - Truncates: true, - LightBg: false, - TruncateLength: 15, - TimeFormat: time.Stamp, - - Palette: DefaultPalette, -} - -func StdioOptsFrom(cfg config.Config) (StdioOpts, []error) { - var errs []error - opts := DefaultStdioOpts - if cfg.Skip != nil { - opts.Skip = sliceToSet(cfg.Skip) - } - if cfg.Keep != nil { - opts.Keep = sliceToSet(cfg.Keep) - } - if cfg.SortLongest != nil { - opts.SortLongest = *cfg.SortLongest - } - if cfg.SkipUnchanged != nil { - opts.SkipUnchanged = *cfg.SkipUnchanged - } - if cfg.Truncates != nil { - opts.Truncates = *cfg.Truncates - } - if cfg.LightBg != nil { - opts.LightBg = *cfg.LightBg - } - if cfg.TruncateLength != nil { - opts.TruncateLength = *cfg.TruncateLength - } - if cfg.TimeFormat != nil { - opts.TimeFormat = *cfg.TimeFormat - } - if cfg.Palette != nil { - pl, err := PaletteFrom(*cfg.Palette) - if err != nil { - errs = append(errs, fmt.Errorf("invalid palette, using default one: %v", err)) - } else { - opts.Palette = *pl - } - } - return opts, errs -} - -var _ Sink = (*Stdio)(nil) - -func NewStdio(w io.Writer, opts StdioOpts) *Stdio { - return &Stdio{ - w: w, - opts: opts, - } -} - -func (std *Stdio) Receive(ev *model.Event) error { - if ev.Structured == nil { - if _, err := std.w.Write(ev.Raw); err != nil { - return err - } - return nil - } - data := ev.Structured - - buf := bytes.NewBuffer(nil) - out := tabwriter.NewWriter(buf, 0, 1, 0, '\t', 0) - - var ( - msgColor *color.Color - msgAbsentColor *color.Color - ) - if std.opts.LightBg { - msgColor = std.opts.Palette.MsgLightBgColor - msgAbsentColor = std.opts.Palette.MsgAbsentLightBgColor - } else { - msgColor = std.opts.Palette.MsgDarkBgColor - msgAbsentColor = std.opts.Palette.MsgAbsentDarkBgColor - } - var msg string - if data.Msg == "" { - msg = msgAbsentColor.Sprint("") - } else { - msg = msgColor.Sprint(data.Msg) - } - - lvl := strings.ToUpper(data.Level)[:imin(4, len(data.Level))] - var level string - switch data.Level { - case "debug": - level = std.opts.Palette.DebugLevelColor.Sprint(lvl) - case "info": - level = std.opts.Palette.InfoLevelColor.Sprint(lvl) - case "warn", "warning": - level = std.opts.Palette.WarnLevelColor.Sprint(lvl) - case "error": - level = std.opts.Palette.ErrorLevelColor.Sprint(lvl) - case "fatal", "panic": - level = std.opts.Palette.FatalLevelColor.Sprint(lvl) - default: - level = std.opts.Palette.UnknownLevelColor.Sprint(lvl) - } - - var timeColor *color.Color - if std.opts.LightBg { - timeColor = std.opts.Palette.TimeLightBgColor - } else { - timeColor = std.opts.Palette.TimeDarkBgColor - } - - _, _ = fmt.Fprintf(out, "%s |%s| %s\t %s", - timeColor.Sprint(data.Time.Format(std.opts.TimeFormat)), - level, - msg, - strings.Join(std.joinKVs(data, "="), "\t "), - ) - - if err := out.Flush(); err != nil { - return err - } - - buf.Write(eol[:]) - - if _, err := buf.WriteTo(std.w); err != nil { - return err - } - - kvs := make(map[string]string, len(data.KVs)) - for _, kv := range data.KVs { - kvs[kv.Key] = kv.Value - } - std.lastEvent = ev - std.lastKVs = kvs - return nil -} - -func (std *Stdio) joinKVs(data *model.Structured, sep string) []string { - - kv := make([]string, 0, len(data.KVs)) - for _, pair := range data.KVs { - k, v := pair.Key, pair.Value - if !std.opts.shouldShowKey(k) { - continue - } - - if std.opts.SkipUnchanged { - if lastV, ok := std.lastKVs[k]; ok && lastV == v && !std.opts.shouldShowUnchanged(k) { - continue - } - } - kstr := std.opts.Palette.KeyColor.Sprint(k) - - var vstr string - if std.opts.Truncates && len(v) > std.opts.TruncateLength { - vstr = v[:std.opts.TruncateLength] + "..." - } else { - vstr = v - } - vstr = std.opts.Palette.ValColor.Sprint(vstr) - kv = append(kv, kstr+sep+vstr) - } - - sort.Strings(kv) - - if std.opts.SortLongest { - sort.Stable(byLongest(kv)) - } - - return kv -} - -func (opts *StdioOpts) shouldShowKey(key string) bool { - if len(opts.Keep) != 0 { - if _, keep := opts.Keep[key]; keep { - return true - } - } - if len(opts.Skip) != 0 { - if _, skip := opts.Skip[key]; skip { - return false - } - } - return true -} - -func (opts *StdioOpts) shouldShowUnchanged(key string) bool { - if len(opts.Keep) != 0 { - if _, keep := opts.Keep[key]; keep { - return true - } - } - return false -} - var DefaultPalette = Palette{ KeyColor: color.New(color.FgGreen), ValColor: color.New(color.FgHiWhite), @@ -383,27 +155,3 @@ var colorAttributeIndex = map[string]color.Attribute{ "bg_hi_cyan": color.BgHiCyan, "bg_hi_white": color.BgHiWhite, } - -type byLongest []string - -func (s byLongest) Len() int { return len(s) } -func (s byLongest) Less(i, j int) bool { return len(s[i]) < len(s[j]) } -func (s byLongest) Swap(i, j int) { s[i], s[j] = s[j], s[i] } - -func imin(a, b int) int { - if a < b { - return a - } - return b -} - -func sliceToSet(arr *[]string) map[string]struct{} { - if arr == nil { - return nil - } - out := make(map[string]struct{}) - for _, key := range *arr { - out[key] = struct{}{} - } - return out -} diff --git a/internal/pkg/sink/stdiosink/stdio.go b/internal/pkg/sink/stdiosink/stdio.go new file mode 100644 index 00000000..4364b36d --- /dev/null +++ b/internal/pkg/sink/stdiosink/stdio.go @@ -0,0 +1,289 @@ +package stdiosink + +import ( + "bytes" + "fmt" + "io" + "sort" + "strings" + "text/tabwriter" + "time" + + "github.com/fatih/color" + "github.com/humanlogio/humanlog/internal/pkg/config" + "github.com/humanlogio/humanlog/internal/pkg/model" + "github.com/humanlogio/humanlog/internal/pkg/sink" +) + +var ( + eol = [...]byte{'\n'} +) + +type Stdio struct { + w io.Writer + opts StdioOpts + + lastRaw bool + lastLevel string + lastKVs map[string]string +} + +type StdioOpts struct { + Keep map[string]struct{} + Skip map[string]struct{} + SkipUnchanged bool + SortLongest bool + TimeFormat string + TruncateLength int + Truncates bool + + ColorFlag string + LightBg bool + Palette Palette +} + +var DefaultStdioOpts = StdioOpts{ + + SkipUnchanged: true, + SortLongest: true, + TimeFormat: time.Stamp, + TruncateLength: 15, + Truncates: true, + + ColorFlag: "auto", + LightBg: false, + Palette: DefaultPalette, +} + +func StdioOptsFrom(cfg config.Config) (StdioOpts, []error) { + var errs []error + opts := DefaultStdioOpts + if cfg.Skip != nil { + opts.Skip = sliceToSet(cfg.Skip) + } + if cfg.Keep != nil { + opts.Keep = sliceToSet(cfg.Keep) + } + if cfg.SortLongest != nil { + opts.SortLongest = *cfg.SortLongest + } + if cfg.SkipUnchanged != nil { + opts.SkipUnchanged = *cfg.SkipUnchanged + } + if cfg.Truncates != nil { + opts.Truncates = *cfg.Truncates + } + if cfg.LightBg != nil { + opts.LightBg = *cfg.LightBg + } + if cfg.TruncateLength != nil { + opts.TruncateLength = *cfg.TruncateLength + } + if cfg.TimeFormat != nil { + opts.TimeFormat = *cfg.TimeFormat + } + if cfg.ColorMode != nil { + colorMode, err := config.GrokColorMode(*cfg.ColorMode) + if err != nil { + errs = append(errs, fmt.Errorf("invalid --color=%q: %v", *cfg.ColorMode, err)) + } + switch colorMode { + case config.ColorModeOff: + color.NoColor = true + case config.ColorModeOn: + color.NoColor = false + default: + // 'Auto' default is applied as a global variable initializer function, so nothing + // to do here. + } + } + if cfg.Palette != nil { + pl, err := PaletteFrom(*cfg.Palette) + if err != nil { + errs = append(errs, fmt.Errorf("invalid palette, using default one: %v", err)) + } else { + opts.Palette = *pl + } + } + return opts, errs +} + +var _ sink.Sink = (*Stdio)(nil) + +func NewStdio(w io.Writer, opts StdioOpts) *Stdio { + return &Stdio{ + w: w, + opts: opts, + } +} + +func (std *Stdio) Receive(ev *model.Event) error { + if ev.Structured == nil { + std.lastRaw = true + std.lastLevel = "" + std.lastKVs = nil + if _, err := std.w.Write(ev.Raw); err != nil { + return err + } + if _, err := std.w.Write(eol[:]); err != nil { + return err + } + return nil + } + data := ev.Structured + + buf := bytes.NewBuffer(nil) + out := tabwriter.NewWriter(buf, 0, 1, 0, '\t', 0) + + var ( + msgColor *color.Color + msgAbsentColor *color.Color + ) + if std.opts.LightBg { + msgColor = std.opts.Palette.MsgLightBgColor + msgAbsentColor = std.opts.Palette.MsgAbsentLightBgColor + } else { + msgColor = std.opts.Palette.MsgDarkBgColor + msgAbsentColor = std.opts.Palette.MsgAbsentDarkBgColor + } + var msg string + if data.Msg == "" { + msg = msgAbsentColor.Sprint("") + } else { + msg = msgColor.Sprint(data.Msg) + } + + lvl := strings.ToUpper(data.Level)[:imin(4, len(data.Level))] + var level string + switch data.Level { + case "debug": + level = std.opts.Palette.DebugLevelColor.Sprint(lvl) + case "info": + level = std.opts.Palette.InfoLevelColor.Sprint(lvl) + case "warn", "warning": + level = std.opts.Palette.WarnLevelColor.Sprint(lvl) + case "error": + level = std.opts.Palette.ErrorLevelColor.Sprint(lvl) + case "fatal", "panic": + level = std.opts.Palette.FatalLevelColor.Sprint(lvl) + default: + level = std.opts.Palette.UnknownLevelColor.Sprint(lvl) + } + + var timeColor *color.Color + if std.opts.LightBg { + timeColor = std.opts.Palette.TimeLightBgColor + } else { + timeColor = std.opts.Palette.TimeDarkBgColor + } + + _, _ = fmt.Fprintf(out, "%s |%s| %s\t %s", + timeColor.Sprint(data.Time.Format(std.opts.TimeFormat)), + level, + msg, + strings.Join(std.joinKVs(data, "="), "\t "), + ) + + if err := out.Flush(); err != nil { + return err + } + + buf.Write(eol[:]) + + if _, err := buf.WriteTo(std.w); err != nil { + return err + } + + kvs := make(map[string]string, len(data.KVs)) + for _, kv := range data.KVs { + kvs[kv.Key] = kv.Value + } + std.lastRaw = false + std.lastLevel = ev.Structured.Level + std.lastKVs = kvs + return nil +} + +func (std *Stdio) joinKVs(data *model.Structured, sep string) []string { + wasSameLevel := std.lastLevel == data.Level + skipUnchanged := !std.lastRaw && std.opts.SkipUnchanged && wasSameLevel + + kv := make([]string, 0, len(data.KVs)) + for _, pair := range data.KVs { + k, v := pair.Key, pair.Value + if !std.opts.shouldShowKey(k) { + continue + } + + if skipUnchanged { + if lastV, ok := std.lastKVs[k]; ok && lastV == v && !std.opts.shouldShowUnchanged(k) { + continue + } + } + kstr := std.opts.Palette.KeyColor.Sprint(k) + + var vstr string + if std.opts.Truncates && len(v) > std.opts.TruncateLength { + vstr = v[:std.opts.TruncateLength] + "..." + } else { + vstr = v + } + vstr = std.opts.Palette.ValColor.Sprint(vstr) + kv = append(kv, kstr+sep+vstr) + } + + sort.Strings(kv) + + if std.opts.SortLongest { + sort.Stable(byLongest(kv)) + } + + return kv +} + +func (opts *StdioOpts) shouldShowKey(key string) bool { + if len(opts.Keep) != 0 { + if _, keep := opts.Keep[key]; keep { + return true + } + } + if len(opts.Skip) != 0 { + if _, skip := opts.Skip[key]; skip { + return false + } + } + return true +} + +func (opts *StdioOpts) shouldShowUnchanged(key string) bool { + if len(opts.Keep) != 0 { + if _, keep := opts.Keep[key]; keep { + return true + } + } + return false +} + +type byLongest []string + +func (s byLongest) Len() int { return len(s) } +func (s byLongest) Less(i, j int) bool { return len(s[i]) < len(s[j]) } +func (s byLongest) Swap(i, j int) { s[i], s[j] = s[j], s[i] } + +func imin(a, b int) int { + if a < b { + return a + } + return b +} + +func sliceToSet(arr *[]string) map[string]struct{} { + if arr == nil { + return nil + } + out := make(map[string]struct{}) + for _, key := range *arr { + out[key] = struct{}{} + } + return out +} diff --git a/json_handler.go b/json_handler.go index 3b21fb1a..f9e9d19b 100644 --- a/json_handler.go +++ b/json_handler.go @@ -67,8 +67,8 @@ func (h *JSONHandler) clear() { // TryHandle tells if this line was handled by this handler. func (h *JSONHandler) TryHandle(d []byte, out *model.Structured) bool { + h.clear() if !h.UnmarshalJSON(d) { - h.clear() return false } out.Time = h.Time diff --git a/logfmt_handler.go b/logfmt_handler.go index 24ae7c7d..f0fdbc1c 100644 --- a/logfmt_handler.go +++ b/logfmt_handler.go @@ -31,8 +31,8 @@ func (h *LogfmtHandler) TryHandle(d []byte, out *model.Structured) bool { if !bytes.ContainsRune(d, '=') { return false } + h.clear() if !h.UnmarshalLogfmt(d) { - h.clear() return false } out.Time = h.Time diff --git a/scanner.go b/scanner.go index 3a1a501c..ce1e6255 100644 --- a/scanner.go +++ b/scanner.go @@ -32,12 +32,11 @@ func Scanner(src io.Reader, sink sink.Sink, opts *HandlerOptions) error { if ev.Structured == nil { ev.Structured = data - } else { - data.Time = time.Time{} - data.Msg = "" - data.Level = "" - data.KVs = data.KVs[:0] } + data.Time = time.Time{} + data.Msg = "" + data.Level = "" + data.KVs = data.KVs[:0] ev.Raw = lineData // remove that pesky syslog crap @@ -60,7 +59,6 @@ func Scanner(src io.Reader, sink sink.Sink, opts *HandlerOptions) error { if err := sink.Receive(ev); err != nil { return err } - } switch err := in.Err(); err { diff --git a/test/cases/00001-json/config.json b/test/cases/00001-json/config.json index f5d93c62..da9f9d0a 100644 --- a/test/cases/00001-json/config.json +++ b/test/cases/00001-json/config.json @@ -1,29 +1,29 @@ { "skip": null, "keep": null, - "time_fields": [ + "time-fields": [ "time", "ts", "@timestamp", "timestamp" ], - "message_fields": [ + "message-fields": [ "message", "msg" ], - "level_fields": [ + "level-fields": [ "level", "lvl", "loglevel", "severity" ], - "sort_longest": true, - "skip_unchanged": true, + "sort-longest": true, + "skip-unchanged": true, "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", "palette": null } \ No newline at end of file diff --git a/test/cases/00002-logfmt/config.json b/test/cases/00002-logfmt/config.json index f5d93c62..1c3e880f 100644 --- a/test/cases/00002-logfmt/config.json +++ b/test/cases/00002-logfmt/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": false, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/00003-zap/config.json b/test/cases/00003-zap/config.json index f5d93c62..1c3e880f 100644 --- a/test/cases/00003-zap/config.json +++ b/test/cases/00003-zap/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": false, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/00004-mixed/config.json b/test/cases/00004-mixed/config.json index f5d93c62..1c3e880f 100644 --- a/test/cases/00004-mixed/config.json +++ b/test/cases/00004-mixed/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": false, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/10000-behavior-base/config.json b/test/cases/10000-behavior-base/config.json index f5d93c62..1c3e880f 100644 --- a/test/cases/10000-behavior-base/config.json +++ b/test/cases/10000-behavior-base/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": false, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/10001-behavior-truncates/config.json b/test/cases/10001-behavior-truncates/config.json index cbc9e4f1..92791fa4 100644 --- a/test/cases/10001-behavior-truncates/config.json +++ b/test/cases/10001-behavior-truncates/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": true, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": true, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/20001-strip-doker-compose/config.json b/test/cases/20001-strip-doker-compose/config.json index f5d93c62..1c3e880f 100644 --- a/test/cases/20001-strip-doker-compose/config.json +++ b/test/cases/20001-strip-doker-compose/config.json @@ -1,29 +1,28 @@ { - "skip": null, - "keep": null, - "time_fields": [ - "time", - "ts", - "@timestamp", - "timestamp" - ], - "message_fields": [ - "message", - "msg" - ], - "level_fields": [ - "level", - "lvl", - "loglevel", - "severity" - ], - "sort_longest": true, - "skip_unchanged": true, - "truncates": false, - "light_bg": false, - "color_mode": 2, - "truncate_length": 15, - "time_format": "Jan _2 15:04:05", - "palette": null - } - \ No newline at end of file + "skip": null, + "keep": null, + "time-fields": [ + "time", + "ts", + "@timestamp", + "timestamp" + ], + "message-fields": [ + "message", + "msg" + ], + "level-fields": [ + "level", + "lvl", + "loglevel", + "severity" + ], + "sort-longest": true, + "skip-unchanged": true, + "truncates": false, + "light-bg": false, + "color-mode": "off", + "truncate-length": 15, + "time-format": "Jan _2 15:04:05", + "palette": null +} diff --git a/test/cases/20001-strip-doker-compose/want b/test/cases/20001-strip-doker-compose/want index abf2b6d4..177cdee5 100644 --- a/test/cases/20001-strip-doker-compose/want +++ b/test/cases/20001-strip-doker-compose/want @@ -1,8 +1,8 @@ Aug 11 13:14:50 || service=web_1 specversion="1.0" type="simple-log" invloglevel="Info" id="01FCV6S4M6S8H3VKAQD9SWFWFP" datacontenttype="application/json" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:The login-api service is running on port 8085. short:service-startup] -Aug 11 13:14:55 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6S9YK70GJ5Q6YT0PYKQDA" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6S9YJXD2SYG3HTGWXHX0G" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:14:59 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6SDKRW3XZDA1FAGZ3QVSH" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6SDKRHB1RR1Q87Q1SKT5P" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:15:00 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6SE597EY6RJ762V59PZQA" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6SE596ZMASA1D79M16KVV" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:15:00 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6SEKCC9RG364AJ60J75KW" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6SEKCNSQJJ2NDEPQ2TGMP" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:15:00 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6SF3DXGB8G1DVX19KQZYT" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6SF3DJZSXTT1RNR6F1QAV" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:15:05 || invweburl="" invwebbytes=0 service=web_1 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 specversion="1.0" invloglevel="Info" invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6SKY9MM7D795258XPQGC9" datacontenttype="application/json" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6SKY9M1D725HTV0ZXKF1V" source="irn:libraries:github.com/InVisionApp/invlogger" data=map[message:incoming HTTP request was served short:http access] -Aug 11 13:15:10 || service=web_1 specversion="1.0" invloglevel="Info" type="service-shutdown" data=map[event:Shutdown] id="01FCV6SR6JZH7JZ6RFDFN9Q99Y" datacontenttype="application/json" source="irn:libraries:github.com/InVisionApp/invlogger" +Aug 11 13:14:55 || invweburl="" invwebbytes=0 invwebstatus=0 invwebbytesin=0 invwebbytesout=0 invwebduration=0 invweburipath="" invwebdesthost="" invweburiquery="" invweburllength=0 invwebcached=false invwebhttpmethod="" invwebhttpuseragent="" invwebhttpcontenttype="" invwebhttpuseragentlength=0 invwebsrcip="::ffff:0.0.0.0" type="incoming_http_request" invwebdestip="::ffff:0.0.0.0" id="01FCV6S9YK70GJ5Q6YT0PYKQDA" invapptracingtequestsource="unset" invapptracingcallingservice="unset" invapptracingrequestid="01FCV6S9YJXD2SYG3HTGWXHX0G" data=map[message:incoming HTTP request was served short:http access] +Aug 11 13:14:59 || id="01FCV6SDKRW3XZDA1FAGZ3QVSH" invapptracingrequestid="01FCV6SDKRHB1RR1Q87Q1SKT5P" +Aug 11 13:15:00 || id="01FCV6SE597EY6RJ762V59PZQA" invapptracingrequestid="01FCV6SE596ZMASA1D79M16KVV" +Aug 11 13:15:00 || id="01FCV6SEKCC9RG364AJ60J75KW" invapptracingrequestid="01FCV6SEKCNSQJJ2NDEPQ2TGMP" +Aug 11 13:15:00 || id="01FCV6SF3DXGB8G1DVX19KQZYT" invapptracingrequestid="01FCV6SF3DJZSXTT1RNR6F1QAV" +Aug 11 13:15:05 || id="01FCV6SKY9MM7D795258XPQGC9" invapptracingrequestid="01FCV6SKY9M1D725HTV0ZXKF1V" +Aug 11 13:15:10 || type="service-shutdown" data=map[event:Shutdown] id="01FCV6SR6JZH7JZ6RFDFN9Q99Y" diff --git a/zap_development_handler_test.go b/zap_development_handler_test.go index b1c0e546..7bb443f8 100644 --- a/zap_development_handler_test.go +++ b/zap_development_handler_test.go @@ -1,7 +1,6 @@ package humanlog import ( - "reflect" "testing" "time" @@ -125,6 +124,7 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine []byte wantMatch bool + wantTime time.Time wantLevel string wantLocation string wantMessage string @@ -144,6 +144,7 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine: logLinesByLevel["DEBUG"], wantMatch: true, + wantTime: time.Date(2021, 2, 5, 12, 41, 48, 53e6, time.FixedZone("", -7*3600)), wantLevel: "debug", wantLocation: "zapper/zapper.go:18", wantMessage: "some message 1", @@ -154,6 +155,7 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine: logLinesByLevel["ERROR"], wantMatch: true, + wantTime: time.Date(2021, 2, 5, 12, 41, 49, 59e6, time.FixedZone("", -7*3600)), wantLevel: "error", wantLocation: "zapper/zapper.go:18", wantMessage: "some message 2", @@ -163,8 +165,8 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine: logLinesByLevel["FATAL"], - wantMatch: true, - + wantMatch: true, + wantTime: time.Date(2021, 2, 5, 15, 45, 4, 425e6, time.FixedZone("", -7*3600)), wantLevel: "fatal", wantLocation: "zapper/zapper.go:18", wantMessage: "some message 5", @@ -175,6 +177,7 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine: logLinesByLevel["INFO"], wantMatch: true, + wantTime: time.Date(2021, 2, 5, 12, 41, 50, 64e6, time.FixedZone("", -7*3600)), wantLevel: "info", wantLocation: "zapper/zapper.go:18", wantMessage: "some message 3", @@ -186,6 +189,7 @@ func Test_tryZapDevPrefix(t *testing.T) { logLine: logLinesByLevel["WARN"], wantMatch: true, + wantTime: time.Date(2021, 2, 5, 12, 41, 51, 69e6, time.FixedZone("", -7*3600)), wantLevel: "warn", wantLocation: "zapper/zapper.go:18", wantMessage: "some message 4", @@ -194,9 +198,8 @@ func Test_tryZapDevPrefix(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - h := &JSONHandler{} ev := new(model.Structured) - m := tryZapDevPrefix(test.logLine, ev, h) + m := tryZapDevPrefix(test.logLine, ev, &JSONHandler{}) if m != test.wantMatch { t.Error("expected the prefix to match, it did not") @@ -206,22 +209,32 @@ func Test_tryZapDevPrefix(t *testing.T) { return } - if reflect.DeepEqual(time.Time{}, h.Time) { - t.Errorf("want a parsed time, got empty time; want != got") + if !test.wantTime.Equal(ev.Time) { + t.Errorf("want %v, got %v; want != got", test.wantTime, ev.Time) } - if h.Level != test.wantLevel { - t.Errorf("want %q, got %q; want != got", test.wantLevel, h.Level) + if ev.Level != test.wantLevel { + t.Errorf("want %q, got %q; want != got", test.wantLevel, ev.Level) } - if h.Message != test.wantMessage { - t.Errorf("want %q, got %q; want != got", test.wantMessage, h.Message) + if ev.Msg != test.wantMessage { + t.Errorf("want %q, got %q; want != got", test.wantMessage, ev.Msg) } - if h.Fields["caller"] != test.wantLocation { - t.Errorf("want %q, got %q; want != got", test.wantLocation, h.Fields["caller"]) + + if findFieldValue(ev, "caller") != test.wantLocation { + t.Errorf("want %q, got %q; want != got", test.wantLocation, findFieldValue(ev, "caller")) } }) } } +func findFieldValue(ev *model.Structured, field string) string { + for _, kv := range ev.KVs { + if kv.Key == field { + return kv.Value + } + } + return "" +} + var dcLogLinesByLevel = map[string][]byte{ "DEBUG": []byte("2021-02-06T22:55:22.004Z\tDEBUG\tzapper/zapper.go:17\tsome message 1\t{\"rand_index\": 1}"), "ERROR": []byte("2021-02-06T22:55:22.008Z\tERROR\tzapper/zapper.go:17\tsome message 2\t{\"rand_index\": 2}"), @@ -340,6 +353,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { logLine []byte wantMatch bool + wantTime time.Time wantLevel string wantLocation string wantMessage string @@ -359,6 +373,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { logLine: dcLogLinesByLevel["DEBUG"], wantMatch: true, + wantTime: time.Date(2021, 2, 6, 22, 55, 22, 4e6, time.UTC), wantLevel: "debug", wantLocation: "zapper/zapper.go:17", wantMessage: "some message 1", @@ -369,6 +384,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { logLine: dcLogLinesByLevel["ERROR"], wantMatch: true, + wantTime: time.Date(2021, 2, 6, 22, 55, 22, 8e6, time.UTC), wantLevel: "error", wantLocation: "zapper/zapper.go:17", wantMessage: "some message 2", @@ -380,6 +396,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { wantMatch: true, + wantTime: time.Date(2021, 2, 6, 22, 55, 22, 9e6, time.UTC), wantLevel: "fatal", wantLocation: "zapper/zapper.go:17", wantMessage: "some message 5", @@ -390,6 +407,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { logLine: dcLogLinesByLevel["INFO"], wantMatch: true, + wantTime: time.Date(2021, 2, 6, 22, 55, 22, 9e6, time.UTC), wantLevel: "info", wantLocation: "zapper/zapper.go:17", wantMessage: "some message 3", @@ -401,6 +419,7 @@ func Test_tryZapDevDCPrefix(t *testing.T) { logLine: dcLogLinesByLevel["WARN"], wantMatch: true, + wantTime: time.Date(2021, 2, 6, 22, 55, 22, 9e6, time.UTC), wantLevel: "warn", wantLocation: "zapper/zapper.go:17", wantMessage: "some message 4", @@ -409,9 +428,8 @@ func Test_tryZapDevDCPrefix(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - h := &JSONHandler{} ev := new(model.Structured) - m := tryZapDevDCPrefix(test.logLine, ev, h) + m := tryZapDevDCPrefix(test.logLine, ev, &JSONHandler{}) if m != test.wantMatch { t.Error("expected the prefix to match, it did not") @@ -421,17 +439,18 @@ func Test_tryZapDevDCPrefix(t *testing.T) { return } - if reflect.DeepEqual(time.Time{}, h.Time) { - t.Errorf("want a parsed time, got empty time; want != got") + if !test.wantTime.Equal(ev.Time) { + t.Errorf("want %v, got %v; want != got", test.wantTime, ev.Time) } - if h.Level != test.wantLevel { - t.Errorf("want %q, got %q; want != got", test.wantLevel, h.Level) + if ev.Level != test.wantLevel { + t.Errorf("want %q, got %q; want != got", test.wantLevel, ev.Level) } - if h.Message != test.wantMessage { - t.Errorf("want %q, got %q; want != got", test.wantMessage, h.Message) + if ev.Msg != test.wantMessage { + t.Errorf("want %q, got %q; want != got", test.wantMessage, ev.Msg) } - if h.Fields["caller"] != test.wantLocation { - t.Errorf("want %q, got %q; want != got", test.wantLocation, h.Fields["caller"]) + + if findFieldValue(ev, "caller") != test.wantLocation { + t.Errorf("want %q, got %q; want != got", test.wantLocation, findFieldValue(ev, "caller")) } }) }