[logback-user] Fwd: logback start listener invoked twice

Евгений Бушуев yevgen.bushuyev at gmail.com
Tue Jul 19 15:26:14 UTC 2016


Hello

Could somebody please explain if it's ok when statusListener.start method
is invoked twice? I.e. can it be bug rather than feature?

As far as I understand it's getting invoked from LogerFactory.bind method:

private final static void bind() {
...
        Set<URL> staticLoggerBinderPathSet = null;
        // skip check under android, see also
http://jira.qos.ch/browse/SLF4J-328
        if (!isAndroid()) {
            staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
            reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
        }
        // the next line does the binding
        StaticLoggerBinder.getSingleton();
<---fist from here
        INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
        reportActualBinding(staticLoggerBinderPathSet);
        replayEvents();
<---then from here
...

}

The stacktraces:

Connected to the target VM, address: 'localhost:7778', transport: 'socket'

at my.app.LogListener.start(PECQuartzListener.java:41)
at ch.qos.logback.core.joran.action.StatusListenerAction.end(StatusListenerAction.java:65)
at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:155)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:142)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:103)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:149)
                       <=================================
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:390)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:340)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:361)
at my.app.AuthorisationListener.<init>(AuthorisationListener.java:34)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
at com.ibm.ws.managedobject.internal.ManagedObjectFactoryImpl.createManagedObject(ManagedObjectFactoryImpl.java:65)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.inject(WebApp.java:1250)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.injectAndPostConstruct(WebApp.java:1416)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.injectAndPostConstruct(WebApp.java:1404)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.loadListener(WebApp.java:813)
at com.ibm.ws.webcontainer.webapp.WebApp.loadLifecycleListeners(WebApp.java:2246)
at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1040)
at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6463)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:446)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:441)
at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1000)
at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:824)
at com.ibm.ws.app.manager.web.internal.WebModuleHandlerImpl.deployModule(WebModuleHandlerImpl.java:103)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployModule(DeployedAppInfoBase.java:871)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployModules(DeployedAppInfoBase.java:831)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:818)
at com.ibm.ws.app.manager.ear.internal.EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:84)
at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:141)
at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1192)
at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:805)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)

java.lang.Exception
at my.app.LogListener.start(PECQuartzListener.java:41)
at ch.qos.logback.core.joran.action.StatusListenerAction.end(StatusListenerAction.java:65)
at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:309)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:193)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:179)
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:155)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:142)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:103)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
at ch.qos.logback.classic.selector.ContextJNDISelector.getLoggerContext(ContextJNDISelector.java:108)
at org.slf4j.impl.StaticLoggerBinder.getLoggerFactory(StaticLoggerBinder.java:108)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:396)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:340)
at org.slf4j.LoggerFactory.replaySingleEvent(LoggerFactory.java:220)
at org.slf4j.LoggerFactory.replayEvents(LoggerFactory.java:195)
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:152)
                  <=================================
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:390)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:340)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:361)
at my.app.AuthorisationListener.<init>(AuthorisationListener.java:34)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
at com.ibm.ws.managedobject.internal.ManagedObjectFactoryImpl.createManagedObject(ManagedObjectFactoryImpl.java:65)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.inject(WebApp.java:1250)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.injectAndPostConstruct(WebApp.java:1416)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.injectAndPostConstruct(WebApp.java:1404)
at com.ibm.ws.webcontainer.osgi.webapp.WebApp.loadListener(WebApp.java:813)
at com.ibm.ws.webcontainer.webapp.WebApp.loadLifecycleListeners(WebApp.java:2246)
at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:1040)
at com.ibm.ws.webcontainer.webapp.WebApp.initialize(WebApp.java:6463)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:446)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:441)
at com.ibm.ws.webcontainer.osgi.WebContainer.startWebApplication(WebContainer.java:1000)
at com.ibm.ws.webcontainer.osgi.WebContainer.startModule(WebContainer.java:824)
at com.ibm.ws.app.manager.web.internal.WebModuleHandlerImpl.deployModule(WebModuleHandlerImpl.java:103)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployModule(DeployedAppInfoBase.java:871)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployModules(DeployedAppInfoBase.java:831)
at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:818)
at com.ibm.ws.app.manager.ear.internal.EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:84)
at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:141)
at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1192)
at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:805)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)


I'm trying to setup logging in an entangled ear app consisting of a bunch
of separate war modules using SiftingAppender
and JNDIBasedContextDiscriminator deployed to IBM Liberty. Can't reproduce
it in simpler configuration. So far I've just removed all modules but one
and start still invoked twice (the bp in AuthorisationListener.java:34 is
triggered only once).

Any help is highly appreciated.

logback version is 1.1.7.

Best regards, Eugene.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20160719/ca6d2de9/attachment-0001.html>


More information about the logback-user mailing list