Operating System: All
Platform: All

Attachment karaf.zip has been added with description: The log with the exception in it + showing that AAA transactions are timing out.

extract from logs:

2015-11-24 20:16:05,209 | INFO | l for user karaf | YangTextSchemaContextResolver | 78 - org.opendaylight.yangtools.yang-parser-impl - 0.8.0.SNAPSHOT | Failed to fully assemble schema context for [SourceIdentifier [name=yang-ext@2013-07-09], SourceIdentifier [name=iana-afn-safi@2013-07-04], SourceIdentifier [name=iana-if-type@2014-05-08], SourceIdentifier [name=ietf-inet-types@2010-09-24], SourceIdentifier [name=ietf-interfaces@2014-05-08], SourceIdentifier [name=ietf-yang-types@2010-09-24], SourceIdentifier [name=ietf-yang-types@2013-07-15], SourceIdentifier [name=ietf-restconf@2013-10-19], SourceIdentifier [name=opendaylight-l2-types@2013-08-27], SourceIdentifier [name=ted@2013-07-12], SourceIdentifier [name=ted@2013-10-21], SourceIdentifier [name=network-topology@2013-07-12], SourceIdentifier [name=network-topology@2013-10-21], SourceIdentifier [name=isis-topology@2013-07-12], SourceIdentifier [name=isis-topology@2013-10-21], SourceIdentifier [name=ospf-topology@2013-07-12], SourceIdentifier [name=ospf-topology@2013-10-21], SourceIdentifier [name=l3-unicast-igp-topology@2013-07-12], SourceIdentifier [name=l3-unicast-igp-topology@2013-10-21], SourceIdentifier [name=ietf-network-topology@2015-06-08], SourceIdentifier [name=ietf-network@2015-06-08], SourceIdentifier [name=ietf-inet-types@2013-07-15], SourceIdentifier [name=config@2013-04-05], SourceIdentifier [name=rpc-context@2013-06-17], SourceIdentifier [name=general-entity@2015-08-20], SourceIdentifier [name=opendaylight-entity-ownership-service@2015-08-10], SourceIdentifier [name=shutdown@2013-12-18], SourceIdentifier [name=shutdown-impl@2013-12-18], SourceIdentifier [name=netty@2013-11-19], SourceIdentifier [name=netty-event-executor@2013-11-12], SourceIdentifier [name=threadgroup@2013-11-07], SourceIdentifier [name=netty-timer@2013-11-19], SourceIdentifier [name=threadpool@2013-04-09], SourceIdentifier [name=threadpool-impl-fixed@2013-12-01], SourceIdentifier [name=threadpool-impl-flexible@2013-12-01], SourceIdentifier [name=threadpool-impl-scheduled@2013-12-01], SourceIdentifier [name=threadpool-impl@2013-04-05], SourceIdentifier [name=opendaylight-config-dom-datastore@2014-06-17], SourceIdentifier [name=opendaylight-md-sal-common@2013-10-28], SourceIdentifier [name=opendaylight-md-sal-dom@2013-10-28], SourceIdentifier [name=opendaylight-operational-dom-datastore@2014-06-17], SourceIdentifier [name=opendaylight-sal-binding-broker-impl@2013-10-28], SourceIdentifier [name=opendaylight-md-sal-binding@2013-10-28], SourceIdentifier [name=opendaylight-inmemory-datastore-provider@2014-06-17], SourceIdentifier [name=opendaylight-sal-dom-broker-impl@2013-10-28], SourceIdentifier [name=opendaylight-pingpong-broker@2014-11-07], SourceIdentifier [name=actor-system-provider-service@2015-10-05], SourceIdentifier [name=remote-rpc-connector@2014-07-07], SourceIdentifier [name=actor-system-provider-impl@2015-10-05], SourceIdentifier [name=cluster-admin-provider@2015-10-13], SourceIdentifier [name=cluster-admin@2015-10-13], SourceIdentifier [name=distributed-datastore-provider@2014-06-12], SourceIdentifier [name=distributed-entity-ownership-service@2015-08-10], SourceIdentifier [name=entity-owners@2015-08-04], SourceIdentifier [name=odl-concurrent-data-broker-cfg@2014-11-24], SourceIdentifier [name=netconf-node-inventory@2014-01-08], SourceIdentifier [name=opendaylight-inventory@2013-08-19], SourceIdentifier [name=opendaylight-topology-inventory@2013-10-30], SourceIdentifier [name=opendaylight-topology-view@2013-10-30], SourceIdentifier [name=opendaylight-topology@2013-10-30], SourceIdentifier [name=opendaylight-action-types@2013-11-12], SourceIdentifier [name=opendaylight-flow-types@2013-10-26], SourceIdentifier [name=opendaylight-group-types@2013-10-18], SourceIdentifier [name=opendaylight-match-types@2013-10-26], SourceIdentifier [name=opendaylight-meter-types@2013-09-18], SourceIdentifier [name=opendaylight-port-types@2013-09-25], SourceIdentifier [name=opendaylight-queue-types@2013-09-25], SourceIdentifier [name=opendaylight-table-types@2013-10-26], SourceIdentifier [name=opendaylight-flow-statistics@2013-08-19], SourceIdentifier [name=opendaylight-flow-table-statistics@2013-12-15], SourceIdentifier [name=opendaylight-group-statistics@2013-11-11], SourceIdentifier [name=opendaylight-meter-statistics@2013-11-11], SourceIdentifier [name=opendaylight-port-statistics@2013-12-14], SourceIdentifier [name=opendaylight-queue-statistics@2013-12-16], SourceIdentifier [name=opendaylight-statistics-types@2013-09-25]]
SchemaResolutionException{unsatisfiedImports={SourceIdentifier [name=opendaylight-flow-table-statistics@2013-12-15]=[ModuleImportImpl [name=flow-node-inventory, revision=2013-08-19], ModuleImportImpl [name=flow-capable-transaction, revision=2015-03-04]], SourceIdentifier [name=opendaylight-flow-statistics@2013-08-19]=[ModuleImportImpl [name=flow-capable-transaction, revision=null], ModuleImportImpl [name=flow-node-inventory, revision=2013-08-19]], SourceIdentifier [name=opendaylight-port-statistics@2013-12-14]=[ModuleImportImpl [name=flow-capable-transaction, revision=2015-03-04]], SourceIdentifier [name=opendaylight-queue-statistics@2013-12-16]=[ModuleImportImpl [name=flow-node-inventory, revision=2013-08-19], ModuleImportImpl [name=flow-capable-transaction, revision=2015-03-04]], SourceIdentifier [name=opendaylight-meter-statistics@2013-11-11]=[ModuleImportImpl [name=flow-node-inventory, revision=2013-08-19], ModuleImportImpl [name=flow-capable-transaction, revision=2015-03-04]], SourceIdentifier [name=opendaylight-group-statistics@2013-11-11]=[ModuleImportImpl [name=flow-node-inventory, revision=2013-08-19], ModuleImportImpl [name=flow-capable-transaction, revision=2015-03-04]]}}
at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$2.apply(SharedSchemaContextFactory.java:77)
at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$2.apply(SharedSchemaContextFactory.java:64)
at com.google.common.util.concurrent.Futures$ChainingListenableFuture.run(Futures.java:906)
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)
at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
at com.google.common.util.concurrent.ExecutionList.add(ExecutionList.java:101)
at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:170)
at com.google.common.util.concurrent.Futures.transform(Futures.java:567)
at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory.createSchemaContext(SharedSchemaContextFactory.java:136)
at org.opendaylight.yangtools.yang.parser.repo.YangTextSchemaContextResolver.getSchemaContext(YangTextSchemaContextResolver.java:204)
at org.opendaylight.yangtools.yang.parser.repo.URLSchemaContextResolver.getSchemaContext(URLSchemaContextResolver.java:63)
at org.opendaylight.controller.sal.dom.broker.GlobalBundleScanningSchemaServiceImpl.tryToUpdateSchemaContext(GlobalBundleScanningSchemaServiceImpl.java:251)
at org.opendaylight.controller.sal.dom.broker.GlobalBundleScanningSchemaServiceImpl$BundleScanner.addingBundle(GlobalBundleScanningSchemaServiceImpl.java:199)
at org.opendaylight.controller.sal.dom.broker.GlobalBundleScanningSchemaServiceImpl$BundleScanner.addingBundle(GlobalBundleScanningSchemaServiceImpl.java:172)
at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:467)[karaf-org.osgi.core.jar:]
at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:414)[karaf-org.osgi.core.jar:]
at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[karaf-org.osgi.core.jar:]
at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[karaf-org.osgi.core.jar:]
at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:443)[karaf-org.osgi.core.jar:]
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847)
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)

