[MDSAL-235] [INFO] Failed to fully assemble schema context for [...] Created: 08/Mar/17  Updated: 28/Feb/20  Resolved: 28/Feb/20

Status: Resolved
Project: mdsal
Component/s: DOM runtime
Affects Version/s: None
Fix Version/s: 6.0.0

Type: Improvement
Reporter: Michael Vorburger Assignee: Robert Varga
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

Issue Links:
Blocks
blocks YANGTOOLS-797 Yangtools log when failing to assembl... Confirmed
is blocked by MDSAL-248 Split out OsgiBundleScanningSchemaSer... Resolved
is blocked by ODLPARENT-86 Milestore: upgrade karaf to 4.1.2 or ... Verified
Relates
relates to MDSAL-392 Clean up BindingRuntimeContext instan... Resolved

 Description   

when running SingleFeatureTest (SFT) on a Karaf 4 feature, e.g. by "mvn -o -Dsft.diag.skip=true clean install" in genius/features/features4-genius from https://git.opendaylight.org/gerrit/#/c/51966/,

but I think completely unrelated to that change, and this happens even on Karaf 3 not just 4 and also in production instances, there are typically a lot of "scary looking" (because they have a stack trace..) INFO messages like the one below in the log.

I'm not aware of any actual issues - just sayin' that this looks quite confusing, e.g. when you scan logs for other errors.

YANGTOOLS-298 looks like it may be vaguely related.. should the level of this particular log perhaps be reduced from INFO to DEBUG? Or should it at least not log it's stack trace?

