log/alt_experimental_level: concept demonstration

[seh]

As a foil to #357 and following up on #368, demonstrate an alternate approach to the "level" package offered via the "github.com/go-kit/kit/log/experimental_package" import path, allowing log event level filtering via instances of the (unexported) level.leveler interface, created by functions that specify the filtering threshold.

Features not accommodated here for now:

• Returning an error from log.Log when squelching an event
• Returning an error from log.Log for events that lack a level
  (This feature doesn't make much sense with this approach.)
• Squelching events that lack a level
  (This feature doesn't make much sense with this approach.)
• Documentation
  (We could adapt much of this from the sibling package.)

See the commit message for then benchstat comparison.

[seh]

Taking a walk immediately after posting the first commit made me realize that this probably doesn't play well with log.Context; wrapping a level.leveler with a Context will fool several of the functions that inspect the type of the log.Logger parameter.

I'll have to do more experimentation over the weekend to see whether that's a fatal flaw, or one that's surmountable.

[seh]

What I can't see how to surmount with this design is the opaque relationship between a log.Context and the log.Logger that it holds in its "logger" field. This is all it takes to break my proposal:

logger := level.AllowingAll(logger)
// ...
level.Debug(logger).Log("msg", "You will see this.")
level.Debug(log.NewContext(logger)).Log("msg", "You'll never see this.")

For my proposed level.Debug(log.Logger) method (and its siblings) to work on arbitrary log.Logger parameters, I'd need a way to drill down through the wrapping layers to see whether there's a level.leveler instance in that agglomeration, kind of like how the "pkg/errors" package's errors.Cause function works. Even if that were possible, it would impose a heavier pointer chasing cost, as these log.Logger types can be wrapped to any depth.

The log.Logger interface is so narrow that there's no way for a "higher level" function to coordinate with a wrapper "lower level" instance, apart from inserting and later inspecting particular key/value pairs. This reinforces my desire to see either the level idea integrated into the "log" package—which allows access to log.Context, but still doesn't help with custom log.Logger implementations—or to see some kind of "configuration context" made available.

[peterbourgon]

Thanks for this. If it were just performance improvements I'd say we should merge the existing experimental_level, but keep this one open and keep hacking on it to see if we can arrive at a solution. But it's also an API change, and in a direction that I think I prefer. This complicates things. Given I want to get something merged for 1.0.0 in O(days), and I'd like to avoid future breaking changes if possible, what do you think the best choice is here? If you think a day or two of applied hacking will make this work, I'm happy to do a spike. If you think it requires more thought, I'm also happy to merge the existing experimental_level and sort of resign myself to a potential breaking change (and version bump) in a month or two. Leaning toward option 2 but eager for your feedback.

[peterbourgon]

@seh Any comment on the above?

[seh]

I am excited to hear that you find my proposal intriguing enough to warrant refining it. I am not sure yet that the idea will bear fruit, but there's one more interface that I'd like to work on adding tomorrow (more easily attempted at the office) that's analogous to the "pkg/errors" package's errors.Cause function. It will impose a performance tax over what I've written here so far, but, then again, what I've written here so far is inadequate to the task—unless we wanted to declare that leveled logging only works directly on the log.Logger created by one of the level-related factory functions, but I don't think that's a tenable restriction.

But it's also an API change, and in a direction that I think I prefer.

Can you tell what you see here that you prefer? I'm not looking for flattery; I just want to know which parts to preserve and emphasize and which parts to eliminate (such as the global state you and @ChrisHines detested from the earlier #368).

Please allow me another day to either show you a more complete solution or declare that the idea isn't worth pursuing further.

[peterbourgon]

Can you tell what you see here that you prefer?

I like that you've implemented the level-setting behavior using something like a decorator. The UX just feels a lot more natural than the existing "invoke a function to get an opaque slice of strings" method. That said, my method allows user-specified levels with a lot less fuss, which I like; though it's not clear to me if anyone would ever bother with it :)

One thing I'd still like to see—and which the existing impl also doesn't have—is a nice way to bind typical commandline flags to levels. In practice I think this would boil down to a helper function that converts a user-given string like info to an AllowingInfoAndAbove decorator.

logLevel = flag.String("log-level", "warn", "debug, info, warn, error, or none")

// ...

var logger log.Logger
logger = log.NewLogfmtLogger(os.Stderr)
logger = level.AllowingLevel(*logLevel)(logger) // or...
logger = level.AllowingLevelDefault(*logLevel, AllowingErrorOnly)(logger)

Something like this.

[seh]

I've made changes to the primary code that allow it to accommodate wrapped log.Logger instances, with the loss of being able to use log.DefaultCaller with no change in the expected call stack depth. Instead, my approach now needs the same log.Caller(5) concession that we see over in the experimental_level implementation.

I'd like to write a few more unit tests before pushing a patch. That will likely take me through early tomorrow morning.

[seh]

Commit c6bd2a9 introduces a potentially controversial pair of exported functions:

• log.Delegate
  Extracts the log.Logger wrapped by a supplied log.Logger, if any.
• log.Context.Delegate
  Implements the interface understood by log.Delegate.

With these functions in place, it's possible to "peel a Context" and recover the Logger that it wraps. That's arguably an information or abstraction leak. If the "level" package wasn't separate from the "log" package, we wouldn't necessarily need to expose this notion of wrapping and unwrapping, but doing so also allows participation from Logger implementations that live outside of the "log" or "level" packages—assuming, that is, that the authors understand the benefit of and opt into participating.

@peterbourgon and @ChrisHines, please let me know if you find this proposal an insulting affront to the "log" package's otherwise clean surface, or whether it's an acceptable trade of abstraction for capability.

[ChrisHines]

The log.Logger interface is so narrow that there's no way for a "higher level" function to coordinate with a wrapper "lower level" instance, apart from inserting and later inspecting particular key/value pairs.

Convince me that inspecting keyvals is a problem.

[seh]

Well, I can cite two deficiencies that I dislike, but whether you'll consider them sufficient evidence is predicated on how time- or allocation-sensitive your application is. We've touched on this before.

Restating my complaints:

• Finding the level key and value pair is an O(n) linear search, involving two type checks and a map lookup (another string comparison to confirm the key match).
  My implementation here started out with an O(1) decision as to whether to suppress a record, but that proved to be inadequate. It is now O(n) in the number of layers wrapping around the Logger returned by AllowingAll and kin.
• Record suppression happens "late," after accumulating values in the Context, only to be discarded later.
  My desire here is to stop the logging functions from doing any work that would contribute to a record that we already know will be dropped.

The benchmarks show a reduction in CPU time and allocation. However, maybe it's not enough of a reduction to convince you that's worth it.

Now, maybe you're suggesting that I could instead tuck the state I need into a key/value pair in a Context, and inspect that during a call to level.Debug and kin. That would require me to be able to bore into log.Context from outside as well to see the set of key/value pairs that it's hiding.

[ChrisHines]

@seh: First, let me be unequivocal in my thanks to you for working on this issue. I am delighted to have others trying to improve the library. :)

