[CONTROLLER-1853] Multiple bundles fails to start due to unresolved dependencies Created: 20/Jul/18  Updated: 20/Jul/18  Resolved: 20/Jul/18

Status: Resolved
Project: controller
Component/s: None
Affects Version/s: Oxygen
Fix Version/s: None

Type: Bug Priority: High
Reporter: Victor Pickard Assignee: Tom Pantelis
Resolution: Duplicate Votes: 0
Labels: csit:3node
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Relates
relates to NETVIRT-1315 Troubleshooting Controller CSIT In Progress

 Description   

Multiple bundles failed to start in the Controller clustering CSIT job. Note, this ODL image had successfully started at least 3 times during earlier tests/startup in this job.

 

Here are the archived job logs:

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/247/controller-csit-3node-clustering-vpickard-all-oxygen/5/ 

 

ODL_1 is the controller with the issue, so those logs are here:

https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/builder-copy-sandbox-logs/247/controller-csit-3node-clustering-vpickard-all-oxygen/5/odl1_karaf.log.gz 

 

This is the timestamp in the log file where ODL is started and fails to resolve bundle dependencies.

Jul 16, 2018 5:55:23 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Trying to lock /tmp/karaf-0.8.3-SNAPSHOT/lock
Jul 16, 2018 5:55:23 PM org.apache.karaf.main.lock.SimpleFileLock lock
INFO: Lock acquired
Jul 16, 2018 5:55:23 PM org.apache.karaf.main.Main$KarafLockCallback lockAquired
INFO: Lock acquired. Setting startlevel to 100

 

There are many exceptions as a result of the bundles failing to start. I started to list them here, but there really are too many. Here are just a couple:

2018-07-16T18:00:36,974 | ERROR | Blueprint Extender: 2 | BlueprintContainerImpl | 86 - org.apache.aries.blueprint.core - 1.8.3 | Unable to start blueprint container for bundle org.opendaylight.aaa.cert/0.7.3.SNAPSHOT due to unresolved dependencies [(objectClass=org.opendaylight.aaa.encrypt.AAAEncryptionService), (objectClass=org.opendaylight.controller.sal.binding.api.RpcProviderRegistry), (&(|(type=default)(!(type=*)))(objectClass=org.opendaylight.mdsal.binding.dom.codec.api.BindingNormalizedNodeSerializer)), (objectClass=org.opendaylight.controller.md.sal.binding.api.DataBroker)]
java.util.concurrent.TimeoutException: null
at org.apache.aries.blueprint.container.BlueprintContainerImpl$1.run(BlueprintContainerImpl.java:370) [86:org.apache.aries.blueprint.core:1.8.3]
at org.apache.aries.blueprint.utils.threading.impl.DiscardableRunnable.run(DiscardableRunnable.java:48) [86:org.apache.aries.blueprint.core:1.8.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]

 

 

2018-07-16T17:59:29,754 | WARN | ForkJoinPool.commonPool-worker-1 | AbstractShardBackendResolver | 291 - org.opendaylight.controller.sal-distributed-datastore - 1.7.3.SNAPSHOT | Failed to resolve shard
java.util.concurrent.TimeoutException: Shard has no current leader

 

2018-07-16T17:59:27,262 | WARN | DeadlockMonitor{TransactionIdentifier{name='ConfigTransaction-26-28'}} | DeadlockMonitor | 262 - org.opendaylight.controller.config-manager - 0.8.3.SNAPSHOT | ModuleIdentifier{factoryName='runtime-generated-mapping', instanceName='runtime-mapping-singleton'} did not finish after 194984 ms

 

 

 

 

 



 Comments   
Comment by Victor Pickard [ 20/Jul/18 ]

I'm not sure what this means just yet, but it doesn't look good. Is this somehow related to getting the bundles loaded?

2018-07-16T18:01:07,285 | WARN | DeadlockMonitor{TransactionIdentifier{name='ConfigTransaction-26-28'}} | DeadlockMonitor | 262 - org.opendaylight.controller.config-manager - 0.8.3.SNAPSHOT | ModuleIdentifier{factoryName='runtime-generated-mapping', instanceName='runtime-mapping-singleton'} did not finish after 295006 ms

Comment by Tom Pantelis [ 20/Jul/18 ]

"org.opendaylight.controller.config-manager" - this does not look like Fluorine - I assume it's Oxygen. vpickard Can you please set the Affect Version?

Comment by Tom Pantelis [ 20/Jul/18 ]

This was the first seed node and timed out after 12s and joined itself :

2018-07-16T17:56:19,505 | INFO  | opendaylight-cluster-data-akka.actor.default-dispatcher-2 | Cluster(akka://opendaylight-cluster-data) | 51 - com.typesafe.akka.slf4j - 2.5.11 | Cluster Node [akka.tcp://opendaylight-cluster-data@10.30.170.222:2550] - Node [akka.tcp://opendaylight-cluster-data@10.30.170.222:2550] is JOINING, roles [member-1, dc-default]
2018-07-16T17:56:19,520 | INFO  | opendaylight-cluster-data-akka.actor.default-dispatcher-2 | Cluster(akka://opendaylight-cluster-data) | 51 - com.typesafe.akka.slf4j - 2.5.11 | Cluster Node [akka.tcp://opendaylight-cluster-data@10.30.170.222:2550] - Leader is moving node [akka.tcp://opendaylight-cluster-data@10.30.170.222:2550] to [Up]

So same as CONTROLLER-1849.

Generated at Wed Feb 07 19:56:37 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.