How to print global progress?

[ztj1993]

Is your feature request related to a problem? Please describe.

Suppose I have a progress field, which will be changed during the execution of my code.

code:

package main

import (
	"go.uber.org/zap"
	"time"
)

func getProgress() time.Time {
	return time.Now()
}

func main() {
	logger, _ := zap.NewProduction()
	sugar := logger.Sugar()
	sugar = sugar.With("progress", getProgress())
	sugar.Infow("log1")
	time.Sleep(time.Second * 2)
	sugar.Infow("log2")
}

output:

{"level":"info","ts":1657523104.5808382,"caller":"awesomeProject1/f.go:17","msg":"log1","progress":1657523104.5808382}
{"level":"info","ts":1657523106.5825582,"caller":"awesomeProject1/f.go:19","msg":"log2","progress":1657523104.5808382}

I want the progress parameter in with to be called when my log is actually printed. But I don't know how to deal with it.

I hope that every time I call log printing, progress will change. For example, I pass a callback function as a parameter.

I have considered solutions such as JSON encoder, but I am not familiar with golang. After investigation for a period of time, there is still no good solution.

[sywhang]

It's printing the same message because the getProgress got invoked once and once only when you sugared the logger with it.

This should give you what you were expecting to see:

package main

import (
	"time"

	"go.uber.org/zap"
)

func getProgress() time.Time {
	return time.Now()
}

func main() {
	logger, _ := zap.NewProduction()
	sugar := logger.Sugar()
	sugar.Infow("log1", "progress", getProgress())
	time.Sleep(time.Second * 2)
	sugar.Infow("log2", "progress", getProgress())
}

Prints:

{"level":"info","ts":1657562165.1191208,"caller":"zapq/main.go:16","msg":"log1","progress":1657562165.11912}
{"level":"info","ts":1657562167.120411,"caller":"zapq/main.go:18","msg":"log2","progress":1657562167.120376}

[ztj1993]

Thank you for your reply! This is really the result I want, but the way is not friendly. I need to print hundreds of logs, which is written in each log. It's a little bad.

[mway]

Quick meta note: zap's fields are intended to be (effectively) static once either (a) attached to a logger or (b) added as part of a log statement, both because the semantics of how/when fields are encoded aren't specified as part of the API, and because it would cause unpredictable behavior e.g. in the case of mutating logger-level fields.

Zap expects field values to be unchanged while it holds them. In the case of non-scalars – for example, zap.Strings(), zap.ByteString(), and various other []T- or any-style fields – Zap does not own those values, does not copy them for performance reasons, and they should not be changed once passed to Zap. It is an error to provide a mutable type to Zap as a field and then mutate it.

Edit:

To correct myself, both log methods (Logger.Info, etc) as well as Logger.With all immediately add any provided fields to the encoder, so mutability is a moot point without the ability to (intentionally, predictably) preempt the goroutine after e.g. Logger.Info is called but before the fields are added to the encoder (which I'd characterize as UB). It is not possible to modify logger-level fields (e.g. Logger.With) between log statements.

The reason for this is because encoding is a two-stage process: first, logger-level fields are encoded with the logger's core's encoder prior to returning the logger back to the user (modulo preemption). This encoder is not used directly for encoding log entries. Second, when writing out log entries, the core encoder is cloned, log-level (e.g. Logger.Info) fields are added to the clone, and the result is flushed to the output encoder (console encoder, json encoder, etc). All of this is to say: fields added to a logger are "resolved" immediately, and their encoding is essentially memoized for any logger calls, hence logger-level fields cannot be modified once added to the logger.

One idea that we've discussed a bit is the concept of "dynamic" fields, for example (pseudocode):

type DynamicField[T] struct {
  key    string
  getter func() T
  // ...
}

func DynamicField[T any](key string, fn func() T) DynamicField[T] {
  return DynamicField[T]{
    key:    key,
    getter: fn,
  }
}

func (f *DynamicField[T]) AddTo(enc ObjectEncoder) {
  // add f.key to enc with value from f.getter()
}

which would enable users to do things like,

func (a *App) getFooValue() string {
  a.mu.RLock()
  defer a.mu.RUnlock()
  return a.someDynamicStringValue
}

logger = logger.With(zap.DynamicField("foo", getFooValue))
logger.Info("hello world", zap.Int("bar", 123))
// -> msg="hello world" fields={"bar":123,"foo":"<current foo value at encoding time>"}

(Obviously this code won't work with zap's API, just used to illustrate the idea.)

The problem with this is that it introduces ambiguity around what value will be logged. Will the expected "current" value (at call time) be used? Will the value change (and potentially be incorrect) prior to encoding? Since the encoding pipeline is (somewhat) abstracted from users, there's no way for this to work deterministically without external synchronization, which would likely be brittle, complicated, and ruin performance.

So, even if we did add the concept of "dynamic" fields to Zap, users would need to be very careful about how they're used, and we would have limited ability to provide guardrails from them being misused. Arguably, they could introduce more problems than they'd solve (depending upon the implementation), so we'd need a compelling reason to add them instead of continuing to use "static" fields as we do now.

[ztj1993]

Dynamic fields are still necessary. For example, for my problem, I want to output the execution progress field in thousands of log lines.

I tried to implement pseudocode, but it didn't work.

[mway]

tl;dr - It's not possible to do what you're trying to do, and the caveats mentioned above would still apply (e.g. correctness, atomicity, predictability, etc), but you might want to check out gopatch to see if it can help you refactor things so you get the same effect with minimal effort.

Dynamic fields don't enable what you're trying to do, but I agree that with a large number of logger calls, it would be easier.

You could use a wrapper - something like:

func log(fn func(string, ...any), msg string, args ...any) {
  // Use a sync.Pool instead if performance-critical
  tmp := make([]any, len(args), len(args)+2)
  copy(tmp, args)
  tmp = append(tmp, "progress", getProgress())
  fn(msg, args...)
}

// Later...

log(logger.Infow, "doing something")
// -> {"level":"info","msg":"doing something","progress":123.456}

log(logger.Debugw, "doing something else", "another", "field")
// -> {"level":"debug","msg":"doing something else","another":"field","progress":456.789}

Or, alternatively, just use a field wrapper:

func fieldsWithProgress(args ...any) []any {
  tmp := make([]any, len(args), len(args)+2)
  copy(tmp, args)
  return append(tmp, "progress", getProgress())
}

// Later...

logger.Infow("doing something", fieldsWithProgress())
// -> {"level":"info","msg":"doing something","progress":123.456}

logger.Debugw("doing something else", fieldsWithProgress("another", "field"))
// -> {"level":"debug","msg":"doing something else","another":"field","progress":456.789}

But both of those probably require more work than simply explicitly adding the field to the callsites. You could wrap the logger to provide the field-adding functionality in order to avoid refactoring log callsites, but that's hacky and brittle and could cause maintenance pain.

All that said, gopatch might be able to help you out, so that you could update all of your callsites to one of the above solutions (add the field directly, or use one of the helpers) without needing to edit them manually.