Str key "level" sets log level

[adubkov]

log.Info().Str("level", log_level).Msg("Logging")

What I expect:

2019-07-28T02:43:45-07:00 INF Logging level=debug

What I'm getting:

2019-07-28T02:43:55-07:00 DBG Logging

[tkrause]

Confirmed, just ran into this myself.

[rs]

I'm not sure to follow what the issue is.

[tkrause]

As OP says, if you set a Str variable called level, it changes the actual level of the message output in the log.

[rs]

I would suspect that you will have the level key twice in the message. The ConsoleWriter will only take the last one, which is the one you set manually.

I'm not sure why you would like to set the level key like this, but what happen is not surprising.

[tkrause]

It does it for all Writers not just the Console one. It seems like a bug to me since you've already set the level prior.

Secondly, it only occurs with Str() not any of the other variable types from what I tested anyways. It only occurs with Str when the level passed in is a supported level by the library.

The point is, level is used in a lot of applications for things other than log level. It should not be a reserved variable like how it is currently. We DONT want to change the log level by passing in Str().

[rs]

There is nothing reserved about the level field name of than the fact it is used to report the message level. You can change the field name used to report it.

Note that it DOES NOT change the log level. If you set the min log level to info and do log.Debug().Str("level", "info").Msg("test"), the message will not be logged.

Also, if you do log.Info().Int("level", 1234).Msg("test") you should end up with a message like {"level": "info", "level": 1234, "msg": "test"}. I'm not sure what the ConsoleWriter would show in this case, certainly something like ???.

[adubkov]

You won't end up with {"level": "info", "level": 1234, "msg": "test"} cause it is not valid json.

[rs]

You will, and it is not invalid JSON, it is unspecified, so each JSON parser might parse it differently or return an error.

For performance reason, zerolog does not prevent your from outputing such JSON. The user is responsible for avoiding such case.

[djmcgreal-cc]

Likewise if you set a field with value 'message', but in this case .Msg seems to overwrite it, so that the previous field set is missing. I wondered about this for a while as I was looking at Console output, would have more obvious what had happened in JSON I suspect.

[NiceGuyIT]

I was working with decrypting a message and wanted to log the "message". It took me a while to figure out it's due to the comment above. Logging a Str with message key does not log anything. I had to read the comments above several times and came to the conclusion that zerolog will convert the log message to JSON and then to a console message. If the JSON log has a duplicate keys, only the last key is used and output to the console. This is why a Str key of level will change the output to show a different level.

As zerolog user, I don't care about the implementation. I only care that it works, and it doesn't work if I use "magic" keywords as the Str key. This is the heart of this issue. I suggest adding to the Caveat at the bottom of the README.

========== README.md ==========

## Caveats

Note that zerolog does no de-duplication of fields. Using the same key multiple times creates multiple keys in final JSON:

