Details
-
Bug
-
Status: Resolved
-
Minor
-
Resolution: Cannot Reproduce
-
4.3.1
-
None
-
None
-
This happens regularly in OpenDaylight verification jobs, which are running Karaf as part of testing feature files via Pax Exam. Some jobs contain upwards of 50 of such Karaf launches.
The failure is not consistently reproducible, but it occurs now and then.
When this error occurs, the test fails, with Pax Exam reporting:
[INFO] Running org.opendaylight.odlparent.featuretest.SingleFeatureTest [ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 182.139 s <<< FAILURE! - in org.opendaylight.odlparent.featuretest.SingleFeatureTest [ERROR] installFeatureCatchAndLog(org.opendaylight.odlparent.featuretest.SingleFeatureTest)[repoUrl: file:/w/workspace/mdsal-maven-verify-master-mvn35-openjdk11/features/odl-mdsal-model-rfc8519/target/feature/feature.xml, Feature: odl-mdsal-model-rfc8519 8.0.0.SNAPSHOT].installFeatureCatchAndLog Time elapsed: 181.223 s <<< ERROR! java.rmi.NotBoundException: aafef1c7-c415-4efc-a6a0-e929277db48d at java.rmi/sun.rmi.registry.RegistryImpl.lookup(RegistryImpl.java:234) at java.rmi/sun.rmi.registry.RegistryImpl_Skel.dispatch(RegistryImpl_Skel.java:133) at java.rmi/sun.rmi.server.UnicastServerRef.oldDispatch(UnicastServerRef.java:468) at java.rmi/sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:298) at java.rmi/sun.rmi.transport.Transport$1.run(Transport.java:200) at java.rmi/sun.rmi.transport.Transport$1.run(Transport.java:197) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.rmi/sun.rmi.transport.Transport.serviceCall(Transport.java:196) at java.rmi/sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:562) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:796) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:677) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:676) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) at java.rmi/sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:303) at java.rmi/sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:279) at java.rmi/sun.rmi.server.UnicastRef.invoke(UnicastRef.java:380) at java.rmi/sun.rmi.registry.RegistryImpl_Stub.lookup(RegistryImpl_Stub.java:123) at org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl.getRemoteBundleContext(RemoteBundleContextClientImpl.java:248) at org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl.waitForState(RemoteBundleContextClientImpl.java:218) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.waitForState(KarafTestContainer.java:721) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.startKaraf(KarafTestContainer.java:304) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.start(KarafTestContainer.java:191) at org.ops4j.pax.exam.spi.reactors.AllConfinedStagedReactor.invoke(AllConfinedStagedReactor.java:79) at org.ops4j.pax.exam.junit.impl.ProbeRunner$2.evaluate(ProbeRunner.java:267) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
This happens regularly in OpenDaylight verification jobs, which are running Karaf as part of testing feature files via Pax Exam. Some jobs contain upwards of 50 of such Karaf launches. The failure is not consistently reproducible, but it occurs now and then. When this error occurs, the test fails, with Pax Exam reporting: [INFO] Running org.opendaylight.odlparent.featuretest.SingleFeatureTest [ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 182.139 s <<< FAILURE! - in org.opendaylight.odlparent.featuretest.SingleFeatureTest [ERROR] installFeatureCatchAndLog(org.opendaylight.odlparent.featuretest.SingleFeatureTest)[repoUrl: file:/w/workspace/mdsal-maven-verify-master-mvn35-openjdk11/features/odl-mdsal-model-rfc8519/target/feature/feature.xml, Feature: odl-mdsal-model-rfc8519 8.0.0.SNAPSHOT].installFeatureCatchAndLog Time elapsed: 181.223 s <<< ERROR! java.rmi.NotBoundException: aafef1c7-c415-4efc-a6a0-e929277db48d at java.rmi/sun.rmi.registry.RegistryImpl.lookup(RegistryImpl.java:234) at java.rmi/sun.rmi.registry.RegistryImpl_Skel.dispatch(RegistryImpl_Skel.java:133) at java.rmi/sun.rmi.server.UnicastServerRef.oldDispatch(UnicastServerRef.java:468) at java.rmi/sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:298) at java.rmi/sun.rmi.transport.Transport$1.run(Transport.java:200) at java.rmi/sun.rmi.transport.Transport$1.run(Transport.java:197) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.rmi/sun.rmi.transport.Transport.serviceCall(Transport.java:196) at java.rmi/sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:562) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:796) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:677) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.rmi/sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:676) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) at java.rmi/sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:303) at java.rmi/sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:279) at java.rmi/sun.rmi.server.UnicastRef.invoke(UnicastRef.java:380) at java.rmi/sun.rmi.registry.RegistryImpl_Stub.lookup(RegistryImpl_Stub.java:123) at org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl.getRemoteBundleContext(RemoteBundleContextClientImpl.java:248) at org.ops4j.pax.exam.rbc.client.intern.RemoteBundleContextClientImpl.waitForState(RemoteBundleContextClientImpl.java:218) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.waitForState(KarafTestContainer.java:721) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.startKaraf(KarafTestContainer.java:304) at org.ops4j.pax.exam.karaf.container.internal.KarafTestContainer.start(KarafTestContainer.java:191) at org.ops4j.pax.exam.spi.reactors.AllConfinedStagedReactor.invoke(AllConfinedStagedReactor.java:79) at org.ops4j.pax.exam.junit.impl.ProbeRunner$2.evaluate(ProbeRunner.java:267) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
Description
We seem to observe the following failure (similar to KARAF-5640), with uninteresting threads filtered out:
2021-05-20T15:46:08,884 | ERROR | Start Level: Equinox Container: 351dc4de-7b03-4540-9b09-9c603b419792 | BootFeaturesInstaller | 16 - org.apache.karaf.features.core - 4.3.1 | Error installing boot features org.osgi.framework.BundleException: Unable to acquire the state change lock for the module: osgi.identity; osgi.identity="org.apache.karaf.features.core"; type="osgi.bundle"; version:Version="4.3.1" [id=16] STOPPED [STARTED] at org.eclipse.osgi.container.Module.lockStateChange(Module.java:350) ~[?:?] at org.eclipse.osgi.container.Module.stop(Module.java:513) ~[?:?] at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:467) ~[?:?] at org.apache.karaf.features.internal.service.BundleInstallSupportImpl.stopBundle(BundleInstallSupportImpl.java:171) ~[?:?] at org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1165) ~[?:?] at org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:1000) ~[?:?] at org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1069) ~[?:?] at org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?] at java.lang.Thread.run(Thread.java:834) ~[?:?] Caused by: java.util.concurrent.TimeoutException: Timeout after waiting 30 seconds to acquire the lock. at org.eclipse.osgi.container.Module.lockStateChange(Module.java:347) ~[?:?] ... 11 more Caused by: org.eclipse.osgi.framework.util.ThreadInfoReport: Thread dump
ThreadId: 19 ThreadName: Start Level: Equinox Container: 351dc4de-7b03-4540-9b09-9c603b419792 ThreadState: WAITING Blocked On: java.util.concurrent.FutureTask@6f139765 LockOwnerId: -1 LockOwnerName: null Synchronizers Locked: java.util.concurrent.locks.ReentrantLock$NonfairSync@151d882b Monitors Locked: java.lang.Object@3d3be3e4 Stack Trace: java.base@11.0.10/jdk.internal.misc.Unsafe.park(Native Method) java.base@11.0.10/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) java.base@11.0.10/java.util.concurrent.FutureTask.awaitDone(FutureTask.java:447) java.base@11.0.10/java.util.concurrent.FutureTask.get(FutureTask.java:190) org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvisionInThread(FeaturesServiceImpl.java:1008) org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvisionInThread(FeaturesServiceImpl.java:978) org.apache.karaf.features.internal.service.FeaturesServiceImpl.installFeatures(FeaturesServiceImpl.java:826) org.apache.karaf.features.internal.service.FeaturesServiceImpl.installFeatures(FeaturesServiceImpl.java:746) org.apache.karaf.features.internal.service.BootFeaturesInstaller.installBootFeatures(BootFeaturesInstaller.java:97) org.apache.karaf.features.internal.service.BootFeaturesInstaller.start(BootFeaturesInstaller.java:87) org.apache.karaf.features.internal.osgi.Activator.doStart(Activator.java:214) org.apache.karaf.util.tracker.BaseActivator.start(BaseActivator.java:92) org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:814) org.eclipse.osgi.internal.framework.BundleContextImpl$2.run(BundleContextImpl.java:1) java.base@11.0.10/java.security.AccessController.doPrivileged(Native Method) org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:806) org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:763) org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1012) org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:366) org.eclipse.osgi.container.Module.doStart(Module.java:605) org.eclipse.osgi.container.Module.start(Module.java:468) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1845) org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1838) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1743) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1665) org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234) org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)
ThreadId: 32 ThreadName: features-2-thread-1 ThreadState: RUNNABLE Blocked On: org.eclipse.osgi.internal.container.EquinoxReentrantLock@13da572a[Locked by thread Start Level: Equinox Container: 351dc4de-7b03-4540-9b09-9c603b419792] Synchronizers Locked: java.util.concurrent.ThreadPoolExecutor$Worker@3fcc74ef Monitors Locked: none Stack Trace: java.management@11.0.10/sun.management.ThreadImpl.dumpThreads0(Native Method) java.management@11.0.10/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:521) java.management@11.0.10/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:509) org.eclipse.osgi.framework.util.ThreadInfoReport.getThreadDump(ThreadInfoReport.java:30) org.eclipse.osgi.framework.util.ThreadInfoReport.<init>(ThreadInfoReport.java:23) org.eclipse.osgi.container.Module.lockStateChange(Module.java:347) org.eclipse.osgi.container.Module.stop(Module.java:513) org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:467) org.apache.karaf.features.internal.service.BundleInstallSupportImpl.stopBundle(BundleInstallSupportImpl.java:171) org.apache.karaf.features.internal.service.FeaturesServiceImpl.stopBundle(FeaturesServiceImpl.java:1165) org.apache.karaf.features.internal.service.Deployer.deploy(Deployer.java:1000) org.apache.karaf.features.internal.service.FeaturesServiceImpl.doProvision(FeaturesServiceImpl.java:1069) org.apache.karaf.features.internal.service.FeaturesServiceImpl.lambda$doProvisionInThread$13(FeaturesServiceImpl.java:1004) org.apache.karaf.features.internal.service.FeaturesServiceImpl$$Lambda$228/0x00000001004c2c40.call(Unknown Source) java.base@11.0.10/java.util.concurrent.FutureTask.run(FutureTask.java:264) java.base@11.0.10/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) java.base@11.0.10/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) java.base@11.0.10/java.lang.Thread.run(Thread.java:834)