Writing Log statements

 

The question of how to write log statement, and what level to use keeps on jumping into my head every while and then. Reading few articles from the net, mainly:

https://devcenter.heroku.com/articles/writing-best-practices-for-application-logs

While we may find it appealing to come up with what we believe "best practice", and put efforts laying a structured approach to how to write logs, I don't believe this is attainable nor productive. Alternatively, I find communicating the why/why not, and leaving it to the developer's judgement is a better approach, and yield more consistent thinking in the long run.

The first question we need to ask is "what are we trying to accomplish?". In my opinion, and as a software engineer, I like to make it easier to find root cause of errors in the software. But this is only me. Other's may have different usage for logs. Business analysts may use logs to decide what feature is used most, helping them making educated decisions about what feature to enhance and what to may be deprecate. Security analyst may find interesting information in how intruders try to gain access into the system.

So back to the question "What are we trying accomplish". We are trying to keep a record of internal and interesting events, that will "hopefully" assist the user to travel back in time and find an answer to some question related to the system operations. This includes a bugs, where we need to go back in history moments before an issue surfaced, and examine the state of the system at that moment.

The root cause may not always be readily available, but by collecting small evidences we may be able to solve a puzzle. 

 

Logging frameworks have more in common than we think. They all have log levels. Those levels can be dialed up or down, depending on the current needs, and without affecting the over all availability of the system. Log systems like Linux syslog, log4j, log4net, log4c, have more or less similar log levels to match the priority of the log statements.

• FINE 
• Trace
• Debug
• INFO
• WARN
• ERROR
• FATAL 
  

 

Do and Don't:

• Don't put log statements at the entry and exit of a method. This is useless. Any instrumentation agent can instrument those method to produce this log at runtime. These agents can be added and removed at application startup. There's no need to clutter the code.

• Don't abuse INFO/ERROR levels.
  

• INFO mostly for events like 
• "Starting Deployment of accounting-app", 
• "Config File found at /path/to/config.xml", 
• "Connection to FTP://ftp.host.name:Port establish",
• "Scheduled process XYZ started Successfully"
• "Kernel: Loading driver web-cam.o",
• "User admin logged in successfully",
  
•  .. and so on

Generally speaking, I may use INFO to indicate starting or ending of an event (NOT a request), but nothing more.

• Exceptions are not errors, when caught (unless you are re throwing them). They are part of the flow of the program.  Yes, they are exceptional flow. Think about them as a beautified "GOTO" statements. They transfer flow up to the caller, indicating unexpected condition occurred.
  

• TRACE/DEBUG are your friends. Most systems, have their log level set to INFO by default. This means that those LEVELS will not clutter your log files with noise, making them less useful. However, we can activate them when needed. Evaluate the priority of the event you are logging when coding business logic. Very likely it will be one of these two.
  
  
•  FATAL is definitely not for every day use. It is intended for events that may render the system unusable, and it signals higher priority action. Possible examples:
• Connection to database refused
• Remote server unreachable
• No space left of disk
  
  
• Avoid log statements inside loops. Those generate a lot of noise, and if your logging framework has latency, they may introduce delay and make the system less performant.

 

Keep in mind, more log lines does not mean more visibility. A noisy log file, that requires efforts searching and understanding traces is another effort wasting task. What you need, is to be able to locate and understand quickly the flow of the program execution that led to specific issue, with minimal efforts.

 

So what do we log and How do we keep our logs meaningful ?

Write log statements for interesting paths. For example:

 

def credit_account(sourceAccount, targetAccount, amount){

    if (sourceAccount.value < amount){

        logger.debug("Available funds in account {}: {} less than requested ", sourceAccountId, amount);

        // this is not error. Just validating the current state of the account.     

         throw new IllegalStateException("Insufficient Fund");

    }

logger.trace("Debiting account {} amount {}", sourceAccId, amount);

sourceAccount.value = sourceAccount.value - amount

logger.trace("Crediting account {} amount {}", targetAccId, amount);

targetAccount.value = targetAccount.value + amount

}

While this example is extreme, but it demonstrates that Business logic like this, is very good candidate to take log statements. We don't have to write log statement for every like of code.

Notice that, we didn't use ERROR level when fund is insufficient to complete the transaction. This is not an error. And not an INFO that we should always see when opening a log file. There's nothing indicates it is a WARN level. In my opinion, there's nothing wrong at all about this flow. It is just normal validation for business rules. However, capturing it, may be useful at some point in the future. And likely to be needed more than the following trace statements.