5 Replies Latest reply on Jun 20, 2011 4:04 PM by pgmjsd

    Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final

    trewig

      Hello,

       

      we try to switch from Jboss 5 AS to JBOSS 6 AS Final. Everything works fine except the logging.

       

      the conf-File /server/default/deploy/jboss-logging.xml look like this:

       

      <?xml version="1.0" encoding="UTF-8"?>
      
      <!-- ===================================================================== -->
      <!--                                                                       -->
      <!--  Logging System Configuration                                         -->
      <!--                                                                       -->
      <!-- ===================================================================== -->
      
      <logging xmlns="urn:jboss:logging:6.0" xmlns:b="urn:jboss:bean-deployer:2.0">
      
         <!-- ================================= -->
         <!-- Preserve messages in a local file -->
         <!-- ================================= -->
      
         <!-- A size based file rolling appender -->
      
         <size-rotating-file-handler
               file-name="${jboss.server.log.dir}/server.log"
               name="FILE"
               autoflush="true"
               append="true"
               rotate-size="500k"
               max-backup-index="5">
      
            <error-manager>
               <only-once/>
            </error-manager>
      
           <formatter>
               <pattern-formatter pattern="%d %-5p [%c] %C{1} (%t) %s%E%n"/>
                 <!-- <pattern-formatter pattern="%d %-5p [%c] (%t) %m%n"/> -->
            </formatter>
         </size-rotating-file-handler>
      
      
         <console-handler name="CONSOLE" autoflush="true" target="System.out">
            <error-manager>
               <only-once/>
            </error-manager>
      
            <level name="INFO"/>
      
            <formatter>
               <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %s%E%n"/>
            </formatter>
         </console-handler>
      
      
         <!-- EMail events to an administrator -->
      
         <log4j-appender name="SMTP" class="org.apache.log4j.net.SMTPAppender">
            <error-manager>
               <only-once/>
            </error-manager>
      
            <level name="ERROR"/>
      
            <properties>
               <property name="to">myemail@example.com</property>
               <property name="from">myemail@example.com</property>
               <property name="subject">JBoss Server Errors JBOSS_TEST</property>
               <property name="SMTPHost">mail.example.net</property>
               <property name="bufferSize">10</property>
            </properties>
      
            <formatter>
               <pattern-formatter pattern="%d %-5p [%c] (%t) %m%n"/>
            </formatter>
         </log4j-appender>
      
      
      ....
      
         <!-- MyAppenders -->
      
      
         <size-rotating-file-handler
               file-name="${jboss.server.log.dir}/performance.log"
               name="PERFORMANCE_LOG_FILE"
               autoflush="true" append="true" rotate-size="500k" max-backup-index="5">
           <error-manager><only-once/></error-manager>
           <formatter>
               <pattern-formatter pattern="%d %-5p [%c] %C{1} (%t) %s%E%n"/>
            </formatter>
         </size-rotating-file-handler>
      
      
         <size-rotating-file-handler
               file-name="${jboss.server.log.dir}/cassandra_hector.log"
               name="CASSANDRA_HECTOR"
               autoflush="true" append="true" rotate-size="500k" max-backup-index="5">
           <error-manager><only-once/></error-manager>
           <formatter>
               <pattern-formatter pattern="%d %-5p [%c] %C{1} (%t) %s%E%n"/>
            </formatter>
         </size-rotating-file-handler>
      
      
      
      ....
      
         <!-- MyCategories -->
      
      
         <logger category="de.test.performance">
           <level name="WARN" />
           <handlers>
              <handler-ref name="PERFORMANCE_LOG_FILE"/>
           </handlers>
         </logger>
      
         <logger category="me.prettyprint.cassandra" additivity="false">
           <level name="WARN" />
           <handlers>
              <handler-ref name="CASSANDRA_HECTOR"/>
           </handlers>
         </logger>
      
      
         <!-- ======================= -->
         <!-- Setup the Root category -->
         <!-- ======================= -->
      
         <root-logger>
            <!-- Set the root logger priority via a system property, with a default value. -->
            <level name="${jboss.server.log.threshold:WARN}"/>
            <handlers>
               <handler-ref name="CONSOLE"/>
               <handler-ref name="FILE"/>
            </handlers>
         </root-logger>
      
      </logging>
      

       

      Although the root logger priority is WARN, I can see all INFO log messages in the server.log - even the cassandra_hector Logs (they should be excluded from the server.log by the additivity="false" propertie)

      And in the cassandra_hector.log I can see all INFO LOGS from Cassandra although the level name is WARN.

       

      The SMTP-Appender doesnt work too even though the email and the SMTPHost is valid (and works in Jboss5AS).

       

      Is there some good documentation for logging with jboss-logging in JBOSS 6 AS. Can you give me a hint, what I do wrong?

       

      Thanks in advance

      Thomas

        • 1. Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final
          genman

          You might want to get the attention of the jboss-logging people. They basically wrote a compatibilty layer that's kind of incomplete...

           

          Check out the source:

          https://github.com/jbossas/jboss-logging

           

          You can file bugs in the JBoss JIRA for this project.

          • 2. Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final
            jaikiran

            Thomas Rewig wrote:

             

            Although the root logger priority is WARN, I can see all INFO log messages in the server.log - even the cassandra_hector Logs (they should be excluded from the server.log by the additivity="false" propertie)

            And in the cassandra_hector.log I can see all INFO LOGS from Cassandra although the level name is WARN.

             

            Hmm... that's something very basic of a logging framework and I would be surprised if that is broken in 6.0.0. Can you please post the logs that you are seeing and also the code (including the logging framework related import statements) which does the logging?

            • 3. Re: Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final
              trewig

              Thanks for your reply.

               

              I also do not think that there is something broken on the logging framework, I'm guessing more to user error on my part ...


              In the server.log I see for example:

               

              2011-04-26 14:10:27,688 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827686] time[2] tag[WRITE.success_]
              2011-04-26 14:10:27,689 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827688] time[1] tag[WRITE.success_]
              2011-04-26 14:10:27,690 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827689] time[1] tag[WRITE.success_]
              2011-04-26 14:10:27,691 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827690] time[1] tag[WRITE.success_]
              2011-04-26 14:11:37,663 INFO  [org.apache.jcs.engine.memory.shrinking.ShrinkerThread] ShrinkerThread (Thread-17) Exceeded maxIdleTime 190002
              2011-04-26 14:11:37,665 INFO  [org.apache.jcs.engine.memory.shrinking.ShrinkerThread] ShrinkerThread (Thread-17) Exceeded maxIdleTime 5740223
              2011-04-26 14:11:37,665 INFO  [org.apache.jcs.engine.memory.shrinking.ShrinkerThread] ShrinkerThread (Thread-17) Exceeded maxIdleTime 155094
              2011-04-26 14:11:37,666 INFO  [org.apache.jcs.engine.memory.shrinking.ShrinkerThread] ShrinkerThread (Thread-17) Exceeded maxIdleTime 6492743
              2011-04-26 14:11:37,666 INFO  [org.apache.jcs.engine.memory.shrinking.ShrinkerThread] ShrinkerThread (Thread-17) Exceeded maxIdleTime 4772087
              2011-04-26 14:11:44,441 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (something) start[1303819904390] time[51] tag[READ.success_]
              2011-04-26 14:11:44,480 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (something) start[1303819904451] time[29] tag[READ.success_]
              

               

              In my opinion, at least the JBoss-specific logging (like org.apache.jcs.engine.memory.shrinking.ShrinkerThread) should not write in the server.log because the rootlogger is on WARN.

               

              The Filter for the cassandra_hector.log would be correct if I want output for INFO and additivity = "true"

               

              2011-04-26 14:10:27,688 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827686] time[2] tag[WRITE.success_]
              2011-04-26 14:10:27,689 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827688] time[1] tag[WRITE.success_]
              2011-04-26 14:10:27,690 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827689] time[1] tag[WRITE.success_]
              2011-04-26 14:10:27,691 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (Queue_Worker_1_23) start[1303819827690] time[1] tag[WRITE.success_]
              2011-04-26 14:11:44,441 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (something) start[1303819904390] time[51] tag[READ.success_]
              2011-04-26 14:11:44,480 INFO  [me.prettyprint.cassandra.hector.TimingLogger] Slf4JStopWatch (something) start[1303819904451] time[29] tag[READ.success_]
              

               

               

              In my code I use the Jboss-Logger ... for example:

               

               

              package de.test.util.logging;
              
              import org.jboss.logging.Logger;
              
              public class TestLogger {
              
                  private static Logger logPerformanceLogger = Logger.getLogger(TestLogger.class);
              
                    public void logSomething {
                      logger.info("log something");
                    }
              
              }
              
              
              • 4. Re: Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final
                trewig

                I've tried around a bit and I noticed ridiculous and illogical things I cant understand.

                 

                The first thing is that the logging categories like

                 

                   <logger category="me.prettyprint.cassandra.hector.TimingLogger" additivity="false">
                     <level name="WARN" />
                     <handlers>
                        <handler-ref name="CASSANDRA_HECTOR"/>
                     </handlers>
                   </logger>

                 

                only seems to work if I change the level name while jboss is running (e.g. change WARN to ERROR after JBOSS has started), prior the logging framework seems to ignore the categories and write all the info loggings in the main appender (server.log ) and the referenced sub-appender.

                 

                The second thing is, that the logger categories (if they appear to be activated) behave differently than in the jboss 5:

                 

                Let's take the Cassandra/Hector logging example:

                 

                In jboss 5 all "childs" of a package are send to its appenders. So if I want to filter me.prettyprint.cassandra.hector.TimingLogger and me.prettyprint.cassandra.connection.NodeAutoDiscoverService I just have to declare a categorie like in the jboss-log4j.xml :

                 

                  <category name="me.prettyprint.cassandra">

                      <priority value="WARN"/>

                     <appender-ref ref="CASSANDRA_HECTOR"/>

                   </category>

                 

                Now in jboss6 it seems that only a categorie works if there is a exact correspondence between the class name and the category name. So there has to be 2 categories for me.prettyprint.cassandra.hector.TimingLogger and

                me.prettyprint.cassandra.connection.NodeAutoDiscoverService

                 

                Has anyone had similar experiences? And has anyone already get a working application wide logging with jboss6 ?

                 

                ... very frustrating, the new improved logging system, especially without documentation of the features!

                 

                Any help and suggestions are welcome.

                Thanks in advance

                Thomas

                • 5. Re: Problems with the migration of logging Jboss 5 AS -> JBoss AS 6 Final
                  pgmjsd

                  @Thomas - WRT category names, I haven't tried that yet with JBoss Logging, but I do remember that the order of the <category> elements in the Log4J configuration was very important when it comes to forwarding to the 'parent' categories.   Maybe JBoss Logging behaves differently?    Like you said, without any documentation the only thing you can do is read the source code.