Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Using global logger fails to bind values causing incorrect context values #3417

Open
jatinrungtaallen opened this issue Sep 6, 2024 · 3 comments · May be fixed by #3420
Open

Using global logger fails to bind values causing incorrect context values #3417

jatinrungtaallen opened this issue Sep 6, 2024 · 3 comments · May be fixed by #3420
Labels
bug Something isn't working

Comments

@jatinrungtaallen
Copy link

What happened:

Using a global logger fails to output correct values from the context. It instead creates a background context and fills data with empty values

What you expected to happen:

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

Because the global logger is of type loggerAppliance, using WithContext causes it to return a new instance without prefix and kvs. This causes the code to not bind values and causes the downstream logger to not have context

image

image
image

Anything else we need to know?:

Environment:

  • Kratos version (use kratos -v):
  • Go version (use go version):
  • OS (e.g: cat /etc/os-release):
  • Others:
@jatinrungtaallen jatinrungtaallen added the bug Something isn't working label Sep 6, 2024
@kvii
Copy link
Contributor

kvii commented Sep 11, 2024

提供一下最小复现呗?最小复现不是指几张截图,而是一个能完全运行的例子。你可以像这样操作:

  1. 创建一个空的 go 项目。只导入 kratos 之类的必要的依赖项
  2. 在 main 方法里用你的方式创建一个 logger。调用这个 logger 的方法,传入你准备的参数。其他和问题无关的代码一行都不要留
  3. 在注释里讲清楚你期望什么结果,实际上的结果是什么。
  4. 最后把 main.go 的源码贴到 github 上来,方便别人复制后在本地运行。

比如说这就是一个最小复现:

package main

import (
	"context"

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

func main() {
	ctx := context.Background()
	ctx = context.WithValue(ctx, traceIdKey{}, "123456")

	global := log.GetLogger()
	logger := log.WithContext(ctx, global)
	// logger = log.With(logger, "traceId", TraceIdValue()) // 看后面的说明
	helper := log.NewHelper(logger)

	helper.Infow("msg", "用户登录", "user", "张三")

	// 期望输出
	// INFO traceId=123456 msg=用户登录 user=张三
	// 实际输出
	// INFO msg=用户登录 user=张三
}

type traceIdKey struct{}

// 看后面的说明
func TraceIdValue() log.Valuer {
	return func(ctx context.Context) any {
		return ctx.Value(traceIdKey{})
	}
}

这只是个例子。如果这个例子刚好能反映你的情况的话。那么问题就简单了。log 库并没有“能把 context 里所有 value 都打印出来” 的能力。想要从 context 里拿数据打印需要自己实现 logger 或者 valuer。比如例子中的 TraceIdValue 就实现了从 context 中提取 trace id 的功能。

@urdarinda
Copy link

@kvii
I have reproduced it below

package main

import (
	"context"

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

func main() {
	ctx := context.Background()
	ctx = context.WithValue(ctx, traceIdKey{}, "123456")


	logger := log.DefaultLogger
	newLogger := log.With(logger, "traceId", TraceIdValue())

	log.SetLogger(newLogger) // setting logger with valuer as global

	helper := log.NewHelper(newLogger)

	helper.WithContext(ctx).Info("This prints the traceID correctly")


	globalLogger := log.NewHelper(log.GetLogger()) // getting the global logger

	globalLogger.WithContext(ctx).Info("This does not print the traceID")

	// INFO traceId=123456 msg=This prints the traceID correctly
	// INFO traceId=<nil> msg=This does not print the traceID
}

type traceIdKey struct{}

func TraceIdValue() log.Valuer {
	return func(ctx context.Context) any {
		return ctx.Value(traceIdKey{})
	}
}

@kvii
Copy link
Contributor

kvii commented Sep 12, 2024

中文省流:因为 log.GetLogger return 的不是 log.SetLogger 存进去的那个 logger。所以导致 log.WithContext 合并 logger 的时候出了问题。最终导致底层的 log.Valuer 取数的时候拿不到 with 的那个 context。解决方案是让 log.GetLogger 返回存进去的那个 logger。

English version:
A minimal reproduce for this issue:

package main

import (
	"context"
	"os"

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

func main() {
	l1 := log.NewStdLogger(os.Stderr)            // *log.stdLogger
	l2 := log.With(l1, "traceId", traceIdValuer) // *log.logger ctx=Background

	log.SetLogger(l2)     // log.global.Logger = l2
	l3 := log.GetLogger() // log.global not l2 *log.loggerAppliance

	ctx := context.TODO()
	ctx = context.WithValue(ctx, traceIdKey{}, "123456")

	// log.WithContext(ctx,l) only "merge" ctx when l is a *log.logger.
	// and l3 is not.
	l4 := log.WithContext(ctx, l3) // *log.logger (not l2) ctx=ctx
	l4.Log(log.LevelInfo, "msg", "m")

	// want:
	// INFO traceId=123456 msg=m
	// got:
	// INFO traceId=<nil> msg=m

	// solution: Let log.global be a place that only stores values, rather than a Logger.
}

type traceIdKey struct{}

var traceIdValuer log.Valuer = func(ctx context.Context) any {
	return ctx.Value(traceIdKey{})
}

Currently log.SetLogger sets the logger to log.global.Logger. But log.SetLogger returns log.global, not log.global.Logger.
And log.WithContext or log.Helper.WithContext only "merge" context when the parameter is *log.logger.
So the logger that log.GetLogger returned can't be "merged".

kratos/log/global.go

Lines 10 to 39 in 908e625

// globalLogger is designed as a global logger in current process.
var global = &loggerAppliance{}
// loggerAppliance is the proxy of `Logger` to
// make logger change will affect all sub-logger.
type loggerAppliance struct {
lock sync.Mutex
Logger
}
func init() {
global.SetLogger(DefaultLogger)
}
func (a *loggerAppliance) SetLogger(in Logger) {
a.lock.Lock()
defer a.lock.Unlock()
a.Logger = in
}
// SetLogger should be called before any other log call.
// And it is NOT THREAD SAFE.
func SetLogger(logger Logger) {
global.SetLogger(logger)
}
// GetLogger returns global logger appliance as logger in current process.
func GetLogger() Logger {
return global
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants