Tuesday, May 22, 2007

Deciding what to log

In this section we will discuss what to log and the various levels at which we can generate log statements.

Even though I have mentioned that we should generate log statements when control enters and exits a method, this is a rather controversial point. Especially generating log statements on exiting; because a method could have multiple exit routes. What do you think? I would say, if in doubt - do NOT generate logs when exiting a method. Logs that show control has entered a method do have value in my personal opinion, however you can leave those out as well if you do not see much value in them.

What is DEBUG? As I have explained, we should log several events from our program as it executes. But all events are not equally important. Hence, Log4J supports six levels for logging, where each level is appropriate for a certain type of log statement. The levels are (starting from the most severe) FATAL, ERROR, WARN, INFO, DEBUG, and TRACE. Log4J also allows us to dynamically (through a configuration file) filter logs below a certain level. This way we can generate logs only for events that have a priority of WARN or higher and turn on the lower levels when there is a problem, due to which we want to see all the generated log statements.

This tutorial on JBoss does a very good job of explaining logging conventions in JBoss. I have excerpted the part that explains different logging levels below.

FATAL - Use the FATAL level priority for events that indicate a critical service failure. If a service issues a FATAL error it is completely unable to service requests of any kind.

ERROR - Use the ERROR level priority for events that indicate a disruption in a request or the ability to service a request. A service should have some capacity to continue to service requests in the presence of ERRORs.

WARN - Use the WARN level priority for events that may indicate a non-critical service error. Resumable errors, or minor breaches in request expectations fall into this category. The distinction between WARN and ERROR may be hard to discern and so its up to the developer to judge. The simplest criterion is would this failure result in a user support call. If it would use ERROR. If it would not use WARN.

INFO - Use the INFO level priority for service life-cycle events and other crucial related information. Looking at the INFO messages for a given service category should tell you exactly what state the service is in.

DEBUG - Use the DEBUG level priority for log messages that convey extra information regarding life-cycle events. Developer or in depth information required for support is the basis for this priority. The important point is that when the DEBUG level priority is enabled, the JBoss server log should not grow proportionally with the number of server requests. Looking at the DEBUG and INFO messages for a given service category should tell you exactly what state the service is in, as well as what server resources it is using: ports, interfaces, log files, etc.

TRACE - Use TRACE the level priority for log messages that are directly associated with activity that corresponds requests. Further, such messages should not be submitted to a Logger unless the Logger category priority threshold indicates that the message will be rendered. Use the Logger.isTraceEnabled() method to determine if the category priority threshold is enabled. The point of the TRACE priority is to allow for deep probing of the JBoss server behavior when necessary. When the TRACE level priority is enabled, you can expect the number of messages in the JBoss server log to grow at least a x N, where N is the number of requests received by the server, a some constant. The server log may well grow as power of N depending on the request-handling layer being traced.