log4j JMS appender not working in AS6 or 6.1 snapshot?

[cdollar393]

Has anyone had success getting a JMS log appender working for AS6? I am currently running AS6 and got the log4j SMTP appender working after following the steps in this JIRA (which makes me think that the hooks between JBoss log manager and log4j are working), but I've not had any luck with the JMS appender (which was working for me back with AS4.2). And I just tried the latest snapshot of 6.1 and its not working for me there either.

First off, I have created the JMS topic, and I can see that it has been created if I go in to the jmx-console, so I don't think that is my issue.

I've tried 2 different ways to get this working. The first is just the basic way with the <server>/deploy/jboss-loggin.xml file:

{code:xml}
  <log4j-appender name="JMS" class="org.apache.log4j.net.JMSAppender">
      <error-manager>
         <only-once/>
      </error-manager> 
      <level name="TRACE"/> 
      <properties>
         <property name="topicConnectionFactoryBindingName">java:/ConnectionFactory</property>
         <property name="topicBindingName">topic/logMessages</property>
      </properties>
   </log4j-appender>
...
   <root-logger>
      <!-- Set the root logger priority via a system property, with a default value. -->
      <level name="${jboss.server.log.threshold:INFO}"/>
      <handlers>
         <handler-ref name="CONSOLE"/>
         <handler-ref name="FILE"/>
         <handler-ref name="JMS"/>
      </handlers>
   </root-logger>
{code}

I've tried with both "java:/ConnectionFactory" and "ConnectionFactory", but neither has worked.

When I start the server with the above configs I start to see this repeated over and over in the console:

{code}
16:02:33,971 ERROR [STDERR] log4j:ERROR No TopicConnection for JMSAppender named [null].
{code}

If I start JBoss without the JMS hander-ref entry and add it in after normal startup I get the same 'No TopicConnection...' log messages as soon as the new log config is picked up.

Back with AS4.2 there was a known issue with log4j initializing before the JMS endpoints were registered within JBoss, so you couldn't use the config file approach for creating the JMS appender. Back then I just created a service MBean like was suggested elsewhere in the forums, and that worked fine. I don't think this is required with AS6+, and with 6.1 SNAPSHOT I can see where the JMS destinations get created as part of the bootstrap startup process, which seems to confirm this. At any rate, I've still tried the MBean approach which didn't work either. Perhaps this is due to JBoss using its own logging manager rather than log4j? Here's the MBean code I was using... I can see in the logs that the MBean gets deployed and there are no errors, but I also never see any logging events make it to the JMS topic, so I'm pretty sure its not working.

{code}
@Service(objectName="MyApp:service=JMSLogger")
public class JMSLogger implements JMSLoggerMBean {
          private final static Logger log = Logger.getLogger(JMSLogger.class);
          private final static String JMS_APPENDER_NAME = "JMSLogger"; 
          public void create() throws Exception {
                    JMSAppender a = new JMSAppender();
                    a.setName(JMS_APPENDER_NAME);
                    a.setErrorHandler(new OnlyOnceErrorHandler());
                    a.setThreshold(Level.TRACE);
                    a.setTopicConnectionFactoryBindingName("ConnectionFactory");
                    a.setTopicBindingName("topic/logMessages"); 
                    a.setInitialContextFactoryName("org.jnp.interfaces.NamingContextFactory");
                    a.setProviderURL("jnp://" + System.getProperty("jboss.bind.address") + ":1100");
                    a.setURLPkgPrefixes("org.jboss.naming:org.jnp.interfaces"); 
                    a.activateOptions();
                    Logger.getRootLogger().addAppender(a);
                    log.info("Created JMS logger log4j appender with name: " + JMS_APPENDER_NAME);
          } 
          public void destroy() throws Exception {
                    Logger.getRootLogger().removeAppender(JMS_APPENDER_NAME);
          }
}
{code}

Does anyone have any ideas on what I need to do to get this to work? Anyone have a working setup with AS6?

Thanks!

Chris

[bwallis42]

This may be related to the problem I just posted here. I've been debugging a similar issue. It seems that the jboss logging framework does not call AppenderSkeleton.activateOptions() which is where the JMS appender sets up its topic connection.

