Logger.Error: nil err allowed? about logr

[pohly]

Example: https://github.com/kubernetes/kubernetes/pull/105969/files#diff-8f987c51b1b80004440b85620ece9d41e6001b437c1e03f2f0005fe685e135bd

[wojas]

I guess it depends on whether we consider Error to just be a friendly alias for Info that makes it easier to log an error, or a different part of the API that does something else. I personally always considered it to be a friendly alias that I also use to log less important events, like transient connection errors.

[wojas]

Regardless, we probably do not want to panic on any kind of log input. If the log sink requires a non-nil error, it should check the value and do something sensible (not panic) if it's nil.

[pohly]

I guess it depends on whether we consider Error to just be a friendly alias for Info that makes it easier to log an error, or a different part of the API that does something else. I personally always considered it to be a friendly alias that I also use to log less important events, like transient connection errors.

There is one major conceptual difference: Error is always logged, Info only when it meets the verbosity threshold.

Regardless, we probably do not want to panic on any kind of log input. If the log sink requires a non-nil error, it should check the value and do something sensible (not panic) if it's nil.

Agreed.

How about we add a clarification saying "Loggers should accept a nil error because the value may intentionally or accidentally be nil."?

"Should" because we didn't specify it as a "Must" when defining the 1.0.0 API.

[wojas]

There is one major conceptual difference: Error is always logged, Info only when it meets the verbosity threshold.

The way I have implemented it, Error is always logged at the current verbosity level, but with an extra error fields. Specifically, with logrus as a backed it simply calls WithError(err) on the logrus Entry.

The current source code comments say:

// Info() and Error() are very similar, but they are separate methods so that
// LogSink implementations can choose to do things like attach additional
// information (such as stack traces) on calls to Error().

and

// Error logs an error, with the given message and key/value pairs as context.
// It functions similarly to Info, but may have unique behavior, and should be
// preferred for logging errors (see the package documentations for more
// information).
//
// The msg argument should be used to add context to any underlying error,
// while the err argument should be used to attach the actual error that
// triggered this log line, if present.

While there is a mention of 'unique behavior' for Error, I don't think it's a good idea to implement it in the sink as 'is always logged'. External library code could call Error to simply attach an error message to a debug level message.

Of course you could decide that in klog calling ErrorS will cause it to always be logged, but then I would also bump the V-level of that message accordingly.

How about we add a clarification saying "Loggers should accept a nil error because the value may intentionally or accidentally be nil."?

"Should" because we didn't specify it as a "Must" when defining the 1.0.0 API.

I think this can be a "Must", because this is merely a clarification, not a change of behaviour. If a sink did not handle it before, the program may have crashed. We currently do not explicitly prohibit calling it with a nil error.

[pohly]

While there is a mention of 'unique behavior' for Error, I don't think it's a good idea to implement it in the sink as 'is always logged'.

I'm surprised that the current docs don't explain this. I thought we had merged a PR which fixed that. I know that it has surprised people before. But it really is the current and intentional behavior.

Error does not call Enabled:

logr/logr.go

Lines 261 to 266 in 8d00e35

	func (l Logger) Error(err error, msg string, keysAndValues ...interface{}) {
	if withHelper, ok := l.sink.(CallStackHelperLogSink); ok {
	withHelper.GetCallStackHelper()()
	}
	l.sink.Error(err, msg, keysAndValues...)
	}

Whereas Info does:

logr/logr.go

Lines 244 to 251 in 8d00e35

	func (l Logger) Info(msg string, keysAndValues ...interface{}) {
	if l.Enabled() {
	if withHelper, ok := l.sink.(CallStackHelperLogSink); ok {
	withHelper.GetCallStackHelper()()
	}
	l.sink.Info(l.level, msg, keysAndValues...)
	}
	}

LogSink.Error also doesn't get the current log level while LogSink.Info does.

This is intentional because then Error can then be used for log messages which are so important that they should always be emitted. If that is not desired, users can call Info with an error key/value pair.

[pohly]

Regarding my original question: I just noticed that there is a "if present" in "the err argument should be used to attach the actual error that triggered this log line, if present."

That indirectly indicates that "not present = nil" is a valid way of calling Error. We can make that more obvious by explicitly stating it, but it's not an API change.

[thockin]

I am +1 to saying "must" support nil errors in comments. @pohly - PR me?

WRT Error() - it is intended to always log. The fact that log.V(11).Error() is a thing is only because V() returns a full Logger. Circa 0.4.0 it returned an InfoLogger which had no Error() method, but that was problematic for other reasons and I didn't want to add V() and Bias() as different things. So I am +1 to clarifying that, too.

[stevekuznetsov]

Is there any possibility to improve the ergonomics past logger.Error(nil, "message")? Most other logging implementations allow e.g. logger.WithError(err).Info("message") or logger.Error("message") separately. I'm currently in a migration to contextual + structured logging and this is one of the more unpleasant translations.

[pohly]

We could add a logger.ErrorMsg("message", ...). But I am not sure whether that is really a big improvement over logger.Error(nil, "message", ...).

[stevekuznetsov]

Up to you. The developer ergonomics today are not ideal - even with nil someone that's not perfectly attuned to this interface and expectations immediately has some questions on review - why nil? Did you mean to pass an error but forgot? Is that a valid input to the loggers ... ?

If not explicitly supporting the "log this always, label it as error level, without a Go-error" case was a side-effect of something, and not an intentional choice, I'd suggest maybe giving the ErrorMsg() or similar approaches some consideration. Clearly some ergonomics and clarity wins there.

[pohly]

Let's reopen for discussion.

@thockin: what do you think about adding ErrorMsg as an alias for Error(nil?

[thockin]

"ErrorMsg" is an unfortunate name, don't you think? I get the point you're making but I don't know if that makes it any clearer? I'm open to being swayed here...

[pohly]

I don't have a strong preference here and could live with just having Error(nil, ...) myself. No idea for a better name.

[thockin]

I'm disinclined to add another method for this, especially if slog is coming eventually. Closing.