Using log4j in PeopleCode - Implementation and Troubleshooting Tips

Many of you in the PeopleSoft space already know that the use of log4j as a logging framework in PeopleCode has been very well detailed and demonstrated in Jim Marion's book.

This post is not intended to explain how to implement log4j (there are several resources on this topic already), but it is intended to share my implementation experience and troubleshooting tips that might be handy.

For my requirement, I built a log4j API (using App Classes) very similar and based on PeopleSoft PeopleTools - Tips and Techniques - Chapter 10. It works great and it is very easy to use in desired locations in PeopleCode.

During my unit testing, I found that the log file rolls (as expected) based on the custom configuration properties but only if I reload the configuration every time I invoke the logging.

If the configuration is loaded once initially (using reloadConfig method in LogManager class), and then subsequently continue logging (using getLogger method in LogManager class) without reloading the configuration every call (until it is necessary... i.e.: until the logger cannot be found by getLogger), the log file does not roll as expected (RollingFileAppender). The logging functionality still works as expected.

It is almost as if the custom appender for maximumFileSize is not taking effect.

#File appender configuration
log4j.appender.cust_file=org.apache.log4j.RollingFileAppender
log4j.appender.cust_file.maximumFileSize=100000
log4j.appender.cust_file.maxBackupIndex=5
log4j.appender.cust_file.File=./LOGS/cust_log4j.log
log4j.appender.cust_file.layout=org.apache.log4j.PatternLayout
log4j.appender.cust_file.layout.ConversionPattern=%d %-5p [%c] - %m%n

While troubleshooting this issue I found a few handy tips. The environment details at the time of writing this post are as follows:
PeopleTools: 8.52.22
Application: Campus Solutions 9.0 Bundle 34
Database: Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
App Server: Linux - oel-5-x86_64

Issues Found with RollingFileAppender:

• The RollingFileAppender does not roll if we use the getLogger method (even after I verified that all the necessary log4j configuration is in memory).

• Another issue with the RollingFileAppender is that it randomly picks old files and starts writing into it. Previously rolled files get activated again. This is very similar to the issue discussed here: log4j file appender.

Handy Tips to Troubleshoot log4j Issues:

• We can use the following code to determine the current log4j properties in the JVM. This proved to be very useful for my troubleshooting (and identify differences between invoking the reloadConfig and the getLogger methods).
  
  /* Get current log4j properties */
  Local JavaObject &bos = CreateJavaObject("java.io.ByteArrayOutputStream");Local JavaObject &pw = CreateJavaObject("java.io.PrintWriter", &bos);
  Local JavaObject &pp = CreateJavaObject("org.apache.log4j.config.PropertyPrinter", &pw);&pp.print(&pw);
  Local string &currentProperties = &bos.toString();
  
  Note: We can either print &currentProperties to some other file or any other preferred logging mechanism (as we cannot rely on log4j while troubleshooting issues with log4j).
  
  Sample of printing &currentProperties string: 

log4j.rootCategory=DEBUG

log4j.appender.cust_file=org.apache.log4j.RollingFileAppender

log4j.appender.cust_file.append=true

log4j.appender.cust_file.bufferSize=8192

log4j.appender.cust_file.bufferedIO=false

log4j.appender.cust_file.file=./LOGS/cust_log4j.log

log4j.appender.cust_file.immediateFlush=true

log4j.appender.cust_file.maxBackupIndex=5

log4j.appender.cust_file.maximumFileSize=100000

log4j.appender.cust_file.layout=org.apache.log4j.PatternLayout

log4j.appender.cust_file.layout.contentType=text/plain

log4j.appender.cust_file.layout.conversionPattern=%d %-5p [%c] - %m%n

log4j.category.TEST_API_LOG4J=ALL, cust_file

log4j.category.TEST_API=OFF

log4j.appender.A1=org.apache.log4j.DailyRollingFileAppender

log4j.appender.A1.append=true

log4j.appender.A1.bufferSize=8192

log4j.appender.A1.bufferedIO=false

log4j.appender.A1.datePattern=.yyyy-MM-dd

log4j.appender.A1.file=./LOGS/PSJChart.log

log4j.appender.A1.immediateFlush=true

log4j.appender.A1.layout=org.apache.log4j.PatternLayout

log4j.appender.A1.layout.contentType=text/plain

log4j.appender.A1.layout.conversionPattern=%d{DATE} [%t] %-5p %c %x - %m%n

log4j.category.com.peoplesoft.pt.charting=WARN, A1 

log4j.category.TEST_API_LOG4J.oprid.PS=OFF