{code}
  /**
   *  Options are activated and become effective only after calling
   *  this method.*/
  public void activateOptions() {
    TopicConnectionFactory  topicConnectionFactory;
    try {
      Context jndi;
      LogLog.debug("Getting initial context.");
      if(initialContextFactoryName != null) {
          Properties env = new Properties( );
          env.put(Context.INITIAL_CONTEXT_FACTORY, initialContextFactoryName);
  if(providerURL != null) {
            env.put(Context.PROVIDER_URL, providerURL);
          } else {
            LogLog.warn("You have set InitialContextFactoryName option but not the "
                         +"ProviderURL. This is likely to cause problems.");
          }
  if(urlPkgPrefixes != null) {
            env.put(Context.URL_PKG_PREFIXES, urlPkgPrefixes);
          }
  if(securityPrincipalName != null) {
            env.put(Context.SECURITY_PRINCIPAL, securityPrincipalName);
            if(securityCredentials != null) {
              env.put(Context.SECURITY_CREDENTIALS, securityCredentials);
            } else {
              LogLog.warn("You have set SecurityPrincipalName option but not the "
                              +"SecurityCredentials. This is likely to cause problems.");
            }
          } 
          jndi = new InitialContext(env);
      } else {
          jndi = new InitialContext();
      }
      LogLog.debug("Looking up ["+tcfBindingName+"]");
      topicConnectionFactory = (TopicConnectionFactory) lookup(jndi, tcfBindingName);
      LogLog.debug("About to create TopicConnection.");
      if(userName != null) {
          topicConnection = topicConnectionFactory.createTopicConnection(userName, 
                                                                                       password); 
      } else {
          topicConnection = topicConnectionFactory.createTopicConnection();
      }
      LogLog.debug("Creating TopicSession, non-transactional, "
                       +"in AUTO_ACKNOWLEDGE mode.");
      topicSession = topicConnection.createTopicSession(false,
                                                                      Session.AUTO_ACKNOWLEDGE);
      LogLog.debug("Looking up topic name ["+topicBindingName+"].");
      Topic topic = (Topic) lookup(jndi, topicBindingName);
      LogLog.debug("Creating TopicPublisher.");
      topicPublisher = topicSession.createPublisher(topic);
      LogLog.debug("Starting TopicConnection.");
      topicConnection.start();
      jndi.close();
    } catch(JMSException e) {
      errorHandler.error("Error while activating options for appender named ["+name+
                               "].", e, ErrorCode.GENERIC_FAILURE);
    } catch(NamingException e) {
      errorHandler.error("Error while activating options for appender named ["+name+
                               "].", e, ErrorCode.GENERIC_FAILURE);
    } catch(RuntimeException e) {
      errorHandler.error("Error while activating options for appender named ["+name+
                               "].", e, ErrorCode.GENERIC_FAILURE);
    }
  }
{code}

Your error message is coming from the checkEntryConditions() method

{code}
 protected boolean checkEntryConditions() {
    String fail = null;
    if(this.topicConnection == null) {
      fail = "No TopicConnection";
    } else if(this.topicSession == null) {
      fail = "No TopicSession";
    } else if(this.topicPublisher == null) {
      fail = "No TopicPublisher";
    }
    if(fail != null) {
      errorHandler.error(fail +" for JMSAppender named ["+name+"].");
      return false;
    } else {
      return true;
    }
  }
{code}

The value for name is null since using the name attribute in the log4j-appender element in the config doesn't work either. You need to specify the name as one of the properties inside the log4j-appender entry instead.

[jm1468]

Chris,

    Did you ever get this working?  Did you have to extend the JMS logging appender with your own to call the activateOptions() method?  I was able to get JMS logging to work in JBoss 5, but had to reload the log4j config file through JMX after the server started up.  I still can't get JMS logging to work in JBoss 6.  Please let me know if you were able to get JMS logging to work and what you did to get it to work.

Thanks,

Jason

[technokrat]

In my case, the log properties init loggers for the main application, but the local bean doesn't see the logger tree and individual logger .

