Enhancement: Method entry/exit logging

[morols]

I've been experimenting with implementing a logging annotation for logging entry and exits to functions. So far, I've only tried getting my hands dirty with javac and I have a very basic implementation working. Before spending more time on it, I wanted to hear if it makes sense to have this feature in Lombok.

Motivation In the projects I work on, it is often essential to take special care around places where the execution enters and exits our code. This may for instance be a REST end-point method, where we want to log the entry and exit with enough context for troubleshooting; and we want to log an exit even if an unexpected exception is thrown. We also have some methods that are called very often (e.g. with price updates), in those cases we don't want to log common entry and exits, but do want to log any exceptions thrown, with enough context.

The enough context mentioned will usually include some identifiers on both the entry and exit entries - and then some additional values from the parameters on the entry (or an exception exit in case no regular entry/exit is logged).

Logging The general logging entries I want to see are something like the following.

Enters <method name> with [param1name=param1value, ..., paramNname=paramNvalue]
...additional logging done during the processing of the method...
Exits <method name> with <return value|exception type and message>
<potential stack trace>

I'm working towards being able to add identifiers to a log diagnostic context (MDC) so they can be used in the log pattern and show up on all log entries done in the processing of the method call. In addition I also want some control over the parameter values logged on the entry (or potentially the exception exit if no regular entry/exit is logged). This control is both to filter away less important information, but also to lookup information inside objects.

Annotations I'm thinking about being able to use annotations like in the following manner. As the name "Log" was already taken, I'm using "CallLogging" here, but better names may exist.

class {

    @CallLogging
    public String doSomething1(@Mdc String itemId, @Param boolean param1, int param2) {
        ...do something...
    }

    @CallLogging(mdc={@Mdc(key="itemId", value="item.getId()")})
    public String doSomething2(Item item, boolean param1) {
        ...do something...
    }
}

This should in both cases produce something like the following lines when called. The itemId put in the MDC can be used in the log pattern used to be shown somewhere in the lines - also on the lines being logged "manually" during the processing of the call.

... <itemId> ... Enters doSomethingX with [param1=true]
... <itemId> ... ...additional logging done during the processing of the method...
... <itemId> ... Exits doSomethingX with a return of "something"

I've tried to indicate that if some parameters are marked with @Param it will only be those shown in the end of the "Enters" line. And if no parameters are marked all will be shown excluding those marked with @Mdc. I've also indicated that when the @Mdc (and @Param) annotation is used on a parameter without any parameters for the annotation it will use the name and value of the parameter directly. I'm not entirely sure how it all should work except it will be best that as little configuration as possible is needed for the most common cases.

Runtime vs. compile-time annotation I'm new to custom annotations and most of the functionality described here might be achieved with runtime annotations and aspects. However, the feature to indicate that some value should in some cases be extracted from within an object seems to require reflection and I'm not sure, but may perhaps also be more difficult to implement. Generally, I imagine there may be a performance benefit of implementing it as a compile-time annotation, but again, I'm not sure and especially I'm unsure if it makes it worthwhile to do it as a compile-time annotation.

Additional features Above I have sketched the main features that I'm interested in. The motivation is to ease troubleshooting and know what is going on in an application at essential junctions as well as to ease searching and browsing the logs. Here are some additional features that I can think of that is not sketched above:

• Ability to put annotations on class level, so all (public) methods will be logged with the common settings on the class level (and with the ability to override on the method level).

• Ability to set the log levels. Usually we would like to have the regular entry and exit logged with INFO level and exceptional exits with ERROR/SEVERE level. However. others may have other preferences and the annotation can handle more use cases if it is made configurable. We might run with the regular entry/exits being logget to a debug level to see them locally, and still have the exceptions logged with an error level so that is seen in production. We may also add the annotation to more internal classes/methods to be able to trace the execution in the logs when developing/testing, but without wanting that to be logged in production.

• Integrate with other annotations for integration points. For instance for REST methods, it may be possible to detect the path from the other annotations and show that in the log message, e.g. "Enters deleteUser (DELETE /users) with [userId=20b9868acd2692f4, trash=true]". For JMS queues it could be the queue names being extracted and so on.

• Ability to also time calls, in just wall clock time. When wrapping the call with the logging code, we could also record the time before and after and log this in the exit, e.g. "Exits deleteUser after 6ms with {userId:20b9868acd2692f4, firstname:Morten, ...}".

• Perhaps it will be possible to add a new annotation for integration calls that will log a call being performed and with what parameters. For instance, when making a REST call to some service, it will be great to be able to see in the logs the data that was send and perhaps also the URL. This is kind of the consumer side of the annotation described here, but it may be harder to make.

[lokesh-chechani]

Should be very helpful in troubleshooting as information logged is consistence. Wondering is the entry/exit method execution logged as well to collect any performance metrics.