Decreased to normal, since this is known behaviour since Hydrogen:

What actually is happening OSGI framework is reporting bundles and models
in random order, even if they have clear depenency resolution hierarchy,
eg. it is common for underyling OSGI Framework to report
every model except ietf-yang-types, which is base for all them,
that means MD-SAL does several cycles till OSGI announce that model.

Unfortunatelly we can not affect the order in which OSGI is reporting bundles (and thus models), so sometimes startup takes longer.

Lithium CONTROLLER-1458 is similar to this.

> sometimes startup takes longer.

I am not sure about this bug, but CONTROLLER-1458 states "longer" is more than 10 minutes.

AAA-72 if marked as fixed. Does that fix this Bug too?

No... AAA-72 was causing lack of initialization of AAA data store (Resulting in 401 exceptions). This bug is separate.

So we are activating via a plain old activator/ServiceTracker. I think this could be solved by activating AAA via config subsystem – where the activation can wait until a specific model is available in the global SchemaContext.

E.g. in the config xml file specify the capability corresponding to the model required for proper operation and then the config pusher will know to wait.

We have applied this workaround a couple of times since Helium, if I remember correctly.

Would that work or is OSGi activation strictly required?

What was the sequence that led up to this? From the stack trace, the resolution error occurs after a bundleChanged event which tells me that this was a result of doing a manual feature:install. Is that correct?