I add log4j.xml to jar with bean. It's finy initiated for the main application, but visibility doesn't changed.

[technokrat]

The patch partly fixed problem. If this patch wasn't fully applied, without adding jboss-logmanager.jar, it prones to works log4j loggers and appenders. But many stack trace falls in console about class not found LogManager.

Also I turned off JBoss beans for logging in ..\deployers\jboss-logging.deployer\META-INF\logmanager-jboss-beans.xml.

[cdollar393]

Well, I did finally manage to get this working with AS 6.1.0 Final. I'll try to outline what I did...

First off, as this thread mentions, there were some logging changes that were supposed to make it into AS 6.1 that didn't. Those changes can be found in this bug report. So the first step is to take the 3 jar files attached to the bug and replace the ones shipped with AS 6.1. That bug report also mentions upgrading ant to 1.2.16, which isn't necessary in AS 6.1 since it already ships with 1.2.16 (I believe AS 6.0 used 1.2.14?). This step gets jboss-logmanager playing nice(r) with log4j.

Another issue that has always plagued the JMS appender setup has been when JMS endpoints get deployed, but this seems to be fixed in AS 6.1. With 6.1 my JMS endpoints are deployed as part of the bootstrap process before the main logging framework kicks in, which is great. This means that configuring the JMS appender in the typical jboss-logging.xml file works and you don't have to do the MBean trick like I explained in my first post. In my case I get my JMS endpoints deployed by adding a someapp-hornetq-jms.xml file into server/<whatever>/deploy-hasingleton/jms directory. That file looks like this:

{code:xml}
<configuration xmlns="urn:hornetq"
                    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
                    xsi:schemaLocation="urn:hornetq /schema/hornetq-jms.xsd">
          <topic name="logMessages">
                    <entry name="/topic/logMessages" />
          </topic>
</configuration>
{code}

The settings needed in jboss-logging.xml are the same as what I posted originally. Brian's note about the appender name wasn't required for me to get the appender working, but it did aid in the debugging processes.

After making these changes I started receiving logging events in my topic.

Now on to the message consumers... My first consumer was a typical MDB (no, I would not do this in a production environment) that subscribed to the topic. When the onMessage() method fired in the MDB I'd start seeing these messages in the logs:

{noformat}
2012-01-26 12:04:47,444 ERROR [STDERR] log4j:WARN Level deserialization failed, reverting to default.
2012-01-26 12:04:47,445 ERROR [STDERR] java.lang.NoSuchMethodException: org.jboss.logmanager.log4j.handlers.Log4jJDKLevel.toLevel(int)
2012-01-26 12:04:47,445 ERROR [STDERR]  at java.lang.Class.getDeclaredMethod(Class.java:1937)
2012-01-26 12:04:47,445 ERROR [STDERR]  at org.apache.log4j.spi.LoggingEvent.readLevel(LoggingEvent.java:436)
2012-01-26 12:04:47,445 ERROR [STDERR]  at org.apache.log4j.spi.LoggingEvent.readObject(LoggingEvent.java:464)
2012-01-26 12:04:47,446 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor399.invoke(Unknown Source)
2012-01-26 12:04:47,446 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2012-01-26 12:04:47,446 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2012-01-26 12:04:47,446 ERROR [STDERR]  at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
2012-01-26 12:04:47,447 ERROR [STDERR]  at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1848)
2012-01-26 12:04:47,447 ERROR [STDERR]  at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
2012-01-26 12:04:47,447 ERROR [STDERR]  at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
2012-01-26 12:04:47,450 ERROR [STDERR]  at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350)
2012-01-26 12:04:47,451 ERROR [STDERR]  at org.hornetq.jms.client.HornetQObjectMessage.getObject(HornetQObjectMessage.java:158)
2012-01-26 12:04:47,451 ERROR [STDERR]  at com.someapp.mdb.LogMessageProcessorBean.onMessage(LogMessageProcessorBean.java:34)
2012-01-26 12:04:47,452 ERROR [STDERR]  at sun.reflect.GeneratedMethodAccessor398.invoke(Unknown Source)
2012-01-26 12:04:47,454 ERROR [STDERR]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2012-01-26 12:04:47,455 ERROR [STDERR]  at java.lang.reflect.Method.invoke(Method.java:597)
2012-01-26 12:04:47,455 ERROR [STDERR]  at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
{noformat}

