Broken data and invalid json!

[Nikolo]

func main() {
    // Create main context
    ctx := context.Background()
        // Setup zerolog
    ctx = zlog.New(os.Stderr).With().Timestamp().Caller().Logger().Level(zlog.DebugLevel).WithContext(ctx)

    wg := sync.WaitGroup{}

    for f := 0; f < 500; f++ {
        wg.Add(1)

        // Create gorutine
        go func(log *zlog.Logger) {
            // Create gorutine context
            ctx := context.Background()

            // Add to context logger from main context
            ctx = log.WithContext(ctx)

            // Update logger in gorutine context 
            SetLogVar(ctx, uint64(41240000+rand.Intn(1000)), strings.Repeat("x", rand.Intn(12)))

            // Use logger
            zlog.Ctx(ctx).Debug().Msg("Test message")

            wg.Done()
        }(zlog.Ctx(ctx))
    }

    wg.Wait()
}

func SetLogVar(ctx context.Context, var1 uint64, var2 string) {
    zlog.Ctx(ctx).UpdateContext(func(c zlog.Context) zlog.Context {
        //In this case of update zlog in context zlog generate invalid data
        return c.Str("string", var2).Uint64("ID", var1)

        //In this case invalid data too but less often
        //return c.Uint64("ID", var1).Str("string", var2)
    })
}

Example wrong output:

