🤗 [Question]: When use fiberzap with WithContext, caller maybe not show properly. How do I change it？

[0xmkzt]

Question Description

Run the code snippet, and the logging is as follows

{"level":"info","ts":1695283707.964828,"caller":"backend2/main.go:23","msg":">>>"}
{"level":"info","ts":1695283707.965184,"caller":"v2@v2.49.2/router.go:145","msg":"ready"}
{"level":"info","ts":1695283707.965214,"caller":"backend2/main.go:25","msg":"<<<"}

caller is v2@v2.49.2/router.go:145, but it is backend2/main.go:24 actually

Code Snippet (optional)

package main

import (
	"github.com/gofiber/contrib/fiberzap/v2"
	"github.com/gofiber/fiber/v2"
	"github.com/gofiber/fiber/v2/log"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	//setup.Init()

	app := fiber.New()
	log.SetLogger(fiberzap.NewLogger(fiberzap.LoggerConfig{
		ZapOptions: []zap.Option{
			zap.AddCaller(),
			zap.AddCallerSkip(3),
			zap.AddStacktrace(zapcore.PanicLevel),
		},
	}))
	app.Get("/ready", func(c *fiber.Ctx) error {
		log.Info(">>>")
		log.WithContext(c.UserContext()).Info("ready")
		log.Info("<<<")
		return c.SendString("ready")
	})
	err := app.Listen(":3000")
	if err != nil {
		log.Error(err)
		return
	}
}

Checklist:

• I agree to follow Fiber's Code of Conduct.
• I have checked for existing issues that describe my questions prior to opening this one.
• I understand that improperly formatted questions may be closed without explanation.

[ReneWerner87]

without the fiber logger wrapper it is working

package main

import (
	"github.com/gofiber/contrib/fiberzap/v2"
	"github.com/gofiber/fiber/v2"
	"github.com/gofiber/fiber/v2/log"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

func main() {
	//setup.Init()

	app := fiber.New()
	zap := fiberzap.NewLogger(fiberzap.LoggerConfig{
		ZapOptions: []zap.Option{
			zap.AddCaller(),
			zap.AddCallerSkip(2),
			zap.AddStacktrace(zapcore.PanicLevel),
		},
	})
	app.Get("/ready", func(c *fiber.Ctx) error {
		zap.Info(">>>")
		zap.WithContext(c.UserContext()).Info("ready")
		zap.Info("<<<")
		return c.SendString("ready")
	})
	err := app.Listen(":3000")
	if err != nil {
		log.Error(err)
		return
	}
}

{"level":"info","ts":1695285876.640757,"caller":"testGo/main.go:23","msg":">>>"}
{"level":"info","ts":1695285876.6409469,"caller":"testGo/main.go:24","msg":"ready"}
{"level":"info","ts":1695285876.640969,"caller":"testGo/main.go:25","msg":"<<<"}

@Skyenought do you have an idea, why the wrapper function is shifting the outside caller level?

https://github.com/gofiber/fiber/blob/e547bea49e19984fddd1131332d43db092b1f58e/log/fiberlog.go#L120-L122

with skip 2

	log.SetLogger(fiberzap.NewLogger(fiberzap.LoggerConfig{
		ZapOptions: []zap.Option{
			zap.AddCaller(),
			zap.AddCallerSkip(2),
			zap.AddStacktrace(zapcore.PanicLevel),
		},
	}))
	app.Get("/ready", func(c *fiber.Ctx) error {
		log.Info(">>>")
		log.WithContext(c.UserContext()).Info("ready")
		log.Info("<<<")
		return c.SendString("ready")
	})

{"level":"info","ts":1695286200.526693,"caller":"log/fiberlog.go:25","msg":">>>"}
{"level":"info","ts":1695286200.526879,"caller":"testGo/main.go:24","msg":"ready"}
{"level":"info","ts":1695286200.526884,"caller":"log/fiberlog.go:25","msg":"<<<"}

[0xmkzt]

@ReneWerner87 thank you!
If use fiber log directly, it will be more perfect

[0xmkzt]

@ReneWerner87 It's still a problem if use fiber log directly when use WithContext.

package main

import (
	"github.com/gofiber/fiber/v2"
	"github.com/gofiber/fiber/v2/log"
)

func main() {
	//setup.Init()

	app := fiber.New()
	app.Get("/ready", func(c *fiber.Ctx) error {
		log.Info(">>>")
		log.WithContext(c.UserContext()).Info("ready")
		log.Info("<<<")
		return c.SendString("ready")
	})
	err := app.Listen(":3000")
	if err != nil {
		log.Error(err)
		return
	}

	log.Info("Exit.")
}

curl -i http://127.0.0.1:3000/ready Output:

2023/09/25 10:56:05.581632 main.go:13: [Info] >>>
2023/09/25 10:56:05.581965 router.go:145: [Info] ready
2023/09/25 10:56:05.581970 main.go:15: [Info] <<<