So it looks like it is expecting to find a toLevel(int) method and isn't finding it. This is coming from the org.apache.log4j.spi.LoggingEvent class in the readLevel() method. This method has in its comments:

{code}
// Note that we use Class.getDeclaredMethod instead of
// Class.getMethod. This assumes that the Level subclass
// implements the toLevel(int) method which is a
// requirement. Actually, it does not make sense for Level
// subclasses NOT to implement this method. Also note that
// only Level can be subclassed and not Priority.
{code}

The jboss-logmanager code subclasses Level in the Log4jJDKLevel.java class (can be found here), but it does not implement the toLevel(int) method. So I used the git URL at the top of that page to clone the jboss-logmanager-log4j project and then made the following changes. I should note there that I'm not sure that this particlar patch does the right thing... I just modeled the method after one from the log4j source. After that I did a rebuild with maven.

{code}
diff --git a/src/main/java/org/jboss/logmanager/log4j/handlers/Log4jJDKLevel.java b/src/main/java/org/jboss/logmanager/log4j/handlers/Log4jJDKLevel.java
index 7e847a8..dcbf5ef 100644
--- a/src/main/java/org/jboss/logmanager/log4j/handlers/Log4jJDKLevel.java
+++ b/src/main/java/org/jboss/logmanager/log4j/handlers/Log4jJDKLevel.java
@@ -110,4 +110,26 @@ public final class Log4jJDKLevel extends Level {
         final Level level = levelMapping.get(name.trim().toUpperCase());
         return level != null ? level : Level.toLevel(name);
     }
-}
\ No newline at end of file
+
+    public static Level toLevel(int val) {
+        switch(val) {
+        case Level.ALL_INT: return Level.ALL;
+        //case Level.DEBUG_INT: return Level.DEBUG;
+        //case Level.INFO_INT: return Level.INFO;
+        //case Level.WARN_INT: return Level.WARN;
+        //case Level.ERROR_INT: return Level.ERROR;
+        case Level.FATAL_INT: return Level.FATAL;
+        case Level.OFF_INT: return Level.OFF;
+        //case Level.TRACE_INT: return Level.TRACE;
+        case Level.ERROR_INT: return SEVERE;
+        case Level.WARN_INT: return WARNING;
+        case Level.INFO_INT: return INFO;
+        case (Level.INFO_INT - 5000): return CONFIG;
+        case Level.DEBUG_INT: return FINE;
+        case (Level.DEBUG_INT - 2500): return FINER;
+        case Level.TRACE_INT: return FINEST;
+        default: return INFO;
+        }
+    }
+}
+
{code}

After the build I replaced the jboss-logmangager-log4j.jar file in JBoss with the one I just build with maven. After this JBoss didn't see any errors in the MDB.

The 2nd consumer was a remote program that just connected to the JMS topic and consumed messages. This was pretty straightforward as its nothing more than a typical JMS client program. The only issue I had here was due to missing classes. Apparently when the jboss logging mechanism sends a logging event over to log4j it converts it to a ConvertedLoggingEvent object, and this class is not in the jboss-logging.jar client jar file (found in JB_HOME/client). This class is in the jboss-logmanager-log4j.jar file that I just rebuilt with maven and end up living in JB_HOME/common/lib.  After adding that to my client program classpath it errored out with not finding the ExtLogRecord class. This one also is not in the client jar, but can be found in JB_HOME/lib/jboss-logmanager.jar. After getting those 2 additional jars (in addition to the typical jars needed for a JMS client program) in my classpath my client program works fine as well.

I've not done extensive testing with these changes, but so far its working well in my development environment. I'll attach the jboss-logmanager-log4j.jar file that was built with the toLevel(int) method along with the patch that you can use to roll your own jar. Hopefully this will help someone in the future!

Chris