ModuleNotFound exception (probably) due to concurrent execution of BundleStartTracker

[akoledzhikov]

I'm using JBoss AS 7.1.1 and have noticed and occasional problem with the osgi framework - sometimes, it won't start some bundle, claiming a ModuleNotFound exception:

@LGW800    2014-10-29T13:46:26.187+0100     org.jboss.osgi.framework.internal.HostBundleState     JB10479     MSC service thread 1-1     AE_1@DTBISVM227     INFO                         Bundle started: bcpg:1.49.0

@LGW800    2014-10-29T13:46:28.481+0100     org.jboss.osgi.framework.internal.HostBundleState     JB10479     MSC service thread 1-2     AE_1@DTBISVM227     INFO                         Bundle started: company.name.dt.base.httpapi:1.10.1

@LGW800    2014-10-29T13:46:28.482+0100     org.jboss.osgi.framework.internal.HostBundleState     JB10479     MSC service thread 1-2     AE_1@DTBISVM227     INFO                         Bundle started: company.name.osgi.slide.webdavlib:2.0.0.CMP2

@LGW800    2014-10-29T13:46:29.153+0100     org.jboss.as.server.moduleservice     JB10479     MSC service thread 1-2     AE_1@DTBISVM227     DEBUG                         Could not load module 'deployment.company.name.osgi.org.apache.ant:1.9.0.CMP1' as corresponding module spec service 'deployment.company.name.osgi.org.apache.ant:1.9.0.CMP1' was not found

@LGW800    2014-10-29T13:46:29.155+0100     org.jboss.as.server.moduleservice     JB10479     MSC service thread 1-2     AE_1@DTBISVM227     DEBUG                         Could not load module 'deployment.company.name.common.landscape-api:1.4.0' as corresponding module spec service 'deployment.company.name.common.landscape-api:1.4.0' was not found

@LGW800    2014-10-29T13:46:29.155+0100     org.jboss.msc.service     JB10479     MSC service thread 1-2     AE_1@DTBISVM227     ERROR                         MSC00002: Invocation of listener "org.jboss.as.osgi.deployment.BundleStartTracker$1@8c6092b" failed: java.lang.IllegalStateException: Cannot load module: deployment.company.name.bis.base.bismt-client:1.4.0

    at org.jboss.osgi.framework.internal.ResolverPlugin.loadModules(ResolverPlugin.java:261)

    at org.jboss.osgi.framework.internal.ResolverPlugin.applyResolverResults(ResolverPlugin.java:229)

    at org.jboss.osgi.framework.internal.ResolverPlugin.resolve(ResolverPlugin.java:161)

    at org.jboss.osgi.framework.internal.AbstractBundleState.ensureResolved(AbstractBundleState.java:551)

    at org.jboss.osgi.framework.internal.HostBundleState.startInternal(HostBundleState.java:211)

    at org.jboss.osgi.framework.internal.AbstractBundleState.start(AbstractBundleState.java:494)

    at org.jboss.as.osgi.deployment.BundleStartTracker$1.processService(BundleStartTracker.java:144)

    at org.jboss.as.osgi.deployment.BundleStartTracker$1.transition(BundleStartTracker.java:119)

    at org.jboss.msc.service.ServiceControllerImpl.invokeListener(ServiceControllerImpl.java:1416)

    at org.jboss.msc.service.ServiceControllerImpl.access$2700(ServiceControllerImpl.java:49)

    at org.jboss.msc.service.ServiceControllerImpl$ListenerTask.run(ServiceControllerImpl.java:1954)

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

    at java.lang.Thread.run(Thread.java:745)

Caused by: org.jboss.modules.ModuleNotFoundException: deployment.company.name.common.landscape-api:1.4.0

    at org.jboss.modules.Module.addPaths(Module.java:864)

    at org.jboss.modules.Module.link(Module.java:1206)

    at org.jboss.modules.Module.relinkIfNecessary(Module.java:1235)

    at org.jboss.modules.ModuleLoader.loadModule(ModuleLoader.java:204)

    at org.jboss.osgi.framework.internal.ModuleManagerPlugin.loadModule(ModuleManagerPlugin.java:556)

at org.jboss.osgi.framework.internal.ResolverPlugin.loadModules(ResolverPlugin.java:259)

    ... 13 more

I've noticed that, in this case, there are 2 threads that are starting the bundles - MSC 1 and 2, respectively. In all cases, in which the server started successfully, only 1 thread was starting the bundles (at least according to the log files).

[wdfink]

7.1.1 is quite old. Is that reproducable with a newer version? You should use WildFly 8 or even 9

[akoledzhikov]

Well, it is hardly reproducible even on 7.1.1 - happens maybe 1 time out of 20 starts, on heavily-loaded system, with around 350 bundles pre-deployed. I'll try to reproduce it on some newer version and report an issue if it happens again.

Just out of curiosity - are there any significant changes between 7.1.1 and newer version in regard how bundles are started (or, more direct question is the same BundleStartTracker service used, is it registered from the same place and triggered in the same way)?

[akoledzhikov]

Think I've found it - it was a case of bad synchronization in the BundleStartTracker class - wildfly/BundleStartTracker.java at 7.1.1.Final · wildfly/wildfly · GitHub

Synchronizing on (this) here cannot prevent multiple threads from entering the if clause, since "this" refers to the anonymous ServiceListener, not to the BundleStartTracker itself. No idea if this will be of any use to you in the newer versions, though, probably the whole mechanism is very different now.