go-kratos / kratos

Your ultimate Go microservices framework for the cloud-native era.
https://go-kratos.dev
MIT License
23.43k stars 4.01k forks source link

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

Closed jatinrungtaallen closed 4 weeks ago

jatinrungtaallen commented 2 months ago

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:

kvii commented 2 months ago

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

  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 commented 2 months ago

@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 commented 2 months ago

中文省流:因为 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".

https://github.com/go-kratos/kratos/blob/908e6256a9f60fd8d94d60c5e7bd5445515381b4/log/global.go#L10-L39

shenqidebaozi commented 4 weeks ago

3455

kratos-ci-bot commented 4 weeks ago

Bot detected the issue body's language is not English, translate it automatically. 👯👭🏻🧑‍🤝‍🧑👫🧑🏿‍🤝‍🧑🏻👩🏾‍🤝‍👨🏿👬🏿


3455