eg. log statement in logs at the exit of the method would be - "Execution completed in xx ms"

thoughts?

[splashvarun]

This is exactly what I am looking for to use Lombok. Currently we use Spring AOP to achieve this, but this has a runtime overhead of proxy classes.

Even if we have only entry and exit static logging with the method name, that should be enough too. While debugging the error, it helps to identify the flow of request in the system. Logging of parameters with the method can become an issue if we have fields like password, credit card details, etc.

[morols]

I also ended up implementing this with aspects instead.

We have an annotation for indicating that a sensitive parameter should not be logged. For complex objects, where we just want to exclude some field(s), we use the lombok annotation to remove fields from the generated toString.

On Fri, Apr 12, 2019 at 10:28 AM Varun Modi notifications@github.com wrote:

This is exactly what I am looking for to use Lombok. Currently we use Spring AOP to achieve this, but this has a runtime overhead of proxy classes.

Even if we have only entry and exit static logging with the method name, that should be enough too. While debugging the error, it helps to identify the flow of request in the system. Logging of parameters with the method can become an issue if we have fields like password, credit card details, etc.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/1365#issuecomment-482486955, or mute the thread https://github.com/notifications/unsubscribe-auth/ABOsZFYOxyjuDePzd6dKzEtfnaL1gqgoks5vgEOngaJpZM4NFBB9 .

[janrieke]

The maintainers also already stated that they will probably not include such a feature, because they feel that using AOP is the better solution for this type of problems.

[cosmicdan]

The maintainers also already stated that they will probably not include such a feature, because they feel that using AOP is the better solution for this type of problems.

Which introduces more bloat and overhead, to be honest.

Lombok having this would be nice.

[rzwitserloot]

What's making it hard to judge the suitability of this feature for lombok is the following dilemma:

• The 'benefit' is very high; it's a heck of a lot of boilerplate or a major impact on your dependency and build stack if you try to use AOP solely to add this stuff.
• The 'cost' is a bit weird; writing and maintaining the feature isn't that much effort, but, it suggests all sorts of falsehoods. This feature existing implies that you should generally log method entries and exists (incorrect - you should almost never do this. I do ackowledge there are rare scenarios where you would prefer this), and even worse, that trying to time the execution time of a single method is a good way to keep track of the performance of your software (very incorrect - the VM is far too complicated for this; the best things to just straight up time aren't so much methods, as operations like invoking a DB query, and even then you often want accumulated stats and not just a gigantic batch of log statements).

So, it's a feature that in basis seems to cross the cost/benefit analysis bar (medium benefit for a relatively low write/maintenance cost), but my issue is how do I document: "Really, don't use this... unless you really know what you are doing and here are a whole bunch of things to read and alternatives to look into before you resort to this dangerous bazooka"? Do we create a separate package in lombok of stuff which definitely should absolutely not be taken as advice on how to write code? Do we 'hide it' on our feature pages?

I'll discuss it with @rspilker before I shoot it down. Maybe we're willing to provide this.

[randakar]

As someone guilty of routinely adding debug logs for method entry in the past some comments:

1) It only really helps as a poor man's debugger. In lieu of a real debugger it can help. .. but .. you really should have a debugger available in the vast majority of cases.

2) If you want something that logs the time it takes your application to do its work end-to-end - sure, there's a benefit to that .. but .. it really should only be added to the entry / exit points of the application at which point Lombok really no longer should be involved since it's no longer real boilerplate.

3) For real performance measurements there are better tools - Dynatrace for one, VisualVM may be able to help as well.

All in all I've pretty much moved beyond method entry logging. It can be a debugging tool with value but not something you should routinely add.

On Tue, Feb 4, 2020 at 3:23 PM Reinier Zwitserloot notifications@github.com wrote:

What's making it hard to judge the suitability of this feature for lombok is the following dilemma:

• The 'benefit' is very high; it's a heck of a lot of boilerplate or a major impact on your dependency and build stack if you try to use AOP solely to add this stuff.
• The 'cost' is a bit weird; writing and maintaining the feature isn't that much effort, but, it suggests all sorts of falsehoods. This feature existing implies that you should generally log method entries and exists (incorrect - you should almost never do this. I do ackowledge there are rare scenarios where you would prefer this), and even worse, that trying to time the execution time of a single method is a good way to keep track of the performance of your software (very incorrect - the VM is far too complicated for this; the best things to just straight up time aren't so much methods, as operations like invoking a DB query, and even then you often want accumulated stats and not just a gigantic batch of log statements).

So, it's a feature that in basis seems to cross the cost/benefit analysis bar (medium benefit for a relatively low write/maintenance cost), but my issue is how do I document: "Really, don't use this... unless you really know what you are doing and here are a whole bunch of things to read and alternatives to look into before you resort to this dangerous bazooka"? Do we create a separate package in lombok of stuff which definitely should absolutely not be taken as advice on how to write code? Do we 'hide it' on our feature pages?

