Panic on wrong number of key value pairs

[leopucci]

I forgot to add a key to a value on
func (s *SugaredLogger) Warn(msg string, keysAndValues ...interface{}) {
And it caused me a panic crash of the app.

Shouldn´t be wise to protect this error from happening?
The code compiles normally, you deploy on production... it stays there for months.. then the log is printed and the system crashes because a log was wrong. (not my case just hypothetical.)

This is a thing that can be protected. We always have the human factor to account for.

zap/sugar.go

Line 264 in a68efdb

key, val := args[i], args[i+1]

[sethvargo]

I wrote a static analysis tool to catch this today, because I've also been bitten by it: https://github.com/sethvargo/zapw

[prashantv]

Thank you for the report, agreed that this should not cause a panic, and instead add a field indicating that there's a missing argument, similar to fmt.Sprint which will add %!v(MISSING) if there's an argument missing for a specific type specifier.

[sethvargo]

@prashantv I think removing the panic would be considered a breaking API change. The panic is clearly documented and people may be depending on that behavior.

[abhinav]

@prashantv I think removing the panic would be considered a breaking API change. The panic is clearly documented and people may be depending on that behavior.

Hello!

We discussed this a little and although we agree that it would be a behavioral
change to switch from panicking to not, we're not convinced it's a breaking
change. Previously that usage simply would not work, and with the planned
change, it will degrade gracefully. We're considering that as going from more
restrictive to less restrictive behavior.

Another data point here is that we don't expect people to depend on panics as
a behavior; panics represent a catastrophic violation of internal assumptions
of a program, not expected behavior.

That said, we're happy to reconsider this if there's a good argument to keep
panicking/if there are legitimate cases where graceful degradation would be a
negative.

[dherbst]

@leopucci I tried to reproduce the panic, but it looks like this test case covers putting a non-string value in as a key

zap/sugar_test.go

Lines 92 to 97 in a68efdb

	{
	desc: "structured field and a dangling non-string key",
	args: []interface{}{Int("foo", 42), 13},
	expected: []Field{Int("foo", 42)},
	errLogs: []observer.LoggedEntry{ignored(13)},
	},

Are you configuring the logger as a Production logger in production and still seeing the panic?

logger, err := zap.NewProduction()

Can you provide an example which will cause a panic please?

[leopucci]

Hey @dherbst , I just changed my job so I don´t have access to the git repository to access the commit and give you the exact situation.

I do have some lines of the old code that could help you narrow down.

log.Warnw("Message", 1 key, 1 value, DATE key, Date value, error key , error value)

Something near this, but without some key or value. Maybe it is related to size. 3 or 4 pairs. try messing on something like this.

I Hope it helps

Pucci

[dherbst]

I cannot reproduce the reported problem when using zap.NewProduction() and without the original reproduction my best guess is that a zap.NewDevelopment() logger was run which resulted in a panic.

Here is my attempt at a reproduction:

package main

import (
	"fmt"

	"go.uber.org/zap"
)

func main() {
	fmt.Println("starting")
	// logger, err := zap.NewProduction()  // does not panic
	logger, err := zap.NewDevelopment()
	if err != nil {
		fmt.Println("err", err)
	}
	defer logger.Sync()
	sugar := logger.Sugar()
	sugar.Warnw("message", "this", "that")
	sugar.Warnw("message", "this", "that", 2)
	fmt.Println("done")
}

[leopucci]

Some of our production code could be under debugging mode.
Usually we do this to debug and fix production issues that we could no catch locally. I was fixing one when this happened.
I don´t have any details about this, because we just add -debug on the command line to start debugging. So I don´t know if it was on zap.NewProduction() or zap.NewDevelopment()

[prashantv]

Looking at the code, I'd also only expect panics in development mode (it uses DPanic to log the mismatch).

I'd recommend against using the development logger in production given the behaviour of DPanic. If this is only a development-mode case (which is intentional, and I think a good way to flag misuses), I think the behaviour should stay as-is, does that seem reasonable?

[leopucci]

As a software pattern, it is common to have defined modes, development/production for instance.
In a perfect world this is what is expected to be used properly.
But several people will use this incorrectly, as it was happening to me.
And I didn't had a clue that I was using development mode as this was encapsulated in other layers.

To me, a wrong key/par does not mean that the software needs to stop completely just for a wrong log entry.
In my case the log was inside a condition, and it was only called in production, not during development. (But in development mode).

I am aligned with @abhinav view, of a less restrictive mode, and that panic is a catastrophic violation approach, that does not make sense for a wrong log entry. Even in Development mode.

[sanposhiho]

Hello.
Is there any progress in this discussion?

Another data point here is that we don't expect people to depend on panics as a behavior; panics represent a catastrophic violation of internal assumptions of a program, not expected behavior.

I agree with @abhinav 's point of view.

And, some people may use NewDevelopment() in our service's dev environment just for changing log level. They just want to change their log level and don't expect panic when they use the func in the wrong way.

[prashantv]

Given that there is unexpected usage of the development mode in production, it does seem safer not to panic.

We're aligned on changing the behaviour here to avoid panics, and welcome any PRs fixing this, thanks!