Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix logging related errors #104

Open
bertfrees opened this issue May 24, 2016 · 4 comments
Open

Fix logging related errors #104

bertfrees opened this issue May 24, 2016 · 4 comments
Labels

Comments

@bertfrees
Copy link
Member

There are a couple of logging related errors when you launch the system. Two of them only show up in the dev-launcher, the third shows up in both the dev-launcher and regular launcher. I'm using Java 8. The dev-launcher is of course less important then the regular one, but it would still be good to understand what is happening.

  1. This is the one that I had previously "hacked around" because it was a fatal one (see 2b5235f and 2639b9b). This happened at the time when I switched to Java 8. The error doesn't seem to make the web service fail anymore, but you can still see it happen if go back to tag v1.9.9.
1:00:46,213 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.daisy.pipeline.logging.IgnoreSiftAppender]
11:00:46,213 |-ERROR in ch.qos.logback.core.joran.action.AppenderAction - Could not create an Appender of type [org.daisy.pipeline.logging.IgnoreSiftAppender]. ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.daisy.pipeline.logging.IgnoreSiftAppender
    at ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.daisy.pipeline.logging.IgnoreSiftAppender
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:74)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:49)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:35)
    at  at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:54)
    at  at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:276)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:148)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:130)
    at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:157)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:143)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:106)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:56)
    at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
    at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
    at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
    at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
    at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
    at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
    at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:269)
    at  at net.kornr.log.LogbackAdaptor.logged(LogbackAdaptor.java:41)
    at  at org.apache.felix.log.LogListenerThread.run(LogListenerThread.java:125)
Caused by: java.lang.ClassNotFoundException: org.daisy.pipeline.logging.IgnoreSiftAppender not found by ch.qos.logback.classic [1]
    at  at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1556)
    at  at org.apache.felix.framework.BundleWiringImpl.access$400(BundleWiringImpl.java:77)
    at  at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1993)
    at  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:61)
    at  ... 21 common frames omitted
11:00:46,213 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:80 - ActionException in Action for tag [appender] ch.qos.logback.core.joran.spi.ActionException: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.daisy.pipeline.logging.IgnoreSiftAppender
    at ch.qos.logback.core.joran.spi.ActionException: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.daisy.pipeline.logging.IgnoreSiftAppender
    at  at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:82)
    at  at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:276)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:148)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:130)
    at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:157)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:143)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:106)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:56)
    at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
    at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
    at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
    at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
    at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
    at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
    at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:269)
    at  at net.kornr.log.LogbackAdaptor.logged(LogbackAdaptor.java:41)
    at  at org.apache.felix.log.LogListenerThread.run(LogListenerThread.java:125)
Caused by: ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type org.daisy.pipeline.logging.IgnoreSiftAppender
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:74)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:49)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassName(OptionHelper.java:35)
    at  at ch.qos.logback.core.joran.action.AppenderAction.begin(AppenderAction.java:54)
    at  ... 18 common frames omitted
Caused by: java.lang.ClassNotFoundException: org.daisy.pipeline.logging.IgnoreSiftAppender not found by ch.qos.logback.classic [1]
    at  at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1556)
    at  at org.apache.felix.framework.BundleWiringImpl.access$400(BundleWiringImpl.java:77)
    at  at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1993)
    at  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at  at ch.qos.logback.core.util.OptionHelper.instantiateByClassNameAndParameter(OptionHelper.java:61)
    at  ... 21 common frames omitted
11:22:42,187 |-ERROR in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Could not create component [filter] of type [org.daisy.pipeline.logging.OSGIFilter] java.lang.ClassNotFoundException: org.daisy.pipeline.logging.OSGIFilter not found by ch.qos.logback.classic [1]
    at java.lang.ClassNotFoundException: org.daisy.pipeline.logging.OSGIFilter not found by ch.qos.logback.classic [1]
    at  at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1556)
    at  at org.apache.felix.framework.BundleWiringImpl.access$400(BundleWiringImpl.java:77)
    at  at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1993)
    at  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at  at ch.qos.logback.core.util.Loader.loadClass(Loader.java:124)
    at  at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.begin(NestedComplexPropertyIA.java:100)
    at  at ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:276)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:148)
    at  at ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:130)
    at  at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:157)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:143)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:106)
    at  at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:56)
    at  at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
    at  at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
    at  at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85)
    at  at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)
    at  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:128)
    at  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:107)
    at  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:295)
    at  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:269)
    at  at net.kornr.log.LogbackAdaptor.logged(LogbackAdaptor.java:41)
    at  at org.apache.felix.log.LogListenerThread.run(LogListenerThread.java:125)
  1. This is the one that can happen in both dev and regular launcher, but not consistently.
