Friday, September 15, 2006

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.

29 comments:

Nethaji Rajendran said...

Hi Jim
I tried your code copying the log4j jar file and xml file in page activate event.I placed these file in appserv\classes.It throwed be class not found error org\apache\log4j\Logger not founf please help

Jim Marion said...

Nethaji,

The error means the app server couldn't find the log4j classes that are in the log4j jar file. PeopleSoft delivers the log4j jar file so you shouldn't get this error if your app server is configured correctly. Nevertheless, since the app server can't find the jar file... Did you reboot your app server after putting the jar file in your app server's class path? Depending on your app server's configuration, you may also need to hard code the jar file in your app server's startup script.

Once you have the jar file in the app server's path and have restarted the app server, you can try your page activate example again. You might also want to look at the post log4j and PeopleCode Part II for some quick test code.

If you can't get the app server to find your log4j jar file, then you can explode the jar file into the class directory of your app server. This probably won't requre a restart, but might.

Make sure your log4j.xml is at the root of your class directory.

Let me know if you need more help.

Jim

Alam Aftab said...

Hi Jim,
I am using the HTML area in a page for displaying the image.But if searching for same data the image is not displaying properly because the image in that URL getting refreshed every time.So I want to store that image from HTML area to PeopleSoft Data base as an Image so that when in search mode I will select that image and Display it on page. Please help me.

Jim Marion said...

@Alam, Can you post this question in the OTN PeopleSoft General Discussion forum? I would like to ask you some clarifying questions, and the OTN forum seems like a more appropriate place for this type of discussion. Likewise, the OTN forum allows you to add screenshots, etc. I monitor the forum and will pick it up there.

James said...

Do you know if there is a way to set breakpoints in Java code, and step through the coding via some sort of debugger line by line?

Jim Marion said...

@James, each Java IDE has its own button for stepping through Java code. If you are trying to do that in the context of PeopleSoft, that is different. I believe you would need a way to attach to a running process. I'm not sure about that.

Honestly? I HATE stepping through code. I would rather print a statement to a log file.

Ganesh said...

Jim,

One thing is not every clear to me, How do you enable Log mode in the application, the time when Log4j code is executed to perform logging. It should be very easy to switch to log mode similar to trace parameters in AE and Trace setting in the peoplecode. I want to use this solution if it is easy to switch to log mode before execution and logging happens.It was not clear to me. please let me know.

Sorry I have not gone thourgh entire chapter in your book.

Jim Marion said...

@Ganesh, in the chapter I show how to use an iScript to change the log level. You could either create a bookmarklet from this or create a PIA Component/Page to adjust trace settings (including appenders and layouts).

Ganesh said...

Hi Jim,

as per the code in your book. I used it in the application engine.

code
____

Local JavaObject &logger = GetJavaClass("org.apache.log4j.Logger").getLogger("AE.APT_LOG4JTST.MAIN.hw_log4j");

Local JavaObject &layout = CreateJavaObject("org.apache.log4j.PatternLayout", "%-4r %d [%t] %-5p %c [%x] - %m%n");
Local JavaObject &appender = CreateJavaObject("org.apache.log4j.ConsoleAppender", &layout);
&logger.addAppender(&appender);
&logger.setLevel(GetJavaClass("org.apache.log4j.Level").DEBUG);
&logger.debug("Hello log4j.");

I got the following erorr no idea what does this mean. I have not place any xml file so for.



ERROR
________


log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: .\LOGS\PSJChart.log (The system cannot find the path specified)
at java.io.FileOutputStream.openAppend(Native Method)
at java.io.FileOutputStream.(Unknown Source)
at java.io.FileOutputStream.(Unknown Source)
at org.apache.log4j.FileAppender.setFile(FileAppender.java:272)
at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:151)
at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:206)
at org.apache.log4j.config.PropertySetter.activate(PropertySetter.java:247)
at org.apache.log4j.config.PropertySetter.setProperties(PropertySetter.java:123)
at org.apache.log4j.config.PropertySetter.setProperties(PropertySetter.java:87)
at org.apache.log4j.PropertyConfigurator.parseAppender(PropertyConfigurator.java:645)
at org.apache.log4j.PropertyConfigurator.parseCategory(PropertyConfigurator.java:603)
at org.apache.log4j.PropertyConfigurator.parseCatsAndRenderers(PropertyConfigurator.java:524)
at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:408)
at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:432)
at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:460)
at org.apache.log4j.LogManager.(LogManager.java:113)
at org.apache.log4j.Logger.getLogger(Logger.java:85)
log4j:ERROR Either File or DatePattern options are not set for appender [A1].
891 2011-10-10 17:17:33,223 [Thread-0] DEBUG AE.APT_LOG4JTST.MAIN.hw_log4j [] - Hello log4j.
PeopleTools 8.48.12 - Application Engine
Copyright (c) 1988-2011 PeopleSoft, Inc.
All Rights Reserved

