Some Thoughts On Logging & API design

Some Thoughts On Logging & API design

Why should anyone care?

On many occasions good logs can make developer’s lives easier. Logs are especially useful during production support because when things go wrong and we need to figure out why logs is our best friend.

In some industries logging can even be part of security and auditing requirements. Baking is the simplest example of that.

In my experience I’ve noticed that usually people do not give much thought to this topic and either follow their gut feeling and write logs whenever they happen to remember about it or do not write any logging at all and later when something breaks they randomly add logs hoping to catch the bug.

If we add Java into the picture it becomes even more fun because we get exceptions & runtime errors which create hidden branches of logic in your code. I’ll will not be arguing here whether it is good or bad because the topic of checked & unchecked exceptions deserves a lengthy discussion. Instead I will concentrate only on messages inside those exceptions because they are important part of any logging and sometimes good error message can save you from hours of debugging.

Too much of a good thing is not a good thing

Before we go further we need to keep in mind why we write logs. Usually we do it because we need to support software to make sure it does the thing it is suppose to do. Exactly like that and not the other way around. Customers usually do not hire developers because they want logs to be written. Usually they need to solve some real-world problems with help of some software and usually they need it to be working reliably and that is the main goal. Logs simply help us to get there. So logs have secondary importance and because of that we should remember to keep it moderate. Do not turn your code into mess of log statements. Do the minimum logging required to get the job done. Balance is very important here.

So what is good logging and what is bad logging?

Obviously good log is the one which tells you what your application does, it should be readable and does not contain too much of duplicate information.

Bad log is the one which does not exist or exist but is of no use to you. If your log is too big it can be as bad as no logs because if you can not find anything in there it won’t help you to do your job.

Dos and Dont's

We can follow simple rules to keep logs short & useful:

I. Whenever you work on a task after you finish implementation make sure to look at your change-set it as a whole and consider if you have proper logging. Git is your best friend here. You can simply use any graphical diff tool go though your changes. It is ok to write logs while you write your code but it is important also to look it after implementation is finished because only then you can see the full picture and see things which you would not notice while writing that code.

  1. Try to think where logging is needed and where is not.
  2. Think if you use correct severity log levels: trace, debug, info, warn, error.
  3. Try to see how your code handles exceptions. Should you add or remove some try-catch blocks? If you throw or catch exceptions think if their messages give enough information to the one who is going to see them. Imagine that you see each exception in log, will you have enough information to understand what to do about it?

II. Usually it is a good idea to add logging before each exit point in your method, which can be:

  1. implicit exit for methods returning “void”, there the code just ends without any “return”
  2. return
  3. throw
  4. unchecked exception inside any other methods you call from your method

The last one is very easy to overlook. Ideally if your method is called whatever the result is you should see in logs what has happened and why. Intellij IDEA can greatly simplify this job. If you put cursor on any “return” or “throw” statement it will automatically highlight all exit points in your method with the exception of runtime exceptions, those won’t be highlighted as well as implicit returns for “void” methods.

III. When you catch an exception and either log it or re-throw wrapped into another exception make sure to describe in the message what does this error mean in current context and not just the fact that it has happened.

In such cases usually you are trying to execute some logic, so you can log what you were trying to do, what has happened actually, why and what consequences it might have in current context. It is important to keep that message detailed enough to give relevant information about the error without making it too generic or stepping out of current method’s zone of responsibility. Do not try to argue about consequences of industrial revolution to modern society in your error messages. You method is supposed to be designed to do one single task, so describe what that error means in scope of that task and what consequences it might have if any in scope of that task.

That way if methods re-throw errors they will be enriching the stack trace with more and more information up to the highest level in your application where you can decide if you want to show it all to the user or log the stack trace and show something more friendly to the user.

IV. Do not write too much logging. If you write code which makes calls to other classes which already have proper logging do not duplicate what they already do. Let them take care of logging. Do not turn your code into mess of log statements and logic unless you really need that. Keep it short and efficient.

V. Do not log too much information because it can become tedious and you will stop doing it. The rule of thumb is to log the required minimum to understand what is going on and why and keep doing it.

Example #1

In this example we have DefaultSearchService class with simple public List<User> search(final String request) method which simply calls someExternalLibraryClass.search(request); and returns the result without any modifications.

Lets see what can go wrong here.

First of all we make a call to an external library or API (that can be database access, network operation, or just a regular library call) someExternalLibraryClass.search(request); and we do not know if it provides decent logging or if that call is simply not going to hang. So it makes sense to log a message saying that we are about to do that call and lets not forget to provide context information like input parameters relevant to that call because LOG.debug("Searching for users by request”) by itself is not very useful, so lets add LOG.debug("Searching for users by request: '{}', request.");

Now it is better but still from logs we won’t be able to figure out if that call was successful or what was the result or it threw an exception which was swallowed by another code.

So lets add another log message describing what has happened and again do not forget to add some context information.

LOG.debug("Found '{}' users by request: '{}', CollectionUtils.size(result), request.");

We use CollectionUtils.size(result) because if result is null and we do result.size() it will crash our code. We do not want logs to crash our application.

Ok, so now if we look into logs we will have a decent picture of what was going on. Let now use this method somewhere.

In this example there are no logs needed because this method does not contain any conditional logic (if-else, loops, try-catch) and does not call any external API or library code and its execution plan is very straightforward:

enter method => call delegate method => return value without any modifications

There are no branches in this logic or even extra steps. So we can assume that the delegate method takes care of all necessary logging because we have implemented it and if necessary can fix it.

If you find yourself in situation where you want to add logging to such straightforward method please consider if you should add that logging to the delegate method instead because that is most likely where it belongs and since you feel like you are not getting enough logs it signals that the delegate is not doing proper job with logging, so it would be better to fix that problem in one place (in the delegate) rather than adding extra logs around all its usages.

Example #2

Now let's make that search method more sophisticated and add some logic to it.

Now we have a method with some custom logic inside and it is worth to think if we need here logging or not. Most likely we do.

We do not need any logging for userSearchService.search(request); because we know that it takes care of its logging and we should not duplicate it. Our method should log only its own actions or calls to the external API.

Fist of all we need to see how much exit points we have in the method. In this case only 3. Again, Intellij IDEA can help you find all of them if you put your cursor on any “return” or “throw” statement. If you have more you might want to think if you should break it down into several methods.

In the exit point #1 we throw an exception. In such case writing any logs usually is redundant because if you want to log something do it via exception’s message. The only case when it makes sense to log something here it is if you need to log big amount of debug information which you can not or do not want to put into the exception. But even then to avoid turning your code into unreadable mess it might be better to create a custom exception class and take care of collecting debug information there or at least extract it into a separate method.

In the exit point #2 and #3 we use “return statement” with some conditional logic. Here we have several execution paths and we should make sure that we have logging for each of those paths so that the log can help us understand which way the execution went.

Conclusion

Logging is an extremely powerful troubleshooting tool. Despite the popular belief "the more logs the better", one should be careful with the amount of logging. Besides it, the information reflected in logs plays a very important role during troubleshooting.