Repository: go-kratos/kratos (go)

Issue:
The trace_id between requests is getting mixed up
#### What happened:

The trace_id between requests is getting mixed up.

#### What you expected to happen:

The `trace_id` between requests is independent.

#### How to reproduce it (as minimally and precisely as possible):

Use a `log.Filter` as the global logger 
and enable both `tracing.Server()` and `logging.Server()` middlewares.

#### Anything else we need to know?:

this is cauased by `log.WithContext()`.

https://github.com/go-kratos/kratos/blob/6cdd81811e102620ec93b125ea6ed38f06a5e03c/log/log.go#L65

#### Environment:

- Kratos version (use `kratos -v`): v2.6.3
- Go version (use `go version`): 1.20


Pull request:
fix(log): `WithContext()` changed the ctx field of the parent log.Filter

#### Description (what this PR does / why we need it):

Fix the concurrent problem of `log.WithContext()` function.

#### Which issue(s) this PR fixes (resolves / be part of):

Fix #3061 

#### Other special notes for the reviewers:



Patch:
diff --git a/.golangci.yml b/.golangci.yml
index b38bf368..556fcfbc 100644
--- a/.golangci.yml
+++ b/.golangci.yml
@@ -29,6 +29,7 @@ linters:
     - whitespace
     - wastedassign
     - unconvert
+    - misspell
 
   # don't enable:
   # - asciicheck
@@ -66,3 +67,5 @@ linters-settings:
     min-complexity: 50
   goimports:
     local-prefixes: github.com/go-kratos # Put imports beginning with prefix after 3rd-party packages
+  misspell: # Finds commonly misspelled English words in comments
+    locale: US
diff --git a/cmd/kratos/go.mod b/cmd/kratos/go.mod
index 0f7bf1bb..64d03ae4 100644
--- a/cmd/kratos/go.mod
+++ b/cmd/kratos/go.mod
@@ -19,7 +19,7 @@ require (
 	github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
 	github.com/stretchr/testify v1.7.0 // indirect
-	golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f // indirect
+	golang.org/x/sys v0.1.0 // indirect
 	golang.org/x/term v0.0.0-20210927222741-03fcf44c2211 // indirect
 	gopkg.in/yaml.v3 v3.0.0 // indirect
 )
diff --git a/cmd/kratos/go.sum b/cmd/kratos/go.sum
index 182fe6a2..df2fa0e5 100644
--- a/cmd/kratos/go.sum
+++ b/cmd/kratos/go.sum
@@ -60,6 +60,8 @@ golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f h1:v4INt8xihDGvnrfjMDVXGxw9wrfxYyCjk0KbXjhR55s=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.1.0 h1:kunALQeHf1/185U1i0GOB/fy1IPRDDpuoOOqRReG57U=
+golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211 h1:JGgROgKl9N8DuW20oFS5gxc+lE67/N3FcwmBPMe7ArY=
 golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8=
diff --git a/contrib/registry/discovery/impl_discover.go b/contrib/registry/discovery/impl_discover.go
index fb1b01d1..38b1fc5c 100644
--- a/contrib/registry/discovery/impl_discover.go
+++ b/contrib/registry/discovery/impl_discover.go
@@ -64,7 +64,7 @@ func (w *watcher) Next() ([]*registry.ServiceInstance, error) {
 	case <-event:
 	// change event come
 	case <-w.cancelCtx.Done():
-		return nil, fmt.Errorf("watch context cancelled: %v", w.cancelCtx.Err())
+		return nil, fmt.Errorf("watch context canceled: %v", w.cancelCtx.Err())
 	}
 
 	ctx, cancel := context.WithTimeout(context.TODO(), 15*time.Second)
diff --git a/log/filter.go b/log/filter.go
index 7ef96655..993fa926 100644
--- a/log/filter.go
+++ b/log/filter.go
@@ -1,7 +1,5 @@
 package log
 
-import "context"
-
 // FilterOption is filter option.
 type FilterOption func(*Filter)
 
