Logging Habits

Got a bug on the production? How often you hear this from the developers ?

1. It works in my environment. I will add more logs to the application.
2. I see a log that there is an error, however it does not print the 'reason'.
3. The logs are not enough. I need to put more logs and deploy a 'debug' patch just to know what is going wrong.
4. It appears that api X is failing intermittently, but I need to look at those 100 MB logs to see if there is a pattern. This will take some time.
5. The issue appears after a days run. I need to put more logs to know the reason, however it will need a restart, which means we will have to wait for another day.

One reason behind such statements is, that the developers are not taking logging seriously enough. Putting log statements is an habit, and developers should cultivate it. Here are some of the things I may suggest ...

1. Put logging framework even before you write the first line of code

Be it log4j or whatever you like. You should add it to your code, and write all the configuration steps. It could be bare-bone, and may evolve later. Writing thousand lines of code with console.log statements, and later adding the framework is not only a waste of time, but also error prone.

2. Your logging framework must support logging level modifications without application restart.

As an example, if a module 'X' is failing, and it's logging level is set to 'warning', then the logging framework should provide a mechanism to change it to, say 'debug', by some external means, say by changing the logging configuration file. It should not need an application restart. Sometimes, it takes a long time to get the application to the state where it exhibits the buggy behavior. You don't want to wait for it. Moreover, it may help you in situations where the problem is intermittently reproducible.

3. Logging should not be added as an afterthought.

In other words, do not add log statements 'after' writing all your code well. Instead, add them while writing the code itself. This will help you in 'covering' all code paths, specify the correct levels, and log necessary context information.

4. Say 'no' to temporary log statements during development, say no to 'console.log' as well

Developers have a habit of putting 'log to console' statements, which they comment out or remove before check in. Discourage such practices. Let those logs stay. Remember to control the amount of logging by using 'logging level'.

5. Code bloat is better than diagnosing production issues

Write log statements everywhere. It should be easy to control the output by controlling the level. This sometimes results in a lot of log statements in the code, more than the actual code. Configure your editor to make it a less distracting. Another way to is write wrappers to reduce the code bloat, for example in coffee script you write something like

    logger.if('warn')?.log 'file not found', path
   
    instead of ...

    if logger.isWarningEnabled()
        logger.log 'warn', 'file not found', path

6. Note that there are sub levels after 'info'

Not everything that comes after 'info' is debug or trace. You may want sub-levels as well. For example, you may want to log

    log.trace 'DownloadFile:started {1}', url
    ...
    log.trace 'DownloadFile:{1} replied : {2}', url, reply
    ...
    log.trace 'DownloadFile:finished {1}; result : {2}', url, result
   
    You may want to print the first and the third statement when 'you really want to step through', whereas statement 2 when you know that the function calls are really making through. It will be simpler if we can write ...
   
    log.ifLevel(100)  log.trace 'foo started {1}', url
    ...
    log.ifLevel(20)  log.trace 'server {1} replied : {2}', url, reply
    ...
    log.ifLevel(100)  log.trace 'foo finished {1}; result : {2}', url, result

   
In this example, the 'log' object is picking up its output level by some external mechanism (say by watching an external settings file). If the output level for the module is set to 20 then only the second statement will be printed to the log file. If it is 10 then node of the statement will make it to the file.

There is a slight overhead in checking the level, and one should analyze the performance impact.

       
7. Every log statement must contain complete context information

Without 'enough' context, the log statement is useless. context should be explicitly printed with each log. Take for example a group of statements

    logger.log 'info', 'calling api', url
    ...
    logger.log 'warn', 'api failed'

In a multi threaded environment, the second statement may not tell you anything at all, because you could be trying multiple urls simultaneously.

    You may simplify it a little by storing the 'context' at the beginning of the operation.
   
    context  = { url : url, attempt : attempt++ }
    logger.log 'info', 'calling api', context
    ...
    logger.log ''warn', 'api failed', context
    
   
8. Format of the output statements should facilitate log analysis

In other words it should be possible to write scripts to analyze log output. You can write scripts to generate statistics of failures, or may be filter statements based on a certain 'context'. You can, for example generate charts that can help you visualize the patterns.

for example, instead of writing

    logger.log 'debug', 'Total memory is = ' +  maxMemory + 'Current Memory is : ' + currentMemory
   
The script that creates a chart from the logs will look much simpler if you write ...
   
    logger.log 'debug', 'memory;{1};{2}', maxMemory, currentMemory

Not much manual tweaking is required to generate a chart from such logs using Excel. 
   
Bottom line; logging habits can save a lot of debugging time.