log filter generates race alarm

[chadlwm]

What happened:

使用log filter时产生race告警

// Log Print log by level and keyvals.
func (f *Filter) Log(level Level, keyvals ...interface{}) error {
    if level < f.level {
        return nil
    }
    // prefixkv contains the slice of arguments defined as prefixes during the log initialization
    var prefixkv []interface{}
    l, ok := f.logger.(*logger)
    if ok {
        l.ctx = f.ctx  // 并发写时，会触发竞争
    }

       ...
}

What you expected to happen:

log filter中对ctx的赋值，未添加所，多个go routine访问时会产生竞争

How to reproduce it (as minimally and precisely as possible):

在main.go logger := log.NewFilter(logger, log.FilterLevel(log.ParseLevel("info")))

在多个server中使用logger： log.NewHelper(logger)

build with -race mkdir -p app/ && go build -race --trimpath -v -ldflags "-X main.Version=$(VERSION)" -o ./app/ ./...

启动 ./app/xxxxx -conf configs

日志warning:

================== WARNING: DATA RACE Write at 0x00c00012a6b0 by goroutine 30: github.com/go-kratos/kratos/v2/log.(Filter).Log() github.com/go-kratos/kratos/v2@v2.6.3/log/filter.go:74 +0x10d github.com/go-kratos/kratos/v2/log.Infof() github.com/go-kratos/kratos/v2@v2.6.3/log/global.go:73 +0x189 github.com/go-kratos/kratos/v2/transport/grpc.(Server).Start() github.com/go-kratos/kratos/v2@v2.6.3/transport/grpc/server.go:205 +0x104 github.com/go-kratos/kratos/v2.(App).Run.func2() github.com/go-kratos/kratos/v2@v2.6.3/app.go:112 +0x81 golang.org/x/sync/errgroup.(Group).Go.func1() golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x82

Previous write at 0x00c00012a6b0 by goroutine 35: github.com/go-kratos/kratos/v2/log.(Filter).Log() github.com/go-kratos/kratos/v2@v2.6.3/log/filter.go:74 +0x10d github.com/go-kratos/kratos/v2/log.(logger).Log() github.com/go-kratos/kratos/v2@v2.6.3/log/log.go:30 +0x242 github.com/go-kratos/kratos/v2/log.(Helper).Infof() github.com/go-kratos/kratos/v2@v2.6.3/log/helper.go:96 +0x192 linkage-signal-service/internal/server.(CS104SingleServer).Start.func1() xxxxxx/internal/server/cs104_single.go:72 +0x14b

Goroutine 30 (running) created at: golang.org/x/sync/errgroup.(Group).Go() golang.org/x/sync@v0.3.0/errgroup/errgroup.go:72 +0x12e github.com/go-kratos/kratos/v2.(App).Run() github.com/go-kratos/kratos/v2@v2.6.3/app.go:110 +0x319 main.main() xxxxxx/cmd/xxxxxx/main.go:94 +0xafa

Goroutine 35 (running) created at: xxxxxx/internal/server.(CS104SingleServer).Start() xxxxxx/internal/server/cs104_single.go:68 +0x8e github.com/go-kratos/kratos/v2.(App).Run.func2() github.com/go-kratos/kratos/v2@v2.6.3/app.go:112 +0x81 golang.org/x/sync/errgroup.(*Group).Go.func1() golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x82

Anything else we need to know?:

Environment:

• Kratos version (use kratos -v): kratos version v2.6.3
• Go version (use go version): go version go1.20.3 linux/amd64
• OS (e.g: cat /etc/os-release): ubuntu 16.04.7 LTS (Xenial Xerus)
• Others:

[kvii]

A minimal reproduce:

package main

import (
    "io"
    "sync"

    "github.com/go-kratos/kratos/v2/log"
)

func main() {
    l := log.With(log.NewStdLogger(io.Discard))
    l = log.NewFilter(l)

    var wg sync.WaitGroup
    for i := 0; i < 3; i++ {
        wg.Add(1)
        go func() { defer wg.Done(); l.Log(log.LevelInfo, "a") }()
    }
    wg.Wait()
}

output:

$ go run -race .

==================
WARNING: DATA RACE
Write at 0x00c000108070 by goroutine 8:
  github.com/go-kratos/kratos/v2/log.(*Filter).Log()
      /Users/kvii/go/pkg/mod/github.com/go-kratos/kratos/v2@v2.7.0/log/filter.go:74 +0xcc
  main.main.func1()
      /Users/kvii/Documents/workspace/qs/go/playground/main.go:17 +0xd8

Previous write at 0x00c000108070 by goroutine 6:
  github.com/go-kratos/kratos/v2/log.(*Filter).Log()
      /Users/kvii/go/pkg/mod/github.com/go-kratos/kratos/v2@v2.7.0/log/filter.go:74 +0xcc
  main.main.func1()
      /Users/kvii/Documents/workspace/qs/go/playground/main.go:17 +0xd8

Goroutine 8 (running) created at:
  main.main()
      /Users/kvii/Documents/workspace/qs/go/playground/main.go:17 +0x144

Goroutine 6 (running) created at:
  main.main()
      /Users/kvii/Documents/workspace/qs/go/playground/main.go:17 +0x144
==================
Found 1 data race(s)
exit status 66

[dosubot[bot]]

Hi, @chadlwm,

I'm helping the Kratos team manage their backlog and am marking this issue as stale. The issue was raised by you regarding a race condition in the log filter of Kratos v2.6.3. User @kvii provided a minimal reproduction of the issue, and you acknowledged it with a thumbs-up reaction. As of now, the issue remains unresolved.

Could you please confirm if this issue is still relevant to the latest version of the Kratos repository? If it is, kindly let the Kratos team know by commenting on the issue. Otherwise, feel free to close the issue yourself, or it will be automatically closed in 7 days.

Thank you for your understanding and cooperation.

[kvii]

Bug has fixed at #3069. @chadlwm You can try it with my previous comment, then close this issue.

[dosubot[bot]]

@shenqidebaozi, could you please assist with the issue raised by @chadlwm regarding the race condition in the log filter of Kratos v2.6.3? User @kvii mentioned that the bug has been fixed at #3069, and @chadlwm is advised to try it with the previous comment and then close the issue. Thank you!