Application Engine program APT_LOG4JTST ended normally

Jim Marion said...

@Ganesh, what you are seeing is expected. PeopleTools comes with a log4j.ini file that attempts to configure a logger for PSJChart.log. I believe my book mentions the delivered log4j.ini and recommends configuring log4j.xml because log4j looks for log4j.xml first.

You can ignore the PSJChart logger errors. They will show up in the output since it isn't configured properly. Properly configured loggers will log correctly.

If you create a log4j.xml, then you will stop seeing the PSJChart errors.

Kunan said...

Hi Jim,

I am trying to use logging mechanism inside Record.FieldFormula.
My classes folder has log4j.jar and log4j.properties.
log4j.properties reads
======================================
# A1 is set to be a ConsoleAppender which outputs to System.out.
log4j.appender.A1=org.apache.log4j.DailyRollingFileAppender
log4j.appender.A1.File=./LOGS/PSJChart.log

# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.DatePattern=.yyyy-MM-dd
log4j.appender.A1.layout.ConversionPattern=%d{DATE} [%t] %-5p %c %x - %m%n

log4j.category.com.peoplesoft.pt.charting=WARN, A1
======================================
So do i need to put the log4j.xml inside classes folder.
If yes, would you please provide the detail overview with example for configuration setting of Record, Field, Component interface etc differently.

Thanks
Kunan

Jim Marion said...

@Kunan, you do NOT need to have a log4j.xml. Instead, you can add your own logger configurations to the existing log4j.properties file. I recommend having your own log4j.xml file so you can configure loggers without modifying the delivered file. The log4j framework first looks for the log4j.xml file. If it doesn't find it, it then looks for the log4j.properties file.

Kunan said...

Hi Jim,
According to my log4j.properties, placed in $PS_HOME/classes folder
=================================================================
# A1 is set to be a ConsoleAppender which outputs to System.out.
log4j.appender.A1=org.apache.log4j.DailyRollingFileAppender
log4j.appender.A1.File=./LOGS/PSJChart.log
=================================================================
the log file will be created inside PSJChart.log file.

I have created a test application package to implement log4j. Please find below the code snippet for this.

/*AP_TEST_CLASS is a class inside AP_TEST application package*/

class AP_TEST_CLASS

method AP_TEST_CLASS();
method testLogging(&str As string) Returns string;

end-class;

/*constructor */
method AP_TEST_CLASS
end-method;

method testLogging
/+ &str as string +/
/+ Returns string +/


Local JavaObject &logger = GetJavaClass("org.apache.log4j.Logger").getLogger("AP_TEST.AP_TEST_CLASS");
&logger.debug("Logger created");
&str = "successfully implement log4j in people code";
&logger.info("Process completed successfully");

return &str;

end-method;

This code complies correctly, but when i try to call the application package, i don't any logs inside PSJChart.log file.

Please guide, if i am doing anything wrong.

Jim Marion said...

@Kunan, that is because the log4j.properties file is only configured to log statements for a logger named com.peoplesoft.pt.charting and ONLY for WARN or higher. You see this on the last line of the log4j.properties file that says, "log4j.category.com.peoplesoft.pt.charting=WARN, A1". To see INFO messages for a different logger, you need to copy this line into:

log4j.category.AP_TEST.AP_TEST_CLASS=INFO, A1

Kunan said...

Thanks a lot for the clarification you have provided, Jim.

Few more clarification needed.

(i)
With the above implementation as suggested by you, do i need to change the below path for generating the log file in a different location?
------------------------------------
log4j.appender.A1.File=./LOGS/PSJChart.log
------------------------------------

