Deferred evaluation of github.com/rs/zerolog Fields

<!-- language-all: lang-go -->

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.

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"}

You can use a zerolog Hook to achieve this. Hooks are interfaces with a Run method which is called before the event data is written to the given io.Writer (in your case os.Stderr).

Here is some example code:

type counter struct {
    name string
    value int32
}

func (c *counter) inc() { atomic.AddInt32(&c.value, 1) }
func (c *counter) dec() { atomic.AddInt32(&c.value, -1) }
func (c *counter) get() { atomic.LoadInt32(&c.value) }

func (c *counter) Run(e *zerolog.Event, _ zerolog.Level, _ string) {
    e.Int32(c.name, c.get())
}

int main() {
    numConsumers, numProducers := 3, 3

    consumersRunning := &counter{
        name: "consumersRunning",
        value: int32(numConsumers),
    }
    producersRunning := &counter{
        name: "producersRunning",
        value: int32(numProducers),
    }
    
    logger := zerolog.New(os.Stderr)
    consumerLogger := logger.With().Str("is", "consumer").Logger().Hook(consumersRunning)
    producerLogger := logger.With().Str("is", "producer").Logger().Hook(producersRunning)

    // your other code
}

You will use the inc and dec methods of the counters to modify the numbers of consumers/producers running.