ERROR OSGI [                  org.eclipse.gemini.jpa] FrameworkEvent ERROR   @net.kornr.log.LogbackAdaptor:61#logged
org.apache.felix.log.LogException: javax.persistence.PersistenceException: Exception [EclipseLink-28018] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.EntityManagerSetupException
Exception Description: Predeployment of PersistenceUnit [pipeline-pu] failed.
Internal Exception: Exception [EclipseLink-28006] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.EntityManagerSetupException
Exception Description: ClassNotFound: [org.daisy.pipeline.persistence.logging.Slf4jSessionLogger] specified in [eclipselink.logging.logger] property.
Internal Exception: java.lang.ClassNotFoundException: org/daisy/pipeline/persistence/logging/Slf4jSessionLogger
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.predeploy(EntityManagerSetupImpl.java:1402) ~[na:na]
    at org.eclipse.persistence.internal.jpa.deployment.JPAInitializer.callPredeploy(JPAInitializer.java:98) ~[na:na]
    at org.eclipse.persistence.internal.jpa.deployment.JPAInitializer.initPersistenceUnits(JPAInitializer.java:306) ~[na:na]
    at org.eclipse.gemini.jpa.provider.GeminiOSGiInitializer.initializeFromBundle(GeminiOSGiInitializer.java:119) ~[na:na]
    at org.eclipse.gemini.jpa.provider.EclipseLinkOSGiProvider.assignPersistenceUnitsInBundle(EclipseLinkOSGiProvider.java:191) ~[na:na]
    at org.eclipse.gemini.jpa.PersistenceBundleExtender.tryAssigningPersistenceUnitsInBundle(PersistenceBundleExtender.java:172) ~[na:na]
    at org.eclipse.gemini.jpa.PersistenceBundleExtender.bundleChanged(PersistenceBundleExtender.java:276) ~[na:na]
    at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:869) ~[felix.jar:na]
    at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:790) ~[felix.jar:na]
    at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:515) ~[felix.jar:na]
    at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4434) ~[felix.jar:na]
    at org.apache.felix.framework.Felix.installBundle(Felix.java:3056) ~[felix.jar:na]
    at org.apache.felix.framework.BundleContextImpl.installBundle(BundleContextImpl.java:165) ~[felix.jar:na]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.installOrUpdateBundle(DirectoryWatcher.java:1030) ~[na:na]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.install(DirectoryWatcher.java:944) ~[na:na]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.install(DirectoryWatcher.java:857) ~[na:na]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:483) ~[na:na]
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.start(DirectoryWatcher.java:224) ~[na:na]
    at org.apache.felix.fileinstall.internal.FileInstall.updated(FileInstall.java:252) ~[na:na]
    at org.apache.felix.fileinstall.internal.FileInstall$ConfigAdminSupport$Tracker.updated(FileInstall.java:422) ~[na:na]
    at org.apache.felix.cm.impl.helper.ManagedServiceFactoryTracker.provideConfiguration(ManagedServiceFactoryTracker.java:88) ~[na:na]
    at org.apache.felix.cm.impl.ConfigurationManager$UpdateConfiguration.run(ConfigurationManager.java:1723) ~[na:na]
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:103) ~[na:na]
    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_65]
Caused by: org.apache.felix.log.LogException: org.eclipse.persistence.exceptions.EntityManagerSetupException:
Exception Description: Predeployment of PersistenceUnit [pipeline-pu] failed.
Internal Exception: Exception [EclipseLink-28006] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.EntityManagerSetupException
Exception Description: ClassNotFound: [org.daisy.pipeline.persistence.logging.Slf4jSessionLogger] specified in [eclipselink.logging.logger] property.
Internal Exception: java.lang.ClassNotFoundException: org/daisy/pipeline/persistence/logging/Slf4jSessionLogger
    at org.eclipse.persistence.exceptions.EntityManagerSetupException.predeployFailed(EntityManagerSetupException.java:221) ~[na:na]
    ... 24 common frames omitted
Caused by: org.apache.felix.log.LogException: org.eclipse.persistence.exceptions.EntityManagerSetupException:
Exception Description: ClassNotFound: [org.daisy.pipeline.persistence.logging.Slf4jSessionLogger] specified in [eclipselink.logging.logger] property.
Internal Exception: java.lang.ClassNotFoundException: org/daisy/pipeline/persistence/logging/Slf4jSessionLogger
    at org.eclipse.persistence.exceptions.EntityManagerSetupException.classNotFoundForProperty(EntityManagerSetupException.java:133) ~[na:na]
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.findClassForProperty(EntityManagerSetupImpl.java:842) ~[na:na]
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.updateLoggers(EntityManagerSetupImpl.java:723) ~[na:na]
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.predeploy(EntityManagerSetupImpl.java:1161) ~[na:na]
    ... 23 common frames omitted