2017-03-08 00:14:14,824 | INFO | Framework stop | YangTextSchemaContextResolver | 244 - org.opendaylight.yangtools.yang-parser-impl - 1.1.0.SNAPSHOT | Failed to fully assemble schema context for [RevisionSourceIdentifier [name=config@2013-04-05], RevisionSourceIdentifier [n
 ame=rpc-context@2013-06-17], RevisionSourceIdentifier [name=netconf-node-inventory@2014-01-08], RevisionSourceIdentifier [name=opendaylight-inventory@2013-08-19], RevisionSourceIdentifier [name=opendaylight-topology-inventory@2013-10-30], RevisionSourceIdentifier [name=opendaylig
 ht-topology-view@2013-10-30], RevisionSourceIdentifier [name=opendaylight-topology@2013-10-30], RevisionSourceIdentifier [name=netty@2013-11-19], RevisionSourceIdentifier [name=netty-event-executor@2013-11-12], RevisionSourceIdentifier [name=threadgroup@2013-11-07], RevisionSourc
 eIdentifier [name=netty-timer@2013-11-19], RevisionSourceIdentifier [name=opendaylight-sal-binding-broker-impl@2013-10-28], RevisionSourceIdentifier [name=opendaylight-md-sal-binding-v1-codec@2016-07-14], RevisionSourceIdentifier [name=opendaylight-md-sal-binding@2013-10-28], Rev
 isionSourceIdentifier [name=cluster-admin-provider@2015-10-13], RevisionSourceIdentifier [name=actor-system-provider-service@2015-10-05], RevisionSourceIdentifier [name=general-entity@2015-08-20], RevisionSourceIdentifier [name=opendaylight-entity-ownership-service@2015-08-10], R
 evisionSourceIdentifier [name=actor-system-provider-impl@2015-10-05], RevisionSourceIdentifier [name=distributed-datastore-provider@2014-06-12], RevisionSourceIdentifier [name=entity-owners@2015-08-04], RevisionSourceIdentifier [name=odl-concurrent-data-broker-cfg@2014-11-24], Re
 visionSourceIdentifier [name=opendaylight-sal-dom-broker-impl@2013-10-28], RevisionSourceIdentifier [name=opendaylight-pingpong-broker@2014-11-07], RevisionSourceIdentifier [name=cluster-singleton-service-impl@2016-07-18], RevisionSourceIdentifier [name=cluster-singleton-service-
 spi@2016-07-18], RevisionSourceIdentifier [name=opendaylight-config-dom-datastore@2014-06-17], RevisionSourceIdentifier [name=opendaylight-legacy-entity-ownership-service-provider@2016-02-26], RevisionSourceIdentifier [name=opendaylight-md-sal-common@2013-10-28], RevisionSourceId
 entifier [name=opendaylight-md-sal-dom@2013-10-28], RevisionSourceIdentifier [name=opendaylight-operational-dom-datastore@2014-06-17], RevisionSourceIdentifier [name=opendaylight-inmemory-datastore-provider@2014-06-17], RevisionSourceIdentifier [name=shutdown@2013-12-18], Revisio
 nSourceIdentifier [name=shutdown-impl@2013-12-18], RevisionSourceIdentifier [name=threadpool@2013-04-09], RevisionSourceIdentifier [name=threadpool-impl-fixed@2013-12-01], RevisionSourceIdentifier [name=threadpool-impl-flexible@2013-12-01], RevisionSourceIdentifier [name=threadpo
 ol-impl-scheduled@2013-12-01], RevisionSourceIdentifier [name=threadpool-impl@2013-04-05], RevisionSourceIdentifier [name=odl-general-entity@2015-09-30], RevisionSourceIdentifier [name=iana-afn-safi@2013-07-04], RevisionSourceIdentifier [name=iana-if-type@2014-05-08], RevisionSou
 rceIdentifier [name=ietf-access-control-list@2016-02-18], RevisionSourceIdentifier [name=ietf-inet-types@2010-09-24], RevisionSourceIdentifier [name=ietf-inet-types@2013-07-15], RevisionSourceIdentifier [name=ietf-interfaces@2014-05-08], RevisionSourceIdentifier [name=ietf-networ
 k-topology@2015-06-08], RevisionSourceIdentifier [name=ietf-network@2015-06-08], RevisionSourceIdentifier [name=ietf-packet-fields@2016-02-18], RevisionSourceIdentifier [name=ietf-restconf@2013-10-19], RevisionSourceIdentifier [name=ted@2013-07-12], RevisionSourceIdentifier [name
 =ted@2013-10-21], RevisionSourceIdentifier [name=network-topology@2013-07-12], RevisionSourceIdentifier [name=network-topology@2013-10-21], RevisionSourceIdentifier [name=isis-topology@2013-07-12], RevisionSourceIdentifier [name=isis-topology@2013-10-21], RevisionSourceIdentifier
 [name=ospf-topology@2013-07-12], RevisionSourceIdentifier [name=ospf-topology@2013-10-21], RevisionSourceIdentifier [name=ietf-yang-types@2010-09-24], RevisionSourceIdentifier [name=ietf-yang-types@2013-07-15], RevisionSourceIdentifier [name=opendaylight-l2-types@2013-08-27], Re
 visionSourceIdentifier [name=yang-ext@2013-07-09], RevisionSourceIdentifier [name=openflow-action@2015-02-03], RevisionSourceIdentifier [name=openflow-approved-extensions@2016-08-02], RevisionSourceIdentifier [name=openflow-augments@2015-02-25], RevisionSourceIdentifier [name=ope
 nflow-configuration@2014-06-30], RevisionSourceIdentifier [name=openflow-extensible-match@2015-02-25], RevisionSourceIdentifier [name=openflow-instruction@2013-07-31], RevisionSourceIdentifier [name=openflow-protocol@2013-07-31], RevisionSourceIdentifier [name=openflow-types@2013
 -07-31], RevisionSourceIdentifier [name=system-notifications@2013-09-27], RevisionSourceIdentifier [name=openflow-switch-connection-provider-impl@2014-03-28], RevisionSourceIdentifier [name=openflow-switch-connection-config@2016-05-06], RevisionSourceIdentifier [name=openflow-swi
 tch-connection-provider@2014-03-28], RevisionSourceIdentifier [name=openflow-provider-impl@2014-03-26], RevisionSourceIdentifier [name=openflow-provider@2014-03-26], RevisionSourceIdentifier [name=openflow-provider-config@2016-05-10], RevisionSourceIdentifier [name=openflow-provi
 der@2015-03-31], RevisionSourceIdentifier [name=statistics-manager-control@2015-08-12], RevisionSourceIdentifier [name=forwarding-rules-manager-config@2016-05-11], RevisionSourceIdentifier [name=lldp-speaker-config@2016-05-12], RevisionSourceIdentifier [name=lldp-speaker@2014-10-
 23], RevisionSourceIdentifier [name=topology-lldp-discovery-config@2016-05-11], RevisionSourceIdentifier [name=openflowplugin-experimenter-types@2015-10-20], RevisionSourceIdentifier [name=openflowplugin-extension-general@2014-07-14], RevisionSourceIdentifier [name=openflowplugin
 -extension-registry@2015-04-25], RevisionSourceIdentifier [name=sal-experimenter-message@2015-10-20], RevisionSourceIdentifier [name=sal-experimenter-mp-message@2015-10-20], RevisionSourceIdentifier [name=openflow-plugin-provider-impl@2015-03-27], RevisionSourceIdentifier [name=o
 pendaylight-action-types@2013-11-12], RevisionSourceIdentifier [name=opendaylight-arbitrary-bitmask-fields@2016-01-30], RevisionSourceIdentifier [name=opendaylight-flow-types@2013-10-26], RevisionSourceIdentifier [name=opendaylight-group-types@2013-10-18], RevisionSourceIdentifie
 r [name=opendaylight-ipv6-arbitrary-bitmask-fields@2016-02-24], RevisionSourceIdentifier [name=opendaylight-match-types@2013-10-26], RevisionSourceIdentifier [name=opendaylight-meter-types@2013-09-18], RevisionSourceIdentifier [name=opendaylight-multipart-types@2017-01-12], Revis
 ionSourceIdentifier [name=opendaylight-port-types@2013-09-25], RevisionSourceIdentifier [name=opendaylight-queue-types@2013-09-25], RevisionSourceIdentifier [name=opendaylight-table-types@2013-10-26], RevisionSourceIdentifier [name=barrier-common@2016-03-15], RevisionSourceIdenti
 fier [name=batch-common@2016-03-22], RevisionSourceIdentifier [name=flow-capable-transaction@2015-03-04], RevisionSourceIdentifier [name=flow-errors@2013-11-16], RevisionSourceIdentifier [name=flow-node-inventory@2013-08-19], RevisionSourceIdentifier [name=flow-topology-discovery
 @2013-08-19], RevisionSourceIdentifier [name=node-config@2014-10-15], RevisionSourceIdentifier [name=node-error@2014-04-10], RevisionSourceIdentifier [name=packet-processing@2013-07-09], RevisionSourceIdentifier [name=sal-echo@2015-03-05], RevisionSourceIdentifier [name=sal-flat-
 batch@2016-03-21], RevisionSourceIdentifier [name=sal-flow@2013-08-19], RevisionSourceIdentifier [name=sal-flows-batch@2016-03-14], RevisionSourceIdentifier [name=sal-group@2013-09-18], RevisionSourceIdentifier [name=sal-groups-batch@2016-03-15], RevisionSourceIdentifier [name=sa
 l-meter@2013-09-18], RevisionSourceIdentifier [name=sal-meters-batch@2016-03-16], RevisionSourceIdentifier [name=sal-port@2013-11-07], RevisionSourceIdentifier [name=sal-queue@2015-03-05], RevisionSourceIdentifier [name=sal-role@2015-07-27], RevisionSourceIdentifier [name=sal-tab
 le@2013-10-26], RevisionSourceIdentifier [name=opendaylight-direct-statistics@2016-05-11], RevisionSourceIdentifier [name=opendaylight-flow-statistics@2013-08-19], RevisionSourceIdentifier [name=opendaylight-flow-table-statistics@2013-12-15], RevisionSourceIdentifier [name=openda
 ylight-group-statistics@2013-11-11], RevisionSourceIdentifier [name=opendaylight-meter-statistics@2013-11-11], RevisionSourceIdentifier [name=opendaylight-port-statistics@2013-12-14], RevisionSourceIdentifier [name=opendaylight-queue-statistics@2013-12-16], RevisionSourceIdentifi
 er [name=opendaylight-statistics-types@2013-09-25]]
 SchemaResolutionException{unsatisfiedImports={RevisionSourceIdentifier [name=isis-topology@2013-10-21]=[ModuleImportImpl [name=l3-unicast-igp-topology, revision=2013-10-21, semanticVersion=0.0.0]], RevisionSourceIdentifier [name=isis-topology@2013-07-12]=[ModuleImportImpl [name=l
 3-unicast-igp-topology, revision=2013-07-12, semanticVersion=0.0.0]], RevisionSourceIdentifier [name=ospf-topology@2013-10-21]=[ModuleImportImpl [name=l3-unicast-igp-topology, revision=2013-10-21, semanticVersion=0.0.0]], RevisionSourceIdentifier [name=ospf-topology@2013-07-12]=[
 ModuleImportImpl [name=l3-unicast-igp-topology, revision=2013-07-12, semanticVersion=0.0.0]]}}
 at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$AssembleSources.apply(SharedSchemaContextFactory.java:203)
 at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$AssembleSources.apply(SharedSchemaContextFactory.java:170)
 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:104)
 at org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory.createSchemaContext(SharedSchemaContextFactory.java:72)
 at org.opendaylight.yangtools.yang.model.repo.api.SchemaContextFactory.createSchemaContext(SchemaContextFactory.java:54)
 at org.opendaylight.yangtools.yang.parser.repo.YangTextSchemaContextResolver.getSchemaContext(YangTextSchemaContextResolver.java:220)
 at org.opendaylight.yangtools.yang.parser.repo.YangTextSchemaContextResolver.getSchemaContext(YangTextSchemaContextResolver.java:186)
 at org.opendaylight.mdsal.dom.broker.osgi.OsgiBundleScanningSchemaService.tryToUpdateSchemaContext(OsgiBundleScanningSchemaService.java:247)
 at org.opendaylight.mdsal.dom.broker.osgi.OsgiBundleScanningSchemaService$BundleScanner.removedBundle(OsgiBundleScanningSchemaService.java:227)
 at org.opendaylight.mdsal.dom.broker.osgi.OsgiBundleScanningSchemaService$BundleScanner.removedBundle(OsgiBundleScanningSchemaService.java:165)
 at org.osgi.util.tracker.BundleTracker$Tracked.customizerRemoved(BundleTracker.java:495)[org.osgi.core-6.0.0.jar:]
 at org.osgi.util.tracker.BundleTracker$Tracked.customizerRemoved(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
 at org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:341)[org.osgi.core-6.0.0.jar:]
 at org.osgi.util.tracker.BundleTracker.close(BundleTracker.java:192)[org.osgi.core-6.0.0.jar:]
 at org.opendaylight.mdsal.dom.broker.osgi.OsgiBundleScanningSchemaService.close(OsgiBundleScanningSchemaService.java:132)
 at org.opendaylight.mdsal.dom.broker.osgi.SchemaServiceActivator.stop(SchemaServiceActivator.java:32)
 at org.eclipse.osgi.internal.framework.BundleContextImpl$4.run(BundleContextImpl.java:827)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.internal.framework.BundleContextImpl$4.run(BundleContextImpl.java:1)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_121]
 at org.eclipse.osgi.internal.framework.BundleContextImpl.stop(BundleContextImpl.java:820)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.internal.framework.EquinoxBundle.stopWorker0(EquinoxBundle.java:955)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.stopWorker(EquinoxBundle.java:323)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
 at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]

 Comments   