Your benchmark improvements are attractive.

The API changes to package log are a concern. Does this change imply that all Logger decorators should implement a Delegate method?

I am reminded of a Slack conversation we had last August in which I proposed yet another alternative that we haven't tried yet. In that conversation I mused:

Thinking out loud… What if there was a special value that a Valuer could return that signaled ⁠⁠⁠⁠Context.Log⁠⁠⁠⁠ to stop processing that record. The level values could be Valuers that somehow know what level to return and also know to return the special terminating value if their level is filtered.

I wonder if that could be made to work, what its performance would be, and if it would be less intrusive and also more general?

Perhaps a way forward here (if possible) is to implement something that is functionally correct and has the sleeker levels API that does not rely on global state that you have shown but without the changes to the base log package. This approach would not be as performant as what you have now, but would let us finalize a v1.0.0 API we like. Then we can iterate on performance improvements and consider your proposed change to package log more carefully.

[freeformz]

Would something along these lines be considered as an alternative: https://gist.github.com/freeformz/3334b5a88602c08927b420de665224dd

[seh]

Does this change imply that all Logger decorators should implement a Delegate method?

It does, though it does not force others to do so. However, if they don't implement Delegate, they can inadvertently (or even deliberately) circumvent the intended level restricting behavior. Consider:

type myLogger struct {
	log.Logger
}

func sneakAroundRestriction(logger log.Logger) {
	logger = level.AllowingErrorOnly(logger)
	logger = myLogger{ logger }
	level.Debug(logger).Log("msg", "Surprise!")
}

I wonder if that could be made to work, what its performance would be, and if it would be less intrusive and also more general?

I haven't look at Valuer in a while to understand how it's used, but I'll study it today and think on it. Did I understand your proposition, though, that you would want to defer any changes that involve Valuer until after a version 1 release, and in the meantime see if it's possible to achieve the desired functional behavior without it?

[ChrisHines]

@freeformz I don't completely understand what you are proposing. Could you provide more detail in a separate issue?

@seh Yes, I was asking if it was possible to implement the behaviors and API of this PR without changing package log as a way to reach v1.0.0. Do you think it would then be possible to work on optimizing performance in a later v1.x.y release that maintained backwards compatibility?

