1 2 Previous Next 24 Replies Latest reply on Jul 14, 2011 7:59 PM by jbhatt

    JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG

    unsavory

      Perhaps I am doing something wrong, but when I deploy my war file to JBoss 6.0.0.M2, I get duplicate log statements while the application is booting.  But the worst part is, no matter what I try I cannot get debug output from my application.

       

      I have tried setting the root logger to DEBUG and everything else starts logging in debug mode (ie: hibernate, spring).  But my application specific code will not output anything but INFO messages.

       

      I am using the default jboss-logging.xml file that shipped with JBoss.  And if I add this to the configuration file, it does nothing:

       

      <logger category="com.so">
              <level name="DEBUG" />
      </logger>

       

      Any ideas?

        • 1. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
          jaikiran

          unsavory wrote:

           

           

           

          I have tried setting the root logger to DEBUG and everything else starts logging in debug mode (ie: hibernate, spring).  But my application specific code will not output anything but INFO messages.

           


          Which file are you checking for the logs? And does your application package any logging implementation (like log4j) configs/jars?

           

          unsavory wrote:

           

          Perhaps I am doing something wrong, but when I deploy my war file to JBoss 6.0.0.M2, I get duplicate log statements while the application is booting.


          Can you post an example? And where the duplicate logging happening? On console or in some log file?

          • 2. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
            unsavory

            I am looking in server/default/log/server.log, and no my application does not package any implementation of any logging frameworks.

             

            It turns out this was indeed an issue with the console only.  I get duplicate messages in the console on boot, and no application debug log statements.

             

            It turns out that if I remove the level element in the console-handler, I can get debug messages in the console.

             

            Old jboss-logging.xml:

             

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

             

               <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] %m%n"/>
                  </formatter>
               </console-handler>

             

            New jboss-logging.xml:

             

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

             

               <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] %m%n"/>
                  </formatter>
               </console-handler>

             

            Now I get debug statements sent to the console.  But strangely enough, I cannot figure out why I cannot seem to set my root logger to INFO.  I am getting trace level output on everything now:

             

            <logger category="org.springframework">
                  <level name="WARN"/>
               </logger>

             

            <root-logger>
                  <!-- Set the root logger priority via a system property, with a default value. -->
                  <level name="INFO"/>
                  <handlers>
                     <handler-ref name="CONSOLE"/>
                     <handler-ref name="FILE"/>
                  </handlers>
               </root-logger>

             

            And the output:

             

            12:13:20,456 TRACE [org.springframework.transaction.support.TransactionSynchronizationManager] Clearing transaction synchronization
            12:13:20,456 TRACE [org.springframework.transaction.support.TransactionSynchronizationManager] Initializing transaction synchronization
            12:13:20,457 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Opening Hibernate Session
            12:13:20,457 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Registering Spring transaction synchronization for new Hibernate Session
            12:13:20,459 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Flushing Hibernate Session on transaction synchronization
            12:13:20,459 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Closing Hibernate Session
            12:13:20,460 TRACE [org.springframework.transaction.support.TransactionSynchronizationManager] Clearing transaction synchronization

            • 3. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
              unsavory
              I should probably note, this all works perfectly under JBoss 6.0.0.M1.  No duplicate log statements, no trace level statements from packages configurated otherwise.
              • 4. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                dmlloyd

                The main thing that has changed are the defaults.

                 

                The way logging level filtering works is, first the logger category's level is checked (which may be inherited from the parent logger, if none is specified).  If that check passes, then each individual handler has the opportunity to filter the message.

                 

                Since the console handler is configured to level INFO by default, you won't see DEBUG output there no matter how the loggers are configured, since anything more detailed than INFO will be filtered out from that handler.  However, by default, the FILE handler should not have any configured level, so whatever the loggers pass on will be logged.

                 

                Thus if you set the root logger to TRACE (via the jboss.server.log.threshold property for example), you will be inundated with TRACE messages.

                 

                However, this only happens once the log service is started up.  If you're looking for log messages which occur before the log service starts, you'll have to configure boot logging instead.

                 

                Since jboss-logging.properties is welded into the runtime JAR, it's usually easiest to use properties to affect its values.

                 

                To set the bootstrap log level limit, set -Djboss.boot.server.log.level=DEBUG or TRACE.  By default, the boot.log handler won't log anything more detailed than DEBUG regardless of the boot log level, so to change that, use -Djboss.boot.server.log.file.level=TRACE.

                 

                For more information about that, see JBossBootLogging.

                • 5. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                  unsavory

                  Thank you for your answer David.  Unfortunately, it still does not address the following issues:

                   

                  A.  The duplicate logging statements in the console during boot.

                   

                  B.  Why am I getting TRACE level log statements from org.springframework when I've specifically set it to WARN?

                   

                  Thanks,

                  Caine

                  • 6. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                    dmlloyd

                    I've never seen behavior like you describe.  Can you post a (brief) excerpt from your log file which demonstrates the duplication problem?

                     

                    As far as the TRACE level stuff goes, does it happen before or after the log system starts up (this is presently towards the end of the boot sequence - you'll see a message like "Removing bootstrap log handlers")?

                    • 7. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                      unsavory

                      This excerpt should show where the duplicates start:

                       

                      13:49:32,840 INFO  [XmlWebApplicationContext] Bean '(inner bean)' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
                      13:49:32,843 INFO  [XmlWebApplicationContext] Bean 'org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource#0' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
                      13:49:32,875 INFO  [XmlWebApplicationContext] Bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
                      13:49:33,230 INFO  [DefaultListableBeanFactory] Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@1e63b60: defining beans [org.springframework.context.weaving.AspectJWeavingEnabler#0,org.springframework.context.config.internalBeanConfigurerAspect,loadTimeWeaver,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,bpmService,preAuthenticatedUserDetailsService,preAuthenticatedUserDetailsServiceOld,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,org.springframework.beans.factory.annotation.RequiredAnnotationBeanPostProcessor#0,org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor#0,org.springframework.transaction.config.internalTransactionAspect,org.springframework.aop.config.internalAutoProxyCreator,dataSource,entityManagerFactory,transactionManager,sessionFactory,InboundFilter,webConfig,mbeanServer,exporter,jmxAttributeSource,assembler,namingStrategy,springHelper,processEngine,org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource#0,org.springframework.security.access.vote.AffirmativeBased#0,org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor#0,org.springframework.security.methodSecurityMetadataSourceAdvisor,org.springframework.security.web.PortMapperImpl#0,org.springframework.security.web.context.HttpSessionSecurityContextRepository#0,org.springframework.security.web.authentication.session.SessionFixationProtectionStrategy#0,org.springframework.security.authentication.ProviderManager#0,org.springframework.security.access.vote.AffirmativeBased#1,org.springframework.security.web.access.intercept.FilterSecurityInterceptor#0,org.springframework.security.web.access.DefaultWebInvocationPrivilegeEvaluator#0,org.springframework.security.authentication.AnonymousAuthenticationProvider#0,org.springframework.security.web.savedrequest.HttpSessionRequestCache#0,org.springframework.security.config.http.UserDetailsServiceInjectionBeanPostProcessor#0,org.springframework.security.filterChainProxy,preAuthenticatedProcessingFilterEntryPoint,appContextFilter,preauthAuthProvider,org.springframework.security.authentication.DefaultAuthenticationEventPublisher#0,org.springframework.security.authenticationManager]; root of factory hierarchy
                      13:49:34,483 INFO  [DispatcherThread] starting DispatcherThread
                      13:49:34,483 INFO  [DispatcherThread] starting DispatcherThread
                      13:49:34,635 INFO  [Configuration] configuring from url: vfsfile:/C:/Agilisant/jboss-6.0.0.M2/server/default/deploy/s1.war/WEB-INF/classes/jbpm.hibernate.cfg.xml
                      13:49:34,635 INFO  [Configuration] configuring from url: vfsfile:/C:/Agilisant/jboss-6.0.0.M2/server/default/deploy/s1.war/WEB-INF/classes/jbpm.hibernate.cfg.xml
                      13:49:34,644 INFO  [Configuration] Reading mappings from resource : jbpm.repository.hbm.xml
                      13:49:34,644 INFO  [Configuration] Reading mappings from resource : jbpm.repository.hbm.xml
                      13:49:34,684 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.repository.DeploymentImpl -> JBPM4_DEPLOYMENT
                      13:49:34,684 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.repository.DeploymentImpl -> JBPM4_DEPLOYMENT
                      13:49:34,711 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.repository.DeploymentProperty -> JBPM4_DEPLOYPROP
                      13:49:34,711 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.repository.DeploymentProperty -> JBPM4_DEPLOYPROP
                      13:49:34,717 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.id.PropertyImpl -> JBPM4_PROPERTY
                      13:49:34,717 INFO  [HbmBinder] Mapping class: org.jbpm.pvm.internal.id.PropertyImpl -> JBPM4_PROPERTY

                       

                      This excerpt shows where it returns to normal, and where trace level messages show up:

                       

                      13:49:38,241 INFO  [DefaultLocalePicker] No locale list specified, defaulting to single locale: en_US
                      13:49:38,241 INFO  [DefaultLocalePicker] No locale list specified, defaulting to single locale: en_US
                      13:49:38,270 WARN  [DefaultMultipartWrapperFactory] No MultipartWrapper implementation could be loaded
                      13:49:38,270 WARN  [DefaultMultipartWrapperFactory] No MultipartWrapper implementation could be loaded
                      13:49:38,286 INFO  [StripesFilter] Stripes Initialization Complete. Version: 1.5.2, Build: 1214
                      13:49:38,286 INFO  [StripesFilter] Stripes Initialization Complete. Version: 1.5.2, Build: 1214
                      13:49:38,331 INFO  [service] Removing bootstrap log handlers
                      13:49:38,331 INFO  [service] Removing bootstrap log handlers
                      13:49:38,581 INFO  [org.jboss.system.server.profileservice.ProfileServiceBootstrap] Loading profile: ProfileKey@17e4c97[domain=default, server=default, name=default]
                      13:49:38,600 INFO  [org.apache.coyote.http11.Http11Protocol] Starting Coyote HTTP/1.1 on http-localhost%2F127.0.0.1-8080
                      13:49:38,603 INFO  [org.apache.coyote.ajp.AjpProtocol] Starting Coyote AJP/1.3 on ajp-localhost%2F127.0.0.1-8009
                      13:49:38,603 INFO  [org.jboss.bootstrap.impl.base.server.AbstractServer] JBossAS [6.0.0.20100216-M2 (build: SVNTag=JBoss_6_0_0_20100216-M2 date=20100216)] Started in 39s:643ms
                      13:49:42,798 TRACE [org.springframework.transaction.support.TransactionSynchronizationManager] Initializing transaction synchronization
                      13:49:42,841 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Opening Hibernate Session
                      13:49:42,841 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Registering Spring transaction synchronization for new Hibernate Session
                      13:49:42,862 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Flushing Hibernate Session on transaction synchronization
                      13:49:42,866 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] Closing Hibernate Session

                       

                      Thanks again david.

                      • 8. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                        dmlloyd

                        OK this gives some insight.  Here's my hypothesis.

                         

                        The duplication starts right when Spring starts its bootstrap.  At this stage, the default bootstrap log Handler must be getting reinstalled somehow - maybe Spring, or something it deploys, is forcibly re-initializing java.util.logging somehow.  The duplication ends when the log service starts up, because the log service removes all handlers from the root logger when it installs its own.  When the container shuts down, odds are the duplication will resume again.

                         

                        The big question is, how are the handlers being duplicated?  A glance over the spring code doesn't tell me much, but I'd find it interesting to know where that "DispatcherThread" comes from (it doesn't appear to be a JBossAS or Spring (core) class; is it something from one of your deployments?).


                        • 9. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                          unsavory

                          Hi David,

                           

                          The DispatcherThread is from Stripes Web Framework.  And yes, the duplication does start back up on shutdown as you suspected.  Please let me know if you need more information.  Would this also explain the trace level logging from Spring?

                          • 10. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                            unsavory
                            By the way, I don't know if it would help to know I am using Spring 3.02.
                            • 11. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                              dmlloyd

                              OK, I don't have Stripes so I couldn't look at the source but that's where I'd start.  I think the TRACE problem is due simply to the fact that jboss-logging.xml doesn't take effect until everything is started, so by then, all the trace logs are written.

                               

                              There are two answers to this.

                               

                              1) To change the boot log settings to add a single category filter, you have to edit logging.properties which is inside bin/run.jar and put the modified file back in the jar.  This, however, is a pain, so...

                              2) We have an open issue to make sure the log service starts up very early on in the boot process for future releases (i.e. before user deployments).  The https://jira.jboss.org/jira/browse/JBAS-7681 issue is where this is being tracked.

                              1 of 1 people found this helpful
                              • 12. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                                unsavory

                                Thanks David,  but just to be clear the trace logging happens after the server has started up and stays on.  I cannot turn it off.

                                • 13. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                                  dmlloyd
                                  It is possible that Spring or another secondary framework is somehow responsible, installing its own handler and/or reconfiguring its own logger.  It looks like in the default jboss-logging.xml we limit "org.springframework" to "WARN", so if it's logging DEBUG or TRACE after that point, then it must be something changing the level programmatically after the log service is started.
                                  1 of 1 people found this helpful
                                  • 14. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
                                    unsavory
                                    Makes sense, I guess I just don't know why it would not happen on JBoss 6.0.0.M1, but it does on 6.0.0.M2.  I am using the exact same project archive and deploying to both servers.  The problem does not exist on M1.
                                    1 2 Previous Next