Operating System: All
Platform: All

Hi Jamo,
we are aware of the problem with missing "Registering Topology Request Listener" message within timeout, but only in all CSIT jobs. This is first time I see it in only job. We already tried set timeout to 5 minutes, in order to fix all jobs, but it didn't help. Currently we don't know, if problem is because 5 minutes is still not enough, or there is some another problem. We want to try different approach of waiting, but we didn't implement it yet in our tests. Currently I don't know, if this fail in only job have the same root cause as in all jobs.

About exceptions related to yang, I don't know what can be the reason, but it doesn't looks like bug in topoprocessing. At least models referenced by these exceptions are not from topoprocessing:
Error in module cluster-admin (QNameModule

)

(In reply to Jamo Luhrsen from comment #0)
> The CSIT job is failing in suite setup, so no test cases are run:
> https://jenkins.opendaylight.org/releng/view/CSIT-Jobs/job/topoprocessing-
> csit-1node-topology-operations-only-beryllium
>
> the reason the robot work fails is because the karaf.log message
> "Registering Topology Request Listener" does not show
> up in within 60 seconds. Maybe it needs to poll for longer? If so, a test
> fix needs to be made. But, 60 seconds
> seems very long to start with.
>
> I also see some worriesome exceptions in the karaf.log. This can be seen
> just by starting karaf from a master
> distribution and installing odl-restconf and
> odl-topoprocessing-network-topology. It is coming from yangtools,
> so maybe this bug belongs in that project?
>
> here is one traceback, but you can grab the entire karaf.log as an artifact
> from the csit job itself.
>
> 2015-12-18 00:13:44,613 | WARN | h for user karaf |
> YangStatementParserListenerImpl | 57 -
> org.opendaylight.yangtools.yang-parser-impl - 0.8.0.SNAPSHOT | Maximal count
> of KEY for LIST is 1, detected 2. Error in module cluster-admin
> (QNameModule

)
> org.opendaylight.yangtools.yang.parser.spi.meta.InvalidSubstatementException:
> Maximal count of KEY for LIST is 1, detected 2. Error in module
> cluster-admin
> (QNameModule

)
> at
> org.opendaylight.yangtools.yang.parser.spi.SubstatementValidator.
> validate(SubstatementValidator.java:105)
> at
> org.opendaylight.yangtools.yang.parser.stmt.rfc6020.
> ListStatementImpl$Definition.onFullDefinitionDeclared(ListStatementImpl.java:
> 108)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.
> StatementDefinitionContext.onDeclarationFinished(StatementDefinitionContext.
> java:61)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextBase.
> endDeclared(StatementContextBase.java:449)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextWriter.
> endStatement(StatementContextWriter.java:54)
> at
> org.opendaylight.yangtools.yang.parser.impl.YangStatementParserListenerImpl.
> exitStatement(YangStatementParserListenerImpl.java:105)
> at
> org.opendaylight.yangtools.antlrv4.code.gen.
> YangStatementParser$StatementContext.exitRule(YangStatementParser.java:117)
> at
> org.antlr.v4.runtime.tree.ParseTreeWalker.exitRule(ParseTreeWalker.java:71)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:54)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at
> org.opendaylight.yangtools.yang.parser.stmt.rfc6020.YangStatementSourceImpl.
> writeFull(YangStatementSourceImpl.java:95)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.SourceSpecificContext.
> loadStatements(SourceSpecificContext.java:318)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.BuildGlobalContext.
> loadPhaseStatements(BuildGlobalContext.java:211)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.BuildGlobalContext.
> buildEffective(BuildGlobalContext.java:177)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.
> CrossSourceStatementReactor$BuildAction.
> buildEffective(CrossSourceStatementReactor.java:107)
> at
> org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$2.
> apply(SharedSchemaContextFactory.java:100)
> 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.sal.binding.generator.impl.
> ModuleInfoBackedContext.tryToCreateSchemaContext(ModuleInfoBackedContext.
> java:86)
> at
> org.opendaylight.yangtools.sal.binding.generator.impl.
> ModuleInfoBackedContext.getSchemaContext(ModuleInfoBackedContext.java:192)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> BindingContextProvider.update(BindingContextProvider.java:25)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> RefreshingSCPModuleInfoRegistry.
> updateService(RefreshingSCPModuleInfoRegistry.java:57)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> ModuleInfoBundleTracker.addingBundle(ModuleInfoBundleTracker.java:89)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> ModuleInfoBundleTracker.addingBundle(ModuleInfoBundleTracker.java:32)
> 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)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEventPrivileged(Framework.java:1568)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEvent(Framework.java:1504)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEvent(Framework.java:1499)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> processDelta(PackageAdminImpl.java:541)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> doResolveBundles(PackageAdminImpl.java:251)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> resolveBundles(PackageAdminImpl.java:192)
> at
> org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.
> java:322)
> at
> org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.
> java:300)
> at
> org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.
> java:292)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> startBundle(FeaturesServiceImpl.java:501)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeatures(FeaturesServiceImpl.java:459)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeature(FeaturesServiceImpl.java:400)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeature(FeaturesServiceImpl.java:378)
> at Proxyb07c3583_6112_4f63_a805_6b5e4cb892b6.installFeature(Unknown Source)
> at
> org.apache.karaf.features.command.InstallFeatureCommand.
> doExecute(InstallFeatureCommand.java:67)
> at
> org.apache.karaf.features.command.FeaturesCommandSupport.
> doExecute(FeaturesCommandSupport.java:38)
> at
> org.apache.karaf.shell.console.AbstractAction.execute(AbstractAction.java:
> 33)[25:org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.karaf.shell.console.OsgiCommandSupport.execute(OsgiCommandSupport.
> java:39)[25:org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.karaf.shell.commands.basic.AbstractCommand.
> execute(AbstractCommand.java:33)[25:org.apache.karaf.shell.console:3.0.3]
> at Proxy3dfa4a2b_952b_41cc_a1fa_f955deab4d00.execute(Unknown Source)[:]
> at Proxy3dfa4a2b_952b_41cc_a1fa_f955deab4d00.execute(Unknown Source)[:]
> at
> org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:78)[25:
> org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:477)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:403)[25:
> org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[25:org.apache.karaf.
> shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.
> java:92)
> at
> org.apache.karaf.shell.console.impl.jline.ConsoleImpl.run(ConsoleImpl.java:
> 208)
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1.
> runConsole(ShellFactoryImpl.java:158)[232:org.apache.karaf.shell.ssh:3.0.3]
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1$1.
> run(ShellFactoryImpl.java:133)
> at java.security.AccessController.doPrivileged(Native Method)[:1.7.0_85]
> at
> org.apache.karaf.jaas.modules.JaasHelper.doAs(JaasHelper.java:57)[26:org.
> apache.karaf.jaas.modules:3.0.3]
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1.run(ShellFactoryImpl.
> java:129)[232:org.apache.karaf.shell.ssh:3.0.3]

I think that this bug belongs to another project.
We are waiting 1 minute for "Registering Topology Request Listener" but there is just too much exceptions you mentioned. I think that these exceptions are the reason why are our tests failing - it takes too much time.
"Registering Topology Request Listener" is present in karaf log after these exceptions as you can see in this log - https://jenkins.opendaylight.org/releng/view/CSIT-Jobs/job/topoprocessing-csit-1node-topology-operations-only-beryllium/146/artifact/karaf.log

(In reply to Jamo Luhrsen from comment #0)
> The CSIT job is failing in suite setup, so no test cases are run:
> https://jenkins.opendaylight.org/releng/view/CSIT-Jobs/job/topoprocessing-
> csit-1node-topology-operations-only-beryllium
>
> the reason the robot work fails is because the karaf.log message
> "Registering Topology Request Listener" does not show
> up in within 60 seconds. Maybe it needs to poll for longer? If so, a test
> fix needs to be made. But, 60 seconds
> seems very long to start with.
>
> I also see some worriesome exceptions in the karaf.log. This can be seen
> just by starting karaf from a master
> distribution and installing odl-restconf and
> odl-topoprocessing-network-topology. It is coming from yangtools,
> so maybe this bug belongs in that project?
>
> here is one traceback, but you can grab the entire karaf.log as an artifact
> from the csit job itself.
>
> 2015-12-18 00:13:44,613 | WARN | h for user karaf |
> YangStatementParserListenerImpl | 57 -
> org.opendaylight.yangtools.yang-parser-impl - 0.8.0.SNAPSHOT | Maximal count
> of KEY for LIST is 1, detected 2. Error in module cluster-admin
> (QNameModule

)
> org.opendaylight.yangtools.yang.parser.spi.meta.InvalidSubstatementException:
> Maximal count of KEY for LIST is 1, detected 2. Error in module
> cluster-admin
> (QNameModule

)
> at
> org.opendaylight.yangtools.yang.parser.spi.SubstatementValidator.
> validate(SubstatementValidator.java:105)
> at
> org.opendaylight.yangtools.yang.parser.stmt.rfc6020.
> ListStatementImpl$Definition.onFullDefinitionDeclared(ListStatementImpl.java:
> 108)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.
> StatementDefinitionContext.onDeclarationFinished(StatementDefinitionContext.
> java:61)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextBase.
> endDeclared(StatementContextBase.java:449)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextWriter.
> endStatement(StatementContextWriter.java:54)
> at
> org.opendaylight.yangtools.yang.parser.impl.YangStatementParserListenerImpl.
> exitStatement(YangStatementParserListenerImpl.java:105)
> at
> org.opendaylight.yangtools.antlrv4.code.gen.
> YangStatementParser$StatementContext.exitRule(YangStatementParser.java:117)
> at
> org.antlr.v4.runtime.tree.ParseTreeWalker.exitRule(ParseTreeWalker.java:71)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:54)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at org.antlr.v4.runtime.tree.ParseTreeWalker.walk(ParseTreeWalker.java:52)
> at
> org.opendaylight.yangtools.yang.parser.stmt.rfc6020.YangStatementSourceImpl.
> writeFull(YangStatementSourceImpl.java:95)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.SourceSpecificContext.
> loadStatements(SourceSpecificContext.java:318)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.BuildGlobalContext.
> loadPhaseStatements(BuildGlobalContext.java:211)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.BuildGlobalContext.
> buildEffective(BuildGlobalContext.java:177)
> at
> org.opendaylight.yangtools.yang.parser.stmt.reactor.
> CrossSourceStatementReactor$BuildAction.
> buildEffective(CrossSourceStatementReactor.java:107)
> at
> org.opendaylight.yangtools.yang.parser.repo.SharedSchemaContextFactory$2.
> apply(SharedSchemaContextFactory.java:100)
> 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.sal.binding.generator.impl.
> ModuleInfoBackedContext.tryToCreateSchemaContext(ModuleInfoBackedContext.
> java:86)
> at
> org.opendaylight.yangtools.sal.binding.generator.impl.
> ModuleInfoBackedContext.getSchemaContext(ModuleInfoBackedContext.java:192)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> BindingContextProvider.update(BindingContextProvider.java:25)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> RefreshingSCPModuleInfoRegistry.
> updateService(RefreshingSCPModuleInfoRegistry.java:57)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> ModuleInfoBundleTracker.addingBundle(ModuleInfoBundleTracker.java:89)
> at
> org.opendaylight.controller.config.manager.impl.osgi.mapping.
> ModuleInfoBundleTracker.addingBundle(ModuleInfoBundleTracker.java:32)
> 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)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEventPrivileged(Framework.java:1568)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEvent(Framework.java:1504)
> at
> org.eclipse.osgi.framework.internal.core.Framework.
> publishBundleEvent(Framework.java:1499)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> processDelta(PackageAdminImpl.java:541)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> doResolveBundles(PackageAdminImpl.java:251)
> at
> org.eclipse.osgi.framework.internal.core.PackageAdminImpl.
> resolveBundles(PackageAdminImpl.java:192)
> at
> org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.
> java:322)
> at
> org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.
> java:300)
> at
> org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.
> java:292)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> startBundle(FeaturesServiceImpl.java:501)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeatures(FeaturesServiceImpl.java:459)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeature(FeaturesServiceImpl.java:400)
> at
> org.apache.karaf.features.internal.FeaturesServiceImpl.
> installFeature(FeaturesServiceImpl.java:378)
> at Proxyb07c3583_6112_4f63_a805_6b5e4cb892b6.installFeature(Unknown Source)
> at
> org.apache.karaf.features.command.InstallFeatureCommand.
> doExecute(InstallFeatureCommand.java:67)
> at
> org.apache.karaf.features.command.FeaturesCommandSupport.
> doExecute(FeaturesCommandSupport.java:38)
> at
> org.apache.karaf.shell.console.AbstractAction.execute(AbstractAction.java:
> 33)[25:org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.karaf.shell.console.OsgiCommandSupport.execute(OsgiCommandSupport.
> java:39)[25:org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.karaf.shell.commands.basic.AbstractCommand.
> execute(AbstractCommand.java:33)[25:org.apache.karaf.shell.console:3.0.3]
> at Proxy3dfa4a2b_952b_41cc_a1fa_f955deab4d00.execute(Unknown Source)[:]
> at Proxy3dfa4a2b_952b_41cc_a1fa_f955deab4d00.execute(Unknown Source)[:]
> at
> org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:78)[25:
> org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:477)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:403)[25:
> org.apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[25:org.apache.karaf.
> shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)[25:org.
> apache.karaf.shell.console:3.0.3]
> at
> org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.
> java:92)
> at
> org.apache.karaf.shell.console.impl.jline.ConsoleImpl.run(ConsoleImpl.java:
> 208)
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1.
> runConsole(ShellFactoryImpl.java:158)[232:org.apache.karaf.shell.ssh:3.0.3]
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1$1.
> run(ShellFactoryImpl.java:133)
> at java.security.AccessController.doPrivileged(Native Method)[:1.7.0_85]
> at
> org.apache.karaf.jaas.modules.JaasHelper.doAs(JaasHelper.java:57)[26:org.
> apache.karaf.jaas.modules:3.0.3]
> at
> org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$1.run(ShellFactoryImpl.
> java:129)[232:org.apache.karaf.shell.ssh:3.0.3]

