zerolog icon indicating copy to clipboard operation
zerolog copied to clipboard

Is it possible to re-use a logger writers for a new logger\add a new output to an existing logger?

Open maxiride opened this issue 3 years ago • 10 comments

Thanks to the explanation in https://github.com/rs/zerolog/issues/361#issuecomment-924580003 the following is now not relevant. Please skip to https://github.com/rs/zerolog/issues/361#issuecomment-924623346


Down the line of execution I'd like to append a new log output to an existing logger. I've tried to play around with the following code and while the log messages are correctly redirected to all the writers a weird formatting happens.

Namely the new log events are logged with no level and with message the whole log message repeated as shown below.


I'm incline to think that I am missing something subtle in the zerolog package.

Example snippet https://play.golang.org/p/F7ofHBDVsLU:

func main() {
	consoleWriter := zerolog.ConsoleWriter{Out: os.Stdout}

	multi := zerolog.MultiLevelWriter(consoleWriter, os.Stdout)

	logger := zerolog.New(multi).With().Timestamp().Logger()

	logger.Info().Msg("INFO 1")


	multi2 := zerolog.MultiLevelWriter(logger, os.Stderr)

	logger = zerolog.New(multi2).With().Logger()

	logger.Info().Msg("INFO 2")

}

And its output:

INF INFO 1  <- correct output of consoleWriter
{"level":"info","message":"INFO 1"} <- correct output of os.Stdout

??? {"level":"info","message":"INFO 2"} <- weird output, should be the consoleWriter
{"message":"{\"level\":\"info\",\"message\":\"INFO 2\"}"} <- weird output, should be os.Stdout
{"level":"info","message":"INFO 2"} <- expected output os.Stderr

Expected output:


INF INFO 1  <- consoleWriter
{"level":"info","message":"INFO 1"} <- os.Stdout


INF INFO 2 <- consoleWriter
{"level":"info","message":"INFO 2"} <- os.Stdout
{"level":"info","message":"INFO 2"} <-  os.Stderr

maxiride avatar Sep 21 '21 13:09 maxiride

You have both stdout and stderr directed to your terminal with logs going to both at the same time so it gets mixed up.

rs avatar Sep 21 '21 13:09 rs

Indeed they all go the terminal, it was expected to get multiple times the same log event (INFO 1 and INFO 2) but what I am not understanding is that I expected the output to be:

FIRST LOG EVENT FIRED BY logger.Info().Msg("INFO 1")
INF INFO 1  <- correct output of consoleWriter
{"level":"info","message":"INFO 1"} <- correct output of os.Stdout

SECOND LOG EVENT FIRED BY logger.Info().Msg("INFO 2")
INF INFO 2 <- consoleWriter
{"level":"info","message":"INFO 2"} <- os.Stdout
{"level":"info","message":"INFO 2"} <-  os.Stderr

Notice how the posted output in the first comment encapsulate the os.Stdout\os.Stderr INFO 2 log event in a log event with no level and only message

Am I misunderstanding your explanation maybe? Thanks 🙏

I've updated the first comment with details.


I am incline to confirm that re-using a logger output causes the logger to wrongly handle the logging events.

Here I create a logger with output set as os.Stdout and later on I overwrite the logger with its clone and its output with a MultiLevelWriter which re-use the original logger output and adds a consoleWriter. However the new logger logs that are passed to the initial writer are logged with no level.

https://play.golang.org/p/I2afld8Mv-n

func main() {
	consoleWriter := zerolog.ConsoleWriter{Out: os.Stderr}
	consoleWriter.NoColor = true

	logger := zerolog.New(os.Stdout)
	logger.Info().Msg("INFO 1")

	multi := zerolog.MultiLevelWriter(logger, consoleWriter)

	logger = logger.Output(multi)
	logger.Info().Msg("INFO 2")

}
{"level":"info","message":"INFO 1"}
{"message":"{\"level\":\"info\",\"message\":\"INFO 2\"}"}
<nil> INF INFO 2

maxiride avatar Sep 21 '21 14:09 maxiride

You are using a logger as a io.Writer for another logger. When used as a io.Writer, whatever is written to the logger is wrapped into a structured log (see https://github.com/rs/zerolog/blob/master/log.go#L418). That's why you get the message generated by the second logger embedded as a json string in the message field of the first logger.

Note that you are not "re-using" a logger. Loggers aren't pointers so each logger is a copy.

rs avatar Sep 22 '21 04:09 rs

Thanks for the clarification on the internals of zerolog, it made it more clear.

So the questions I'm left with are:

  • is there a way to add a new output to an existing logger?
  • is there a way to create a new logger which uses the writers of a previously created logger (and possibly with new writers added to it?)

In both cases we don't have access to the writers used to create the loggers.

For instance:

  1. we create logger A with certain writers
  2. down the line we don't have access anymore to those writers (they are defined and passed to .New() elsewhere in the code)
  3. we want to add a new writer to A or use its writers to create a new logger B

maxiride avatar Sep 22 '21 06:09 maxiride

A writer will get Write calls with the JSON bytes of each event. If you want to add something to the even there, you would need to parse the JSON, alter it and remarshal it. That is what the console writer is doing and it is highly inefficient, but ok for console writer as it is for debug purpose only.

rs avatar Sep 22 '21 11:09 rs

I'm sorry but I'm getting confused, is there a way to create a new logger from an existing one and append a new writer or there isn't?

Please see my questions above:

So the questions I'm left with are:

  • is there a way to add a new output to an existing logger?
  • is there a way to create a new logger which uses the writers of a previously created logger (and possibly with new writers added to it?)

In both cases we don't have access to the writers used to create the loggers.

For instance:

  1. we create logger A with certain writers
  2. down the line we don't have access anymore to those writers (they are defined and passed to .New() elsewhere in the code)
  3. we want to add a new writer to A or use its writers to create a new logger B

maxiride avatar Sep 22 '21 12:09 maxiride

You can set a writer. This new writer can be a multi writer. You need to store the other writers if you want to append it, as a logger does not expose its internal writer.

rs avatar Sep 22 '21 12:09 rs

You need to store the other writers if you want to append it, as a logger does not expose its internal writer.

Ah that's it! So a logger writers can't be re-used elsewhere from where they have been defined if not stored somewhere. Thanks for the clarification!

I believe it might be a niche but it would be neat if there was a method to expose a logger writers to reuse them or have MultiLevelWriter append a logger writers to the newly passed writers.

maxiride avatar Sep 22 '21 12:09 maxiride

I'm currently struggling with this issue as well. In my use case, I'm trying to compile all the error logs from a request/event into an email and then send it to an administrator. This makes it easy to quickly troubleshoot an urgent issue without having to query a large error log database using only the trace ID. I'm trying to solve that by adding a bytes.Buffer to the logger to record the series of error logs. Not sure if there is a better way to do it.

haveachin avatar Jul 05 '23 12:07 haveachin

@haveachin I think your use case might be addressed with #583 as well.

mitar avatar Aug 22 '23 10:08 mitar