From be376eeb6c485b7f0b8d677b771ab2476ed90920 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 21 Nov 2024 17:37:58 +0100 Subject: [PATCH 1/9] test: avoid linter warning Recent golangci-lint warns about shadowing the print function. --- test/output.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/output.go b/test/output.go index 1857f500..e93d46ef 100644 --- a/test/output.go +++ b/test/output.go @@ -543,10 +543,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() From f6c62f00652d3773b1095bef7a3812fa8340a66b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 21 Nov 2024 17:19:42 +0100 Subject: [PATCH 2/9] GitHub: test with Go >= 1.21, update actions 1.21 enables the usage of generics and the slices package. --- .github/workflows/lint.yml | 4 ++-- .github/workflows/test.yml | 16 ++++++++-------- 2 files changed, 10 insertions(+), 10 deletions(-) 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 From 1fcaaa91ef71dff22e0c73532034de14e1d0935b Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Nov 2024 11:55:43 +0100 Subject: [PATCH 3/9] examples: bump Go version + tools dependency When testing with Go v1.23.0 in the PATH, `go test go_vet` panics. Bumping the tools dependency adds 1.23 as toolchain requirement and bumps the Go version. This is limited to the examples module and thus does not affect users of klog. panic: runtime error: invalid memory address or nil pointer dereference [recovered] panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x62d74f] goroutine 97 [running]: go/types.(*Checker).handleBailout(0xc0005bb340, 0xc0001afc88) /nvme/gopath/go-1.23.0/src/go/types/check.go:412 +0x88 panic({0x6e6c40?, 0x954490?}) /nvme/gopath/go-1.23.0/src/runtime/panic.go:785 +0x132 go/types.(*StdSizes).Sizeof(0x0, {0x7a5420, 0x957e40}) /nvme/gopath/go-1.23.0/src/go/types/sizes.go:229 +0x30f go/types.(*Config).sizeof(...) /nvme/gopath/go-1.23.0/src/go/types/sizes.go:334 go/types.representableConst.func1({0x7a5420?, 0x957e40?}) /nvme/gopath/go-1.23.0/src/go/types/const.go:77 +0x86 go/types.representableConst({0x7a7548, 0x94bb80}, 0xc0005bb340, 0x957e40, 0xc0001af588) /nvme/gopath/go-1.23.0/src/go/types/const.go:93 +0x173 go/types.(*Checker).representation(0xc0005bb340, 0xc00015be00, 0x957e40) /nvme/gopath/go-1.23.0/src/go/types/const.go:257 +0x65 go/types.(*Checker).implicitTypeAndValue(0xc0005bb340, 0xc00015be00, {0x7a5588, 0xc0000ec380}) /nvme/gopath/go-1.23.0/src/go/types/expr.go:377 +0x2d7 go/types.(*Checker).assignment(0xc0005bb340, 0xc00015be00, {0x7a5588, 0xc0000ec380}, {0x738a90, 0x14}) /nvme/gopath/go-1.23.0/src/go/types/assignments.go:70 +0x451 go/types.(*Checker).initConst(0xc0005bb340, 0xc000720a80, 0xc00015be00) /nvme/gopath/go-1.23.0/src/go/types/assignments.go:144 +0x1da go/types.(*Checker).constDecl(0xc0005bb340, 0xc000720a80, {0x7a6580, 0xc0002828a0}, {0x7a6580, 0xc0002828c0}, 0x0) /nvme/gopath/go-1.23.0/src/go/types/decl.go:482 +0x2e8 go/types.(*Checker).objDecl(0xc0005bb340, {0x7a9e78, 0xc000720a80}, 0x0) /nvme/gopath/go-1.23.0/src/go/types/decl.go:185 +0xa09 go/types.(*Checker).packageObjects(0xc0005bb340) /nvme/gopath/go-1.23.0/src/go/types/resolver.go:714 +0x454 go/types.(*Checker).checkFiles(0xc0005bb340, {0xc00016cb10, 0x3, 0x3}) /nvme/gopath/go-1.23.0/src/go/types/check.go:467 +0x15a go/types.(*Checker).Files(0xc0001b2000?, {0xc00016cb10?, 0xc000474120?, 0x6?}) /nvme/gopath/go-1.23.0/src/go/types/check.go:430 +0x75 golang.org/x/tools/go/packages.(*loader).loadPackage(0xc0001b2000, 0xc000432780) /nvme/gopath/pkg/mod/golang.org/x/tools@v0.1.5/go/packages/packages.go:961 +0x70f golang.org/x/tools/go/packages.(*loader).loadRecursive.func1() /nvme/gopath/pkg/mod/golang.org/x/tools@v0.1.5/go/packages/packages.go:799 +0x1a9 sync.(*Once).doSlow(0x0?, 0x0?) /nvme/gopath/go-1.23.0/src/sync/once.go:76 +0xb4 sync.(*Once).Do(...) /nvme/gopath/go-1.23.0/src/sync/once.go:67 golang.org/x/tools/go/packages.(*loader).loadRecursive(0x0?, 0x0?) /nvme/gopath/pkg/mod/golang.org/x/tools@v0.1.5/go/packages/packages.go:787 +0x3b golang.org/x/tools/go/packages.(*loader).loadRecursive.func1.1(0x0?) /nvme/gopath/pkg/mod/golang.org/x/tools@v0.1.5/go/packages/packages.go:794 +0x26 created by golang.org/x/tools/go/packages.(*loader).loadRecursive.func1 in goroutine 96 /nvme/gopath/pkg/mod/golang.org/x/tools@v0.1.5/go/packages/packages.go:793 +0x94 FAIL k8s.io/klog/examples/go_vet 0.438s FAIL --- examples/go.mod | 13 ++++++++-- examples/go.sum | 15 ++++++------ examples/go_vet/testdata/calls.go | 40 +++++++++++++++---------------- 3 files changed, 39 insertions(+), 29 deletions(-) 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, From 15e9f9d3637d61704084df652dc0c560e83656bc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 21 Nov 2024 11:25:58 +0100 Subject: [PATCH 4/9] test: enhance failure output Printing the actual expected string makes it easier to run a diff, something that we cannot do here automatically because we cannot depend on testify or go-cmp. --- test/output.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/output.go b/test/output.go index e93d46ef..e4d639a5 100644 --- a/test/output.go +++ b/test/output.go @@ -575,9 +575,9 @@ func Output(t *testing.T, config OutputConfig) { 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 +843,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) } } }) From eb9c3c200216298533f0e1c39445b0bf8d580818 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Nov 2024 11:47:32 +0100 Subject: [PATCH 5/9] test: add OpenTelemetry span/trace test case Span and trace ID are potentially going to be duplicated a lot. --- test/output.go | 89 ++++++++++++++++++++++++++++++++++++++++++++++++++ test/zapr.go | 40 +++++++++++++++++++++++ 2 files changed, 129 insertions(+) diff --git a/test/output.go b/test/output.go index e4d639a5..ca7dbc53 100644 --- a/test/output.go +++ b/test/output.go @@ -19,6 +19,7 @@ package test import ( "bytes" + "encoding/hex" "encoding/json" "errors" "flag" @@ -424,6 +425,32 @@ 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", + + // No de-duplication among WithValues calls at the moment! + expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" 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", + + // No de-duplication among WithValues calls at the moment! + expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 `, }, } @@ -1022,3 +1049,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..be766c72 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -258,6 +258,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="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" 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" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" 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} `, } } @@ -345,6 +365,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="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" 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" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" 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 } From 2bcc94a73c8fcf7bc3ca2db489bb9f9ba8724c2c Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Nov 2024 18:19:36 +0100 Subject: [PATCH 6/9] remove MergeKVs tests MergeKVs is about to become a lot simpler. Removing the tests and benchmarks simplifies the before/after performance comparison. --- internal/serialize/keyvalues_test.go | 138 --------------------------- 1 file changed, 138 deletions(-) diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index b9e066c6..07ac25fd 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" @@ -191,140 +190,3 @@ No whitespace.`, } } } - -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) - } -} From 32d409f4376d531914debb666fba8398e82a356f Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Nov 2024 16:04:33 +0100 Subject: [PATCH 7/9] de-duplicate all key/value pairs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously, de-duplication was limited such that keys passed to a log call as parameters overwrote keys passed earlier to WithValues. Using the same key in different WithValues calls or multiple times in a WithValues call or the parameters led to duplicates in the output. Now all key/value pairs get checked for duplicates. The last one wins and is printed at the place where it was added. A potential improvement would be to keep it at the place where it first appeared if the value is the same because then different log entries are more likely to have it at the beginning of their key/value pairs because it was added by a common WithValues call. Because the new implementation avoids memory allocations, the performance impact is minimal. Some cases even become faster. goos: linux goarch: amd64 pkg: k8s.io/klog/examples/benchmarks cpu: Intel(R) Core(TM) i9-7980XE CPU @ 2.60GHz │ before │ after1 │ │ sec/op │ sec/op vs base │ Output/klog/fail-verbosity-non-standard-struct-key-check/objects/0-36 385.5n ± 9% 358.9n ± 5% -6.91% (p=0.041 n=6) Output/klog/fail-verbosity-non-standard-struct-key-check/objects/10-36 374.3n ± 4% 357.3n ± 5% -4.55% (p=0.015 n=6) Output/klog/fail-verbosity-non-standard-struct-key-check/objects/20-36 388.4n ± 3% 359.2n ± 4% -7.53% (p=0.002 n=6) ... Output/zapr/fail-verbosity-non-standard-int-key-check/objects/90-36 380.9n ± 4% 379.4n ± 2% ~ (p=0.937 n=6) Output/zapr/fail-verbosity-non-standard-int-key-check/objects/100-36 375.1n ± 3% 381.9n ± 4% ~ (p=0.093 n=6) geomean 3.461µ 3.442µ -0.55% pkg: k8s.io/klog/examples/output_test ZaprOutput/regular_error_types_as_value-36 3.270µ ± 10% 3.530µ ± 9% ~ (p=0.132 n=6) ZaprOutput/struct_values-36 3.932µ ± 11% 4.107µ ± 10% ~ (p=1.000 n=6) ZaprOutput/klog.Format-36 4.276µ ± 12% 4.439µ ± 7% ~ (p=0.132 n=6) ZaprOutput/regular_error_types_when_using_logr.Error-36 2.790µ ± 7% 2.834µ ± 15% ~ (p=0.699 n=6) ZaprOutput/map_values-36 5.802µ ± 9% 5.829µ ± 3% ~ (p=1.000 n=6) ZaprOutput/log_with_name_and_values-36 4.051µ ± 4% 3.864µ ± 6% -4.63% (p=0.015 n=6) ... geomean 5.581µ 5.646µ +1.16% pkg: k8s.io/klog/v2 Header-36 1.339µ ± 5% 1.311µ ± 6% ~ (p=0.513 n=6) ... KlogOutput/klog.Format-36 4.207µ ± 10% 4.667µ ± 3% +10.95% (p=0.009 n=6) KlogOutput/cyclic_list-36 151.3µ ± 1% 151.1µ ± 1% ~ (p=0.818 n=6) KlogOutput/override_single_value-36 2.308µ ± 9% 3.501µ ± 15% +51.66% (p=0.002 n=6) KlogOutput/multiple_WithValues-36 10.91µ ± 9% 12.46µ ± 7% +14.16% (p=0.004 n=6) ... KlogOutput/duplicates-36 21.34µ ± 2% 22.52µ ± 7% ~ (p=0.065 n=6) ... geomean 252.6n 260.6n +3.18% pkg: k8s.io/klog/v2/textlogger TextloggerOutput/html_characters-36 1.982µ ± 12% 1.978µ ± 6% ~ (p=0.937 n=6) TextloggerOutput/map_values-36 3.215µ ± 6% 3.429µ ± 4% +6.67% (p=0.041 n=6) ... TextloggerOutput/mixed_duplicates-36 19.33µ ± 5% 19.59µ ± 7% ~ (p=0.818 n=6) ... TextloggerOutput/print_duplicate_keys_in_arguments-36 2.067µ ± 7% 2.388µ ± 6% +15.53% (p=0.002 n=6) ... TextloggerOutput/duplicates-36 16.80µ ± 11% 17.06µ ± 4% ~ (p=0.310 n=6) ... geomean 2.798µ 2.860µ +2.24% --- internal/serialize/keyvalues.go | 210 +++++++++++++----------- internal/serialize/keyvalues_no_slog.go | 10 +- internal/serialize/keyvalues_slog.go | 12 +- klogr.go | 4 +- klogr/klogr.go | 8 +- klogr/klogr_test.go | 8 +- ktesting/testinglogger_test.go | 6 +- test/output.go | 33 ++-- test/zapr.go | 36 ++-- 9 files changed, 175 insertions(+), 152 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index d1a4751c..bff34361 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -51,51 +51,6 @@ 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 } @@ -105,46 +60,7 @@ 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 - } - - 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 - } - - // 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 - } - 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) - } + f.formatKVs(b, first, second) } func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { @@ -156,16 +72,7 @@ const missingValue = "(MISSING)" // 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 - } - f.KVFormat(b, k, v) - } + f.formatKVs(b, keysAndValues) } func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { @@ -176,6 +83,119 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { Formatter{}.KVFormat(b, k, v) } +// 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 { + // The old entry gets obsoleted. This ensures + // that if the more recent one has a different value, + // that value remains. If the value is the same, + // then we could also keep the old entry. That + // would lead to a more natural order of key/value + // pairs in the output (shared key/value in multiple + // log entries always at the beginning) but at the + // cost of another memory comparison. + obsolete = append(obsolete, 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) + } + } + } + + // 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) + + for nextObsolete < len(obsolete) { + if from == obsolete[nextObsolete].start { + // Skip also the next obsolete key/value. + from = obsolete[nextObsolete].end + nextObsolete++ + continue + } + + // 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++ + } + // Copy end of buffer. + valid := all[from:] + b.Write(valid) + } +} + +type obsoleteKV struct { + key string + interval +} + +// 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 // example, for YAML encoding) and itself uses JSON encoding. func (f Formatter) formatAny(b *bytes.Buffer, v interface{}) { 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/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/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 ca7dbc53..caedf3fc 100644 --- a/test/output.go +++ b/test/output.go @@ -178,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": { @@ -217,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": { @@ -433,11 +433,10 @@ I output.go:] "test" firstKey=1 secondKey=3 evenMoreValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728")}, text: "duplicates", - // No de-duplication among WithValues calls at the moment! expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" `, }, "mixed duplicates": { @@ -446,11 +445,10 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" evenMoreValues: []interface{}{"c", 3, "trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728"), "d", 4}, text: "duplicates", - // No de-duplication among WithValues calls at the moment! expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 `, }, } @@ -467,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 { @@ -505,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. @@ -597,7 +586,7 @@ 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 { diff --git a/test/zapr.go b/test/zapr.go index be766c72..bc9e03ab 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" @@ -261,9 +265,9 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +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} @@ -271,9 +275,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" 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} @@ -295,8 +299,6 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" // - 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() @@ -331,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 @@ -367,9 +373,9 @@ I output.go:] "test" firstKey=1 secondKey=3 `: ``, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +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"} @@ -377,9 +383,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" 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} From 5964d1bcbaeeec274eed6e8fe1f172a0abf089f5 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 21 Nov 2024 11:01:57 +0100 Subject: [PATCH 8/9] keep original key/value pair during de-duplicatation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Suppose the same key/value pair gets logged multiple times: WithValues("sameKey", 1).WithValues("newKey", 2).WithValues("sameKey", 1) Previously, the de-duplication code would have emitted it near the end: "hello world" newKey=2 sameKey=1 Now, it gets emitted at the place where it first appeared: "hello world" sameKey=1 newKey=2 This makes log entries more consistent when some repeat the key/value pair and others don't. Performance is about the same as before. goos: linux goarch: amd64 pkg: k8s.io/klog/examples/benchmarks cpu: Intel(R) Core(TM) i9-7980XE CPU @ 2.60GHz │ after1 │ after2 │ │ sec/op │ sec/op vs base │ ... geomean 3.442µ 3.445µ +0.09% pkg: k8s.io/klog/examples/output_test geomean 5.646µ 5.631µ -0.26% pkg: k8s.io/klog/v2 geomean 260.6n 260.5n -0.07% pkg: k8s.io/klog/v2/textlogger TextloggerOutput/odd_WithValues-36 6.956µ ± 4% 7.263µ ± 4% +4.42% (p=0.041 n=6) ... TextloggerOutput/log_with_multiple_names_and_values-36 3.353µ ± 4% 3.172µ ± 2% -5.40% (p=0.002 n=6) ... TextloggerOutput/duplicates-36 17.06µ ± 4% 17.16µ ± 9% ~ (p=0.937 n=6) ... TextloggerOutput/mixed_duplicates-36 19.59µ ± 7% 20.35µ ± 5% ~ (p=0.065 n=6) ... TextloggerOutput/print_duplicate_keys_in_arguments-36 2.388µ ± 6% 2.218µ ± 7% -7.12% (p=0.026 n=6) ... geomean 2.860µ 2.849µ -0.38% --- go.mod | 2 +- internal/serialize/keyvalues.go | 29 +++++++++++++++++++---------- test/output.go | 4 ++-- test/zapr.go | 8 ++++---- 4 files changed, 26 insertions(+), 17 deletions(-) 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 bff34361..af35211a 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" @@ -115,16 +116,24 @@ func (f Formatter) formatKVs(b *bytes.Buffer, kvs ...[]interface{}) { e.end = b.Len() i := findObsoleteEntry(existing, e.key) if i >= 0 { - // The old entry gets obsoleted. This ensures - // that if the more recent one has a different value, - // that value remains. If the value is the same, - // then we could also keep the old entry. That - // would lead to a more natural order of key/value - // pairs in the output (shared key/value in multiple - // log entries always at the beginning) but at the - // cost of another memory comparison. - obsolete = append(obsolete, existing[i].interval) - existing[i].interval = e.interval + 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 diff --git a/test/output.go b/test/output.go index caedf3fc..c56a46e9 100644 --- a/test/output.go +++ b/test/output.go @@ -446,9 +446,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" text: "duplicates", expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +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" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" a=1 c=3 span="2122232425262728" d=4 `, }, } diff --git a/test/zapr.go b/test/zapr.go index bc9e03ab..1e669fa5 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -275,9 +275,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +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" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +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} @@ -383,9 +383,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +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" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +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} From 662c5da54af7e5c8d6894712195b9f225d22616c Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 21 Nov 2024 18:01:43 +0100 Subject: [PATCH 9/9] simplify de-duplication code This is a follow-up which removes several functions which don't provide enough additional value anymore. This wasn't done earlier to keep the previous commits simple. --- internal/serialize/keyvalues.go | 28 ++++------------------------ internal/serialize/keyvalues_test.go | 2 +- klog.go | 5 +++-- klogr_slog.go | 5 +++-- ktesting/testinglogger.go | 7 ++++--- textlogger/textlogger.go | 5 +++-- 6 files changed, 18 insertions(+), 34 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index af35211a..9c3858ec 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -58,35 +58,15 @@ type Formatter struct { 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{}) { - f.formatKVs(b, first, second) -} - -func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { - Formatter{}.MergeAndFormatKVs(b, first, second) -} - const missingValue = "(MISSING)" -// 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{}) { - f.formatKVs(b, keysAndValues) -} - -func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { - Formatter{}.KVListFormat(b, keysAndValues...) -} - -func KVFormat(b *bytes.Buffer, k, v interface{}) { - Formatter{}.KVFormat(b, k, v) +func FormatKVs(b *bytes.Buffer, kvs ...[]interface{}) { + Formatter{}.FormatKVs(b, kvs...) } -// formatKVs formats all key/value pairs such that the output contains no +// 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{}) { +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. diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index 07ac25fd..772577d2 100644 --- a/internal/serialize/keyvalues_test.go +++ b/internal/serialize/keyvalues_test.go @@ -184,7 +184,7 @@ 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) } 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_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/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') }