Configuring Log4j for JBOSS EAP 6 (and probably 7) and using log4j.MDC

This tutorial covers 2 items:

• Jboss application-specific log4j configuration
• Using MDC parameters to make reading logs easier

Background

Reading the logs from a multi-user server application is quite difficult, especially when many users are using it and traffic volumes are high.

As a support person looking after production environments, one woud like to have a way of easily viewing the logs for a particular transaction while the server is live. Also as a development aid,  a developer would like to get easy to read logs from the support person who's logged a production defect.

Having this ability will help you trouble-shoot issues faster, and make your life a lot easier. Obviously, before you can get to this stage, you need to correctly configure your logging.

JBoss Log4j configuration

Generally you could just ship your JEE application with its own log4j file, and after configuring it to use its own class-loader, it should be good enough for production use (if you don't intend changing your log levels frequently). How this is done is described here.

However, what happens if you want to change the log level or reconfigure the logging method for example? You would need to change you log4j config file, which means the rebuild and deploy cycle needs to happen.

In addition you would lose the ability to manage the logging from the JBOSS Server's Administration Web console, which is definitely handy in a production environment. As I will show you below, configuring the logging on the server is pretty straightforward, and you should be up and running within 10 minutes.

Log4j MDC Usage

My application has an RestEasy interceptor which checks the request for a sessionId parameter in the HTTP header. If its not there I generate a UUID which will uniquely identify the transaction. Using this value, I set a parameter called “sessionId” in the log4j MDC hashmap; this information can be made to  appear on every logging line for that transaction. This will make it much easier to read the logs in a multi-threaded environment as shown later. You can use any parameter you want to in the MDC, e.g. subscriber number, account number etc and as many parameters as you wish in any combination.

Tested Platforms

This was tested on Jboss EAP 6.3+ and 6.4

Log4j Configuration Steps

This configuration is done via the jboss command-line.



1.  Log into the admin console



[kiren@saraswati:bin]cd /home/kiren/app/jboss/EAP-6.4.6/bin
[kiren@saraswati:bin]./jboss-cli.sh
    You are disconnected at the moment. Type 'connect' to connect to the server or 'help' for the list of supported commands.
[disconnected /] connect
[standalone@localhost:9999 /] 

2.  Run the following 2 commands to create the SCP logger handler.



/subsystem=logging/periodic-rotating-file-handler=MY_SUPER_APP:add(file={"path"=>"mySuperApp.log", "relative-to"=>"jboss.server.log.dir"}, suffix=".yyyy.MM.dd")
/subsystem=logging/periodic-rotating-file-handler=MY_SUPER_APP:write-attribute(name="formatter",value="%d{HH:mm:ss,SSS} (%t) {%X{sessionId}} %-5p [%c{1}] %s%E %n")



This adds the following to the standalone.xml file:

 <periodic-rotating-file-handler name="MY_SUPER_APP">  
    <formatter>  
      <pattern-formatter pattern="%d{HH:mm:ss,SSS} (%t) {%X{sessionId}} %-5p [%c{1}] %s%E %n"/>  
    </formatter>  
    <file relative-to="jboss.server.log.dir" path="mySuperApp.log"/>  
    <suffix value=".yyyy.MM.dd"/>  
 </periodic-rotating-file-handler>  

Then run the following 4 commands:
/subsystem=logging/logger=com.supercoder.superApp:add
/subsystem=logging/logger=com.supercoder.superApp:write-attribute(name="level",value="DEBUG")
/subsystem=logging/logger=com.supercoder.superApp:write-attribute(name="use-parent-handlers", value="true")
/subsystem=logging/logger=com.supercoder.superApp:assign-handler(name="MY_SUPER_APP")

The following will be added to standalone.xml:

 <periodic-rotating-file-handler name="MY_SUPER_APP">  
    <formatter>  
      <pattern-formatter pattern="%d{HH:mm:ss,SSS} (%t) {%X{sessionId}} %-5p [%c{1}] %s%E %n"/>  
    </formatter>  
    <file relative-to="jboss.server.log.dir" path="mySuperApp.log"/>  
    <suffix value=".yyyy.MM.dd"/>  
 </periodic-rotating-file-handler>  

3. All your application logging for package com.supercoder.superApp will appear in the mySuperApp.log file.
4. Here's an extract from the file



    13:23:20,276 (http-localhost/127.0.0.1:7080-1) {ceef921d-a256-454b-bac3-534994909fc7} DEBUG [UserService] Querying LDAP for username:account10554
    13:23:20,318 (http-localhost/127.0.0.1:7080-1) {ceef921d-a256-454b-bac3-534994909fc7} DEBUG [LdapDao] Searching online10554
    13:23:20,361 (http-localhost/127.0.0.1:7080-1) {ceef921d-a256-454b-bac3-534994909fc7} DEBUG [ConfigDao] ldap.ad.search.base:dc=mydev,dc=opt
    13:23:20,382 (http-localhost/127.0.0.1:7080-1) {ceef921d-a256-454b-bac3-534994909fc7} DEBUG [LdapDao] Entries found 0


Where

• (http-localhost/127.0.0.1:7080-1) is the thread name 
  
• {ceef921d-a256-454b-bac3-534994909fc7} is the unique sessionId. 
  
• Note that the classname is without the package, this is achieved by specifying the depth of 1 in the pattern [%c{1}]
  

6. NB: You need to restart the server for the changes to take effect.
7. If you know the sessionId/transactionId of the request you're looking for, you would just use:

tail -f ../log/mySuperApp.log | grep ceef921d-a256-454b-bac3-534994909fc7

MDC Interceptor Code

This is an extract of the interceptor code in my REST application. You would need to write the appropriate interceptor for your application of course:)

 @Provider  
 @ServerInterceptor  
 public class LogInterceptor implements PreProcessInterceptor,  
 PostProcessInterceptor {  
 Logger logger = Logger.getLogger(LogInterceptor.class);  
 .  
 @Context  
 private HttpServletRequest servletRequest;  
 .  
 .  
 public ServerResponse preProcess(HttpRequest request,  
 ResourceMethod resourceMethod) throws Failure,  
 WebApplicationException {  
 String sessionId = extractSessionInHeader(request);  
 MDC.put("sessionId", sessionId);  
 servletRequest.setAttribute(REQUEST_START_TIME,  
 System.currentTimeMillis());  
 return null;  
 }  
 /**  
 * Retrieves the Session Id from the Header.  
 * If not, generates a UUID  
 * @param request  
 * @return  
 */  
 private String extractSessionInHeader(HttpRequest request) {  
 String sessionId;  
 List requestHeader = request.getHttpHeaders().getRequestHeader(  
 "sessionId");  
 if (requestHeader!=null && requestHeader.size() >= 1)  
 sessionId = requestHeader.get(0);  
 else  
 sessionId = UUID.randomUUID().toString();  
 return sessionId;  
 }  

Of course, how, and with which variables you populate the MDC hashmap is up to you. Remember also that the MDC is thread-local, so its safe to use in a multi-threaded server environment.

Management Console

The above configuration will result in the following views on the management console.

Periodic Rotating File Appender

 Here is the Rolling file appender.

Log Categories

Our category of  com.supercode.superApp is present in this view. The current log level is set at DEBUG.

 Log Level Modification

The log levels an be changed here to effect logging at a different level. There are more levels than log4j has, I'm assuming its mapped to the log4j equivalents.

As can be seen, these items could be created from the console, but I find using the CLI is the quickest and easiest.

Conclusion

Hopefully this helps you configure you log4j with JBOSS easily. Also the MDC usage will definitely help you get the most out of your logging.

Happy Coding!

Final Logging Subsystem XML

 <subsystem xmlns="urn:jboss:domain:logging:1.4">  
 <console-handler name="CONSOLE">  
 <level name="INFO" />  
 <formatter>  
 <named-formatter name="COLOR-PATTERN" />  
 </formatter>  
 </console-handler>  
 <periodic-rotating-file-handler name="FILE"  
 autoflush="true">  
 <formatter>  
 <named-formatter name="PATTERN" />  
 </formatter>  
 <file relative-to="jboss.server.log.dir" path="server.log" />  
 <suffix value=".yyyy-MM-dd" />  
 <append value="true" />  
 </periodic-rotating-file-handler>  
 <periodic-rotating-file-handler name="MY_SUPER_APP">  
 <formatter>  
 <pattern-formatter  
 pattern="%d{HH:mm:ss,SSS} (%t) {%X{sessionId}} %-5p [%c{1}] %s%E %n" />  
 </formatter>  
 <file relative-to="jboss.server.log.dir" path="MY_SUPER_APP.log" />  
 <suffix value=".yyyy.MM.dd" />  
 </periodic-rotating-file-handler>  
 <logger category="com.arjuna">  
 <level name="WARN" />  
 </logger>  
 <logger category="org.apache.tomcat.util.modeler">  
 <level name="WARN" />  
 </logger>  
 <logger category="org.jboss.as.config">  
 <level name="DEBUG" />  
 </logger>  
 <logger category="sun.rmi">  
 <level name="WARN" />  
 </logger>  
 <logger category="jacorb">  
 <level name="WARN" />  
 </logger>  
 <logger category="jacorb.config">  
 <level name="ERROR" />  
 </logger>  
 <logger category="org.switchyard">  
 <level name="INFO" />  
 </logger>  
 <logger category="org.picketlink">  
 <level name="TRACE" />  
 </logger>  
 <logger category="org.jboss.as.quickstarts">  
 <level name="DEBUG" />  
 </logger>  
 <logger category="org.jboss.weld.ClassLoading">  
 <level name="DEBUG" />  
 </logger>  
 <logger category="org.apache.deltaspike.core.api.provider.BeanManagerProvider">  
 <level name="ERROR" />  
 </logger>  
 <logger category="com.supercoder.superApp" use-parent-handlers="true">  
 <level name="DEBUG" />  
 <handlers>  
 <handler name="MY_SUPER_APP" />  
 </handlers>  
 </logger>  
 <root-logger>  
 <level name="INFO" />  
 <handlers>  
 <handler name="CONSOLE" />  
 <handler name="FILE" />  
 </handlers>  
 </root-logger>  
 <formatter name="PATTERN">  
 <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />  
 </formatter>  
 <formatter name="COLOR-PATTERN">  
 <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />  
 </formatter>  
 </subsystem>