@@ -41,7 +39,6 @@ func FilterFunc(f func(level Level, keyvals ...interface{}) bool) FilterOption {
 
 // Filter is a logger filter.
 type Filter struct {
-	ctx    context.Context
 	logger Logger
 	level  Level
 	key    map[interface{}]struct{}
@@ -70,9 +67,6 @@ func (f *Filter) Log(level Level, keyvals ...interface{}) error {
 	// 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
-	}
 	if ok && len(l.prefix) > 0 {
 		prefixkv = make([]interface{}, 0, len(l.prefix))
 		prefixkv = append(prefixkv, l.prefix...)
diff --git a/log/log.go b/log/log.go
index 38cef805..b3c34d37 100644
--- a/log/log.go
+++ b/log/log.go
@@ -50,28 +50,16 @@ func With(l Logger, kv ...interface{}) Logger {
 // WithContext returns a shallow copy of l with its context changed
 // to ctx. The provided ctx must be non-nil.
 func WithContext(ctx context.Context, l Logger) Logger {
-	c, ok := l.(*logger)
-	if ok {
-		return &logger{
-			logger:    c.logger,
-			prefix:    c.prefix,
-			hasValuer: c.hasValuer,
-			ctx:       ctx,
-		}
-	}
-
-	f, ok := l.(*Filter)
-	if ok {
-		f.ctx = ctx
-		return &Filter{
-			ctx:    ctx,
-			logger: f.logger,
-			level:  f.level,
-			key:    f.key,
-			value:  f.value,
-			filter: f.filter,
-		}
+	switch v := l.(type) {
+	default:
+		return &logger{logger: l, ctx: ctx}
+	case *logger:
+		lv := *v
+		lv.ctx = ctx
+		return &lv
+	case *Filter:
+		fv := *v
+		fv.logger = WithContext(ctx, fv.logger)
+		return &fv
 	}
-
-	return &logger{logger: l, ctx: ctx}
 }


Test patch:
diff --git a/contrib/metrics/prometheus/gauge_test.go b/contrib/metrics/prometheus/gauge_test.go
index 31744a5a..fdeb94e9 100644
--- a/contrib/metrics/prometheus/gauge_test.go
+++ b/contrib/metrics/prometheus/gauge_test.go
@@ -7,21 +7,21 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 )
 
-func TestGuage(t *testing.T) {
-	expect := `# HELP test_request_test_guage_metric test
-# TYPE test_request_test_guage_metric gauge
-test_request_test_guage_metric{code="test",kind="test",operation="test",reason="test"} %d
+func TestGauge(t *testing.T) {
+	expect := `# HELP test_request_test_gauge_metric test
+# TYPE test_request_test_gauge_metric gauge
+test_request_test_gauge_metric{code="test",kind="test",operation="test",reason="test"} %d
 `
 
 	guageVec := prometheus.NewGaugeVec(prometheus.GaugeOpts{
 		Namespace: "test",
-		Name:      "test_guage_metric",
+		Name:      "test_gauge_metric",
 		Subsystem: "request",
 		Help:      "test",
 	}, []string{"kind", "operation", "code", "reason"})
 
-	guage := NewGauge(guageVec)
-	guage.With("test", "test", "test", "test").Set(1)
+	gauge := NewGauge(guageVec)
+	gauge.With("test", "test", "test", "test").Set(1)
 
 	reg := prometheus.NewRegistry()
 	reg.MustRegister(guageVec)
@@ -35,7 +35,7 @@ test_request_test_guage_metric{code="test",kind="test",operation="test",reason="
 		t.Fatal("metrics error")
 	}
 
-	guage.With("test", "test", "test", "test").Add(1)
+	gauge.With("test", "test", "test", "test").Add(1)
 	result, err = gatherLatest(reg)
 	if err != nil {
 		t.Fatal(err)
@@ -44,7 +44,7 @@ test_request_test_guage_metric{code="test",kind="test",operation="test",reason="
 		t.Fatal("metrics error")
 	}
 
-	guage.With("test", "test", "test", "test").Sub(1)
+	gauge.With("test", "test", "test", "test").Sub(1)
 	result, err = gatherLatest(reg)
 	if err != nil {
 		t.Fatal(err)
diff --git a/contrib/registry/consul/registry_test.go b/contrib/registry/consul/registry_test.go
index 791c2efc..02b61720 100644
--- a/contrib/registry/consul/registry_test.go
+++ b/contrib/registry/consul/registry_test.go
@@ -333,7 +333,7 @@ func TestRegistry_Watch(t *testing.T) {
 			},
 		},
 		{
-			name: "ctx has been cancelled",
+			name: "ctx has been canceled",
 			args: args{
 				ctx:      canceledCtx,
 				cancel:   cancel,
diff --git a/log/filter_test.go b/log/filter_test.go
index 679fbe8c..8463a472 100644
--- a/log/filter_test.go
+++ b/log/filter_test.go
@@ -5,7 +5,9 @@ import (
 	"context"
 	"io"
 	"strings"
+	"sync"
 	"testing"
+	"time"
 )
 
 func TestFilterAll(_ *testing.T) {
@@ -172,3 +174,52 @@ func TestFilterWithContext(t *testing.T) {
 		t.Error("don't read ctx value")
 	}
 }
+
+type traceIDKey struct{}
+
+func setTraceID(ctx context.Context, tid string) context.Context {
+	return context.WithValue(ctx, traceIDKey{}, tid)
+}
+
+func traceIDValuer() Valuer {
+	return func(ctx context.Context) any {
+		if ctx == nil {
+			return ""
+		}
+		if tid := ctx.Value(traceIDKey{}); tid != nil {
+			return tid
+		}
+		return ""
+	}
+}
+
+func TestFilterWithContextConcurrent(t *testing.T) {
+	var buf bytes.Buffer
+	pctx := context.Background()
+	l := NewFilter(
+		With(NewStdLogger(&buf), "trace-id", traceIDValuer()),
+		FilterLevel(LevelInfo),
+	)
+
+	var wg sync.WaitGroup
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		time.Sleep(time.Second)
+		NewHelper(l).Info("done1")
+	}()
+
+	wg.Add(1)
+	go func() {
+		defer wg.Done()
+		tid := "world"
+		ctx := setTraceID(pctx, tid)
+		NewHelper((WithContext(ctx, l))).Info("done2")
+	}()
+
+	wg.Wait()
+	expected := "INFO trace-id=world msg=done2\nINFO trace-id= msg=done1\n"
+	if got := buf.String(); got != expected {
+		t.Errorf("got: %#v", got)
+	}
+}
diff --git a/log/log_test.go b/log/log_test.go
index 8221d9ef..7adbba8d 100644
--- a/log/log_test.go
+++ b/log/log_test.go
@@ -1,7 +1,6 @@
 package log
 
 import (
-	"context"
 	"testing"
 )
 
@@ -11,7 +10,3 @@ func TestInfo(_ *testing.T) {
 	logger = With(logger, "caller", DefaultCaller)
 	_ = logger.Log(LevelInfo, "key1", "value1")
 }
-
-func TestWithContext(_ *testing.T) {
-	WithContext(context.Background(), nil)
-}