Application Logs

Logging has many purposes. Notably, it allows tracing of what is happening when something goes wrong. However, a user/developer does not always want to see EVERY log entry-besides clutter, it may slow down the application. In this light, the framework has wrapped the powerful and flexible log4j logging framework as an API.  There are two important aspects:

·         Placing logging statements within application code so that logging entries may be created at runtime.

·         Configuring logging at runtime so that the appropriate logging entries are created and directed to the appropriate log destination.

Contents

Logging within Business Logic

Configuring Logging at Runtime

Logging within Business Logic

The following describes how to implement logging when adding a class that implements business logic:

·         Add a constant referencing the logger for the class.  By convention logger should be named “logger” and should pass the declaring class as its argument.  For example, a logger in the Adjustment_CHandler class would be declared as follows:

private static final Logger logger

= LoggerFactory.getLogger(Adjustment_CHandler.class);

 

·         Add entries with the appropriate logging level.  The levels are: “debug”, “info”, “warn”, “error” and “fatal”.  The following will log a warning entry to the log:

logger.warn("Unexpected status for frozen adjustment: " + status);

 

·         In general, we expect entries of level “info” or more severe to be rare and therefore not to impose a substantial performance penalty.  However, “debug” entries we can expect to be very fine grained and that they usually will not find their way to actual logs but will be filtered out via runtime configuration.  To lessen the performance impact of debug logging, the logging statement should be wrapped as follows:

if (logger.isDebugEnabled()) {

   logger.debug("Processing adjustment " + adjustment.getId());

}

 

·         There are times when you want to know how long code block takes to execute. In general, the logging provides the time each log statement is issued. However, it is clearer to see an actual elapsed time of some process being investigated. In this case, there are some additional methods on the logger:

debugStart(message) or infoStart(message)

debugTime(message, start) or infoTime(message, start)

 

These should be used in the pairs given, as such:

long start = debugStart("Starting process");

//... code for process

debugTime("End process", start);

 

This will cause each statement to be logged, plus the final "End Process" statement will give the elapsed time since debugStart was called.

 

Please refer to the JavaDocs on the com.splwg.shared.logging.Logger class for more detail.

Configuring Logging at Runtime

Having instrumented the code to create logging entries, the question remains, how to cause the various logger level messages to actually trigger at runtime?  A very detailed description of this can be found at http://logging.apache.org/log4j/docs/manual.html

 

Contents

Property Configuration

Trace Flags

Property Configuration

Control of log4j occurs based on properties typically set in the log4j.properties file in the application classpath.  You can change the log level of a given logger in this file.  Note, however, that values may be overridden on the command line by specifying system properties (i.e. via “–Dlog4j…”).  Note that "inheritance" of logger levels works such that (in our standard of qualified class name as the logger name) you can change a whole package’s log level by specifying only a portion of the logger name. Note that you may commonly desire to enable ("global") debug logging on your local environment. To do this, you can simply change the line

 

 log4j.logger.com.splwg=info

 

to

 log4j.logger.com.splwg=debug

Trace Flags

Trace flags allow for specialized logging that cuts across many classes.  They can be set for user requests by entering the online system in “debug” mode and setting the “trace” flags appropriately.  Likewise, they can be set in batch either by interactive prompts for the trace flag values when a job starts or by setting system property values.  See the JobSubmitterConfiguration class for specific system property names.

·         traceProgramStart, traceProgramEnd, traceProgramStandardOut—These parameters are specific to COBOL programs and will cause entries for the start and end of program execution and enable any embedded logging statements within the COBOL code.

·         traceSQL—Causes special detail of SQL being submitted.  This can be useful when troubleshooting performance problems.

·         traceTime—This can only be enabled for online requests or JUnit tests by setting traceTime(true) on the request context.  Enabling time tracing will cause special profiling entries to be placed in the application log for the purpose of attributing request latency to the various layers of the application or to specific SQL statements.  These entries are queued in memory until after profiling entries are no longer being generated and then spooled to the logs so as not to corrupt the performance instrumentation with logging overhead.  The ProfilingReport standalone Java program can be run to post-process these logs, or a portion of them and generate a report.