Configurable LogCallerFinder via system properties and other improvements

[google]

Configurable LogCallerFinder via system properties and other improvements

[hagbard]

You just answered your own question :) ""something is wrong with some requests"".

I'm currently working on open-sourcing something that Flogger's had internally in Google for a while. It uses scoped contexts to provide more information to Flogger depending on the code scope in which the logging statement is run. Typically this will be (at least) a request scope.

Thus you will be able to add tags and control logging on a per request basis (including increasing log levels and bypassing rate limiting). This is far more useful than configuring the underlying log levels for several reasons:

1. If your server is running 100s of QPS, turning up logging in some areas just gives you loads of noise to sift through (since it's hard to decipher which request created which logs)
2. If you system is being debugged in production you won't increase user latency nearly as much (turning on full logging for a tiny number of requests is far less processing than turning on some logging for all requests).
3. You need a Flogger-side mechanism if you want to disable Flogger's built in rate limiting for requests.

This all stems from the observation (based on analysing lots of Google logging) that each additional log level that's enabled creates roughly 10x more logs (finer logging tends to be larger and in loops etc.). So if your baseline is "INFO", then if you enable "FINEST" logging, you get about 1000x more log output. On a high throughput server, it's therefore impractical to just "turn on more logging to debug an issue" because your user latency goes up too much. This makes "global" logging control rather less useful in big systems.

But if you can turn up logging for just the tiny number of potential problem requests, it's totally doable and won't impact all users. Obviously with this mechanism you can still turn up logging for all requests if you want, but you don't have to.

Gerrit already did their own version of this mechanism with Flogger in open-source (since the hooks are in there already), but I now want to make it generally available to everyone.

[hagbard]

Thanks for taking an interest in Flogger. As you have noticed some of the "internal" platform code and APIs are not very mature yet. I've deliberately left them as "constrained" as possible so that when we do need to extend them it's for a good reason.

I do want to make CallerFinder work with the latest "StackWalker" API, so there's definitely some work to be done there.

One point I'm not sure I agree with though is the idea of not using the class name for loggers. I think you want a consistent naming scheme (for configuration purposes) that's consistent between backends. I would not want changing a backend to mean that I cannot know what namespace loggers live in.

As a bit of background, I carefully designed the "forEnclosingClass()" as a constructor for the fluent loggers in the hope that one day we'd be able to make most logger instances shared. The current issue with the JDK loggers is that you only need a different backend logger instance per fluent logger in order to have different configuration. So you end up with thousands of "java.util.logging.Logger" instances which only really exist to hold the log level (since almost nobody uses filters of handlers on a per logger basis).

Thus rather than having "getLogger(name)" which ties you to really making new underlying JDK loggers, I went with "forEnclosingClass()" so that one day the system could share a single logger for the same package or higher.

In particular, if your logging was only ever statically defined, you could determine a minimal set of loggers needed (i.e. only those which had explicit static configuration) and reduce your application from having many thousands individual fluent logger instances to maybe just 5 or so (since most configuration is very coarse).

This would mean you couldn't change log levels while an application is running ... but I don't think that's a big issue (yeah, this sounds surprising, but please read on...). The reason I think it's okay to not have runtime logger configuration is that changing log levels while an application is running is a poor way to do debugging (which is mostly what it's used for). Flogger is designed to support "forcing" logging by using scopes. It lets you turn logging up within a "scope" (e.g. for the current request). This is far more useful that just turning the logger logs levels up and having all requests suddenly create more logs.

Because of all this I try very hard to not even give loggers "names" in the classes that use them. When using Flogger I don't think you should care what a logger is "called", you just get the one that's "right for your class" and use it. It might be shared between many classes, or not. You should not have to know.

You could, for example, have a mapping from class name to "module name" (i.e. every logger in "com.foo.bar" is given an internal module ID of "BAR" and then your configuration system could configure logging by module ID, not class name. But you still start with the class name and pass that into the backend, allowing it to map it to something else if it wants (I don't think there's any other natural starting identifier for a logger other than the class it's in).

Anyway, that's the idea, though since I'm mostly stuck with using the JDK backends in Google, I have not been able to prioritise this much.

I also agree that SimpleMessageFormatter is ... too simple. Backends are free to format things in different ways (including structured JSON) and I wanted to see if I could do something like what log4j2 does with its "Layout" classes. But even today it should be possible to have a backend that simply does something different to the default formatting.

[Maaartinus]

@hagbard I see that having thousands of logger instances doesn't sound optimal, but what is the possible gain worth? Sure, changing log levels is far from perfect, but there are cases when it's invaluable (something is wrong with some requests, it's not reproducible and you can't see any system therein).

[agsimeonov]

@hagbard Thank you for the response, love all the hard work and awesome design that went into this project. I agree with you that having thousands of fluent logger instances is not a good idea. What I am going for is more in line with what you mentioned as to using the module name as the logger name. In fact for my purposes currently I need to use a single logger for an entire application thus I define an application/service name to be used. Using the class name is just too much and results in too many loggers for some internal projects in a highly microserviced setup. For my use case in specific there is no easy way to infer the application/service name so I must define it in some static way such as an environment variable or system property however this allows you to keep using a getSingletonLogger() style method instead of getLogger(name). I think minimizing the set of loggers even further like so aligns more with the original design and I just want to see if we could devise a way to accomplish this whether it be by making LogCallerFinder configurable or some other means. I suggested the configurable LogCallerFinder change as it would preserve everything else including the forEnclosingClass() functionality by simply changing a single line here:
https://github.com/google/flogger/blob/master/api/src/main/java/com/google/common/flogger/backend/system/DefaultPlatform.java#L69

As for SimpleMessageFormatter I think I will go the route of devising my own MessageBuilder. My primary question there was really whether we could reuse some of the code from SimpleMessageFormatter as I would certainly be doing something similar on my own and simply changing the few lines that handle Metadata as for my use case the final result inevitably ends up as JSON.

[hagbard]

SimpleMessageFormatter is not intended to be a public API, so it's not something I want to make general purpose. Feel free to make your own formatter (and if you were to make it general purpose I might just pull it back as an alternate format). I quite like the style of things like "PatternLayout" that log4j2 has, though it would need some tweaking to work with tags etc.

So one thing I've realized I probably got wrong with the design (though it's not terrible) is having the "getLoggerName()" method on the LoggerBackend. I think the "name" should have been an attribute of the FluentLogger and nothing else.

You can still work through this by having your (many) backend instances have different names but sharing the same underlying logging instance, but I'll look at deprecating or changing the getLoggerName() method, so you can just have a single shared backend instance everywhere.

The name (or something like it) will need to be kept somewhere so it can be visible to LogData, because that's how you control logging with this new request scope mechanism (by class name) but perhaps it can just be on the FluentLogger instance and not the backend. I'll investigate.

[hagbard]

In fact you've just made me see an issue in the JDK backend, since it uses the underlying logger name for "getLoggerName()". This is wrong since it prevents JDK loggers being shared. If the loggers were ever shared then the logger name would have to be stored in the backend or the fluent logger itself.

However I like not having to have the extra field in the fluent logger when it's not needed. I'll have to think about this a bit more. Thanks for the feedback.