(ii)
As our IB server being used by different project team. So i don't want to modify the existing log4j.properties file.
Is there any way to put my customized log4j.xml in other location other than $PS_HOME/classes?
So that, when ever i call my own application package or record.peoplecode, then the logger object will look into my customized log4j.xml instead of looking into the existing one.
The main aspect of customizing the log4j file and putting in different location is only not to affect other project team's people code implementation in same IB server.

(iii)
Once the modification to the property file or xml file is done, does it require a IB server restart.

Thanks in advance.
Kunan

Jim Marion said...

@Kunan, You can configure your own appenders and loggers that no one will know about. It will have no impact on existing functionality. Configure your own appender to use a different file location.

I can't remember whether or not it requires an app server restart.

Kunan said...

Hi Jim,

Will you please provide the step to configure own appenders and loggers.

Thanks in advance.
Kunan

Jim Marion said...

@Kunan, The Apache log4j Introduction Manual explains appenders and loggers. About 2/3's of the way down the document you can see a sample log4j.properties file.

Kunan said...

Thanks for the reply, Jim.
I explore through the logger and appender class in order to built my own customized log4j property file through java object and build the below code piece.
------------------------------------------------------------------------------------------------------
Local JavaObject &logger = GetJavaClass("org.apache.log4j.Logger").getLogger("AP_TEST.AP_TEST_CLASS");
Local JavaObject &layout = CreateJavaObject("org.apache.log4j.PatternLayout", "%-4r %d [%t] %-5p %c [%x] - %m%n");
Local JavaObject &dailyRollingFileAppender = CreateJavaObject("org.apache.log4j.DailyRollingFileAppender",&layout, “./LOGS/Perforamance.log”, "'.'dd-MM-yyyy");
&logger.addAppender(&dailyRollingFileAppender);
&logger.setLevel(GetJavaClass("org.apache.log4j.Level").INFO);
&logger.debug("Hello log4j.");
&logger.info("Logger created");
&str = "successfully implement log4j in people code";
&logger.info("Process completed successfully");
------------------------------------------------------------------------------------------------------

Please let me know, if i am going in right direction or not.

Thanks in advance.
Kunan

Jim Marion said...

@Kunan, Well done! You are using PeopleCode configuration rather than file configuration. That is fine. It is a perfectly acceptable direction.

Kunan said...

Hi Jim,

