ClassNotFoundException when redeploying a bundle with Job

Question

When redeploying a bundle that has a quartz job, I get following exception. However, it seems that the Job works on restart. What is wrong?

2019-02-26 07:23:31,653: INFO  [ModuleManagerImpl] - Stopping existing version of the module org.jahia.modules/jobsample/1.0.0.SNAPSHOT before starting org.jahia.modules/jobsample/1.0.0.SNAPSHOT...
2019-02-26 07:23:31,654: DEBUG [Activator] - Received event STOPPING for bundle jobsample v1.0-SNAPSHOT [147]
2019-02-26 07:23:31,654: INFO  [Activator] - --- Stopping Jahia OSGi bundle jobsample v1.0-SNAPSHOT [147] --
2019-02-26 07:23:31,656: INFO  [Activator] - --- Finished stopping Jahia OSGi bundle jobsample v1.0-SNAPSHOT [147] in 2ms --
2019-02-26 07:23:31,657: INFO  [JahiaOsgiBundleXmlApplicationContext] - Unpublishing application context OSGi service for bundle jobsample (jobsample)
2019-02-26 07:23:31,658: INFO  [JahiaOsgiBundleXmlApplicationContext] - Closing JahiaOsgiBundleXmlApplicationContext(bundle=jobsample, config=classpath:org/jahia/defaults/config/spring/modules-applicationcontext-registry.xml,osgibundle:/META-INF/spring/*.xml): startup date [Tue Feb 26 07:23:31 CET 2019]; parent: Root WebApplicationContext
2019-02-26 07:23:31,658: INFO  [JobSchedulingBean] - Unscheduling job MyGroup.myJob
2019-02-26 07:23:31,679: ERROR [ModulesResourceLoaderClassLoadHelper] - Unable to lookup class org.jahia.modules.mymodule.jobs.MyJob for the job scheduler.
java.lang.ClassNotFoundException: Unable to find class 'org.jahia.modules.mymodule.jobs.MyJob' in the class loaders of modules
 at org.jahia.osgi.BundleUtils.loadModuleClass(BundleUtils.java:351)
 at org.jahia.services.scheduler.ModulesResourceLoaderClassLoadHelper.loadClass(ModulesResourceLoaderClassLoadHelper.java:91)
 at org.quartz.impl.jdbcjobstore.StdJDBCDelegate.selectJobForTrigger(StdJDBCDelegate.java:1974)
 at org.quartz.impl.jdbcjobstore.JobStoreSupport.removeTrigger(JobStoreSupport.java:1474)
 at org.quartz.impl.jdbcjobstore.JobStoreSupport$8.execute(JobStoreSupport.java:1462)
 at org.quartz.impl.jdbcjobstore.JobStoreSupport.executeInNonManagedTXLock(JobStoreSupport.java:3788)
 at org.quartz.impl.jdbcjobstore.JobStoreTX.executeInLock(JobStoreTX.java:90)
 at org.quartz.impl.jdbcjobstore.JobStoreSupport.removeTrigger(JobStoreSupport.java:1458)
 at org.quartz.core.QuartzScheduler.unscheduleJob(QuartzScheduler.java:965)
 at org.quartz.impl.StdScheduler.unscheduleJob(StdScheduler.java:290)
 at org.jahia.services.scheduler.ReadOnlyModeAwareScheduler.unscheduleJob(ReadOnlyModeAwareScheduler.java:164)
 at org.jahia.services.scheduler.JobSchedulingBean.unscheduleJob(JobSchedulingBean.java:198)
 at org.jahia.services.scheduler.JobSchedulingBean.destroy(JobSchedulingBean.java:117)
 at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:239)
 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:510)
 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:486)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:751)
 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:455)
 at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1092)
 at org.eclipse.gemini.blueprint.context.support.AbstractOsgiBundleApplicationContext.destroyBeans(AbstractOsgiBundleApplicationContext.java:194)
 at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1066)
 at org.eclipse.gemini.blueprint.context.support.AbstractOsgiBundleApplicationContext.doClose(AbstractOsgiBundleApplicationContext.java:187)
 at org.eclipse.gemini.blueprint.context.support.AbstractDelegatedExecutionApplicationContext.access$501(AbstractDelegatedExecutionApplicationContext.java:60)
 at org.eclipse.gemini.blueprint.context.support.AbstractDelegatedExecutionApplicationContext$2.run(AbstractDelegatedExecutionApplicationContext.java:194)
 at org.eclipse.gemini.blueprint.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
 at org.eclipse.gemini.blueprint.context.support.AbstractDelegatedExecutionApplicationContext.normalClose(AbstractDelegatedExecutionApplicationContext.java:190)
 at org.jahia.bundles.blueprint.extender.config.JahiaOsgiBundleXmlApplicationContext.normalClose(JahiaOsgiBundleXmlApplicationContext.java:147)
 at org.eclipse.gemini.blueprint.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.close(DependencyWaiterApplicationContextExecutor.java:382)
 at org.eclipse.gemini.blueprint.context.support.AbstractDelegatedExecutionApplicationContext.doClose(AbstractDelegatedExecutionApplicationContext.java:214)
 at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1012)
 at org.eclipse.gemini.blueprint.extender.internal.activator.LifecycleManager.closeApplicationContext(LifecycleManager.java:316)
 at org.eclipse.gemini.blueprint.extender.internal.activator.LifecycleManager.access$200(LifecycleManager.java:54)
 at org.eclipse.gemini.blueprint.extender.internal.activator.LifecycleManager$2.run(LifecycleManager.java:291)
 at org.eclipse.gemini.blueprint.extender.internal.util.concurrent.RunnableTimedExecution$MonitoredRunnable.run(RunnableTimedExecution.java:55)
 at org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:70)
 at java.util.TimerThread.mainLoop(Timer.java:555)
 at java.util.TimerThread.run(Timer.java:505)
2019-02-26 07:23:31,682: INFO  [JahiaOsgiBundleApplicationContextListener] - Application context succesfully closed for bundle jobsample (jobsample)
2019-02-26 07:23:31,682: INFO  [ModulesSourceSpringInitializer] - Unmounting source for bundle jobsample
2019-02-26 07:23:31,682: INFO  [JCRStoreProvider] - Unmounting provider of mount point /modules/jobsample/1.0-SNAPSHOT/sources
2019-02-26 07:23:31,682: INFO  [JCRSessionFactory] - Removed provider module-jobsample-1.0-SNAPSHOT at mount point /modules/jobsample/1.0-SNAPSHOT/sources using implementation org.jahia.modules.external.ExternalContentStoreProvider
2019-02-26 07:23:31,683: DEBUG [Activator] - Received event STOPPED for bundle jobsample v1.0-SNAPSHOT [147]
2019-02-26 07:23:31,683: INFO  [ModuleManagerImpl] - ...done stopping existing version of the module org.jahia.modules/jobsample/1.0.0.SNAPSHOT before starting org.jahia.modules/jobsample/1.0.0.SNAPSHOT
2019-02-26 07:23:31,683: DEBUG [Activator] - Received event STARTING for bundle jobsample v1.0-SNAPSHOT [147]
2019-02-26 07:23:31,683: DEBUG [Activator] - Received event STARTED for bundle jobsample v1.0-SNAPSHOT [147]
2019-02-26 07:23:31,684: INFO  [Activator] - --- Start Jahia OSGi bundle jobsample v1.0-SNAPSHOT [147] --
2019-02-26 07:23:31,685: INFO  [TemplatePackageRegistry] - Registered 'jobsample' [jobsample] version 1.0-SNAPSHOT
2019-02-26 07:23:31,687: DEBUG [Activator] - No HTTP resources found for bundle jobsample v1.0-SNAPSHOT [147]
2019-02-26 07:23:31,687: INFO  [Activator] - --- Finished starting Jahia OSGi bundle jobsample v1.0-SNAPSHOT [147] in 3ms --
2019-02-26 07:23:31,689: INFO  [JahiaOsgiBundleXmlApplicationContext] - Refreshing JahiaOsgiBundleXmlApplicationContext(bundle=jobsample, config=classpath:org/jahia/defaults/config/spring/modules-applicationcontext-registry.xml,osgibundle:/META-INF/spring/*.xml): startup date [Tue Feb 26 07:23:31 CET 2019]; parent: Root WebApplicationContext
2019-02-26 07:23:31,689: INFO  [JahiaOsgiBundleXmlApplicationContext] - Application Context service already unpublished
2019-02-26 07:23:31,689: INFO  [ModulesSourceSpringInitializer] - Mounting source for bundle jobsample
2019-02-26 07:23:31,695: INFO  [ModulesDataSource] - Registering CND from source file /Users/pol/Desktop/jobsample/src/main/resources/META-INF/definitions.cnd
2019-02-26 07:23:31,696: INFO  [JCRStoreService] - Previously deployed jobsample was done at : Mon Feb 25 18:25:20 CET 2019, ignoring version jobsample / 1.0-SNAPSHOT / Wed Feb 13 20:21:14 CET 2019
2019-02-26 07:23:31,697: INFO  [JCRSessionFactory] - Added provider module-jobsample-1.0-SNAPSHOT at mount point /modules/jobsample/1.0-SNAPSHOT/sources using implementation org.jahia.modules.external.ExternalContentStoreProvider
2019-02-26 07:23:31,698: INFO  [ModuleManagerImpl] - Installation completed for bundles [file [/Users/pol/jahia/www4/install/tomcat/temp/module-2846034320389324449.jar]] on target null in 597 ms. Operation result: org.jahia.services.modulemanager.OperationResult@4049a7df[bundleInfos=[org.jahia.services.modulemanager.BundleInfo@71ad9f50[groupId=org.jahia.modules,key=org.jahia.modules/jobsample/1.0.0.SNAPSHOT,symbolicName=jobsample,version=1.0.0.SNAPSHOT]],message=Operation successful]
2019-02-26 07:23:31,712: INFO  [JahiaOsgiBeanFactoryPostProcessor] - Start post-processing of the Spring bean factory for bundle jobsample (jobsample)
2019-02-26 07:23:31,713: INFO  [JahiaOsgiBeanFactoryPostProcessor] - Finished post-processing of the Spring bean factory for bundle jobsample (jobsample) in 1 ms
2019-02-26 07:23:31,718: INFO  [DependencyWaiterApplicationContextExecutor] - No outstanding OSGi service dependencies, completing initialization for JahiaOsgiBundleXmlApplicationContext(bundle=jobsample, config=classpath:org/jahia/defaults/config/spring/modules-applicationcontext-registry.xml,osgibundle:/META-INF/spring/*.xml)
2019-02-26 07:23:31,728: INFO  [JobSchedulingBean] - Deleting job MyGroup.myJob
2019-02-26 07:23:31,732: INFO  [JobSchedulingBean] - Unscheduling job MyGroup.myJob
2019-02-26 07:23:31,732: INFO  [JobSchedulingBean] - Scheduling persistent job MyGroup.myJob using CronTrigger [0 0 4 * * ?]

Answer

You can ignore this message.

In the scenario, when a module is stopping and its Spring context is closed, we unschedule the corresponding job.

The thing is that the Spring context is closed asynchronously. So, it happens after the bundle is already stopped.
We see it in the lines:

2019-02-26 07:23:31,656: INFO [Activator] - --- Finished stopping Jahia OSGi bundle jobsample v1.0-SNAPSHOT [147] in 2ms --
2019-02-26 07:23:31,657: INFO [JahiaOsgiBundleXmlApplicationContext] - Unpublishing application context OSGi service for bundle jobsample (jobsample)
2019-02-26 07:23:31,658: INFO [JahiaOsgiBundleXmlApplicationContext] - Closing JahiaOsgiBundleXmlApplicationContext(bundle=jobsample, config=classpath:org/jahia/defaults/config/spring/modules-applicationcontext-registry.xml,osgibundle:/META-INF/spring/*.xml): startup date [Tue Feb 26 07:23:31 CET 2019]; parent: Root WebApplicationContext

The ModulesResourceLoaderClassLoadHelper is looking up the job class in the bundle, but it only considers bundles in Active state. Which is no longer the case.

The class catches the exception and uses a dummy "NoOpJob" class instead, so the job is unscheduled properly. But it still logs an error with a stack trace.