Double logging output in JBoss 7

[haukegulich]

Hello everyone,

I have, hopefully, a tiny problem with my application deployed on JBoss 7.0.2 (and older versions as well).

I have a class snippet like this

{code}
package de.hauke.server.jms;
import org.apache.log4j.Logger;
public class JMSWatcher implements MessageListener {
    private static final Logger LOG = Logger.getLogger(JMSWatcher.class);
    public void onMessage(){
         LOG.debug("Der Server hat eine JMS Nachricht empfangen auf (toServer)");
         ....
    }
{code}

If I look at the log output when I start the jboss (standalone.bat) I will see this

07:00:10,192 INFO  (stdout) (T h r e a d - 1 (group:HornetQ-client-global-threads-823604252)) 07:00:10,192 INFO  (JMSWatcher                
) | Der Server hat eine JMS Nachricht empfangen auf (toServer)

The right side of the log output

07:00:10,192 INFO  [JMSWatcher                ] | ....

is like I defined the output in my log4j.xml inside the resource folder from my application. Here is my log4j.xml (just the important part)

{code:xml}
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <param name="Threshold" value="DEBUG" />
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%-30.30c{1}] | %m%n"/>
        </layout>
    </appender>{code}

Then I looked in the standalone.xml configuration and found this line:

{code:xml}

	<console-handler name="CONSOLE" autoflush="true">
	<level name="INFO"/>
	<formatter>
	<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
	</formatter>
	</console-handler>

{code}

------------------------------------------------------------------------------------

Now I modified the log4j.xml to the pattern

%m%n

and inside the standalone.xml the pattern to

pattern="%d{HH:mm:ss,SSS} %-5p [%-30.30c{1}] | %s%E%n

with the result of

07:14:50,229 INFO  [stdout

] | Der Server hat eine JMS Nachricht empfangen auf (toServer)

This looks better, but I always get the log level as INFO and the class name as stdout.

What do I have to do to get that working?

Thanks and greetings,

Hauke

[jamezp]

Hello Hauke,

It seems correct to me that you should be receiving duplicate console output. You're defining a log4j console logger and AS7 is defining a JBoss Logging console handler.

As far as the format goes. What happens is JBoss Logging captures standard out which log4j is writing to and processes it through itself. Basically JBoss Logging is grabbing stdout and processing through it's own format.

What you would really want to do is change the format in the standalone.xml or create a new handler in standalone.xml that uses a different format. You could then create a new logger for a category, e.g. "de.hauke.server", that would use the new handler you created.

<subsystem xmlns="urn:jboss:domain:logging:1.1">
    ...
    <console-handler name="customConsole">
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%-30.30c{1}] | %s%E%n"/>
        </formatter>
    </console-handler>
    <logger category="de.hauke.server"> 
        <level name="INFO"/>
        <handlers>
             <handler name="customConsole"/>
        </handlers>
    </logger>
    ...
</subsystem>

We are working on support for JBoss AS7 to reconginize JUL logging and log4j configurations per deployment.

--

James R. Perkins

[haukegulich]

Hello James,

thanks for your time helping me out here.

What you wrote seems to me logically but it isn't working.

You said, that Jboss captures the output from log4j and prints them as stdout in the jboss logs. How can JBoss interpret the output from log4j if it comes from stdout? I mean, I can modify the logging in log4j.xml like I want and JBoss can not understand if this line is a debug or warning message. Or am I wrong?

Also I am asking myself if this is the right way for logging? Can't I use the jboss logging in some way? I just changed the import from log4j to org.jboss.logging but after that no log messages apears at all.

Or is my thinking completely wrong? Or do I need to say log4j to create a log file with an org.apache.log4j.FileAppender and look at this log file? But do I get JBoss exceptions there as well? I don't think so.

Kind of strange with the logging :-)

Kind regards,

Hauke

[jamezp]

Hello Hauke,

What happens is log4j just outputs to stdout. JBoss Logging just grabs what's being sent to stdout and logs it.

You should be able to use JBoss Logging instead of log4j. In fact I prefer JBoss Logging as it has vararg logging methods. It also accepts the String.format() format, so it's much richer than the old message format style.

