-
1. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
jaikiran Mar 1, 2010 12:46 PM (in response to unsavory)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 Mar 1, 2010 3:13 PM (in response to jaikiran)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 Mar 1, 2010 3:36 PM (in response to 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 Mar 1, 2010 3:49 PM (in response to unsavory)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 Mar 1, 2010 4:42 PM (in response to dmlloyd)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 Mar 1, 2010 4:45 PM (in response to unsavory)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 Mar 1, 2010 5:01 PM (in response to dmlloyd)This excerpt should show where the duplicates start:
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_PROPERTYThis 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,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 SessionThanks again david.
-
8. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
dmlloyd Mar 1, 2010 5:11 PM (in response to unsavory)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 Mar 1, 2010 5:17 PM (in response to dmlloyd)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 Mar 1, 2010 5:22 PM (in response to 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 Mar 1, 2010 5:34 PM (in response to unsavory)1 of 1 people found this helpfulOK, 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.
-
12. Re: JBoss 6.0.0.M2 Duplicate Log Messages and No DEBUG
unsavory Mar 1, 2010 6:00 PM (in response to dmlloyd)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 Mar 1, 2010 6:26 PM (in response to unsavory)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 Mar 1, 2010 7:09 PM (in response to dmlloyd)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.