```go
logger := zerolog.New(os.Stderr).With().Timestamp().Logger()
logger.Info().
       Timestamp().
       Msg("dup")
// Output: {"level":"info","time":1494567715,"time":1494567715,"message":"dup"}

In this case, many consumers will take the last value, but this is not guaranteed; check yours if in doubt.

When using the default ConsoleWriter, duplicate fields may cause unexpected output.

zerolog.SetGlobalLevel(zerolog.DebugLevel)
log.Logger = log.Output(zerolog.ConsoleWriter{
	Out:     os.Stderr,
	NoColor: true,
})

log.Debug().
	Str("level", "warn").
	Str("app_message", "This message will print").
	Str("message", "But this message will not print").
	Msg("Application message of level Debug")
// Output: 11:00PM WRN Application message of level Debug app_message="This message will print"

========== End of README.md ==========

Here's a more complete example showing the problem.

https://go.dev/play/p/2jacr7VEW_J

// You can edit this code!
// Click here and start typing.
package main

import (
	"fmt"
	"os"

	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
)

func main() {
	// UNIX Time is faster and smaller than most timestamps
	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix

	var app_debug_level = "debug" // zerolog.DebugLevel
	var app_info_level = "info"   // zerolog.InfoLevel
	var app_warn_level = "warn"   // zerolog.WarnLevel
	var app_err_level = "error"   // zerolog.ErrorLevel

	// Changing this to InfoLevel will cause nothing to be logged because everything is using Debug.
	zerolog.SetGlobalLevel(zerolog.DebugLevel)

	log.Debug().
		Str("message", "This message will not be printed").
		Str("level", app_warn_level).
		Msg("The message and log level are being set from the user input?")
	log.Debug().
		Str("message", "This is a user entered message that will not be printed").
		Msg("Will the message associated with this log entry be printed?")
	log.Debug().
		Str("level", app_debug_level).
		Str("app_message", "I want to print an application debug message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a DEBUG message?")
	log.Debug().
		Str("level", app_info_level).
		Str("app_message", "I want to print an application info message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a INFO message?")
	log.Debug().
		Str("level", app_warn_level).
		Str("app_message", "I want to print an application warn message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a WARN message?")
	log.Debug().
		Str("level", app_err_level).
		Str("app_message", "I want to print an application error message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a ERROR message?")

	fmt.Println("")
	fmt.Println("Now let's print the same message using the console writer")
	log.Logger = log.Output(zerolog.ConsoleWriter{
		Out:     os.Stderr,
		NoColor: true,
	})
	log.Debug().
		Str("message", "This message will not be printed").
		Str("level", app_warn_level).
		Msg("The message and log level are being set from the user input?")
	log.Debug().
		Str("message", "This is a user entered message that will not be printed").
		Msg("Will the message associated with this log entry be printed?")
	log.Debug().
		Str("level", app_debug_level).
		Str("app_message", "I want to print an application debug message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a DEBUG message?")
	log.Debug().
		Str("level", app_info_level).
		Str("app_message", "I want to print an application info message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a INFO message?")
	log.Debug().
		Str("level", app_warn_level).
		Str("app_message", "I want to print an application warn message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a WARN message?")
	log.Debug().
		Str("level", app_err_level).
		Str("app_message", "I want to print an application error message").
		Str("message", "But this message will not print").
		Msg("Will this message be printed as a ERROR message?")
}

{"level":"debug","message":"This message will not be printed","level":"warn","time":1257894000,"message":"The message and log level are being set from the user input?"}
{"level":"debug","message":"This is a user entered message that will not be printed","time":1257894000,"message":"Will the message associated with this log entry be printed?"}
{"level":"debug","level":"debug","app_message":"I want to print an application debug message","message":"But this message will not print","time":1257894000,"message":"Will this message be printed as a DEBUG message?"}
{"level":"debug","level":"info","app_message":"I want to print an application info message","message":"But this message will not print","time":1257894000,"message":"Will this message be printed as a INFO message?"}
{"level":"debug","level":"warn","app_message":"I want to print an application warn message","message":"But this message will not print","time":1257894000,"message":"Will this message be printed as a WARN message?"}
{"level":"debug","level":"error","app_message":"I want to print an application error message","message":"But this message will not print","time":1257894000,"message":"Will this message be printed as a ERROR message?"}

Now let's print the same message using the console writer
11:00PM WRN The message and log level are being set from the user input?
11:00PM DBG Will the message associated with this log entry be printed?
11:00PM DBG Will this message be printed as a DEBUG message? app_message="I want to print an application debug message"
11:00PM INF Will this message be printed as a INFO message? app_message="I want to print an application info message"
11:00PM WRN Will this message be printed as a WARN message? app_message="I want to print an application warn message"
11:00PM ERR Will this message be printed as a ERROR message? app_message="I want to print an application error message"

[mitar]

I think there are two threads conflated here:

• One is that zerolog allows you to output the same field multiple times: this is hard to prevent in efficient manner and zerolog does not do it.
• It is possible to use .Str and others to log with "reserved" field names which leads to confusion.

I think for most people in this issue (correct me if I am wrong), the first thread is not so problematic than the second.

Maybe zerolog should just have a simple check that for all .Str and others, you cannot pass field name which equals one of the "reserved" field names (however they are configured). Given that you can rename those reserved field names, this would allow you to keep using .Str and others with fields you want if you do configure reserved field names to something different.

So, zerolog does not have to be perfect here and prevent any field repetition, but for fields with special meaning, just panic or something.

[w3aponx]

Also, if you do log.Info().Int("level", 1234).Msg("test") you should end up with a message like {"level": "info", "level": 1234, "msg": "test"}. I'm not sure what the ConsoleWriter would show in this case, certainly something like ???.

It will show ??? if value is nil. But otherwise it will try to convert to a string (via fmt.Sprintf) and keep characters 0:3. This is problematic because we had a case in one of our applications where we would (very rarely) log with a numeric level, and we found out that if this happens with a value < 100, the application would panic and die. This is definitely not something that should happen with your logging library.

[mitar]

But .Int("level", 1234) is not the way how you set the logging level. Use .WithLevel(123) if you want to do numeric levels. Do note it is just int8.

Setting the level this way allows you to also filter by the level.

[w3aponx]

But .Int("level", 1234) is not the way how you set the logging level. Use .WithLevel(123) if you want to do numeric levels. Do note it is just int8.

I don't want to affect the logging level, I want to log information about (business-specific) level information. Think of wanting to do something like:

   logger.Warn().Int("level", volumeLevel).Msg("Volume too high!")

If your volume level is below 100 and you have a ConsoleWriter enabled, your application will crash and burn.

I would restate your second "thread" as:

• User-defined fields share a common namespace with built-in ("reserved") fields, which is not documented and not obvious and can lead to catastrophic failures.

[mitar]

Then set zerolog.LevelFieldName to logLevel and you will be fine.

[mitar]

(But I agree that .Int("level", ...) should fail early until you change zerolog.LevelFieldName.)

[w3aponx]

That would reduce the risk, but it assumes that no one uses or ever will use that as a field name, which is difficult to enforce. Just in the one project I currently have open, we have over 2000 logging calls. Every developer and reviewer needs to be aware of those (undocumented?) rules and pay close attention to any logging code changes. Plus it might not affect only the level field, but also (from a quick inspection) time, level, message, error, caller, stack. They might not all lead to catastrophic failures (panics), but I can't tell without going through the code meticulously.

There are many possible mitigations to the problem, from (lower impact first):

1. Documenting the built-in names as "reserved".
2. Ensuring that using built-in (or even overridden) names can not lead to a panic (so for my specific case maybe the code needs to change from:

	l = strings.ToUpper(fmt.Sprintf("%s", i))[0:3]

to something like:

	l = strings.ToUpper(fmt.Sprintf("%s", i))
	if len(l) > 3 {
		l = l[0:3]
	} else {
		l = l + "???"[len(l):]
	}

3. Validating reserved field names in the various field methods to ensure they do not collide and "fixing" them if they do -- maybe add an underscore prefix or suffix for example.
4. Somehow keeping user-defined and built-in field names into separate name spaces, either by keeping two distinct lists or adding a prefix to built-in names to effectively reserve them. These prefixes can be removed when outputting to JSON or other.

[goodevilgenius]

I think there are two threads conflated here:

• One is that zerolog allows you to output the same field multiple times: this is hard to prevent in efficient manner and zerolog does not do it.
• It is possible to use .Str and others to log with "reserved" field names which leads to confusion.

I think for most people in this issue (correct me if I am wrong), the first thread is not so problematic than the second.

Personally, I think the second is easier to deal with. It's easier to know which specific fields I just can't use: level, message, and time. These can be changed if I want to use those fields, but I can just avoid using those, and use a different name if I want.

For me, the first issue is more of a problem. If I do something like this:

logger := zerolog.New(os.Stderr).With().Timestamp().Logger()

// do some more things, and then ..
logger = logger.With().Str("key", "value).Int("age", 41).Logger()

// Some more things, maybe adding other fields, using `With`
logger.Error().Int("age", 16).Msg("too young")

I'm going to end up with the following output:

{"level":"error","key":"value","age":41,"age":16,"message":"too young"}

This may be fine for some logging applications, but some JSON validators call that invalid, and some logging applications (for me, I had an issue with Datadog) won't process it if it's "invalid" json.

So, the duplicate key issue is actually much more important to me. If I'm passing around a logger, it can be harder to keep track of what keys have been used.