Deferred evaluation of github.com/rs/zerolog Fields

Question

Introduction

zerolog fields

I'm using github.com/rs/zerolog in my golang project.

I know that I can add fields to the output by using something like this:

package main

import (
    "os"

    "github.com/rs/zerolog"
)

func main() {
    logger := zerolog.New(os.Stderr).With().Timestamp().Logger()
    logger.Int("myIntField", 42)
    logger.Info("a regular log output") // this log entry will also contain the integer field `myIntField`
}

But what I would like to have is something evaluates at runtime of the line logger.Info("a regular log output") what the value of a field myIntField is.

The setting

I have a producer/consumer setup (for example see https://goplay.tools/snippet/hkoMAwqKcwj) with go-routines and I have two integers that are atomically counted down the number of consumer and producer go-routines still in business. Upon tear down of the consumer and producer I want to display these numbers at runtime.

Here's the code when using log instead of zerolog:

package main

import (
    "fmt"
    "log"
    "os"
    "sync"
    "sync/atomic"
)

func main() {
    numProducers := int32(3)
    numConsumers := int32(3)

    producersRunning := numProducers
    consumersRunning := numConsumers

    var wg sync.WaitGroup

    l := log.New(os.Stderr, "", 0)

    // producers
    for i := int32(0); i < numProducers; i++ {
        idx := i
        wg.Add(1)
        go (func() {
            // producer tear down
            defer func() {
                atomic.AddInt32(&producersRunning, -1)
                l.Printf("producer-%3d . producersRunning: %3d\n", idx, producersRunning)
                wg.Done()
            }()

            // this is where the actual producer works is happening
        })()
    }

    // consumers
    for i := int32(0); i < numConsumers; i++ {
        idx := i
        wg.Add(1)
        go (func() {
            // consumer tear down
            defer func() {
                atomic.AddInt32(&consumersRunning, -1)
                l.Printf("consumer-%3d . consumersRunning: %3d\n", idx, consumersRunning)
                wg.Done()
            }()

            // this is where the actual consumer works is happening
        })()
    }

    fmt.Println("waiting")
    wg.Wait()
}

It outputs something like this:

waiting
producer-  1 . producersRunning:   2
producer-  0 . producersRunning:   1
consumer-  1 . consumersRunning:   2
producer-  2 . producersRunning:   0
consumer-  2 . consumersRunning:   1
consumer-  0 . consumersRunning:   0

A logger per consumer / producer

With zerolog you can create loggers an pass them to each go-rountine:

logger := zerolog.New(os.Stderr)

go myConsumer(logger.With().Str("is", "consumer").Logger())
go myProducer(logger.With().Str("is", "producer").Logger())

Then you can easily find out in the logs if a message came from a consumer or a producer just by looking at the is field in each log line.

But what if I want to always print the number of currently active consumers/producers in each log line? You might be tempted to do something like this:

go myConsumer(logger.With().Str("is", "consumer").Int("consumersRunning", consumersRunning).Logger())
go myProducer(logger.With().Str("is", "producer").Int("producersRunning", producersRunning).Logger())

But of course, this will only print the momentary value of consumersRunning and producersRunning at the time of creating the go-routine. Instead I would like the log output to reflect the values at the time of the log output.

Summary

I hope my question is clear. I'm not sure if it is against the concept of zero-ness but a function like

func (e *Event) DeferredInt(key string, i func()int) *Event

would probably work, if only it existed.

Is there another way to achieve the same effect?

Potential workaround

I mean one way could be to replace the logger variable with a function call like this:

logFunc := func() zerolog.Logger {
  return logger.With().Int("runningConcumers", runningConsumers).Logger()
}

And then a log entry can be created with logFunc().Msg("hello"). This defers the evaluation of runningConsumers but also creates a logger for each log entry which feels like overkill.

By now I hope I haven't confused you.

Answer 1

You can add a hook. Hook is evaluated for each logging event

https://go.dev/play/p/Q7doafJGaeE

package main

import (
    "os"

    "github.com/rs/zerolog"
)

type IntHook struct {
    Count int
}

func (h *IntHook) Run(e *zerolog.Event, l zerolog.Level, msg string) {
    e.Int("count", h.Count)
    h.Count++
}

func main() {
    var intHook IntHook
    log := zerolog.New(os.Stdout).Hook(&intHook)

    log.Info().Msg("hello world")
    log.Info().Msg("hello world one more time")
}

Output is

{"level":"info","count":0,"message":"hello world"}
{"level":"info","count":1,"message":"hello world one more time"}

Pointer is required to save Count between calls to Hook.Run

May be for you a HookFunc is better. It is a stateless function that is called for each event. Here is an example of a function hook that calls PRNG for each message: https://go.dev/play/p/xu6aXpUmE0v

package main

import (
    "math/rand"
    "os"

    "github.com/rs/zerolog"
)

func RandomHook(e *zerolog.Event, l zerolog.Level, msg string) {
    e.Int("random", rand.Intn(100))
}

func main() {
    var randomHook zerolog.HookFunc = RandomHook
    log := zerolog.New(os.Stdout).Hook(randomHook)

    log.Info().Msg("hello world")
    log.Info().Msg("hello world one more time")
}

Output

{"level":"info","random":81,"message":"hello world"}
{"level":"info","random":87,"message":"hello world one more time"}