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

Anxiety

Not JBoss but %d{ABSOLUTE} gave you 10:44:55,893 message – Hallette

Could you clarify -- what is ugly about setting a custom conversion pattern? – Railing

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);

Melodie

even when I use all what you've suggested I still can't get rid of this annoying "13:13:43,428 INFO [STDOUT]" in front of anything that I change in my appender, your settings work but only after this part.. – Anxiety

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}.

Josefajosefina

Answer 3

Try to use this pattern as it will give you clean message:

 <param name="ConversionPattern" value="%d{HH:mm:ss.SSS} %-5p %c %X %m/>

It is a good idea to add some unique value to MDC when request comes in, then add %X{uniqueValueKey} to your pattern. It will allow you to track logs for this unique request.

Hallette

Answer 4

If you do not like the log4j xml configuration file you could switch to a property file instead. You cannot configure filters using the simple property file but since it seems you don't need them this shouldn't be an issue.

Given that you're

...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.

then I'm afraid that your desired output won't give you many insights at all, it won't scale well, and it will make you loose your mind once the application gets big as expected...

Please refer to Log4j Best Practices for a good reference of logs design. Please take a look at ALL its paragraphs including the cosmetic consideration at the very end. Hope this helps.

Providenciaprovident

Answer 5

to print only messages , the following conversion pattern will do.

<param name="ConversionPattern" value="%m%n"/>

Depending on your requirement, you can set the conversion pattern to whatever you want to

1. %-5p refers to the type of log entry. This would appear in the log file as INFO, DEBUG, ERROR, etc. Technically, %p would be enough to include this description; the -5 is there to include the word in a 5-character width column.
2. %d refers to the date.
3. %t to the name of the thread that raised this log entry.
4. %c lists the category that generated this log which usually is the class name.
5. %m displays the message
6. %n adds a carriage return.

Are you going to put all relevant information in messages only? I am not sure but its not a good idea.

Stratigraphy