• We can use the following code to clear all log4j properties from the JVM. Again, this is handy while unit testing to clear any loaded properties and starting over again without having to restart the app server.
  
  Local JavaObject &manager = GetJavaClass("org.apache.log4j.LogManager");&manager.resetConfiguration();
  
  The result of invoking the above code would reset the current JVM log4j properties as follows:
  
  log4j.rootCategory=DEBUG

Findings and Workarounds:

Note: The findings and workarounds are completely based on my experience and environment. This might not be reproducible and appropriate for all cases. The intention is to share and provide ideas if others run into similar or related issues.

• I found that there are several different threads that are in play at the app server level (although there was only app server domain in the environment). And it appears that each of these threads have its own JVM (and associated log4j configuration) of sorts. Basically, the first time I do a configuration load (I might be on one thread where the custom log4j configuration is loaded), then every subsequent time I call the getLogger (I might be on other threads which does not have the custom log4j configuration).

• To work around the above issue, I wrote some code to compare the custom configuration in the message catalog with the current log4j properties in memory. If any differences were found, then configuration would be reloaded.

Here is my addition to the getLogger method of LogManager class:

This ensures that all threads on the app server domain are properly initialized with the custom log4j properties.



method getLogger
   /+ &name as String +/
  
   If (%This.isNotInitialized()) Then
      %This.initialize();  
   End-If;
  
   If (%This.isNotInMemory()) Then
      %This.initialize();
   End-If;
   /* Note: %This.isNotInMemory() method implementation is detailed in the Appendix Code below */
   Return create TEST_API:UTIL:Logger(&name);
  
end-method;

• While the above item solved my problem partially, I still have not found a way to work around the issue of RollingFileAppender randomly picking old files to write into.

• As a work around to the above issues identified, I decided to reload the configuration every time. Additionally, I am not sure if the juice is worth the squeeze in trying to avoid the configuration reload (if it is already loaded) and rather just reload every time? I am guessing that the cost in trying to do the determination might be the same as the actual configuration reload itself. At least, with the configuration reload every time we can be guaranteed that the rolling works as expected.
  Here is my work around getLogger method of LogManager class.

method getLogger
   /+ &name as String +/
  
      %This.initialize(); 
  
   Return create TEST_API:UTIL:Logger(&name);
  
end-method;

Appendix Code:

%This.isNotInMemory() Method Implementation in LogManager Class (if anyone is interested):

method isNotInMemory

   /+ Returns Boolean +/

   Local JavaObject &baos, &pw, &pp;

   Local string &inMemoryProps, &fileName, &customConfig, &temp;

   Local number &prev, &index, &i;

  

   Local array of string &arrProps = CreateArrayRept("", 0);

  

   /* Get Current In Memory Properties */

   &baos = CreateJavaObject("java.io.ByteArrayOutputStream");

   &pw = CreateJavaObject("java.io.PrintWriter", &baos);

   &pp = CreateJavaObject("org.apache.log4j.config.PropertyPrinter", &pw);

   &pp.print(&pw);

  

   &inMemoryProps = &baos.toString();

  

   /* Get Custom Properties from Message Catalog Entry */

   &fileName = GetEnv("PS_SERVDIR") | "/LOGS/test_log4j.log";

   &customConfig = MsgGetExplainText(27000, 1, "", &fileName);

  

   /******** Split Message Catalog Text into Property Array ********/

   /* Find first line in Configuration */

   &prev = 0;

   &index = Find(Char(10), &customConfig);

  

   While &index > 0

     

      &temp = Substring(&customConfig, (&prev + 1), (&index - &prev - 1));

      If All(&temp) And

            Substring(&temp, 1, 1) <> "#" Then

         &arrProps.Push(&temp);

      End-If;

     

      &prev = &index;

      &index = Find(Char(10), &customConfig, &index + 1);

     

      /* Check if last line (because carriage return might not exist at the end) */

      If &index = 0 And

            &prev < Len(&customConfig) Then

         &temp = Substring(&customConfig, (&prev + 1), (Len(&customConfig) - &prev));

         If All(&temp) And

               Substring(&temp, 1, 1) <> "#" Then

            &arrProps.Push(&temp);

         End-If;

      End-If;

     

   End-While;

    /******** Split Message Catalog Text into Property Array ********/

  

   /* Find Custom Properties in JVM (In Memory) */

   For &i = 1 To &arrProps.Len

     

      If Find(&arrProps [&i], &inMemoryProps) = 0 Then

         /* Configuration needs to be re-loaded */

         Return True;

      End-If;

   End-For;

  

   Return False;

  

end-method;