Logging PeopleCode

Using log4j to debug applications

Developers log many different things about applications for various reasons. For example, a developer may log application state, application execution, or application usage for the purposes of finding bugs, resolving errors, recovering from system failures, tracking usage, or auditing security. While all these reasons are necessary, this post is going to focus primarily on logging state and execution for the purposes of finding bugs and resolving errors.

PeopleTools 8.4 provides developers with a mechanism for tracing PeopleCode and SQL. I have found the SQL trace facility to be very valuable. I usually use an SQL trace value of 7 (the first 3 options: 1, 2, 4). This SQL trace value displays SQL statements, bind values, and commit/rollbacks.

While the verbosity of a PeopleCode trace provides a developer with all of the information necessary to debug a PeopleCode program, I find that it provides too much information to be valuable. Fortunately, there are alternatives for determining application state and "peeking" at variable values when debugging an application.


MessageBox

The MessageBox function is one of the most useful debugging tools available to a PeopleSoft developer. By inserting a single line of code into a program, a developer can instantly view information about a program's execution. Unlike a PeopleCode trace, the MessageBox function only displays the information that you, the developer, want to see.

What is wrong with the MessageBox function? The MessageBox function was my best PeopleCode debugging tool. Unfortunately, those MessageBox statements didn't disappear by themselves after I found and fixed a bug in a PeopleCode program. Rather, I had to manually find and remove those statements. Maybe it is the pack-rat in me, but I don't like to delete anything. You never know when you might need those MessageBox debugging statements again... right? Wouldn't it be nice if you could just turn off those debugging statements rather than delete them?

What about PeopleCode programs that don't have a user interface? Yes, the MessageBox function works fine for AppEngine PeopleCode programs. However, rather than just print the message to the message log, the MessageBox function prints several unwanted informational lines for each call to the MessageBox function.

What about additional targets? The MessageBox function is a user interface function. Don't expect to log to an SMTP or other Socket target from the MessageBox function.


log4j, An Alternative

Caveat: This post is not meant to be a log4j tutorial. Rather, with this post, I hope to demonstrate an alternative method for debugging and logging PeopleCode program executions. For a better understanding of the log4j framework, I refer you to the log4j web site.

I have used log4j for several years. It is my favorite Java logging framework. As you will see from the various ports of log4j, I'm not the only programmer that prefers log4j. Unfortunately, I didn't see a log4pc (pc=PeopleCode) on the list of ports.

Because I have had a lot of success using log4j, I took my turn at writing a PeopleCode port of log4j using Application Packages. I was quite pleased with my work! About half way through the code porting process, I ran into some log4j functionality that I couldn't seem to replicate in PeopleCode, specifically the MDC and NDC. To work past these, limitations, I thought I would just use the log4j Java compliments (not a pure PeopleCode approach, I know, but it worked). As I was considering this approach, I thought... Hmmm... Why not just use the log4j package as written directly from PeopleCode? PeopleCode supports Java objects and PeopleSoft delivers the log4j lib in the PS_HOME/class directory.


Why log4j instead of MessageBox?

The log4j framework is very flexible. With log4j you can litter your code with debug statements. Those debug statements will hide silently in your code until you turn on debugging. log4j also allows you to specify multiple targets. Delivered log4j targets include socket, database, file, e-mail, and system log appenders. log4j allows you to use layouts to configure how log statements are written to logging targets. You can configure some statements to log to one target while other statements log to a different target. Best of all, you can configure the log level, targets, and layouts from a configuration file without touching your production code.


Using log4j

The following is an example of some PeopleCode that creates a log4j logger and writes debug information to a target.

Local JavaObject &logger = GetJavaClass("org.apache.log4j.Logger").getLogger("com.mycompany.mydepartment.PS.Component.Record.Field.Event");
logger.debug("Logger created");
... do some processing ...
logger.info("Process completed successfully");

Line 1 creates a log4j logger with a name of com.mycompany.mydepartment.PS.Component.Record.Field.Event. log4j recommends using the Java class name of the object that is executing logging statements. Since we are using PeopleCode, not Java, I like to use a concatenation of my domain name, department name, PS (for PeopleSoft, or ERP for enterprise applications, etc), the object name (component, record, field), and event name.

Line 2 writes a debug level statement to the logger.

Line 4 writes an informational statement to the logger.

If the log level in the configuration file was specifically set to only display information, warnings, and errors, then statement 2 above would have executed silently. Using the log4j API from PeopleCode, your code can dynamically change the log4j configuration. For example, you could use &logger.setLevel(...) to set the log level to a level other than the configuration file value.

You can find a sample log4j.xml configuration file here. Place this file in your AppServer PS_HOME/class directory. If you are logging from an AppEngine program, then be sure to put your configuration file in your process scheduler's PS_HOME/class directory.

Because log4j uses the logger name to create an inheritance tree of loggers, you don't have to explicitly define every logger by name. Instead, you can define a short name logger and all loggers with the same prefix will inherit the definition of the shorter logger name. For example, if you defined a logger named com.mycompany.mydepartment.PS and then created a logger named com.mycompany.mydepartment.PS.Component.Record.Field.Event, then the com.mycompany.mydepartment.PS.Component.Record.Field.Event logger would inherit the definition of the com.mycompany.mydepartment named logger.


AppEngine log statements that communicate to users

Because the process scheduler redirects an AppEngine program's stdout to a a text file, any output written to the console by log4j is available to your users from the View log/trace link in the process scheduler. Using layout patterns and log4j, you can create logs that can be used by you, the developer, and your users to tell your users what happened and to tell you where that "what" happened.


Writing to the database

Rather than maintain a database user to log statements through the log4j JDBCAppender, I wrote a custom log4j appender that used PeopleSoft's Java PeopleCode objects. The benefit of using these PeopleSoft Java objects was that I could use the existing database session to write to the database. However, since database connectivity problems are something I have to occasionally debug, I never used this appender in production. Instead, I chose to use one of the delivered, simple appenders like the file or console appender.