Since the GlobalBundleScanningSchemaServiceImpl scans resolved bundles this shouldn't happen on a restart or if featuresBoot is used b/c it gets all bundles at once and all yang models should be available when GlobalBundleScanningSchemaServiceImpl is activated and tries to build the schema context he first time.

Also, even on feature:install, all new bundles have to be resolved before it can start activating them. So even if the GlobalBundleScanningSchemaServiceImpl failed initially b/c it hadn't gotten notified of a dependent yang model bundle yet, it should eventually get all the bundle change events and succeed. At least that's what I think - I may be missing something. I would suggest turning on GlobalBundleScanningSchemaServiceImpl debug to see if that's the case.

Does the clustered data store fail to initialize and is rendered useless b/c of this? Or is it just AAA that is affected? If the former then this is a bigger problem and the rest of the system is hosed so it doesn't really matter that AAA can't authenticate and not using md-sal in AAA isn't really a solution. If the latter then Robert's suggestion sounds like it should work.

(In reply to Tom Pantelis from comment #7)
> What was the sequence that led up to this? From the stack trace, the
> resolution error occurs after a bundleChanged event which tells me that this
> was a result of doing a manual feature:install. Is that correct?
>
> Since the GlobalBundleScanningSchemaServiceImpl scans resolved bundles this
> shouldn't happen on a restart or if featuresBoot is used b/c it gets all
> bundles at once and all yang models should be available when
> GlobalBundleScanningSchemaServiceImpl is activated and tries to build the
> schema context he first time.

Cannot reproduce this anymore.