diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index b2582a79..ca1b400b 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -15,9 +15,9 @@ jobs: runs-on: ubuntu-latest steps: - name: Checkout code - uses: actions/checkout@v2 + uses: actions/checkout@v4 - name: Lint - uses: golangci/golangci-lint-action@v2 + uses: golangci/golangci-lint-action@v6 with: # version of golangci-lint to use in form of v1.2 or v1.2.3 or `latest` to use the latest version version: latest diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 09e62ea0..b05d56fd 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -4,16 +4,16 @@ jobs: test: strategy: matrix: - go-version: ["1.18", "1.19", "1.20", "1.21"] + go-version: ["1.21", "1.22", "1.23"] platform: [ubuntu-latest, macos-latest, windows-latest] runs-on: ${{ matrix.platform }} steps: - name: Install Go - uses: actions/setup-go@v1 + uses: actions/setup-go@v5 with: go-version: ${{ matrix.go-version }} - name: Checkout code - uses: actions/checkout@v2 + uses: actions/checkout@v4 - name: Test klog run: | go get -t -v ./... @@ -25,20 +25,20 @@ jobs: if: github.base_ref steps: - name: Install Go - uses: actions/setup-go@v1 + uses: actions/setup-go@v5 with: - go-version: 1.21 + go-version: 1.23 - name: Add GOBIN to PATH run: echo "PATH=$(go env GOPATH)/bin:$PATH" >>$GITHUB_ENV - name: Install dependencies - run: GO111MODULE=off go get golang.org/x/exp/cmd/apidiff + run: go install golang.org/x/exp/cmd/apidiff@latest - name: Checkout old code - uses: actions/checkout@v2 + uses: actions/checkout@v4 with: ref: ${{ github.base_ref }} path: "old" - name: Checkout new code - uses: actions/checkout@v2 + uses: actions/checkout@v4 with: path: "new" - name: APIDiff diff --git a/examples/go.mod b/examples/go.mod index be4bff14..a260ac36 100644 --- a/examples/go.mod +++ b/examples/go.mod @@ -1,6 +1,8 @@ module k8s.io/klog/examples -go 1.13 +go 1.22.0 + +toolchain go1.23.0 require ( github.com/go-logr/logr v1.4.1 @@ -8,8 +10,15 @@ require ( github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b go.uber.org/goleak v1.1.12 go.uber.org/zap v1.19.0 - golang.org/x/tools v0.1.5 + golang.org/x/tools v0.27.0 k8s.io/klog/v2 v2.30.0 ) +require ( + go.uber.org/atomic v1.7.0 // indirect + go.uber.org/multierr v1.6.0 // indirect + golang.org/x/mod v0.22.0 // indirect + golang.org/x/sync v0.9.0 // indirect +) + replace k8s.io/klog/v2 => ../ diff --git a/examples/go.sum b/examples/go.sum index c3ac4096..6256519d 100644 --- a/examples/go.sum +++ b/examples/go.sum @@ -10,10 +10,10 @@ github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A= github.com/go-logr/zapr v1.2.3/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b h1:VKtxabqXZkF25pY9ekfRL6a582T4P37/31XEstQ5p58= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q= -github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI= +github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= +github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo= github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= -github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= @@ -39,19 +39,21 @@ golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACk golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI= golang.org/x/lint v0.0.0-20190930215403-16217165b5de h1:5hukYrvBGR8/eNkX5mdUezrA6JiaEZDtJb9Ei+1LlBs= golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc= -golang.org/x/mod v0.4.2 h1:Gz96sIWK3OalVv/I/qNygP42zyoKp3xptRVCWRFEBvo= golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA= +golang.org/x/mod v0.22.0 h1:D4nJWe9zXqHOmWqj4VMOJhvzj7bEZg4wEYa759z1pH4= +golang.org/x/mod v0.22.0/go.mod h1:6SkKJ3Xj0I0BrPOZoBy3bdMptDDU9oJrpohJ3eWZ1fY= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= +golang.org/x/sync v0.9.0 h1:fEo0HyrW1GIgZdpbhCRO0PkJajUS5H9IFUztCgEo2jQ= +golang.org/x/sync v0.9.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210510120138-977fb7262007 h1:gG67DSER+11cZvqIMb8S8bt0vZtiN6xWYARwirrOSfE= golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= @@ -60,14 +62,13 @@ golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGm golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs= golang.org/x/tools v0.0.0-20191108193012-7d206e10da11/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= -golang.org/x/tools v0.1.5 h1:ouewzE6p+/VEB31YYnTbEJdi8pFqKp4P4n85vwo3DHA= golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk= +golang.org/x/tools v0.27.0 h1:qEKojBykQkQ4EynWy4S8Weg69NumxKdn40Fce3uc/8o= +golang.org/x/tools v0.27.0/go.mod h1:sUi0ZgbwW9ZPAq26Ekut+weQPR5eIM6GQLQ1Yjm1H0Q= golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= -golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE= golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= -gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY= gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10= diff --git a/examples/go_vet/testdata/calls.go b/examples/go_vet/testdata/calls.go index 60d8ab3c..3eb9a3e5 100644 --- a/examples/go_vet/testdata/calls.go +++ b/examples/go_vet/testdata/calls.go @@ -23,72 +23,72 @@ import ( func calls() { klog.Infof("%s") // want `k8s.io/klog/v2.Infof format %s reads arg #1, but call has 0 args` klog.Infof("%s", "world") - klog.Info("%s", "world") // want `k8s.io/klog/v2.Info call has possible formatting directive %s` + klog.Info("%s", "world") // want `k8s.io/klog/v2.Info call has possible Printf formatting directive %s` klog.Info("world") - klog.Infoln("%s", "world") // want `k8s.io/klog/v2.Infoln call has possible formatting directive %s` + klog.Infoln("%s", "world") // want `k8s.io/klog/v2.Infoln call has possible Printf formatting directive %s` klog.Infoln("world") klog.InfofDepth(1, "%s") // want `k8s.io/klog/v2.InfofDepth format %s reads arg #1, but call has 0 args` klog.InfofDepth(1, "%s", "world") - klog.InfoDepth(1, "%s", "world") // want `k8s.io/klog/v2.InfoDepth call has possible formatting directive %s` + klog.InfoDepth(1, "%s", "world") // want `k8s.io/klog/v2.InfoDepth call has possible Printf formatting directive %s` klog.InfoDepth(1, "world") - klog.InfolnDepth(1, "%s", "world") // want `k8s.io/klog/v2.InfolnDepth call has possible formatting directive %s` + klog.InfolnDepth(1, "%s", "world") // want `k8s.io/klog/v2.InfolnDepth call has possible Printf formatting directive %s` klog.InfolnDepth(1, "world") klog.Warningf("%s") // want `k8s.io/klog/v2.Warningf format %s reads arg #1, but call has 0 args` klog.Warningf("%s", "world") - klog.Warning("%s", "world") // want `k8s.io/klog/v2.Warning call has possible formatting directive %s` + klog.Warning("%s", "world") // want `k8s.io/klog/v2.Warning call has possible Printf formatting directive %s` klog.Warning("world") - klog.Warningln("%s", "world") // want `k8s.io/klog/v2.Warningln call has possible formatting directive %s` + klog.Warningln("%s", "world") // want `k8s.io/klog/v2.Warningln call has possible Printf formatting directive %s` klog.Warningln("world") klog.WarningfDepth(1, "%s") // want `k8s.io/klog/v2.WarningfDepth format %s reads arg #1, but call has 0 args` klog.WarningfDepth(1, "%s", "world") - klog.WarningDepth(1, "%s", "world") // want `k8s.io/klog/v2.WarningDepth call has possible formatting directive %s` + klog.WarningDepth(1, "%s", "world") // want `k8s.io/klog/v2.WarningDepth call has possible Printf formatting directive %s` klog.WarningDepth(1, "world") - klog.WarninglnDepth(1, "%s", "world") // want `k8s.io/klog/v2.WarninglnDepth call has possible formatting directive %s` + klog.WarninglnDepth(1, "%s", "world") // want `k8s.io/klog/v2.WarninglnDepth call has possible Printf formatting directive %s` klog.WarninglnDepth(1, "world") klog.Errorf("%s") // want `k8s.io/klog/v2.Errorf format %s reads arg #1, but call has 0 args` klog.Errorf("%s", "world") - klog.Error("%s", "world") // want `k8s.io/klog/v2.Error call has possible formatting directive %s` + klog.Error("%s", "world") // want `k8s.io/klog/v2.Error call has possible Printf formatting directive %s` klog.Error("world") - klog.Errorln("%s", "world") // want `k8s.io/klog/v2.Errorln call has possible formatting directive %s` + klog.Errorln("%s", "world") // want `k8s.io/klog/v2.Errorln call has possible Printf formatting directive %s` klog.Errorln("world") klog.ErrorfDepth(1, "%s") // want `k8s.io/klog/v2.ErrorfDepth format %s reads arg #1, but call has 0 args` klog.ErrorfDepth(1, "%s", "world") - klog.ErrorDepth(1, "%s", "world") // want `k8s.io/klog/v2.ErrorDepth call has possible formatting directive %s` + klog.ErrorDepth(1, "%s", "world") // want `k8s.io/klog/v2.ErrorDepth call has possible Printf formatting directive %s` klog.ErrorDepth(1, "world") - klog.ErrorlnDepth(1, "%s", "world") // want `k8s.io/klog/v2.ErrorlnDepth call has possible formatting directive %s` + klog.ErrorlnDepth(1, "%s", "world") // want `k8s.io/klog/v2.ErrorlnDepth call has possible Printf formatting directive %s` klog.ErrorlnDepth(1, "world") klog.Fatalf("%s") // want `k8s.io/klog/v2.Fatalf format %s reads arg #1, but call has 0 args` klog.Fatalf("%s", "world") - klog.Fatal("%s", "world") // want `k8s.io/klog/v2.Fatal call has possible formatting directive %s` + klog.Fatal("%s", "world") // want `k8s.io/klog/v2.Fatal call has possible Printf formatting directive %s` klog.Fatal("world") - klog.Fatalln("%s", "world") // want `k8s.io/klog/v2.Fatalln call has possible formatting directive %s` + klog.Fatalln("%s", "world") // want `k8s.io/klog/v2.Fatalln call has possible Printf formatting directive %s` klog.Fatalln("world") klog.FatalfDepth(1, "%s") // want `k8s.io/klog/v2.FatalfDepth format %s reads arg #1, but call has 0 args` klog.FatalfDepth(1, "%s", "world") - klog.FatalDepth(1, "%s", "world") // want `k8s.io/klog/v2.FatalDepth call has possible formatting directive %s` + klog.FatalDepth(1, "%s", "world") // want `k8s.io/klog/v2.FatalDepth call has possible Printf formatting directive %s` klog.FatalDepth(1, "world") - klog.FatallnDepth(1, "%s", "world") // want `k8s.io/klog/v2.FatallnDepth call has possible formatting directive %s` + klog.FatallnDepth(1, "%s", "world") // want `k8s.io/klog/v2.FatallnDepth call has possible Printf formatting directive %s` klog.FatallnDepth(1, "world") klog.V(1).Infof("%s") // want `\(k8s.io/klog/v2.Verbose\).Infof format %s reads arg #1, but call has 0 args` klog.V(1).Infof("%s", "world") - klog.V(1).Info("%s", "world") // want `\(k8s.io/klog/v2.Verbose\).Info call has possible formatting directive %s` + klog.V(1).Info("%s", "world") // want `\(k8s.io/klog/v2.Verbose\).Info call has possible Printf formatting directive %s` klog.V(1).Info("world") - klog.V(1).Infoln("%s", "world") // want `\(k8s.io/klog/v2.Verbose\).Infoln call has possible formatting directive %s` + klog.V(1).Infoln("%s", "world") // want `\(k8s.io/klog/v2.Verbose\).Infoln call has possible Printf formatting directive %s` klog.V(1).Infoln("world") klog.V(1).InfofDepth(1, "%s") // want `\(k8s.io/klog/v2.Verbose\).InfofDepth format %s reads arg #1, but call has 0 args` klog.V(1).InfofDepth(1, "%s", "world") - klog.V(1).InfoDepth(1, "%s", "world") // want `\(k8s.io/klog/v2.Verbose\).InfoDepth call has possible formatting directive %s` + klog.V(1).InfoDepth(1, "%s", "world") // want `\(k8s.io/klog/v2.Verbose\).InfoDepth call has possible Printf formatting directive %s` klog.V(1).InfoDepth(1, "world") - klog.V(1).InfolnDepth(1, "%s", "world") // want `\(k8s.io/klog/v2.Verbose\).InfolnDepth call has possible formatting directive %s` + klog.V(1).InfolnDepth(1, "%s", "world") // want `\(k8s.io/klog/v2.Verbose\).InfolnDepth call has possible Printf formatting directive %s` klog.V(1).InfolnDepth(1, "world") // Detecting format specifiers for klog.InfoS and other structured logging calls would be nice, diff --git a/go.mod b/go.mod index c0a06788..ced285f9 100644 --- a/go.mod +++ b/go.mod @@ -1,5 +1,5 @@ module k8s.io/klog/v2 -go 1.18 +go 1.21 require github.com/go-logr/logr v1.4.1 diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index d1a4751c..9c3858ec 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -20,6 +20,7 @@ import ( "bytes" "encoding/json" "fmt" + "slices" "strconv" "github.com/go-logr/logr" @@ -51,129 +52,137 @@ func WithValues(oldKV, newKV []interface{}) []interface{} { return kv } -// MergeKVs deduplicates elements provided in two key/value slices. -// -// Keys in each slice are expected to be unique, so duplicates can only occur -// when the first and second slice contain the same key. When that happens, the -// key/value pair from the second slice is used. The first slice must be well-formed -// (= even key/value pairs). The second one may have a missing value, in which -// case the special "missing value" is added to the result. -func MergeKVs(first, second []interface{}) []interface{} { - maxLength := len(first) + (len(second)+1)/2*2 - if maxLength == 0 { - // Nothing to do at all. - return nil - } - - if len(first) == 0 && len(second)%2 == 0 { - // Nothing to be overridden, second slice is well-formed - // and can be used directly. - return second - } - - // Determine which keys are in the second slice so that we can skip - // them when iterating over the first one. The code intentionally - // favors performance over completeness: we assume that keys are string - // constants and thus compare equal when the string values are equal. A - // string constant being overridden by, for example, a fmt.Stringer is - // not handled. - overrides := map[interface{}]bool{} - for i := 0; i < len(second); i += 2 { - overrides[second[i]] = true - } - merged := make([]interface{}, 0, maxLength) - for i := 0; i+1 < len(first); i += 2 { - key := first[i] - if overrides[key] { - continue - } - merged = append(merged, key, first[i+1]) - } - merged = append(merged, second...) - if len(merged)%2 != 0 { - merged = append(merged, missingValue) - } - return merged -} - type Formatter struct { AnyToStringHook AnyToStringFunc } type AnyToStringFunc func(v interface{}) string -// MergeKVsInto is a variant of MergeKVs which directly formats the key/value -// pairs into a buffer. -func (f Formatter) MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { - if len(first) == 0 && len(second) == 0 { - // Nothing to do at all. - return - } +const missingValue = "(MISSING)" - if len(first) == 0 && len(second)%2 == 0 { - // Nothing to be overridden, second slice is well-formed - // and can be used directly. - for i := 0; i < len(second); i += 2 { - f.KVFormat(b, second[i], second[i+1]) - } - return - } +func FormatKVs(b *bytes.Buffer, kvs ...[]interface{}) { + Formatter{}.FormatKVs(b, kvs...) +} - // Determine which keys are in the second slice so that we can skip - // them when iterating over the first one. The code intentionally - // favors performance over completeness: we assume that keys are string - // constants and thus compare equal when the string values are equal. A - // string constant being overridden by, for example, a fmt.Stringer is - // not handled. - overrides := map[interface{}]bool{} - for i := 0; i < len(second); i += 2 { - overrides[second[i]] = true - } - for i := 0; i < len(first); i += 2 { - key := first[i] - if overrides[key] { - continue +// FormatKVs formats all key/value pairs such that the output contains no +// duplicates ("last one wins"). +func (f Formatter) FormatKVs(b *bytes.Buffer, kvs ...[]interface{}) { + // De-duplication is done by optimistically formatting all key value + // pairs and then cutting out the output of those key/value pairs which + // got overwritten later. + // + // In the common case of no duplicates, the only overhead is tracking + // previous keys. This uses a slice with a simple linear search because + // the number of entries is typically so low that allocating a map or + // keeping a sorted slice with binary search aren't justified. + // + // Using a fixed size here makes the Go compiler use the stack as + // initial backing store for the slice, which is crucial for + // performance. + existing := make([]obsoleteKV, 0, 32) + obsolete := make([]interval, 0, 32) // Sorted by start index. + for _, keysAndValues := range kvs { + for i := 0; i < len(keysAndValues); i += 2 { + var v interface{} + k := keysAndValues[i] + if i+1 < len(keysAndValues) { + v = keysAndValues[i+1] + } else { + v = missingValue + } + var e obsoleteKV + e.start = b.Len() + e.key = f.KVFormat(b, k, v) + e.end = b.Len() + i := findObsoleteEntry(existing, e.key) + if i >= 0 { + data := b.Bytes() + if bytes.Compare(data[existing[i].start:existing[i].end], data[e.start:e.end]) == 0 { + // The new entry gets obsoleted because it's identical. + // This has the advantage that key/value pairs from + // a WithValues call always come first, even if the same + // pair gets added again later. This makes different log + // entries more consistent. + // + // The new entry has a higher start index and thus can be appended. + obsolete = append(obsolete, e.interval) + } else { + // The old entry gets obsoleted because it's value is different. + // + // Sort order is not guaranteed, we have to insert at the right place. + index, _ := slices.BinarySearchFunc(obsolete, existing[i].interval, func(a, b interval) int { return a.start - b.start }) + obsolete = slices.Insert(obsolete, index, existing[i].interval) + existing[i].interval = e.interval + } + } else { + // Instead of appending at the end and doing a + // linear search in findEntry, we could keep + // the slice sorted by key and do a binary search. + // + // Above: + // i, ok := slices.BinarySearchFunc(existing, e, func(a, b entry) int { return strings.Compare(a.key, b.key) }) + // Here: + // existing = slices.Insert(existing, i, e) + // + // But that adds a dependency on the slices package + // and made performance slightly worse, presumably + // because the cost of shifting entries around + // did not pay of with faster lookups. + existing = append(existing, e) + } } - f.KVFormat(b, key, first[i+1]) - } - // Round down. - l := len(second) - l = l / 2 * 2 - for i := 1; i < l; i += 2 { - f.KVFormat(b, second[i-1], second[i]) - } - if len(second)%2 == 1 { - f.KVFormat(b, second[len(second)-1], missingValue) } -} -func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { - Formatter{}.MergeAndFormatKVs(b, first, second) -} + // If we need to remove some obsolete key/value pairs then move the memory. + if len(obsolete) > 0 { + // Potentially the next remaining output (might itself be obsolete). + from := obsolete[0].end + // Next obsolete entry. + nextObsolete := 1 + // This is the source buffer, before truncation. + all := b.Bytes() + b.Truncate(obsolete[0].start) -const missingValue = "(MISSING)" + for nextObsolete < len(obsolete) { + if from == obsolete[nextObsolete].start { + // Skip also the next obsolete key/value. + from = obsolete[nextObsolete].end + nextObsolete++ + continue + } -// KVListFormat serializes all key/value pairs into the provided buffer. -// A space gets inserted before the first pair and between each pair. -func (f Formatter) KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { - for i := 0; i < len(keysAndValues); i += 2 { - var v interface{} - k := keysAndValues[i] - if i+1 < len(keysAndValues) { - v = keysAndValues[i+1] - } else { - v = missingValue + // Preserve some output. Write uses copy, which + // explicitly allows source and destination to overlap. + // That could happen here. + valid := all[from:obsolete[nextObsolete].start] + b.Write(valid) + from = obsolete[nextObsolete].end + nextObsolete++ } - f.KVFormat(b, k, v) + // Copy end of buffer. + valid := all[from:] + b.Write(valid) } } -func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { - Formatter{}.KVListFormat(b, keysAndValues...) +type obsoleteKV struct { + key string + interval } -func KVFormat(b *bytes.Buffer, k, v interface{}) { - Formatter{}.KVFormat(b, k, v) +// interval includes the start and excludes the end. +type interval struct { + start int + end int +} + +func findObsoleteEntry(entries []obsoleteKV, key string) int { + for i, entry := range entries { + if entry.key == key { + return i + } + } + return -1 } // formatAny is the fallback formatter for a value. It supports a hook (for diff --git a/internal/serialize/keyvalues_no_slog.go b/internal/serialize/keyvalues_no_slog.go index d9c7d154..b8c7e443 100644 --- a/internal/serialize/keyvalues_no_slog.go +++ b/internal/serialize/keyvalues_no_slog.go @@ -28,7 +28,7 @@ import ( // KVFormat serializes one key/value pair into the provided buffer. // A space gets inserted before the pair. -func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) string { // This is the version without slog support. Must be kept in sync with // the version in keyvalues_slog.go. @@ -37,13 +37,15 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments // for the sake of performance. Keys with spaces, // special characters, etc. will break parsing. + var key string if sK, ok := k.(string); ok { // Avoid one allocation when the key is a string, which // normally it should be. - b.WriteString(sK) + key = sK } else { - b.WriteString(fmt.Sprintf("%s", k)) + key = fmt.Sprintf("%s", k) } + b.WriteString(key) // The type checks are sorted so that more frequently used ones // come first because that is then faster in the common @@ -94,4 +96,6 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { default: f.formatAny(b, v) } + + return key } diff --git a/internal/serialize/keyvalues_slog.go b/internal/serialize/keyvalues_slog.go index 89acf977..8e008436 100644 --- a/internal/serialize/keyvalues_slog.go +++ b/internal/serialize/keyvalues_slog.go @@ -29,8 +29,8 @@ import ( ) // KVFormat serializes one key/value pair into the provided buffer. -// A space gets inserted before the pair. -func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { +// A space gets inserted before the pair. It returns the key. +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) string { // This is the version without slog support. Must be kept in sync with // the version in keyvalues_slog.go. @@ -39,13 +39,15 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments // for the sake of performance. Keys with spaces, // special characters, etc. will break parsing. + var key string if sK, ok := k.(string); ok { // Avoid one allocation when the key is a string, which // normally it should be. - b.WriteString(sK) + key = sK } else { - b.WriteString(fmt.Sprintf("%s", k)) + key = fmt.Sprintf("%s", k) } + b.WriteString(key) // The type checks are sorted so that more frequently used ones // come first because that is then faster in the common @@ -112,6 +114,8 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { default: f.formatAny(b, v) } + + return key } // generateJSON has the same preference for plain strings as KVFormat. diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index b9e066c6..772577d2 100644 --- a/internal/serialize/keyvalues_test.go +++ b/internal/serialize/keyvalues_test.go @@ -19,7 +19,6 @@ package serialize_test import ( "bytes" "fmt" - "reflect" "testing" "time" @@ -185,146 +184,9 @@ No whitespace.`, for _, d := range testKVList { b := &bytes.Buffer{} - serialize.KVListFormat(b, d.keysValues...) + serialize.FormatKVs(b, d.keysValues) if b.String() != d.want { t.Errorf("KVListFormat error:\n got:\n\t%s\nwant:\t%s", b.String(), d.want) } } } - -func TestDuplicates(t *testing.T) { - for name, test := range map[string]struct { - first, second []interface{} - expected []interface{} - }{ - "empty": {}, - "no-duplicates": { - first: makeKV("a", 3), - second: makeKV("b", 3), - expected: append(makeKV("a", 3), makeKV("b", 3)...), - }, - "all-duplicates": { - first: makeKV("a", 3), - second: makeKV("a", 3), - expected: makeKV("a", 3), - }, - "start-duplicate": { - first: append([]interface{}{"x", 1}, makeKV("a", 3)...), - second: append([]interface{}{"x", 2}, makeKV("b", 3)...), - expected: append(append(makeKV("a", 3), "x", 2), makeKV("b", 3)...), - }, - "subset-first": { - first: append([]interface{}{"x", 1}, makeKV("a", 3)...), - second: append([]interface{}{"x", 2}, makeKV("a", 3)...), - expected: append([]interface{}{"x", 2}, makeKV("a", 3)...), - }, - "subset-second": { - first: append([]interface{}{"x", 1}, makeKV("a", 1)...), - second: append([]interface{}{"x", 2}, makeKV("b", 2)...), - expected: append(append(makeKV("a", 1), "x", 2), makeKV("b", 2)...), - }, - "end-duplicate": { - first: append(makeKV("a", 3), "x", 1), - second: append(makeKV("b", 3), "x", 2), - expected: append(makeKV("a", 3), append(makeKV("b", 3), "x", 2)...), - }, - "middle-duplicate": { - first: []interface{}{"a-0", 0, "x", 1, "a-1", 2}, - second: []interface{}{"b-0", 0, "x", 2, "b-1", 2}, - expected: []interface{}{"a-0", 0, "a-1", 2, "b-0", 0, "x", 2, "b-1", 2}, - }, - "internal-duplicates": { - first: []interface{}{"a", 0, "x", 1, "a", 2}, - second: []interface{}{"b", 0, "x", 2, "b", 2}, - // This is the case where Merged keeps key/value pairs - // that were already duplicated inside the slices, for - // performance. - expected: []interface{}{"a", 0, "a", 2, "b", 0, "x", 2, "b", 2}, - }, - } { - t.Run(name, func(t *testing.T) { - t.Run("Merged", func(t *testing.T) { - actual := serialize.MergeKVs(test.first, test.second) - expectEqual(t, "merged key/value pairs", test.expected, actual) - }) - }) - } -} - -// BenchmarkMergeKVs checks performance when MergeKVs is called with two slices. -// In practice that is how the function is used. -func BenchmarkMergeKVs(b *testing.B) { - for firstLength := 0; firstLength < 10; firstLength++ { - firstA := makeKV("a", firstLength) - for secondLength := 0; secondLength < 10; secondLength++ { - secondA := makeKV("a", secondLength) - secondB := makeKV("b", secondLength) - b.Run(fmt.Sprintf("%dx%d", firstLength, secondLength), func(b *testing.B) { - // This is the most common case: all key/value pairs are kept. - b.Run("no-duplicates", func(b *testing.B) { - expected := append(firstA, secondB...) - benchMergeKVs(b, expected, firstA, secondB) - }) - - // Fairly unlikely... - b.Run("all-duplicates", func(b *testing.B) { - var expected []interface{} - if firstLength > secondLength { - expected = firstA[secondLength*2:] - } - expected = append(expected, secondA...) - benchMergeKVs(b, expected, firstA, secondA) - }) - - // First entry is the same. - b.Run("start-duplicate", func(b *testing.B) { - first := []interface{}{"x", 1} - first = append(first, firstA...) - second := []interface{}{"x", 1} - second = append(second, secondB...) - expected := append(firstA, second...) - benchMergeKVs(b, expected, first, second) - }) - - // Last entry is the same. - b.Run("end-duplicate", func(b *testing.B) { - first := firstA[:] - first = append(first, "x", 1) - second := secondB[:] - second = append(second, "x", 1) - expected := append(firstA, second...) - benchMergeKVs(b, expected, first, second) - }) - }) - } - } -} - -func makeKV(prefix string, length int) []interface{} { - if length == 0 { - return []interface{}{} - } - kv := make([]interface{}, 0, length*2) - for i := 0; i < length; i++ { - kv = append(kv, fmt.Sprintf("%s-%d", prefix, i), i) - } - return kv -} - -func benchMergeKVs(b *testing.B, expected []interface{}, first, second []interface{}) { - if len(expected) == 0 { - expected = nil - } - actual := serialize.MergeKVs(first, second) - expectEqual(b, "trimmed key/value pairs", expected, actual) - b.ResetTimer() - for i := 0; i < b.N; i++ { - serialize.MergeKVs(first, second) - } -} - -func expectEqual(tb testing.TB, what string, expected, actual interface{}) { - if !reflect.DeepEqual(expected, actual) { - tb.Fatalf("Did not get correct %s. Expected:\n %v\nActual:\n %v", what, expected, actual) - } -} diff --git a/klog.go b/klog.go index a5997e06..40b1b20b 100644 --- a/klog.go +++ b/klog.go @@ -819,10 +819,11 @@ func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, b := buffer.GetBuffer() b.Write(qMsg) + var errKV []interface{} if err != nil { - serialize.KVListFormat(&b.Buffer, "err", err) + errKV = []interface{}{"err", err} } - serialize.KVListFormat(&b.Buffer, keysAndValues...) + serialize.FormatKVs(&b.Buffer, errKV, keysAndValues) l.printDepth(s, nil, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. buffer.PutBuffer(b) diff --git a/klogr.go b/klogr.go index efec96fd..6204c7bb 100644 --- a/klogr.go +++ b/klogr.go @@ -53,7 +53,7 @@ func (l *klogger) Init(info logr.RuntimeInfo) { } func (l *klogger) Info(level int, msg string, kvList ...interface{}) { - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) // Skip this function. VDepth(l.callDepth+1, Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } @@ -63,7 +63,7 @@ func (l *klogger) Enabled(level int) bool { } func (l *klogger) Error(err error, msg string, kvList ...interface{}) { - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) ErrorSDepth(l.callDepth+1, err, msg, merged...) } diff --git a/klogr/klogr.go b/klogr/klogr.go index a154960c..3528a1ef 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -138,11 +138,11 @@ func (l *klogger) Info(level int, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: msgStr := flatten("msg", msg) - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) kvStr := flatten(merged...) klog.VDepth(l.callDepth+1, klog.Level(level)).InfoDepth(l.callDepth+1, msgStr, " ", kvStr) case FormatKlog: - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) klog.VDepth(l.callDepth+1, klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } } @@ -160,11 +160,11 @@ func (l *klogger) Error(err error, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: errStr := flatten("error", loggableErr) - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) kvStr := flatten(merged...) klog.ErrorDepth(l.callDepth+1, msgStr, " ", errStr, " ", kvStr) case FormatKlog: - merged := serialize.MergeKVs(l.values, kvList) + merged := serialize.WithValues(l.values, kvList) klog.ErrorSDepth(l.callDepth+1, err, msg, merged...) } } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 57ebf7a2..0d61bcea 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -69,22 +69,22 @@ func testOutput(t *testing.T, format string) { expectedKlogOutput: `"test" logger="hello.world" akey="avalue" `, }, - "may print duplicate keys with the same value": { + "de-duplicate keys with the same value": { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, expectedOutput: `"msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" akey="avalue" + expectedKlogOutput: `"test" akey="avalue" `, }, - "may print duplicate keys when the values are passed to Info": { + "de-duplicate keys when the values are passed to Info": { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, expectedOutput: `"msg"="test" "akey"="avalue2" `, - expectedKlogOutput: `"test" akey="avalue" akey="avalue2" + expectedKlogOutput: `"test" akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { diff --git a/klogr_slog.go b/klogr_slog.go index 0010e934..901e28dd 100644 --- a/klogr_slog.go +++ b/klogr_slog.go @@ -69,10 +69,11 @@ func slogOutput(file string, line int, now time.Time, err error, s severity.Seve b := buffer.GetBuffer() b.Write(qMsg) + var errKV []interface{} if err != nil { - serialize.KVListFormat(&b.Buffer, "err", err) + errKV = []interface{}{"err", err} } - serialize.KVListFormat(&b.Buffer, kvList...) + serialize.FormatKVs(&b.Buffer, errKV, kvList) // See print + header. buf := logging.formatHeader(s, file, line, now) diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index b6c7bb2e..31569357 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -302,7 +302,7 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) { l.shared.t.Helper() buf := buffer.GetBuffer() - l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.shared.formatter.FormatKVs(&buf.Buffer, l.values, kvList) l.log(LogInfo, msg, level, buf, nil, kvList) } @@ -320,10 +320,11 @@ func (l tlogger) Error(err error, msg string, kvList ...interface{}) { l.shared.t.Helper() buf := buffer.GetBuffer() + var errKV []interface{} if err != nil { - l.shared.formatter.KVFormat(&buf.Buffer, "err", err) + errKV = []interface{}{"err", err} } - l.shared.formatter.MergeAndFormatKVs(&buf.Buffer, l.values, kvList) + l.shared.formatter.FormatKVs(&buf.Buffer, errKV, l.values, kvList) l.log(LogError, msg, 0, buf, err, kvList) } diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 57c7c2d8..fc22e62b 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -57,13 +57,13 @@ func TestInfo(t *testing.T) { "should not print duplicate keys with the same value": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: `Ixxx test akey="avalue" akey="avalue" + expectedOutput: `Ixxx test akey="avalue" `, }, - "should only print the last duplicate key when the values are passed to Info": { + "should print no duplicate keys when the values are passed to Info": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `Ixxx test akey="avalue" akey="avalue2" + expectedOutput: `Ixxx test akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { diff --git a/test/output.go b/test/output.go index 1857f500..c56a46e9 100644 --- a/test/output.go +++ b/test/output.go @@ -19,6 +19,7 @@ package test import ( "bytes" + "encoding/hex" "encoding/json" "errors" "flag" @@ -177,9 +178,9 @@ var tests = map[string]testcase{ }, "override single value": { withValues: []interface{}{"akey", "avalue"}, - text: "test", + text: "test-with-values", values: []interface{}{"akey", "avalue2"}, - expectedOutput: `I output.go:] "test" akey="avalue2" + expectedOutput: `I output.go:] "test-with-values" akey="avalue2" `, }, "override WithValues": { @@ -216,9 +217,9 @@ I output.go:] "test" firstKey=1 secondKey=3 `, }, "print duplicate keys in arguments": { - text: "test", + text: "test-arguments", values: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `I output.go:] "test" akey="avalue" akey="avalue2" + expectedOutput: `I output.go:] "test-arguments" akey="avalue2" `, }, "preserve order of key/value pairs": { @@ -424,6 +425,30 @@ I output.go:] "test" firstKey=1 secondKey=3 text: "cycle", values: []interface{}{"list", newCyclicList()}, expectedOutput: `I output.go:] "cycle" list="" +`, + }, + "duplicates": { + withValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("0102030405060708")}, + moreValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("1112131415161718")}, + evenMoreValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728")}, + text: "duplicates", + + expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +`, + }, + "mixed duplicates": { + withValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("0102030405060708"), "a", 1}, + moreValues: []interface{}{"b", 2, "trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("1112131415161718")}, + evenMoreValues: []interface{}{"c", 3, "trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728"), "d", 4}, + text: "duplicates", + + expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4 `, }, } @@ -440,6 +465,7 @@ func printWithLogger(logger logr.Logger, test testcase) { logger = logger.WithValues(test.withValues...) // loggers := []logr.Logger{logger} if test.moreValues != nil { + // Intentionally append the logger again: WithValues must not change what it prints. loggers = append(loggers, logger.WithValues(test.moreValues...), logger) // } if test.evenMoreValues != nil { @@ -478,22 +504,12 @@ func initPrintWithKlog(tb testing.TB, test testcase) { func printWithKlog(test testcase) { kv := []interface{}{} - haveKeyInValues := func(key interface{}) bool { - for i := 0; i < len(test.values); i += 2 { - if key == test.values[i] { - return true - } - } - return false - } appendKV := func(withValues ...interface{}) { if len(withValues)%2 != 0 { withValues = append(withValues, "(MISSING)") } for i := 0; i < len(withValues); i += 2 { - if !haveKeyInValues(withValues[i]) { - kv = append(kv, withValues[i], withValues[i+1]) - } + kv = append(kv, withValues[i], withValues[i+1]) } } // Here we need to emulate the handling of WithValues above. @@ -543,10 +559,10 @@ func Output(t *testing.T, config OutputConfig) { t.Run(n, func(t *testing.T) { initPrintWithKlog(t, test) - testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) { + testOutput := func(t *testing.T, expectedLine int, logToBuffer func(buffer *bytes.Buffer)) { var tmpWriteBuffer bytes.Buffer klog.SetOutput(&tmpWriteBuffer) - print(&tmpWriteBuffer) + logToBuffer(&tmpWriteBuffer) klog.Flush() actual := tmpWriteBuffer.String() @@ -570,14 +586,14 @@ func Output(t *testing.T, config OutputConfig) { } expectedWithPlaceholder := expected expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", callLine)) - expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-18)) + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-19)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-15)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-12)) if actual != expected { if expectedWithPlaceholder == test.expectedOutput { - t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual) + t.Errorf("Output mismatch.\n\nExpected with placeholders:\n%s\nExpected without placeholders:\n%s\nActual:\n%s\n", expectedWithPlaceholder, expected, actual) } else { - t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.expectedOutput, expectedWithPlaceholder, actual) + t.Errorf("Output mismatch. klog:\n%s\n\nExpected with placeholders:\n%s\nExpected without placeholders:\n%s\nActual:\n%s\n", test.expectedOutput, expectedWithPlaceholder, expected, actual) } } } @@ -843,9 +859,9 @@ func Output(t *testing.T, config OutputConfig) { expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", callLine)) if actual != expected { if expectedWithPlaceholder == test.output { - t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expectedWithPlaceholder, actual) + t.Errorf("Output mismatch. Expected with placeholders:\n%s\nExpected without placeholders:\n%s\nActual:\n%s\n", expectedWithPlaceholder, expected, actual) } else { - t.Errorf("Output mismatch. klog:\n%s\nExpected:\n%s\nActual:\n%s\n", test.output, expectedWithPlaceholder, actual) + t.Errorf("Output mismatch. klog:\n%s\nExpected with placeholders:\n%s\nExpected without placeholders:\n%s\nActual:\n%s\n", test.output, expectedWithPlaceholder, expected, actual) } } }) @@ -1022,3 +1038,65 @@ func newCyclicList() *myList { a.Next = b return a } + +// SpanID mimicks https://pkg.go.dev/go.opentelemetry.io/otel/trace#SpanID. +type SpanID [8]byte + +var ( + _ json.Marshaler = SpanID{} + _ fmt.Stringer = SpanID{} +) + +func (s SpanID) MarshalJSON() ([]byte, error) { + return json.Marshal(s.String()) +} + +func (s SpanID) String() string { + return hex.EncodeToString(s[:]) +} + +func spanIDFromHex(str string) SpanID { + decoded, err := hex.DecodeString(str) + if err != nil { + panic(fmt.Sprintf("invalid hex string %q: %v", str, err)) + } + if len(decoded) != len(SpanID{}) { + panic(fmt.Sprintf("invalid length of hex string %q: need %d bytes", str, len(SpanID{}))) + } + var result SpanID + for i := range result { + result[i] = decoded[i] + } + return result +} + +// TraceID mimicks https://pkg.go.dev/go.opentelemetry.io/otel/trace#TraceID. +type TraceID [16]byte + +var ( + _ json.Marshaler = TraceID{} + _ fmt.Stringer = TraceID{} +) + +func (s TraceID) MarshalJSON() ([]byte, error) { + return json.Marshal(s.String()) +} + +func (s TraceID) String() string { + return hex.EncodeToString(s[:]) +} + +func traceIDFromHex(str string) TraceID { + decoded, err := hex.DecodeString(str) + if err != nil { + panic(fmt.Sprintf("invalid hex string %q: %v", str, err)) + } + if len(decoded) != len(TraceID{}) { + panic(fmt.Sprintf("invalid length of hex string %q: need %d bytes", str, len(TraceID{}))) + } + var result TraceID + for i := range result { + result[i] = decoded[i] + } + return result +} diff --git a/test/zapr.go b/test/zapr.go index 96f175f4..1e669fa5 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -32,8 +32,12 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"caller":"test/output.go:","msg":"helper","v":0,"akey":"avalue"} `, - `I output.go:] "test" akey="avalue" akey="avalue2" -`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue","akey":"avalue2"} + `I output.go:] "test-arguments" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-arguments","v":0,"akey":"avalue","akey":"avalue2"} +`, + + `I output.go:] "test-with-values" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-with-values","akey":"avalue","v":0,"akey":"avalue2"} `, `I output.go:] "test" logger="hello.world" akey="avalue" @@ -258,6 +262,26 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `I output.go:] "cycle" list="" `: `{"caller":"test/output.go:","msg":"cycle","v":0,"listError":"json: unsupported value: encountered a cycle via *test.myList"} +`, + + `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +`: `{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718","v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"2122232425262728","v":0} +`, + + `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4 +`: `{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718","v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0} +{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"c":3,"trace":"101112131415161718191a1b1c1d1e1f","span":"2122232425262728","d":4,"v":0} `, } } @@ -275,8 +299,6 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" // - Output does that without emitting the warning that we get // from zapr. // - zap drops keys with missing values, here we get "(MISSING)". -// - zap does not de-duplicate key/value pairs, here klog does that -// for it. func ZaprOutputMappingIndirect() map[string]string { mapping := ZaprOutputMappingDirect() @@ -311,12 +333,16 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `: `{"caller":"test/output.go:","msg":"test","v":0,"akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","akey5":"avalue5","akey4":"avalue4"} `, - `I output.go:] "test" akey="avalue2" -`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue2"} + `I output.go:] "test-arguments" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-arguments","v":0,"akey":"avalue","akey":"avalue2"} +`, + + `I output.go:] "test-with-values" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-with-values","v":0,"akey":"avalue","akey":"avalue2"} `, `I output.go:] "test" X="y" duration="1m0s" A="b" -`: `{"caller":"test/output.go:","msg":"test","v":0,"X":"y","duration":"1m0s","A":"b"} +`: `{"caller":"test/output.go:","msg":"test","v":0,"duration":"1h0m0s","X":"y","duration":"1m0s","A":"b"} `, `I output.go:] "test" firstKey=1 @@ -345,6 +371,26 @@ I output.go:] "test" firstKey=1 secondKey=3 // discards these messages. `I output.go:] "v=11: you see me because of -vmodule output=11" `: ``, + + `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +`: `{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708"} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718"} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708"} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"2122232425262728"} +`, + + `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 b=2 span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4 +`: `{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718"} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1} +{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"c":3,"trace":"101112131415161718191a1b1c1d1e1f","span":"2122232425262728","d":4} +`, } { mapping[key] = value } diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 7aaad6a2..6b9aab86 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -132,10 +132,11 @@ func (l *tlogger) printWithInfos(file string, line int, now time.Time, err error b.Write(qMsg) + var errKV []interface{} if err != nil { - serialize.KVFormat(&b.Buffer, "err", err) + errKV = []interface{}{"err", err} } - serialize.MergeAndFormatKVs(&b.Buffer, l.values, kvList) + serialize.FormatKVs(&b.Buffer, errKV, l.values, kvList) if b.Len() == 0 || b.Bytes()[b.Len()-1] != '\n' { b.WriteByte('\n') }