using go-logfmt/logfmt

[kevinburke]

I did some work to switch the logfmt code to use github.com/go-logfmt/logfmt. The following tests fail (uses nil instead of null):

    log15_test.go:138: Got 518-07:00 lvl=eror msg="some message" x=1 y=3.2 equals="=" quote="\"" nil=null
        , expected lvl=eror msg="some message" x=1 y=3.200 equals="=" quote="\"" nil=nil

and this one (formats the time.Time to 9 digits after the second, instead of to the second)

    log15_test.go:270: Got log line 6817-07:00 lvl=info msg=test x=1
        , expected lvl=info msg=test x=1

The diff is here: https://github.com/inconshreveable/log15/compare/master...kevinburke:use-logfmt?expand=1

[kevinburke]

cc @ChrisHines

[kevinburke]

Benchmarks also fail to complete:

goroutine 15 [running]:
panic(0x1a7680, 0xc4200145b0)
    /Users/kevin/go/src/runtime/panic.go:500 +0x1a1
github.com/inconshreveable/log15.logfmt(0xc420058070, 0xc42002bde8, 0x6, 0x6, 0x0)
    /Users/kevin/code/go/src/github.com/inconshreveable/log15/format.go:100 +0x128
github.com/inconshreveable/log15.LogfmtFormat.func1(0xc420096000, 0x19a500, 0x576a1401, 0x2db9e8)
    /Users/kevin/code/go/src/github.com/inconshreveable/log15/format.go:92 +0x2ee
github.com/inconshreveable/log15.formatFunc.Format(0x1f1ac0, 0xc420096000, 0x2c1460, 0x3dff7, 0x2c87b8)
    /Users/kevin/code/go/src/github.com/inconshreveable/log15/format.go:35 +0x30
github.com/inconshreveable/log15.BenchmarkLogfmtNoCtx(0xc4200aa140)
    /Users/kevin/code/go/src/github.com/inconshreveable/log15/bench_test.go:58 +0x15f
testing.(*B).runN(0xc4200aa140, 0x1)
    /Users/kevin/go/src/testing/benchmark.go:139 +0xaa
testing.(*B).run1.func1(0xc4200aa140)
    /Users/kevin/go/src/testing/benchmark.go:208 +0x5a
created by testing.(*B).run1
    /Users/kevin/go/src/testing/benchmark.go:209 +0x7f
exit status 2

[kevinburke]

The four benchmarks that ran didn't show much better perf, but they might not be representative :(

Master:

BenchmarkStreamNoCtx-4            500000          3537 ns/op
BenchmarkDiscard-4               2000000           819 ns/op
BenchmarkCallerFileHandler-4     1000000          1925 ns/op
BenchmarkCallerFuncHandler-4     1000000          1700 ns/op

Best run on the branch:

BenchmarkStreamNoCtx-4            300000          3881 ns/op
BenchmarkDiscard-4               2000000           837 ns/op
BenchmarkCallerFileHandler-4     1000000          1910 ns/op
BenchmarkCallerFuncHandler-4     1000000          1680 ns/op

[ChrisHines]

To help performance you'll likely want to use a sync.Pool of logfmt.Encoders similar to what we recently added in https://github.com/go-kit/kit/pull/253.

The use of "null" instead of "nil" for nil values is intentionally modeled after JSON. Since values are escaped with the same logic as JSON strings it seems natural to do the same for empty values. There is no official logfmt spec, but I leaned heavily on the parsing behavior of github.com/kr/logfmt and the discussion here https://gist.github.com/kr/0e8d5ee4b954ce604bb2. The latter is where you will see examples of "null" values.

github.com/go-logfmt/logfmt checks for values that implement encoding/TextMarshaler first and then fmt.Stringer, so time.Time values get formatted by their MarshalText method which uses the time.RFC3339Nano format. A different format can be used by wrapping time.Time values in a type that implements MarshalText the way you want or by formatting the time.Time to a string before passing it to EncodeKeyvals.

What was the error message for the benchmark panic? I am having trouble figuring out what happened from the stack trace alone.

[kevinburke]

@ChrisHines sorry - it's complaining that this leads to an invalid key:

    r := Record{
        Time: time.Now(),
        Lvl:  LvlInfo,
        Msg:  "test message",
        Ctx:  []interface{}{},
    }

    logfmt := LogfmtFormat()
    for i := 0; i < b.N; i++ {
        logfmt.Format(&r)
    }

I suppose I can edit the code to not attempt to encode an empty array.

[kevinburke]

Er, never mind, it's complaining because the key is the empty string:

encoding []interface {}{"", time.Time{sec:63602209626, nsec:716296270, loc:(*time.Location)(0x2c1460)}, "", 3, "", "test message"}
panic: invalid key

[kevinburke]

The other thing I think the old way supported was putting ANSI escape sequences in. I suppose we can hide the go-logfmt/logfmt call in one side of this conditional:

        // XXX: we should probably check that all of your key bytes aren't invalid
        if color > 0 {
            fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=%s", color, k, v)
        } else {
            buf.WriteString(k)
            buf.WriteByte('=')
            buf.WriteString(v)
        }

[inconshreveable]

Any chance we can put up a PR? Happy to help get this merged.

Where are we specifying an empty string key? It seems reasonable for go-logfmt to panic on that. I'm not a big fan of go-logfmt formatting time.Time to 9 decimal places, but that's a thing we can fix on our side. Yeah, we use ANSI escape sequences for color formatting in the terminal format, so we'll need to figure that out.

I much prefer nil over null because that's what we call it in Go, but I'm ambivalent. We could also normalize this before the call too.