Rules and advice for logging?

Question

In my organization we've put together some rules / guildelines about logging that I would like to know if you can add to or comment.

We use Java but you may comment in general about loggin - rules and advice

1. Use the correct logging level

   • ERROR: Something has gone very wrong and need fixing immediately
   • WARNING: The process can continue without fixing. The application should tolerate this level but the warning should always get investigated.
   • INFO: Information that an important process is finished
   • DEBUG. Is only used during development

2. Make sure that you know what you're logging.

3. Avoid that the logging influences the behavior of the application

The function of the logging should be to write messages in the log.

1. Log messages should be descriptive, clear, short and concise.

There is not much use of a nonsense message when troubleshooting.

1. Put the right properties in log4j

Put in that the right method and class is written automatically.

Example:

Datedfile -web

log4j.rootLogger=ERROR, DATEDFILE
log4j.logger.org.springframework=INFO
log4j.logger.waffle=ERROR
log4j.logger.se.prv=INFO
log4j.logger.se.prv.common.mvc=INFO
log4j.logger.se.prv.omklassning=DEBUG

log4j.appender.DATEDFILE=biz.minaret.log4j.DatedFileAppender
log4j.appender.DATEDFILE.layout=org.apache.log4j.PatternLayout
log4j.appender.DATEDFILE.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%C{1}.%M] - %m%n

log4j.appender.DATEDFILE.Prefix=omklassning.
log4j.appender.DATEDFILE.Suffix=.log
log4j.appender.DATEDFILE.Directory=//localhost/WebSphereLog/omklassning/

1. Log value.

Please log values from the application.

1. Log prefix.

State which part of the application it is that the logging is written from, preferably with something for the project agreed prefix e.g. PANDORA_DB

1. The amount of text.

Be careful so that there is not too much logging text. It can influence the performance of the app.

1. Loggning format:

-There are several variants and methods to use with log4j but we would like a uniform use of the following format, when we log at exceptions:

logger.error("PANDORA_DB2: Fel vid hämtning av frist i TP210_RAPPORTFRIST", e);

In the example above it is assumed that we have set log4j properties so that it automatically write the class and the method.

Always use logger and not the following:

System.out.println(), System.err.println(), e.printStackTrace()

If the web app uses our framework you can get very detailed error information from EJB, if using try-catch in the handler and logging according to the model above:

In our project we use this conversion pattern with which method and class names are written out automatically . Here we use two different pattents for console and for datedfileappender:

log4j.appender.CONSOLE.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log4j.appender.DATEDFILE.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

In both the examples above method and class wioll be written out. In the console row number will also be written our.

 

1. toString()

Please have a toString() for every object. EX:

@Override
public String toString() {
  StringBuilder sb = new StringBuilder();
  sb.append(" DwfInformation [ ");
  sb.append("cc: ").append(cc);
  sb.append("pn: ").append(pn);
  sb.append("kc: ").append(kc);
  sb.append("numberOfPages: ").append(numberOfPages);
  sb.append("publicationDate: ").append(publicationDate);
  sb.append("version: ").append(version);
  sb.append(" ]");
  return sb.toString();
}

instead of special method which make these outputs

public void printAll()
{
    logger.info("inbet: " + getInbetInput());
    logger.info("betdat: " + betdat);
    logger.info("betid: " + betid);
    logger.info("send: " + send);
    logger.info("appr: " + appr);
    logger.info("rereg: " + rereg);   
    logger.info("NY: " + ny);   
    logger.info("CNT: " + cnt);   
}

So is there anything you can add, comment or find questionable with these ways of using the logging? Feel free to answer or comment even if it is not related to Java, Java and log4j is just an implementation of how this is reasoned.

Answer 1

As an extension of your rule of logging where in the application the log statement came from, you may want to add per module level logging flags. Instead of logging everything, all the time, this allows you to selectively target sections of your application instead. There is overhead in this, and you need to create a facility that allows you to enable / disable that logging. Ideally, you would be able to enable / disable on-the-fly as the application is running.