First exception is thrown at 02:44:47 and "Registering Topology Request Listener" is at 02:46:32. So it takes more than 1 minute.

(In reply to Samuel Kontriš from comment #2)
> I think that this bug belongs to another project.
> We are waiting 1 minute for "Registering Topology Request Listener" but
> there is just too much exceptions you mentioned. I think that these
> exceptions are the reason why are our tests failing - it takes too much time.
> "Registering Topology Request Listener" is present in karaf log after these
> exceptions as you can see in this log -
> https://jenkins.opendaylight.org/releng/view/CSIT-Jobs/job/topoprocessing-
> csit-1node-topology-operations-only-beryllium/146/artifact/karaf.log
>
> (In reply to Jamo Luhrsen from comment #0)
> > The CSIT job is failing in suite setup, so no test cases are run:
> > https://jenkins.opendaylight.org/releng/view/CSIT-Jobs/job/topoprocessing-
> > csit-1node-topology-operations-only-beryllium
> >
> > the reason the robot work fails is because the karaf.log message
> > "Registering Topology Request Listener" does not show
> > up in within 60 seconds. Maybe it needs to poll for longer? If so, a test
> > fix needs to be made. But, 60 seconds
> > seems very long to start with.
> >
> > I also see some worriesome exceptions in the karaf.log. This can be seen
> > just by starting karaf from a master
> > distribution and installing odl-restconf and
> > odl-topoprocessing-network-topology. It is coming from yangtools,
> > so maybe this bug belongs in that project?
> >
> > here is one traceback, but you can grab the entire karaf.log as an artifact
> > from the csit job itself.
> >
> > 2015-12-18 00:13:44,613 | WARN | h for user karaf |
> > YangStatementParserListenerImpl | 57 -
> > org.opendaylight.yangtools.yang-parser-impl - 0.8.0.SNAPSHOT | Maximal count
> > of KEY for LIST is 1, detected 2. Error in module cluster-admin
> > (QNameModule

)
> > org.opendaylight.yangtools.yang.parser.spi.meta.InvalidSubstatementException:
> > Maximal count of KEY for LIST is 1, detected 2. Error in module
> > cluster-admin
> > (QNameModule

)
> > ...

Some updates:

A)
I've sent an email to the controller-dev list asking about the yangtools exceptions I have pasted
originally in this bug. I also noticed those exceptions in a controller clustering karaf.log so
I'm pretty confident it has nothing to do with topoprocessing.

https://lists.opendaylight.org/pipermail/integration-dev/2015-December/005429.html

B)
In the sandbox I increased the polling time to 10 minutes, and the "Registering Topology Request Listener"
message does show up after aprox 5m 40s of polling. My gut tells me something inefficient is going
on for things to take that long to register.