Comment by Michael Vorburger [ 08/Mar/17 ]

I just noticed that these errors are from "Framework stop" (which I hadn't noticed before..) in SFT, and also similarly below when you Ctrl-D a non-SFT real Karaf - IMHO it probably should be more silent particularly when it goes down...

2017-03-07 21:25:12,616 | INFO | Bundle Shutdown | YangTextSchemaContextResolver | 107 - org.opendaylight.yangtools.yang-parser-impl - 1.1.0.SNAPSHOT | Failed to fully assemble schema context for [RevisionSourceIdentifier [name=fib-rpc@2016-01-21], RevisionSourceIdentifier [name=l3nexthop@2015-04-09], RevisionSourceIdentifier [name=odl-fib@2015-03-30]]

Comment by Michael Vorburger [ 08/Mar/17 ]

MDSAL-236 opened for a generalization (this bug is re. 1 particularly frequent message).

Comment by Robert Varga [ 24/Mar/17 ]

Well, the crux of the problem is that the caller (mdsal/controller?) does not interact with Karaf feature service enough to be plugged into the lifecycle, hence it ends up recomputing the schema context during installation/shutdown process as the set of available models is still in flux.

If we silence these logs, we can end up with a karaf instance which does not work due to a single model missing, hence INFO is appropriate here.

Once the root cause is fixed, these will automatically go away.

Comment by Robert Varga [ 26/Apr/17 ]

Opened https://issues.apache.org/jira/browse/KARAF-5107 upstream.

Comment by Robert Varga [ 27/Apr/17 ]

Once MDSAL-248 is addressed, we need to create mdsal-dom-schema-service-karaf, which will talk to Karaf's FeatureService and do bundle scan throttling based on the events from it.

Comment by Robert Varga [ 27/Apr/17 ]

This new implementation should then be packaged into the feature in place of the osgi scanner, hence our karaf deployments will not see the log entries mentioned.

Comment by Robert Varga [ 02/May/17 ]

Karaf 4.1.2 and 4.2.0 will have FeatureService.registerListener(DeploymentListener), which gives events on start, resolve and end of deployment.

Comment by Robert Varga [ 28/Feb/20 ]

Resolved by adding a Karaf-specific wrapper around YangModuleInfoRegistry, which is bypassed if FeaturesService is not available.

Generated at Wed Feb 07 20:09:10 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.