Most appenders I don't currently work as most people expect I've realized. That is one reason we're working on getting them to work properly.

--

James R. Perkins

[t3rm1]

This is a really weird behavior. Is there a way to deactivate the redirection? Let's say I want to use my own log4j or any other third party logging which prints text to stdout. I don't want JBoss to format this again. I want to see it on the console as I would expect it. Please tell me that this is possible.

I tried this but it still gives me double output:

<logger category="stdout">
                <handlers>
                    <handler name="PASSTHROUGH"/>
                </handlers>
            </logger>
<console-handler name="PASSTHROUGH">
                <formatter>
                    <pattern-formatter pattern="%s%E%n"/>
                </formatter>
            </console-handler>

[jamezp]

How is this behavior weird? The stdio stream has to be captured or System.out.println() wouldn't work. You can use a third party logging framework if you'd like, but why would add a console handler when there is already one there?

[t3rm1]

Well, like I said. Assume that I have an application which logs to stdout in a specific format. JBoss catures all this and applies its own pattern. I don't want that. If I write something to stdout in the format x I don't want to see it in format y. Is it possible? I don't want to adjust the logging in my whole application.

In the example above I added another console handler which doesn't change the pattern. It kinda works. I see my message in the right format but for some odd reason the second console handler is used as well and the output is changed again.

[jamezp]

I can't say I would advise this, but you could potentially create a stdout logger and that may work.

<subsystem xmlns="urn:jboss:domain:logging:1.1">
    ...
    <console-handler name="stdout-console" autoflush="true">
        <level name="ALL"/>
        <formatter>
            <pattern-formatter pattern="%s%n"/>
        </formatter>
    </console-handler>
    <logger category="stdout" use-parent-handlers="false">
        <handlers>
            <handler name="stdout-console"/>
        </handlers>
    </logger>
    ...
</subsystem>

This will override anything that writes to stdout. If you want to use this with log4j you'll have to make sure to exclude the servers version of log4j.

Again, I wouldn't encourage this use-case. If anything outside your application prints to standard out there will be no format.

[haukegulich]

Hello everyone and thanks for your replies.

I finally figured out the problem by myself. I didn't know that I actually should have used commons-logging with is working as a kind of proxy for different logging frameworks like log4j.

As soon as I removed the log4j.xml and changed the imports from log4j to commons logging everything worked fine.

Like always I thought way to complicated.

Maybe somebody else finds this information usefull.

Thanks again and greetings

Hauke

[t3rm1]

If anything else prints to stdout then something is wrong with its design

If I use your settings I get an extra new line after each output. Why is there no option to turn this "stdout redirection feature" off?

[jamezp]

Maybe you already have a new line character defined in your format. If you remove the %n of the patter in your standalone.xml then that will stop that new line from printing.

There is no option to turn the stdout redirection off because it's not a feature :-). There is no way we could get around not redirecting the output. In fact I wouldn't even use the solution I suggested.

[ianmichael930]

I thought I would add one more enhancement to this post.  After following all of these steps, I was still experiencing double-logging from an external JAR that had explcit log4j imports.

Adding this log4j.xml to my classpath solved those as well, without interrupting Jboss logging whatsoever.  This log4j.xml explicitly disables log4j logging, so any log4j imports buried in an external jar will stop printing to [stdout], yet its log entries will still be recorded by Jboss.  Note the threshold="off" attribute of <log4j:configuration>.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<!-- This dummy config silences log4j in external jars from printing to stdout, which are
     re-logged by Jboss. Jboss logger continues to capture the logs and print them correctly
     using jboss logging; this merely eliminates duplicate logging. -->
<log4j:configuration 
  xmlns:log4j="http://jakarta.apache.org/log4j/"
  threshold="off">
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c (%F:%L) - %m%n"/>
</layout>
</appender>
<root>
<priority value="off"/>
<appender-ref ref="CONSOLE"/>
</root>
</log4j:configuration>

This should also work if you would prefer not to switch your application imports to commons logging or sl4j, although there are other advantages to making the transition to commons or slf4j to consider.

Ian