here is the link, but it will not be there forever as the sandbox is deleted every weekend:
https://jenkins.opendaylight.org/sandbox/job/topoprocessing-csit-1node-topology-operations-only-beryllium/2/robot/report/log.html

C)
Next, after waiting long enough, the "Insert Underlay Topologies" is still failing, but not like in
CONTROLLER-1461. The Error is still a 500, but the trace is this:

<errors xmlns="urn:ietf:params:xml:ns:yang:ietf-restconf"><error><error-type>application</error-type><error-tag>operation-failed</error-tag><error-message>canCommit encountered an unexpected failure</error-message><error-info>org.opendaylight.yangtools.yang.data.impl.schema.tree.SchemaValidationFailedException: Child (urn:opendaylight:params:xml:ns:yang:topology:pcep?revision=2013-10-24)path-computation-client is not valid child according to schema.
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.verifyStructure(AbstractNodeContainerModificationStrategy.java:53)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.verifyStructure(AbstractNodeContainerModificationStrategy.java:51)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.verifyStructure(AbstractNodeContainerModificationStrategy.java:51)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.MinMaxElementsValidation.verifyStructure(MinMaxElementsValidation.java:171)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractNodeContainerModificationStrategy.verifyStructure(AbstractNodeContainerModificationStrategy.java:51)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.ModifiedNode.seal(ModifiedNode.java:297)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.AbstractReadyIterator.process(AbstractReadyIterator.java:45)
at org.opendaylight.yangtools.yang.data.impl.schema.tree.InMemoryDataTreeModification.ready(InMemoryDataTreeModification.java:280)
at org.opendaylight.controller.sal.core.spi.data.SnapshotBackedWriteTransaction.ready(SnapshotBackedWriteTransaction.java:139)
at org.opendaylight.controller.cluster.datastore.LocalTransactionFactoryImpl.onTransactionReady(LocalTransactionFactoryImpl.java:76)
at org.opendaylight.controller.cluster.datastore.LocalTransactionContext.ready(LocalTransactionContext.java:115)
at org.opendaylight.controller.cluster.datastore.LocalTransactionContext.directCommit(LocalTransactionContext.java:130)
at org.opendaylight.controller.cluster.datastore.TransactionProxy.getReadyOrDirectCommitFuture(TransactionProxy.java:284)
at org.opendaylight.controller.cluster.datastore.TransactionProxy.createSingleCommitCohort(TransactionProxy.java:270)
at org.opendaylight.controller.cluster.datastore.TransactionProxy.ready(TransactionProxy.java:237)
at org.opendaylight.controller.cluster.datastore.TransactionProxy.ready(TransactionProxy.java:45)
at org.opendaylight.controller.cluster.databroker.AbstractDOMBrokerWriteTransaction.submit(AbstractDOMBrokerWriteTransaction.java:134)
at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.putDataViaTransaction(BrokerFacade.java:258)
at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.commitConfigurationDataPut(BrokerFacade.java:114)
at org.opendaylight.netconf.sal.restconf.impl.RestconfImpl.updateConfigurationData(RestconfImpl.java:722)
at org.opendaylight.netconf.sal.restconf.impl.StatisticsRestconfServiceWrapper.updateConfigurationData(StatisticsRestconfServiceWrapper.java:133)
at org.opendaylight.netconf.sal.rest.impl.RestconfCompositeWrapper.updateConfigurationData(RestconfCompositeWrapper.java:82)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)
at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:247)
at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:210)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:82)
at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:256)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:69)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:240)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:75)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:370)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:982)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1043)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
at java.lang.Thread.run(Thread.java:745)
</error-info></error></errors>

