Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Proposal: Add zap.WithLeveler(leveler ...zapcore.LevelEnabler) #763

Closed
cstockton opened this issue Nov 19, 2019 · 4 comments
Closed

Proposal: Add zap.WithLeveler(leveler ...zapcore.LevelEnabler) #763

cstockton opened this issue Nov 19, 2019 · 4 comments

Comments

@cstockton
Copy link

cstockton commented Nov 19, 2019

Discussion on this in #591 (comment) with the use case. I would be happy to create a pull request for it.

Declaration:

package zap

// WithLeveler sets the loggers leveler to be the maximum level of each
// of the given LevelEnablers.
func WithLeveler(leveler ...zapcore.LevelEnabler) Option

Example (WithLeveler)

// Raise the log level by passing the current core and the maximum desired
// level. Useful for muting a particularly noisy region of code without affecting
// other sections of your application.
lr = lr.WithOptions(zap.WithLeveler(lr.Core(), zapcore.ErrorLevel))

// Lower the current log level by passing a single lower LevelEnabler. Useful for
// debugging a specific region of problematic code without the noise of your
// entire application.
lr = lr.WithOptions(zap.WithLeveler(zapcore.DebugLevel))
@prashantv
Copy link
Collaborator

As mentioned in the previous discussion, with the current APIs of Core, I don't think it's possible to build this feature where the level can be both increased or decreased. I think the level can only be increased (E.g., it'll print less logs than the previous logger).

This is because the logger interface is using the Core interface:
https://godoc.org/go.uber.org/zap/zapcore#Core

There are a couple of methods here that deal with the level:

  • Enabled(Level) bool through the embedded LevelEnabler
  • Check(Entry, *CheckedEntry) *CheckedEntry

The implementation of Core can have any custom logic in Check, for example we have sampling cores that will drop logs if there's been too many. Let's imagine we have a Core that only ever writes logs with "error" level or higher, while also doing some sampling.

Now when we wrap this core, we cannot force it to change the level to log any higher logs. In fact, the core might have something like this:

func (fatalCore) Enabled(l Level) bool {
  return l >= FatalLevel {
}

We can't change this level -- the only thing we can do is to ignore the result of Enabled or Check, but then we are likely violating sampling or other features of the core.

@cstockton
Copy link
Author

I understand your argument I just don't really see how it applies as a counter argument to the feature. Lets look at the simplest implementation possible done externally:

// WithLevel sets the loggers leveler to the one given.
func WithLevel(level zapcore.LevelEnabler) zap.Option {
	return zap.WrapCore(func(core zapcore.Core) zapcore.Core {
		return &lvlCore{Core: core, l: level}
	})
}

type lvlCore struct {
	zapcore.Core
	l zapcore.LevelEnabler
}

func (c *lvlCore) Enabled(zapcore.Level) bool { return false }
func (c *lvlCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
	if c.l.Enabled(ent.Level) {
		return ce.AddCore(ent, c)
	}
	return ce
}
func ExampleWithLevel() {
	lr := zap.NewExample()
	defer lr.Sync()

	lr.Debug("debug message - shown")

	// Raise the log level by passing the current core and the maximum desired
	// level. Useful for muting a particularly noisy region of code without affecting
	// other sections of your application.
	lr = lr.WithOptions(WithLevel(zapcore.ErrorLevel))
	lr.Info("info message - hidden")
	lr.Error("error message - shown")

	// Lower the current log level by passing a single lower LevelEnabler. Useful for
	// debugging a specific region of problematic code without the noise of your
	// entire application.
	lr = lr.WithOptions(WithLevel(zapcore.InfoLevel))
	lr.Debug("debug message - hidden")
	lr.Info("info message - shown")

	// Output:
	// {"level":"debug","msg":"debug message - shown"}
	// {"level":"error","msg":"error message - shown"}
	// {"level":"info","msg":"info message - shown"}
}

What specifically about the above is a violation of the Core?

  • The purpose of WithCore is documented to be for wrapping or replacing an existing core.
  • The interface for Write explicitly calls out Write must always log the Entry and fields, it
    should not replicate the logic of check. Meaning we can safely use the Write of another
    core.

Now the implementation details of the current sampler implemented by zap being ignored is a fair point, but you have lots of options. For example change the implementation slightly:

func (c *lvlCore) Enabled(zapcore.Level) bool { return false }
func (c *lvlCore) Check(ent zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry {
	switch ok := c.l.Enabled(ent.Level); {
	case ok && c.Core.Enabled(ent.Level):
		return c.Core.Check(ent, ce) // regular path, both log levels in agreement
	case ok:
		return ce.AddCore(ent, c) // we want more verbosity, so ignoring sampling makes sense
	default:
		return ce // not enabled
	}
}

Which aligns with my objective:

  • When I want to adhoc debug an area of code by lowering the level, I'm specifically seeking more noise so ignoring sampling is actually desired.
  • When I am trying to reduce the noise of a section of code by raising the level, I potentially reduce noise all together by forbidding the entry in the first level condition. Otherwise I call the parent core before emitting the log entry which aligns with my goal of reducing log output

There are other options with various degrees of reliability, optional interfaces, walking parent Cores and checking for *sampler and reusing the same internals and so on. I admit none of the options are "great" that try to accommodate Check calls of existing cores due to the convention that Check calls their own leveler. If it was a caller burden the problem wouldn't exist and contextual levels would be lightweight and simple. Ship has sailed though, I get it.

That all said the implementation is not a problem in my eyes, it's a matter of should users be able to have scoped log levels as they do with fields, name etc. I think yes- as it was a surprise there was no way to do this for me given the flexibility of zap. If the zap maintainers disagree about the merit of the feature- then fair enough I can tuck it into a zaputil package and call it a day - it will be here for anyone else who wants it in a small copy paste.

@prashantv
Copy link
Collaborator

prashantv commented Nov 26, 2019

Now the implementation details of the current sampler implemented by zap being ignored is a fair point, but you have lots of options.

This feature can be made to work if we assume that the only implementations of Core are in zap, but Core is an interface that can have any custom filtering logic, not just sampling. Sampling is an example. Another example is #766 where the core may filter out messages with a specific prefix. An interface means any user may have their own custom logic for filtering, and I don't think we should add an option that assumes "the user increased the level, so it's OK to ignore any other filters the user has set up".

This is about API guarantees, and the current API guarantee of a core is that the Check must return a non-nil entry for a message to be logged via the logger, and an option WithLevel changing that expectation is unexpected.

If you want to have a custom package that supports increasing levels, I would suggest add a note that any filtering in underlying cores may not be respected. Please do link to any external package you make, as it will help others looking for the same feature.

Closing the issue since there's no zap work.

@dcepelik
Copy link

Hi @prashantv,

If I understand you correctly, the issue is that the way the Core decides whether an Entry should be written or not (in Check) can be completely arbitrary. In other words, Check may even ignore the Level of the Entry completely and return true from Enabled, without violating anything. The question then is, what does it even mean to "decrease the log level" (go from less verbose to more verbose) at all?

The core functionality of Core seems to be Check. As per the doc comment:

// Check determines whether the supplied Entry should be logged (using the
// embedded LevelEnabler and possibly some extra logic). If the entry
// should be logged, the Core adds itself to the CheckedEntry and returns
// the result.
//
// Callers must use Check before calling Write.

"Using the embedded LevelEnabler" suggests that the notion of Entries having a Level and Core only allowing Entries with certain Levels to be logged is inherent to the Core. For example, I understand this to mean that !Enabled(Level) means that any Entry with that Level will not be logged, i.e. Check will return nil for those Entries.

So there are two orthogonal concepts here:

  • Filtering logs based on log level
  • Filtering logs based on arbitrary custom logic

I suppose that Level-based filtering can mean that we disregard the Entries' Level completely and always return true from Enabled.

In order to support the requested feature, it seems Core itself could support changing of the Level - since the notion of there being a Level is inherent to the design of the interface.

The Zap cores for example take the Level at which they log as one of the constructor parameters. For example, ioCore could implement this by simply assigning a different LevelEnabler into the embedded interface.

In generality, the changing of the log level may fail, as for some Core implementations, it probably needn't make sense to try to change the log level. I cannot think of a practical example, but it's legal. So the operation should be allowed to fail (return an error).

Since you probably don't want to introduce BC breaks by adding another method in Core's method set, we could leverage duck typing and provide a package-level function in zapcore to change the log level of a Core (for example database/sql does that). It's hardly optimal, but would work.

Do you think there's a way forward here?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

3 participants