{"level":"debug","string":"","ID":D":41240888,"time":"2022-09-30T22:21:47+03:00","message":"Test message"}
{"level":"debug","string":"xx","ID":412407,"time":"2022-09-30T22:21:47+03:00","message":"Test message"}
{"level":"debug","string":"xxxxx","ID":412401,"time":"2022-09-30T22:21:47+03:00","message":"Test message"}
{"level":"debug","string":"xxxxxxxx","ID":4124,"time":"2022-09-30T22:21:47+03:00","message":"Test message"}
{"level":"debug","string":"xxxxxx","ID":":41240405,"time":"2022-09-30T22:21:47+03:00","message":"Test message"}

Go playground link

[pscheid92]

Hello @Nikolo I tried to understand your issue, but I just don't get it. Could you add more information? What did you expect? What is the actual behaviour you see? Why is it wrong, in your opinion? 😇

[Nikolo]

Oh. I'm sorry. All json in exaples is broken... I expected to see the valid json. And I expect to see valid data in json, all ID must be more than 41240000.

[pscheid92]

💡 Now I got it and can reproduce it with your script.

I got somewhat garbled output like this, where symbols are totally out of place.

"string":"xxxxxxx,"I,"I41240731048,"time":
"xxxxxxxxx","ID":4,"time":"20

---

I tried running your example with just two log lines and activated race detection:

go run -race .                                                                                                                                    master-!?
==================
WARNING: DATA RACE
Write at 0x00c00014a001 by goroutine 7:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/string.go:46 +0xa8
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/base.go:18 +0x153
  github.com/rs/zerolog.Context.Str()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/context.go:77 +0x73
  main.SetLogVar.func1()
      /Projects/delegation_poker/main.go:62 +0xb7
  github.com/rs/zerolog.(*Logger).UpdateContext()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:288 +0x29d
  main.SetLogVar()
      /Projects/delegation_poker/main.go:60 +0x95
  main.main.func1()
      /Projects/delegation_poker/main.go:47 +0x14f
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Previous read at 0x00c00014a001 by goroutine 8:
  runtime.slicecopy()
      /Go/go1.19.2/src/runtime/slice.go:307 +0x0
  github.com/rs/zerolog/internal/json.Encoder.AppendObjectData()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/types.go:388 +0x4e8
  github.com/rs/zerolog.(*Logger).newEvent()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:459 +0x1d0
  github.com/rs/zerolog.(*Logger).Debug()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:326 +0x16d
  main.main.func1()
      /Projects/delegation_poker/main.go:50 +0x150
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Goroutine 7 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c

Goroutine 8 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c
==================
==================
WARNING: DATA RACE
Write at 0x00c00014a008 by goroutine 7:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/string.go:63 +0x2c8
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/base.go:18 +0x153
  github.com/rs/zerolog.Context.Str()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/context.go:77 +0x73
  main.SetLogVar.func1()
      /Projects/delegation_poker/main.go:62 +0xb7
  github.com/rs/zerolog.(*Logger).UpdateContext()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:288 +0x29d
  main.SetLogVar()
      /Projects/delegation_poker/main.go:60 +0x95
  main.main.func1()
      /Projects/delegation_poker/main.go:47 +0x14f
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Previous read at 0x00c00014a008 by goroutine 8:
  runtime.slicecopy()
      /Go/go1.19.2/src/runtime/slice.go:307 +0x0
  github.com/rs/zerolog/internal/json.Encoder.AppendObjectData()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/types.go:388 +0x4e8
  github.com/rs/zerolog.(*Logger).newEvent()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:459 +0x1d0
  github.com/rs/zerolog.(*Logger).Debug()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:326 +0x16d
  main.main.func1()
      /Projects/delegation_poker/main.go:50 +0x150
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Goroutine 7 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c

Goroutine 8 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c
==================
==================
WARNING: DATA RACE
Write at 0x00c00014a016 by goroutine 7:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/string.go:63 +0x2c8
  github.com/rs/zerolog.Context.Str()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/context.go:77 +0x1c4
  main.SetLogVar.func1()
      /Projects/delegation_poker/main.go:62 +0xb7
  github.com/rs/zerolog.(*Logger).UpdateContext()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:288 +0x29d
  main.SetLogVar()
      /Projects/delegation_poker/main.go:60 +0x95
  main.main.func1()
      /Projects/delegation_poker/main.go:47 +0x14f
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Previous read at 0x00c00014a010 by goroutine 8:
  runtime.slicecopy()
      /Go/go1.19.2/src/runtime/slice.go:307 +0x0
  github.com/rs/zerolog/internal/json.Encoder.AppendObjectData()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/types.go:388 +0x4e8
  github.com/rs/zerolog.(*Logger).newEvent()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:459 +0x1d0
  github.com/rs/zerolog.(*Logger).Debug()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:326 +0x16d
  main.main.func1()
      /Projects/delegation_poker/main.go:50 +0x150
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Goroutine 7 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c

Goroutine 8 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c
==================
==================
WARNING: DATA RACE
Write at 0x00c00014a018 by goroutine 7:
  github.com/rs/zerolog/internal/json.Encoder.AppendString()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/string.go:46 +0xa8
  github.com/rs/zerolog/internal/json.Encoder.AppendKey()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/base.go:18 +0x136
  github.com/rs/zerolog.Context.Uint64()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/context.go:290 +0x56
  main.SetLogVar.func1()
      /Projects/delegation_poker/main.go:62 +0x131
  github.com/rs/zerolog.(*Logger).UpdateContext()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:288 +0x29d
  main.SetLogVar()
      /Projects/delegation_poker/main.go:60 +0x95
  main.main.func1()
      /Projects/delegation_poker/main.go:47 +0x14f
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Previous write at 0x00c00014a018 by goroutine 8:
  runtime.slicecopy()
      /Go/go1.19.2/src/runtime/slice.go:307 +0x0
  strconv.formatBits()
      /Go/go1.19.2/src/strconv/itoa.go:196 +0x26d
  strconv.AppendUint()
      /Go/go1.19.2/src/strconv/itoa.go:54 +0x1a4
  github.com/rs/zerolog/internal/json.Encoder.AppendUint64()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/internal/json/types.go:281 +0x19e
  github.com/rs/zerolog.Context.Uint64()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/context.go:290 +0x56
  main.SetLogVar.func1()
      /Projects/delegation_poker/main.go:62 +0x131
  github.com/rs/zerolog.(*Logger).UpdateContext()
      /Go/pkg/mod/github.com/rs/zerolog@v1.28.0/log.go:288 +0x29d
  main.SetLogVar()
      /Projects/delegation_poker/main.go:60 +0x95
  main.main.func1()
      /Projects/delegation_poker/main.go:47 +0x14f
  main.main.func2()
      /Projects/delegation_poker/main.go:53 +0x47

Goroutine 7 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c

Goroutine 8 (running) created at:
  main.main()
      /Projects/delegation_poker/main.go:39 +0x65c
==================
{"level":"debug","string":"xxx","ID":41240081,"time":"2022-10-08T13:04:32+02:00","caller":"/Projects/delegation_poker/main.go:50","message":"Test message"}
{"level":"debug","string":"xxxxxxxxxxx","ID":41240847,"time":"2022-10-08T13:04:32+02:00","caller":"/Projects/delegation_poker/main.go:50","message":"Test message"}
Found 4 data race(s)
exit status 66

[pscheid92]

I dug into your example, and I think I now understand what is happening.

You share the one logger created in main() with several hundred goroutines. Those concurrently write/change data in the logger's context without synchronisation. Thus, data races occur, which leads to garbled output.

The documentation of UpdateContext states that it should be used with caution:

Use this method with caution. If unsure, prefer the With method.

Perhaps creating child loggers with With would be better? This depends on your specific use case. Maybe something like this:

go func(log *zlog.Logger) {
    var1 := uint64(41240000 + rand.Intn(1000))
    var2 := strings.Repeat("x", rand.Intn(12))

    localLogger := log.With().
        Str("string", var2).
        Uint64("ID", var1).
        Logger()

    ctx := localLogger.WithContext(context.Background())

    zlog.Ctx(ctx).Debug().Msg("Test message")

    wg.Done()
}(zlog.Ctx(ctx))

[rs]

A Logger is not thread safe. Pass copies and not a pointer to goroutines.

[Nikolo]

But I'm creating new context as context.Background and associate with him a logger. And I expect that UpdateContext will update new context instance. How I can copy logger instance before create gorutine?

[rs]

You don't need context:

func main() {
        // Setup zerolog
    logger = zlog.New(os.Stderr).With().Timestamp().Caller().Logger().Level(zlog.DebugLevel)

    wg := sync.WaitGroup{}

    for f := 0; f < 500; f++ {
        wg.Add(1)

        // Create gorutine
        go func(logger zlog.Logger) {
            // Update logger in gorutine context 
            logger  = SetLogContext(logger, uint64(41240000+rand.Intn(1000)), strings.Repeat("x", rand.Intn(12)))

            // Use logger
            logger.Debug().Msg("Test message")

            wg.Done()
        }(logger)
    }

    wg.Wait()
}

func SetLogContext(logger zlog.Logger, var1 uint64, var2 string) {
    return logger.With().Str("string", var2).Uint64("ID", var1).Logger()
}

[Nikolo]

But what if I have many functions that call each other and only the first function add to logger any variable? Should I pass logger through all functions?

func FirstFunc() {
    logger  = SetLogContext(logger, uint64(41240000+rand.Intn(1000)), strings.Repeat("x", rand.Intn(12)))
    SecondFunc(logger)
}

func SecondFunc(logger *zerolog.Logger) {
    // Use logger
    logger.Debug().Msg("Test message from SecondFunc")

    AnotherFunc(logger)
} 

func AnotherFunc(logger *zerolog.Logger) {
    // Use logger
    logger.Debug().Msg("Test message from AnotherFunc")
}

[sdavispluto]

My teammates and I experienced the same problem and independently arrived at the same solution before I found this issue report. We are happy calling .With() to create a child logger before setting any fields from within a child goroutine. However, in order to diagnose the problem and arrive at this solution, we found it necessary to trace the zerolog library using a debugger.

I feel it shouldn't be necessary to browse the issues reports or use a debugger to learn the proper use of this library with concurrency. Would it be possible to add a note about this to the README to assist future users?

[sruehl]

A Logger is not thread safe. Pass copies and not a pointer to goroutines.

@rs short question: How is it then safe to use the global Logger? (e.g. log.Debug() from "github.com/rs/zerolog/log")

[rs]

@sruehl You always get a copy of the logger. It can’t be change underneath you. When stored in a context, it is stored as a pointer so you can update the logger. It was probably a design mistake on my part.

[sdavispluto]

In the case of the OP's code sample, goroutines and pointers were created directly.

In my particular case, neither pointers nor goroutines were directly used. From within a request handler, it looked something like:

logger := log.Logger.Level(zerolog.InfoLevel)
logger.UpdateContext(...)

This seemed to be a perfectly reasonable thing to do. No pointers were created (directly) and no goroutines were created (directly). However:

1. UpdateContext uses a pointer receiver
2. The application framework was creating a new goroutine for each http request, thus there were concurrent goroutines

I noticed the following inside the godoc for UpdateContext:

Use this method with caution. If unsure, prefer the With method.

So actually, there is a warning about this. However, I was confused because the warning did not say specifically why caution is required, when not to use UpdateContext (or when it can be safely used), and what might go wrong otherwise.

I was wondering if it would be possible to make the warning in the godoc more specific, something like.

UpdateContext is not concurrency safe. Concurrent goroutines will overwrite a shared context. Use the With method to create a child logger before modifying the context from concurrent goroutines.

Updating the global logger from the main goroutine before starting any additional goroutines would be safe. I don't know if it's necessary to mention this in the documentation, though.

FYI, even if UpdateContext were to use a value receiver, I still don't think it would be adequate protection because value receivers only make a shallow copy, the specific implementation of adding fields uses append()to modify the Logger.context []byte, and append can modify the contents of the array in-place if sufficient capacity is allocated. However, With() makes a copy of the Logger.context []byte, which is complete protection.

[rs]

Good idea, feel free to open a PR.

[sdavispluto]

PR opened (see automated comment, above). Does someone have a chance to review it? Thanks!