https://lists.opendaylight.org/pipermail/controller-dev/2015-December/011267.html

Hi Jamo,

Insert Underlay Topologies are failing, because we try to insert to configuration some model (path-computation-client from network-topology-pcep.yang) which have config false statement. So after 1014 was merged it is failing. I already write mail where I ask what we can do.
https://lists.opendaylight.org/pipermail/release/2015-December/005067.html

(In reply to Jamo Luhrsen from comment #4)
> C)
> Next, after waiting long enough, the "Insert Underlay Topologies" is still
> failing, but not like in
> CONTROLLER-1461. The Error is still a 500, but the trace is this:

I pushed fix for this issue:
https://git.opendaylight.org/gerrit/#/c/31694/1

(In reply to Andrej Zan from comment #6)
> Hi Jamo,
>
> Insert Underlay Topologies are failing, because we try to insert to
> configuration some model (path-computation-client from
> network-topology-pcep.yang) which have config false statement. So after 1014
> was merged it is failing. I already write mail where I ask what we can do.
> https://lists.opendaylight.org/pipermail/release/2015-December/005067.html
>
> (In reply to Jamo Luhrsen from comment #4)
> > C)
> > Next, after waiting long enough, the "Insert Underlay Topologies" is still
> > failing, but not like in
> > CONTROLLER-1461. The Error is still a 500, but the trace is this:

(In reply to Andrej Zan from comment #7)
> I pushed fix for this issue:
> https://git.opendaylight.org/gerrit/#/c/31694/1

great. I just merged the above gerrit. This bug is now resolved, so I'll
mark it as such. One thing to point out is that your CSIT job still has
failures, so maybe there is more test work to do, or possibly another
bug to resolve on topoprocessing side:

https://jenkins.opendaylight.org/releng/job/topoprocessing-csit-verify-1node-topology-operations/40/

(In reply to Jamo Luhrsen from comment #8)
> (In reply to Andrej Zan from comment #7)
> > I pushed fix for this issue:
> > https://git.opendaylight.org/gerrit/#/c/31694/1
>
> great. I just merged the above gerrit. This bug is now resolved, so I'll
> mark it as such. One thing to point out is that your CSIT job still has
> failures, so maybe there is more test work to do, or possibly another
> bug to resolve on topoprocessing side:
>
> https://jenkins.opendaylight.org/releng/job/topoprocessing-csit-verify-1node-
> topology-operations/40/

This one is related to another bug - 4673
https://bugs.opendaylight.org/show_bug.cgi?id=4673

There are also other bugs in topoprocessing, which we are aware of and which will cause some tests will fail. If it is better to exlude these tests from csit jobs, please let me know. We are now a little out of resources, but we will try the best to fix as much as we can.

(In reply to Andrej Zan from comment #9)
> (In reply to Jamo Luhrsen from comment #8)
> > (In reply to Andrej Zan from comment #7)
> > > I pushed fix for this issue:
> > > https://git.opendaylight.org/gerrit/#/c/31694/1
> >
> > great. I just merged the above gerrit. This bug is now resolved, so I'll
> > mark it as such. One thing to point out is that your CSIT job still has
> > failures, so maybe there is more test work to do, or possibly another
> > bug to resolve on topoprocessing side:
> >
> > https://jenkins.opendaylight.org/releng/job/topoprocessing-csit-verify-1node-
> > topology-operations/40/
>
> This one is related to another bug - 4673
> https://bugs.opendaylight.org/show_bug.cgi?id=4673
>
> There are also other bugs in topoprocessing, which we are aware of and which
> will cause some tests will fail. If it is better to exlude these tests from
> csit jobs, please let me know. We are now a little out of resources, but we
> will try the best to fix as much as we can.

When we have to make the decision to release we'll want to know what's
going on with each CSIT failure. If it's a valid bug, it would be cool to
make it easy to know in the robot suite itself. Vratko gave a link [0] in
the gerrit (31694: link above) about how to make the tests more verbose in
case of failure. We also have a teardown keyword that helps. I gave a
patch [1] that might work... In the end, we'll somehow have to figure out
if the bugs are serious and we should delay release, or if it's ok to ship
with the failure. I would rather see failing test cases where it's obvious
why it fails, than to hide them with "exclude" or some other way.

[0] https://wiki.opendaylight.org/view/Integration/Test/Test_Code_Guidelines#Test_case_Failing
[1] https://git.opendaylight.org/gerrit/31784