phuslu / log

Fastest structured logging
MIT License
672 stars 44 forks source link

`Fields` cause not expected caller value #84

Closed Dreamacro closed 2 months ago

Dreamacro commented 2 months ago

When Field is at the beginning of a chain call, the value of caller is not expected.

poc:

package main

import (
    "github.com/phuslu/log"
)

func main() {
    log.DefaultLogger = log.Logger{
        TimeFormat: "15:04:05",
        Caller:     1,
    }

    log.Info().Str("foo", "bar").Int("number", 42).Msg("hi, phuslog")

    fields := log.Fields{
        "foo": "bar",
    }

    log.Info().Fields(fields).Int("number", 42).Msg("hi, phuslog")
    log.Info().Int("number", 42).Fields(fields).Msg("hi, phuslog")
}

output:

> go run .
{"time":"21:45:01","level":"info","caller":"logpoc/main.go:13","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"21:45:01","level":"info","caller":"log@v1.0.107/logger.go:2280","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"21:45:01","level":"info","caller":"logpoc/main.go:20","goid":1,"number":42,"foo":"bar","message":"hi, phuslog"}
phuslu commented 2 months ago

Seems that I cannot repro this issue, see https://go.dev/play/p/ZOu6SPP5l67

And here're my local screenshot, image

Dreamacro commented 2 months ago

It looks like this is a problem only since go 1.23, I took go 1.22 and it didn't reproduce the situation

root in /mnt/mac/tmp/logpoc took 3s
# go version
go version go1.22.5 linux/arm64

root in /mnt/mac/tmp/logpoc
# go run .
{"time":"22:02:15","level":"info","caller":"logpoc/main.go:13","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"22:02:15","level":"info","caller":"logpoc/main.go:19","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"22:02:15","level":"info","caller":"logpoc/main.go:20","goid":1,"number":42,"foo":"bar","message":"hi, phuslog"}
/tmp/logpoc via go v1.23.0 took 1m27s
> go version
go version go1.23.0 darwin/arm64

/tmp/logpoc via go v1.23.0
> go run .
{"time":"22:02:40","level":"info","caller":"logpoc/main.go:13","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"22:02:40","level":"info","caller":"log@v1.0.107/logger.go:2280","goid":1,"foo":"bar","number":42,"message":"hi, phuslog"}
{"time":"22:02:40","level":"info","caller":"logpoc/main.go:20","goid":1,"number":42,"foo":"bar","message":"hi, phuslog"}
phuslu commented 2 months ago

Oh, reproduced. Let me try to fix it.

phuslu commented 2 months ago

Seems that go1.23 has an "improved" inlining mechanism in arm64, I disable it https://github.com/phuslu/log/commit/12d35e2e509470109392b85bc4dda604328e34a7

Would you please verify this code with go get -v github.com/phuslu/log@12d35e2e509470109392b85bc4dda604328e34a7, thanks!

Dreamacro commented 2 months ago

I confirmed that the new version doesn't have this problem anymore.

phuslu commented 2 months ago

thanks again. I tagged and released this master commit in v1.0.108

Due to this is an ad-hoc fix, let me keep this issue open, because it indicates a potential inline problem need to be confirm/investigated.

Dreamacro commented 2 months ago

Thanks for the timely response

phuslu commented 2 months ago

Totally fixed in v1.0.110 https://github.com/phuslu/log/commit/29412f8bb622c37fbb0bbb5f889599060407c236 , thanks.