I'll discuss it with @rspilker https://github.com/rspilker before I shoot it down. Maybe we're willing to provide this.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/1365?email_source=notifications&email_token=AABIERKNZUHXJ3FGGJPTLODRBF27TA5CNFSM4DIUCB62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKXZPYI#issuecomment-581933025, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIERPHWPYT74DLVLBIJ3TRBF27TANCNFSM4DIUCB6Q .

-- "Don't only practice your art, but force your way into it's secrets, for it and knowledge can raise men to the divine." -- Ludwig von Beethoven

[rzwitserloot]

@randakar See, that. Precisely that. I don't need any convincing that you've got the right idea, but how often do scenarios come up where 'just do it right, use different / better tools, and learn how to debug properly' is valid advice, and how often is that more of a: "Yeah duh, thanks, sherlock. I KNOW! But this is some weird exotic scenario which makes doing it right somewhat complicated, and entry/exit logging is what I'm gonna do no matter how much convincing you try, so, is lombok going to make that easy for me or what?"

I'm 100% convinced we need to take extra care that any potential users are very explicitly reminded to think thrice, and then think twice more to be sure, before resorting to this. I have some ideas on how to do that.

The real question is: Should lombok be in the business of catering to this, and with that caveat in mind, does this feature still cross the benefit vs. cost analysis bar?

[randakar]

Well, there are a few situations in which being able to add this quickly is a nice to have.

• Load related problems If you have some kind of concurrency issue or memory issue you need to know what thread does what in what order. Having a debugger pause threads is less helpful than a good log in such a case.

• Hard to reproduce problems Heisenbugs, problems that happen so rarely that you need some kind of log to even have a chance of getting a handle on it.

• Debugging unavailable Sometimes you can only reproduce something in an environment where debugging is not possible..

Having the ability to quickly annotate a class in order to get (some) logs in place can be helpful in such cases. Most of these are rare (item one on this list I have needed to do exactly once) but when you need to do something like that it is pretty painful.

Still not convinced it really is much better than just writing your code manually though ;)

On Tue, Feb 4, 2020, 17:02 Reinier Zwitserloot notifications@github.com wrote:

@randakar https://github.com/randakar See, that. Precisely that. I don't need any convincing that you've got the right idea, but how often do scenarios come up where 'just do it right, use different / better tools, and learn how to debug properly' is valid advice, and how often is that more of a: "Yeah duh, thanks, sherlock. I KNOW! But this is some weird exotic scenario which makes doing it right somewhat complicated, and entry/exit logging is what I'm gonna do no matter how much convincing you try, so, is lombok going to make that easy for me or what?"

I'm 100% convinced we need to take extra care that any potential users are very explicitly reminded to think thrice, and then think twice more to be sure, before resorting to this. I have some ideas on how to do that.

The real question is: Should lombok be in the business of catering to this, and with that caveat in mind, does this feature still cross the benefit vs. cost analysis bar?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/rzwitserloot/lombok/issues/1365?email_source=notifications&email_token=AABIERLENYO6C5JDNPCUEG3RBGGSLA5CNFSM4DIUCB62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKYFG5Y#issuecomment-581981047, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABIERO676QZ36PYJFUSEG3RBGGSLANCNFSM4DIUCB6Q .

[Maaartinus]

The 'benefit' is very high; it's a heck of a lot of boilerplate or a major impact on your dependency and build stack if you try to use AOP solely to add this stuff.

Moreover, tools love to interact in bad ways, so I could imagine spending a whole day on this. For example, I'd bet there'd be problems with proxy-generating AOP tools interacting with Hibernate proxies.

Debugging unavailable

For me, debugging is sort of the last resort. At the end, you find the culprit, but that's all - unlike with assertions, preconditions and logging.

Do we create a separate package in lombok of stuff which definitely should absolutely not be taken as advice on how to write code? Do we 'hide it' on our feature pages?

I guess, a package like lombok.unwise would be fine. However, all features should be listed somewhere... maybe with requiring one more click to show and starting with a warning, but it should be there.

[MalikKillian]

To respond to the "you should use a real debugger" comment, using a debugger isn't always an option. Locally I can use a debugger but in my org you aren't allowed to run debug sessions on deployed/remote code. Adding logs to the nth degree is fine though.

I like this suggestion and there's probably a few times I would've implemented it for debugging purposes. This would be way easier than adding AOP to a project that has never used it before. It would also be a bit more obvious as an annotation whereas AOP can be implemented in some subtle ways that may miss a code review and end up in Production.

[Alois-Komenda]

Hi, any news on this topic?

Despite all the drawbacks, this feature would solve the task of method entry logging in a very convenient way.