[seh]

Do you think it would then be possible to work on optimizing performance in a later v1.x.y release that maintained backwards compatibility?

It probably is possible to do the filtering, given what's already present over in the experimental_level implementation, but without the same short-circuiting behavior. Callers that neither use custom Valuer instances nor benchmark their programs wouldn't know the difference.

I'll need a few more hours to think about it and try it out. I'll report back here with what I learn.

[freeformz]

@ChrisHines I am effectively proposing an alternative to this proposal that doesn't expand the core API of log.Logger. To be fair though I only found this issue not long before posting the gist, which is purely a design foil, and not an implementation. So feel free to ignore. I am willing to implement though as a PR if there is interest.

[seh]

I am effectively proposing an alternative to this proposal that doesn't expand the core API of log.Logger.

I'm confused by that statement; your proposal appears to introduce a very important new function in the log.Logger interface:

func Log(level Level, keyvals ...interface{}) error

[freeformz]

@seh, no I am not. it's just another part of ...interface{}

[ChrisHines]

@seh I'm spending some time playing with the code in this PR. Here is a test that fails.

func TestMultiLoggerDifferentLevels(t *testing.T) {
	var out1, out2 [][]interface{}

	logger1 := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
		out1 = append(out1, keyvals)
		return nil
	}))

	logger2 := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
		out2 = append(out2, keyvals)
		return nil
	}))

	logger1 = level.AllowingErrorOnly(logger1)
	logger2 = level.AllowingAll(logger2)

	multi := NewMultiLogger(logger1, logger2)

	level.Error(multi).Log("foo", "bar")
	level.Info(multi).Log("foo", "bar")

	if got, want := len(out1), 1; got != want {
		t.Errorf("out1 len: got %v, want %v, data %v", got, want, out1)
	}

	if got, want := len(out2), 2; got != want {
		t.Errorf("out2 len: got %v, want %v, data %v", got, want, out2)
	}
}

type multiLogger []log.Logger

func (l multiLogger) Log(keyvals ...interface{}) error {
	for _, logger := range l {
		logger.Log(keyvals...)
	}
	return nil
}

func NewMultiLogger(loggers ...log.Logger) log.Logger {
	return multiLogger(loggers)
}

It would be nice to support this use case. It is easily accomplished with log15 and is also similar to the default behavior of glog. Thoughts?

[seh]

I am not ignoring you deliberately, @ChrisHines; I've read the test case (nicely written, by the way), but haven't had enough spare time today to concentrate on it. Perhaps tomorrow morning will afford me a better chance to look into it with the attention it deserves.

In private, I'd be happy to complain about what's demanding my attention by day.

[ChrisHines]

@seh No worries. We're all busy.

[seh]

I finally have some time to write down what I wanted to say shortly after you posted your multi-logger example.

As you asked and I responded here, in this case it matters gravely whether type multLogger implements the delegator interface (via method Delegate). When level.Error or level.Info inspects your multiLogger instance to find a level.leveler, it finds neither a level.leveledLogger, nor a log.Context, nor level.delegator, so it concludes that the logger was not restricted at all by one of the level.Allowing... factory functions, and allows all the messages through.

It's not enough to implement a Delegate method on multiLogger, though. multiLogger doesn't delegate to just one logger; it delegates to any number of them, requiring that we widen the Delegate method to the following:

func Delegate() []log.Logger

If Go were a different language with a generic programming facility at this point, I might suggest instead something more like this:

func ReduceDelegates(f func(T result, logger log.Logger) T, T initial) T