I'm used to seeing a layer below debug which I term "Trace", but that's not necessarily a universal term. "Trace" level logging tracks as much as you can possibly stand, including module entry / exit, timestamps with entry / exit, and bonus points for capturing passed values. Obviously, that generates a LOT of data and it's not something you turn on willy-nilly. But it has advantages with respect to debugging when you can't attach to the process or you don't have a core dump of the errant application.

I like to see file / module references and timestamps with my log information. It can be handy when trying to hunt down race conditions between threads as well as coordinating the activities of multiple areas of the application. To be fair, I know of some folk who think these details clutter the log file. Adding in the timestamp is something to discuss with the team. (Apologies if log4j already does that.)

If the logging isn't being taken care of by it's own thread / process, that's something to consider as well. Instead of making the application thread wait for the logging to process, the log message gets passed off to the log handler and the application thread goes on its merry way. Alternatively, creating some sort of buffer mechanism to handle the log messages is another way to speed up application responsiveness.

Having controls on the size and history of log files is another feature to consider. You don't want the app blowing out all the disk space on the host system, nor do you necessarily want to keep all log files for all eternity.

Answer 2

One thing to keep in mind is to check the logging level before you do any kind of string operations for logging. That is, don't go to all the work of setting up a date formatter or concatenating a bunch of strings to create the log message if you aren't actually going to log it. That's just wasted work that slows your application down.

FYI, the Apache Commons project has a ToStringBuilder class that simplifies creating your toString() methods.

Answer 3

I do not find anything questionable in what you have added here Nick. This is how I have been doing it for some time . The post that you have provided is very detailed and probably can be used as a kind of a tutorial for logging. However, i do want to add one thing here, which is : In many places, i have been seeing chaps using conditional logging, for e.g. :

     if(env_local)
     {
     write_to_local();
     }    
     else if(env_IT)
     {
     write_to_IT();
     } 
     else if(env_PROD)
     {
     write_to_prod();
     } 
     else
     dosomething();

I do think this kind of conditional tracing or debugging is not the best way to go .

Answer 4

In addition to logging the Class / Method that raised the error, it would be useful to also log the parameters passed into that method. Knowing where an error was raised isn't very useful if it only happens 1 time out of 1000; you also need to know what data caused the error to occur.

I've also found it useful to have a variable which defines the default level of logging for an application. That way you can have DEBUG and INFO code alongside WARNING and ERROR code. When running in production mode you default it to not output DEBUG info, but when a bug shows up you can update a flag and start writing DEBUG messages to the log as well.

Answer 5

Logging is most of the time a cross cutting concern. Java alone is not sufficient expressive to make you able to seperate the logging from the your actual business logics. This means you cannot for example just take one method and put it into another project but you you have to remove and adjust all your logging before you do. And that is just the tip of the iceberg.

To prevent that and other issues when mingling logging and "real" business logics you should regard using aspect oriented programming. For Java the most used framework would be AspectJ. There is this youtube video from google tech talks that explains AspectJ and its uses beyond logging pretty well. You will find many examples for logging yourself of course here on stackexchange too.

Answer 6

It is useful to dynamically change log level at module level or application level (or more detail level) without restarting the running system or rebuilding them (especially when it takes time to restart/rebuild).

There are options to achieve the dynamic log-level change, for example:

• Check whether log configuration file (if exists) is modified, check that periodically or on the event of saving the change, then apply the change to running application, you could do that by setting up cron jobs or task queue.
• Create API, make log-level change through the API from external system, but you have to handle authentication and authorization issues.
• Apply publish–subscribe pattern, one application changes log level of module(s) within the application(s) by sending message to these applications. It's complicated, you need message broker, but effective in distributed system.

Answer 7

One thing I would suggest would be that you have a means of having multiple logging contexts associated with any particular log file, and arrange so that anything written to any logging context will get logged unless code explicitly asks the logging context to discard its contents. Such a design will allow one to capture rather detailed logs during an operation and discard them if the operation succeeds, but have them available if the operation fails. Absent such a logging feature, having good logs available when something fails may require that an application waste lots of time logging useless data in the 99.99% of times when everything works.