Now i am able to print log in the file. Thanks a lot Jim. but our application server has more than 15 instances.`so more than 15 log files are getting created in the all the instances.

so is there any way(people code configuration) to mail those log file to a particular mail recipient every day. Once the mail get sent, i want to remove all the contents of all the log files.

Thanks in advance
Bibhu

Jim Marion said...

@Kunan, yes, I know exactly what you are saying. I ran into the same issue. One option would be to use a shared file location, but you might have some concurrency/locking issues. There are SMTP appenders, etc. What I did as an alternative was create a PeopleSoft database appender that uses log4j to write to a PeopleSoft table using the current app server database connection. The code for the appender is included with my PeopleSoft PeopleTools Tips & Techniques book.

Kunan said...

Hi Jim,

Now i am facing a strange issue.
I place the below logging code inside a independent record people code.

------------------------------------------------------------------------------------------------------
function createLoggerObject(&strClassName as String)
Local JavaObject &logger = GetJavaClass("org.apache.log4j.Logger").getLogger(strClassName);
Local JavaObject &layout = CreateJavaObject("org.apache.log4j.PatternLayout", "%-4r %d [%t] %-5p %c [%x] - %m%n");
Local JavaObject &dailyRollingFileAppender = CreateJavaObject("org.apache.log4j.DailyRollingFileAppender",&layout, “./LOGS/Perforamance.log”, "'.'dd-MM-yyyy");
&logger.addAppender(&dailyRollingFileAppender);
&logger.setLevel(GetJavaClass("org.apache.log4j.Level").INFO);
return &logger
end-function;
------------------------------------------------------------------------------------------------------

I am calling a application package which consists of different function inside different record people code(for example REC_SAVE_OBJECT_1.FIELD_SAVE_OBJECT_1,REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2, REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3 REC_SAVE_OBJECT_UTIL.FIELD_SAVE_OBJECT_UTIL Record Peoplecode etc.).
At different record people code i call the logging function by

------------------------------------------------------------------------------------------------------
JavaObject &logger = createLoggerObject(REC_SAVE_OBJECT_1.FIELD_SAVE_OBJECT_1);
&logger.info("I am at REC_SAVE_OBJECT_1.FIELD_SAVE_OBJECT_1");
JavaObject &logger = createLoggerObject(REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2);
&logger.info("I am at REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2");
JavaObject &logger = createLoggerObject(REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3);
&logger.info("I am at REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3");
JavaObject &logger = createLoggerObject(REC_SAVE_OBJECT_UTIL.FIELD_SAVE_OBJECT_UTIL);
&logger.info("I am at REC_SAVE_OBJECT_UTIL.FIELD_SAVE_OBJECT_UTIL");
------------------------------------------------------------------------------------------------------

Then try to print the log at logical points as mentioned above.
For a single application package call, the output in the log file is getting generated as below(its a example to convey you the problem).
------------------------------------------------------------------------------------------------------
Mon Sep 24 2012 20:59:06 GMT+0600 - I am at REC_SAVE_OBJECT_1.FIELD_SAVE_OBJECT_1
Mon Sep 24 2012 20:59:07 GMT+0600 - I am at REC_SAVE_OBJECT_1.FIELD_SAVE_OBJECT_1
Mon Sep 24 2012 20:59:08 GMT+0600 - I am at REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2
Mon Sep 24 2012 20:59:09 GMT+0600 - I am at REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2
Mon Sep 24 2012 20:59:11 GMT+0600 - I am at REC_SAVE_OBJECT_2.FIELD_SAVE_OBJECT_2
Mon Sep 24 2012 20:59:12 GMT+0600 - I am at REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3
Mon Sep 24 2012 20:59:13 GMT+0600 - I am at REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3
Mon Sep 24 2012 20:59:14 GMT+0600 - I am at REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3
Mon Sep 24 2012 20:59:15 GMT+0600 - I am at REC_SAVE_OBJECT_3.FIELD_SAVE_OBJECT_3
Mon Sep 24 2012 20:59:16 GMT+0600 - I am at REC_SAVE_OBJECT_UTIL.FIELD_SAVE_OBJECT_UTIL
Mon Sep 24 2012 20:59:17 GMT+0600 - I am at REC_SAVE_OBJECT_UTIL.FIELD_SAVE_OBJECT_UTIL
------------------------------------------------------------------------------------------------------

The problem here is for single application package call, single logger object printing multiple times.

Is this happening because of new java log object getting created but not getting destroyed.
If yes, then how will i destroy the log object, when it was done with its logging operation.
Please assist me.

Thanks in advance
Kunan

Jim Marion said...

@Kunan, change your PatternLayout to include the logger name. That way you can see why there is overlap. The getLogger method does not create a new logger instance on each request. Once the JVM loads into an app server, it stays loaded until you restart the app server.

Saeem said...

HI JIM,
I have a small requirement here.

I need to change the portal greeting or welcome message in Peoplesoft PIA dynamically based on the the user is in. For example a user navigates to job data page and searches for the employee 012562, then the portal greeting should change to something like "EMPLID on JOB DATA ".
I dont want to make any modification to my delivered PT_BRANDING app package. Is there any other way to achieve this.??

Jim Marion said...

@Saeem, you can add some JavaScript to PT_COPYURL or PT_COMMON (depending on your tools release. If the page has PIA_KEYSTRUCT, you can get the values you need from there. Otherwise, you may be able to parse them out of the strCurrUrl JavaScript variable.

Appsian said...

Really enjoyed your article as its highly informative

Anu said...

I am trying to code following in PeopleCode and wondering if you can help. “java -jar filename.jar -verbose:class”. I am new to Java class in PeopleSoft and have no idea where to start. My current code is calling CreateJavaObject to create the java object and I want to add the verbose in the call. Thanks for any help you can provide.

Jim Marion said...

Great question. The Java command line parameters go in the App server or process scheduler server configuration file. The PeopleCode runtime will initialize the JVM for us based on the configuration file.