Rather than level.outermostLevelerOr and company digging through a linked list, they have to dig through a graph (which could even be cyclic, but let's not worry about that for now). What we want to find is the most restrictive leveler in that graph. In the current implementation, since we know that the various level.Allowing... functions already maximize that restriction, finding the outermost (or closest) leveler is also the most restrictive one. We can't be sure of such an ordering with a type like multiLogger.

I started thinking through how to write that maximizing graph traversal. It would benefit from memoization to preclude inspecting the structure again and again.

That explains why your example doesn't work correctly. The next question is whether you think it's worth it to try to make it work, or whether it's sufficiently damning evidence against the Delegate method technique that I introduced here.

[ChrisHines]

My feeling at this point is that the complexity costs outweigh the gains for this sort of optimization. I suspect there are more configurations that pose additional challenges and require even more complexity to work around. The acknowledged problem with having to adjust log.Caller is another ding against this PR. I don't want our log/level package to be encumbered by these caveats, so I don't think this PR should be our approach for v1.0.0. It would be nice to have the speedup you found, but the other costs are just too high.

I do appreciate the work you have done to explore this idea. You've done a fantastic job with the code, benchmarking and communicating your idea. Thanks!

[seh]

Thank you.

On the subject of log.Caller, I noticed that the implementation in the experimental_level directory also requires that same adjustment. It is hard to to comply with introducing no additional stack frames. Do you have any advice to guide design for another attempt at this that won't bump into that problem only at the end?

[ChrisHines]

log.NewContext and log.Context.With take care to not introduce new stack frames when wrapping another *log.Context. With the current implementation you pretty much have to inject new k/v pairs using log.Context and return a *log.Context so that application code calls *log.Context.Log. That is why I suggested the idea that *log.Context.Log could short-circuit if it finds a special value in the keyvals before delegating down the chain.

At one point we exported a Wither interface that log.NewContext and log.Context.With checked for so that other implementations could play this game and we also exported log.bindValues and log.containsValuer functions as helpers for those (at the time unknown) implementations. We made them unexported pretty early on to keep the API slim. The implementation of log.Context has also evolved since then, so I am not sure if exporting these things would help (or even work) now, but if so I think that's could be on the table.

[ChrisHines]

@seh said:

On the subject of log.Caller, I noticed that the implementation in the experimental_level directory also requires that same adjustment.

Note that it only needs that when the log.Context containing the log.Caller is buried beneath the filtering layer. As you can see in TestLevelContext the implementation in experimental_level can use log.DefaultCaller and still pass that logger to level.Info and friends, which is more compatible than the approach taken in this experiment. That's because experimental_level/level.Info follows the advice I gave in my last comment.

[seh]

I spent a while yesterday experimenting with the idea of teaching log.Context to understand the sentinel return value that @ChrisHines had mentioned in the "go-kit" Slack channel last August. I didn't wind up incorporating it directly into log.Valuer, but rather introduced a different type to help keep the purpose separate as I explored.

While that log record dropping is an appealing facility to generalize like this, it still falls prey to the same problem I ran into in my earlier attempts at solving this level filtering problem: a free function like level.Debug has no context or oracle with which to make a decision, so it's queuing a proposition, and the only thing in the stack of log.Logger and log.Context instances that can evaluate that proposition is the leveled log.Logger type; it's the only thing that knows which levels are allowed.

My goal has been to find a way to short-circuit the building up of key/value pairs in log.Context and the interpolation of log.Valuer instances for log records that will be dropped lower in the stack. However, I don't think that's feasible, given the "distance" and deliberate isolation between oracles (or facts) and queries that need to know those facts. If there's a log.Logger that makes filtering decisions, the current interfaces don't allow anything stacked above it to coordinate with it—until it receives a log.Logger.Log call, at which point all the work "above it" has already been done.

Introducing a way for a log.Valuer (or a similar type) to indicate that a log record should be dropped doesn't address this problem for local (non-global) oracles. If one wanted to drop log records when the current time of day is an odd hour, we can cheat by consulting the global system clock. The filtering predicate there is not contextual. In the level filtering example that @ChrisHines mentioned in Slack, though, the predicate is contextual.

The level values could be Valuers that somehow know what level to return and also know to return the special terminating value if their level is filtered.

Note second part: "if their level is filtered." How does a Valuer inserted by a free function know whether or not its level is filtered, when the only oracle in the system that does know that is a special log.Logger lower down in the stack, inaccessible from that free function higher up the stack?

The multiLogger type shown here earlier also poses challenges, as it creates a graph of log.Logger instances in which "closer" (higher up) log.Loggers can't easily make summarizing decisions for those "further way" (lower down).

I haven't given up yet, but I am much less certain that there's a big optimization here to be captured. I'll work on it more today to see whether any of my other ideas bear fruit.

[ChrisHines]

@seh Nice summary of the problem. I too have played with the sentinel value idea and have come to the same conclusions as you. It won't work without global state or a stateful layer above the log.Context, and both of those have their own baggage.

As you point out, trying to optimize away the construction of a keyvals slice cannot be done in general because the next Logger in the sequence may need that slice of values. Consider also something like the log15 EscalateErrHandler.

[seh]

I did come up with yet another approach. As of the end of the day when I have to stop, the benchmarks show some improvements compared to the experimental_level implementation, but in some cases this one is worse. I'll look over it tomorrow to see if I can figure out how to fix those cases where we do worse here.

It takes advantage of installing an optional projection function into log.Context—a function that allows changing the proposed key/value pairs and suppressing the record. This allows one to write an analog to log15.EscalateErrHandler.

More on this tomorrow.

[seh]

Please see #453.