Java Logging – Rules and Advice for Effective Logging

javalogging

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

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
Make sure that you know what you're logging.
Avoid that the logging influences the behavior of the application

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

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

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

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/

Log value.

Please log values from the application.

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

The amount of text.

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

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.

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.

Best Answer

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.

Related Solutions

Best practices for logging and tracing in .NET

The importance of trace types must be chosen not because of where the trace is in code, but because the traced message is more or less important. Example:

Trace a "Start" event when beginning a method, which should represent a single logical operation or a pipeline, along with a string representation of the parameter values passed in to the method.

Use start type when you start a logical operation. This doesn't mean that the start trace must be at the beginning of a method, nor does it mean that a method must have a start trace.

This being said, in most cases, a logical operation will actually start at the beginning of the method. Otherwise, you should ask yourself if the code is refactored correctly.

Tracing parameters may also be a bad idea. You have to think what to trace, case by case. For example it is really bad to trace parameters of a method void Authenticate(string userName, string plainPassword).

Trace an "Information" event when inserting an item into the database.

It depends. Some items must be traced, but not every item.

For example imagine you are actually inserting a log item into your database. Would you trace logs? And then log traces? And then trace the logging of the trace?
Another example: you're inserting a sensitive data. This requires auditing. Since you audited the insertion, why tracing it?

Trace an "Information" event when taking one path or another in an important if/else statement.

Again, it depends.

Trace a "Critical" or "Error" in a catch block depending on weather this is a recoverable error.

The action taken after a non-recoverable error can be more than tracing. For example server-side, you would like to store the exception in the database for further analysis. Also, some exceptions are less important than others, and does not require tracing.

Trace a "Stop" event when finishing the execution of the method.

See the first point.

please clarify when best to trace Verbose and Warning event types.

Verbose:

Verbose is used to trace what you need to trace when something goes really wrong. It means that in most cases, you will disable the tracing of verbose messages, but sometimes, you have to debug some parts of your code to understand why something fails on an edge case.

You usually have lots of verbose messages which let you understand really well the application flow. It also means that those messages must be disabled most of the time because:

otherwise, the log will grow really fast,
you don't need them most of the time,
they may contain sensitive data about the application flow.

Think about verbose as a tool you have to use when you don't have an access to the debugger.

Warning:

Warning type trace is used when something wrong and important happens, but is not too crucial to be treated as an error. For example low RAM may emit a warning, but there is no reason to trace an error, since your application can continue, even if it will be slower than usual.

Examples:

Example 1: the application failed to open the file the user requested to open. The file exists and is not in use, permissions are set correctly, but something blocks the opening of a file. In this case, you will trace an error, since your application cannot manage this case and continue to work as expected by the user (i.e. actually read the file).
Example 2: after inspection of the error in the first example, you find that the error is caused by the fact that the file path is longer than 259 characters. So you refactor your code to catch PathTooLongException. When, the next time, the user tries to open the same file, the new version of the application shows a message explaining that the file is too long and must be moved to another folder to shorten the full path in order to open this file in this application. You also trace a message.
Example 3: your application spent twenty seconds opening and parsing a small file while most files take ten to one hundred milliseconds to open and parse. You trace a warning with relevant info: the type of disk where the file actually is, the file system, the size of the file, the exact time spent, the time the computer was on, etc. When the user complains that it takes twenty seconds to open the file, you take the trace to find what happens. You find for example that it takes so long to load the files from a network share when the computer have just started. You explain to the user that the delay is due to the network and is not related to your application.
Example 4: the opened file is displayed incorrectly. You enable verbose trace where you actually see how the data is loaded from file and then parsed, step by step.

Forcing logger/appender to output line logged at lower than its current level

So, you need different treshold within the same class. I think you use a different logger corresponding to a specific name. You can thus set the log level to INFO for this specific Logger in DispatchServlet class.

For me, the benefits would be:

the possibility to specificly reduce the treshold to INFO as you required (the goal).
if one day you realize that your specific logs become too verbose and finally useless because the functionnality is 100% stable and doesn't cause any issue, you still can reduce the treshold by configuration and without impacting the rest of the logs. Logging in WARNING level or do something based on forcedLog would imply you to modify the sources for such a purpose.

The only CON I see is that it might be "surprising" but a correct documentation solves everything.

For example in your log4j.xml file, you could have:

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <!-- general application log -->
    <appender name="MyLogFileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="mylog.log" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy MM dd - HH:mm:ss,SSS} %-5p %t [%-40.40c] %x - %m%n"/>
        </layout>
    </appender>
    <logger name="DispatchServletSpecific">
        <level value="INFO" />
        <appender-ref ref="MyLogFileAppender" />
    </logger>
    <root>
         <level value="WARNING" />
         <appender-ref ref="MyLogFileAppender" />
    </root>
</log4j:configuration>

And in the Java code you create a specific Logger

Logger specificLogger = Logger.getLogger("DispatchServletSpecific");

This way the log treshold should be set to INFO while the rest of your app should be log only WARNING logs. Hope it helps.

Best Answer

Related Solutions

Best practices for logging and tracing in .NET

Forcing logger/appender to output line logged at lower than its current level

Related Topic