Best way to modify log4j appended for logging

Question

I'm currently developing soon to be big(functional wise) rest web service and I want to capture logs really good, so I can have a good insight of what is going on where. For now I use log4j for logging, using this appended setting :

<!-- Appenders -->
<appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%-5p: %c - %m%n" />
    </layout>
</appender>

which produces these kind of logs :

10:44:55,893 INFO  [STDOUT] INFO : my.package.MyClass - I'm class message

1. How can I make this message look like i.e.

   10:44:55,893 INFO : my.package.MyClass - I'm class message
   

2. Can I make a special appender or whatever it is, and use it in some classes not in all, i.e. I want to have in few of my logs this :

   • Payload: some request parameters
   • Response: some response that my service returns
   • extra data : some extra data

Without having these INFO [STDOUT] INFO my.package.MyClass in front of it

UPDATE

I forgot to mention in the question that I'm using Jboss 5. I think the jboss might be adding the 10:44:55,893 INFO [STDOUT] to any format that I put in my log4j config.

BOUNTY UPDATE

I changed this :

<!-- ============================== -->
   <!-- Append messages to the console -->
   <!-- ============================== -->

   <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="Target" value="System.out"/>
      <param name="Threshold" value="INFO"/>

      <layout class="org.apache.log4j.PatternLayout">
         <!-- The default pattern: Date Priority [Category] Message\n -->
         <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
      </layout>
   </appender>

to this:

<!-- ============================== -->
   <!-- Append messages to the console -->
   <!-- ============================== -->

       <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
          <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
          <param name="Target" value="System.out"/>
          <param name="Threshold" value="INFO"/>

          <layout class="org.apache.log4j.PatternLayout">
             <!-- The default pattern: Date Priority [Category] Message\n -->
             <param name="ConversionPattern" value="%m%n"/>
          </layout>
       </appender>

And it worked, but it seems kind of ugly to do it like this. Is there any other way? I'm using spring MVC/JBoss combination.

I'm now getting nice clean messages :

10:44:55,893 INFO : my.package.MyClass - I'm class message

without annoying

10:44:55,893 INFO  [STDOUT]

prefix

Answer 1

Question 1:

Use the following pattern layout for your appender:

<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p: %c - %m%n" />

The conversion pattern in the configuration file you stated does not result in the kind of log you stated. For example the date/time is not included in your conversion pattern.

---

Question 2:

You can use a special logger which uses another appender that is only logging the pure message.

Your configuration would for example look like the following:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="consoleAppender" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n" />
        </layout>
    </appender>

    <appender name="consoleAppender2" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p: %c - %m%n" />
        </layout>
    </appender>

    <logger name="specialLogger" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender" />
    </logger>

    <root>
        <priority value="INFO" />
        <appender-ref ref="consoleAppender2" />
    </root>

</log4j:configuration>

You use the specialLogger for the pure messages without the additional information. It can be used in multiple classes.

In the configuration of the specialLogger, additivity = "false" is needed, because otherwise also the appender consoleAppender2 of the root logger would log the same message. (The message would be logged two times in this case.)

Your code could for example look like this:

public class TestClassA
{
    private static Logger specialLogger = Logger.getLogger("specialLogger");
    private static Logger logger = Logger.getLogger(TestClassA.class);    

    public TestClassA() {

    }

    public void doSomething() {
        logger.info("Some message from TestClassA");
        specialLogger.info("Some message via the specialLogger from TestClassA");
    }
}

Calling doSomething results in:

17:17:18,125 INFO : com.foo.TestClassA - Some message from TestClassA
Some message via the specialLogger from TestClassA

Somewhere in your main class you need to configure log4j as usual, e.g.:

DOMConfigurator.configureAndWatch("log4j.xml", 60 * 1000);

Answer 2

The INFO [STDOUT] normally comes from log4j listening for System.out as well. We had a similiar case where the application itself had its own log4j configuration and thus got its own root appender. This would log to the console which is listened to by the JBoss log4j. This in turn adds the INFO [STDOUT] as if you were writing directly to System.out (or ERROR [STDERR] when writing to System.err).

The solution in our case was to remove the application specific log4j config and just use the one that JBoss writes to.

Another way might be to directly write to an application specific log file rather than writing to the console. In a server environment you'd most probably refer to log files anyway.

As for the second part, i.e. automatically extending logs with response, request etc. data:

In one case we had a super class for stateless session beans that provided logging functionality and had a (overwritable) logger per instance. The base methods like info would then call the logger and add the required data automatically.

A second approach could be MCD, i.e. you put some data (like the request) into the thread local MDC (basically a map) and then access them in your pattern definition.

For example, we have several similar applications each of which has some classes the others have too. So we'd need which application the message originated from and thus added the application name to the MDC:

In the code:
MDC.put("app.name", "myapplication");

In the log4j pattern config:
<param name="ConversionPattern" value="%d %-5p [%c (%X{app.name})] %m%n"/> (note the %X{app.name})

I didn't test whether you could do something like putting the request into the MDC and then use : %X{request.getAttribute('xyz')} but if it just gets the value in the MDC and calls toString() on it, you might create a request wrapper like this:

class RequestLogWrapper {
  private HttpServletRequest request; //initialize through constructor etc.

  public String toString() {
    return request.getAttribute("xyz") + ";" + request.getAttribute("abc") + ... //handle null etc. as well
  }
}

Then call MDC.put("request", new RequestLogWrapper(request)); and in the config use %X{request}.