Caused by: java.lang.ClassNotFoundException: org/daisy/pipeline/persistence/logging/Slf4jSessionLogger
    at java.lang.Class.forName0(Native Method) ~[na:1.8.0_65]
    at java.lang.Class.forName(Class.java:348) ~[na:1.8.0_65]
    at org.eclipse.persistence.internal.security.PrivilegedAccessHelper.getClassForName(PrivilegedAccessHelper.java:119) ~[na:na]
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.findClass(EntityManagerSetupImpl.java:832) ~[na:na]
    at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.findClassForProperty(EntityManagerSetupImpl.java:838) ~[na:na]
    ... 25 common frames omitted
@bertfrees
Copy link
Member Author

I thought I had fixed the dev-launcher issues (1) and (2) by removing the logback bundles from the "felix" directory and replacing them with *.cfg files pointing to the bundles' locations under ~/.m2. I thought that by doing this I was making sure the logback bundles would start only after logging-appender is resolved. Unfortunately it turned out none of this mattered. The fact that things worked after my change was merely a coincidence. After I changed the names of the *.cfg files things suddenly stopped working. It seems that somehow the file names help determine the order in which bundles are resolved/installed/started. The whole thing is very indeterministic. I noticed that not only changing the file names of the *.cfg files, but even moving the whole "target" directory to a different location can have an effect. On the other hand, whatever start levels I give the logback and logging-appender bundles, the result is always the same. I'm afraid I have too little understanding of OSGi to grasp what's going on when Felix boots up. I've tried a lot of different things today but haven't gotten much wiser :(

I guess this is also very much related to the other startup issues we've been having with the braille modules for some time (services randomly not being available after a (re)start). I think this is indeed related because I've never experienced these startup issues with the dev-launcher, and apart from the way the bundles are started there are no differences between the two launchers.

I haven't tried controlling the start levels of the different braille modules yet, that might help. Although that'll require some guess work too. And if I already knew which bundles are the problem, I would probably try to fix them instead. Because people say it is better to not rely on start levels. The problem is that I have no idea what kind of things make a bundle rely on a start level and how you would avoid it. Moreover, I'm not sure where in this whole story fragment and host bundles come into play.

Anyone's help on this would be highly appreciated! Need to get this sorted out because at the moment I can't package and deploy my system and be sure it starts up the way I want, which makes it pretty useless :'(

@bertfrees
Copy link
Member Author

@rdeltour Could we talk about this tomorrow at the team meeting?

@bertfrees
Copy link
Member Author

Some more information that might help:

  • The OSGiFilter exception (2) is related to Log the exceptions thrown by Declarative Services pipeline#437. When the exception happens, you will see a bunch of log messages of the form INFO OSGI [...] ...Event ... on STDOUT.
  • On recent branches of me you might see an (4th) exception with EventBusAppender. This is related to Mechanism for sending messages to execution log from Java pipeline-framework#112. When the exception happens, job messages from Java do no longer work.
  • There is an additional logging issue, but it's presence does not depend on whether there was an exception in the startup or not (at least no exception that is visible in the logs). The issue is that log messages originating from libraries that use the java.util.logging framework (e.g. Dotify) do sometimes not end up in our log (see jul-to-slf4j bridge #87). I thought I had found a pattern between the position of the line DEBUG [ o.daisy.pipeline.logging.impl.Activator] earlyStartup slf4j SLF4JBridgeHandler... and whether the JUL messages show up or not, but I'm not seeing that pattern anymore.

bertfrees added a commit that referenced this issue Jun 21, 2016
@bertfrees bertfrees added the bug label Dec 6, 2017
bertfrees added a commit that referenced this issue Dec 15, 2017
in order to solve startup issues. It doesn't make sense to use file
install for these bundles because they can not be reloaded dynamically
without breaking things.

see #104
bertfrees added a commit to daisy/pipeline that referenced this issue Feb 19, 2018
in order to solve startup issues. It doesn't make sense to use file
install for these bundles because they can not be reloaded dynamically
without breaking things.

see daisy/pipeline-assembly#104
bertfrees added a commit that referenced this issue Mar 11, 2018
in order to solve startup issues. It doesn't make sense to use file
install for these bundles because they can not be reloaded dynamically
without breaking things.

see #104
bertfrees added a commit that referenced this issue Mar 13, 2018
in order to solve startup issues. It doesn't make sense to use file
install for these bundles because they can not be reloaded dynamically
without breaking things.

see #104
bertfrees added a commit that referenced this issue Mar 28, 2018
in order to solve startup issues. It doesn't make sense to use file
install for these bundles because they can not be reloaded dynamically
without breaking things.

see #104
@bertfrees
Copy link
Member Author

This issue has been addressed in 1.11.0 but I'm not sure if all the errors are gone now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

1 participant