Re: [ovirt-devel] Failure on start VM in ovirt-system-tests from patches merged to master on the 25/10/2016

The 004 CI is now passing, and it fails on 006. I merged a patch for the failure, let's see where we get next. On Thu, Oct 27, 2016 at 3:13 PM, Allon Mureinik <amureini(a)redhat.com&gt; wrote: > > Now I also see it in the CI. > > I merged the patch so we can squeeze in as many CI runs as possible before > the weekend. > > On Thu, Oct 27, 2016 at 11:38 AM, Allon Mureinik <amureini(a)redhat.com&gt; > wrote: >> >> [Adding Martin Sivak.] >> >> That reproduces on my setup too, but didn't see it in CI, and is not >> related to the recent injection issues. >> >> Martin - This issue seems to have been introduced in your patch 0e4ae6b. >> I'm not sure eaxctly why java doesn't like the @NotNull annotation on >> schedule, but ampyrically it does, as removing it solves the issue. >> I've posted https://gerrit.ovirt.org/65784 to do so - please review (or >> suggest a better solution, of course :-)) >> >> Thanks, >> Allon >> >> On Thu, Oct 27, 2016 at 9:12 AM, Yaniv Kaul <ykaul(a)redhat.com&gt; wrote: >>> >>> I still fail to run a VM: >>> 2016-10-27 02:01:02,849 ERROR >>> [org.ovirt.engine.core.bll.RunVmOnceCommand] (default task-17) [78897d21] >>> Command 'org.ovirt.engine.core.bll.RunVmOnceCommand' failed: HV000186: The >>> constraint of type 'javax.valida >>> tion.constraints.NotNull' defined on 'schedule.<return value>' has >>> multiple matching constraint validators which is due to an additional value >>> handler of type 'org.hibernate.validator.internal.engine.valuehandli >>> ng.OptionalValueUnwrapper'. It is unclear which value needs validating. >>> Clarify configuration via @UnwrapValidatedValue. >>> 2016-10-27 02:01:02,849 ERROR >>> [org.ovirt.engine.core.bll.RunVmOnceCommand] (default task-17) [78897d21] >>> Exception: javax.validation.UnexpectedTypeException: HV000186: The >>> constraint of type 'javax.validation.con >>> straints.NotNull' defined on 'schedule.<return value>' has multiple >>> matching constraint validators which is due to an additional value handler >>> of type 'org.hibernate.validator.internal.engine.valuehandling.Optio >>> nalValueUnwrapper'. It is unclear which value needs validating. Clarify >>> configuration via @UnwrapValidatedValue. >>> at >>> org.hibernate.validator.internal.engine.constraintvalidation.ConstraintTree.getConstraintValidatorInstanceForAutomaticUnwrapping(ConstraintTree.java:266) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Fin >>> al] >>> at >>> org.hibernate.validator.internal.engine.constraintvalidation.ConstraintTree.getInitializedConstraintValidator(ConstraintTree.java:163) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.constraintvalidation.ConstraintTree.validateConstraints(ConstraintTree.java:116) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.constraintvalidation.ConstraintTree.validateConstraints(ConstraintTree.java:87) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.metadata.core.MetaConstraint.validateConstraint(MetaConstraint.java:73) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateConstraintsForGroup(ValidatorImpl.java:1488) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateReturnValueForSingleGroup(ValidatorImpl.java:1459) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateReturnValueForGroup(ValidatorImpl.java:1422) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateReturnValueInContext(ValidatorImpl.java:1338) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateReturnValue(ValidatorImpl.java:317) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at >>> org.hibernate.validator.internal.engine.ValidatorImpl.validateReturnValue(ValidatorImpl.java:277) >>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final] >>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >>> [rt.jar:1.8.0_111] >>> at >>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) >>> [rt.jar:1.8.0_111] >>> at >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >>> [rt.jar:1.8.0_111] >>> at java.lang.reflect.Method.invoke(Method.java:498) >>> [rt.jar:1.8.0_111] >>> at >>> org.jboss.weld.bean.proxy.AbstractBeanInstance.invoke(AbstractBeanInstance.java:38) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:100) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weldx.validation.ExecutableValidator$Validator$976505265$Proxy$_$$_WeldClientProxy.validateReturnValue(Unknown >>> Source) >>> at >>> org.hibernate.validator.internal.cdi.interceptor.ValidationInterceptor.validateMethodInvocation(ValidationInterceptor.java:80) >>> [hibernate-validator-cdi-5.2.4.Final.jar:5.2.4.Final] >>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >>> [rt.jar:1.8.0_111] >>> at >>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) >>> [rt.jar:1.8.0_111] >>> at >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >>> [rt.jar:1.8.0_111] >>> at java.lang.reflect.Method.invoke(Method.java:498) >>> [rt.jar:1.8.0_111] >>> at >>> org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) >>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final] >>> at >>> org.ovirt.engine.core.bll.scheduling.SchedulingManager$Proxy$_$$_WeldSubclass.schedule(Unknown >>> Source) [bll.jar:] >>> at >>> org.ovirt.engine.core.bll.RunVmCommand.getVdsToRunOn(RunVmCommand.java:818) >>> [bll.jar:] >>> at >>> org.ovirt.engine.core.bll.RunVmCommand.runVm(RunVmCommand.java:231) >>> [bll.jar:] >>> at >>> org.ovirt.engine.core.bll.RunVmCommand.perform(RunVmCommand.java:414) >>> [bll.jar:] >>> at >>> org.ovirt.engine.core.bll.RunVmCommand.executeVmCommand(RunVmCommand.java:339) >>> [bll.jar:] >>> at >>> org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:106) >>> [bll.jar:] >>> >>> >>> On Thu, Oct 27, 2016 at 5:12 AM, Allon Mureinik <amureini(a)redhat.com&gt; >>> wrote: >>>> >>>> Seems like we cleared up the engine issues related to the recent >>>> injection changes. >>>> >>>> I am now seeing stop errors, e.g.: >>>> >>>> {"jsonrpc": "2.0", "id": "ea0c564f-bc17-4fc2-8f1b-67c4d28257c6", >>>> "result": {"cpuStatistics": {"1": {"cpuUser": "3.07", "nodeIndex": 0, >>>> "cpuSys": "3.00", "cpuIdle": "93.93"}, "0": {"cpuUser": "1.67", "nodeIndex": >>>> 0, "cpuSys": "2.07", "cpuIdle": "96.26"}}, "numaNodeMemFree": {"0": >>>> {"memPercent": 83, "memFree": "359"}}, "memShared": 0, "thpState": "always", >>>> "ksmMergeAcrossNodes": true, "vmCount": 0, "memUsed": "20", >>>> "storageDomains": {"b2bb3220-1eb3-426a-90c2-5e236aefbe1a": {"code": 0, >>>> "actual": true, "version": 0, "acquired": true, "delay": "0.000840117", >>>> "lastCheck": "7.1", "valid": true}, "3130195a-73f9-4490-b554-98a9205cead6": >>>> {"code": 0, "actual": true, "version": 4, "acquired": true, "delay": >>>> "0.00150771", "lastCheck": "7.5", "valid": true}, >>>> "1a9e202b-83b7-4bdc-9b0c-e76b83676068": {"code": 0, "actual": true, >>>> "version": 4, "acquired": true, "delay": "0.000590956", >>>> 2016-10-26 21:51:09,878 DEBUG >>>> [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] >>>> (DefaultQuartzScheduler7) [6d206bd1] Rescheduling >>>> DEFAULT.org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods#-9223372036854775783 >>>> as there is no unfired trigger. >>>> 2016-10-26 21:51:28,705 DEBUG >>>> [org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient] (SSL Stomp Reactor) >>>> [383dd6a0] Heartbeat exceeded. Closing channel >>>> 2016-10-26 21:51:28,708 DEBUG >>>> [org.ovirt.vdsm.jsonrpc.client.reactors.Reactor] (SSL Stomp Reactor) >>>> [383dd6a0] Internal server error: null: java.lang.NullPointerException >>>> at >>>> org.ovirt.vdsm.jsonrpc.client.reactors.SSLClient.write(SSLClient.java:102) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> at >>>> org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient.processOutgoing(ReactorClient.java:245) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> at >>>> org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient.process(ReactorClient.java:208) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> at >>>> org.ovirt.vdsm.jsonrpc.client.reactors.SSLClient.process(SSLClient.java:125) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> at >>>> org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.processChannels(Reactor.java:89) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> at org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.run(Reactor.java:65) >>>> [vdsm-jsonrpc-java-client.jar:] >>>> >>>> >>>> Piotr - any idea? >>>> >>>> >>>> On Wed, Oct 26, 2016 at 9:34 PM, Nadav Goldin <ngoldin(a)redhat.com&gt; >>>> wrote: >>>>> >>>>> Its running now: >>>>> >>>>> http://jenkins.ovirt.org/job/ovirt-engine_master_build-artifacts-fc24-x86..., >>>>> when it finishes it will trigger the deploy job which will trigger the >>>>> experimental job. The build_artifacts job is triggered approximately >>>>> every 2 hours(depends on the load). >>>>> Inside the build-artifacts job you can see the last >>>>> commit(https://gerrit.ovirt.org/65776, which is already after your >>>>> commit) >>>>> >>>>> >>>>> On Wed, Oct 26, 2016 at 9:26 PM, Allon Mureinik <amureini(a)redhat.com&gt; >>>>> wrote: >>>>> > @Infra - the last experimental job I saw was from ~17:30 local >>>>> > Israel time. >>>>> > Any idea why another one isn't being triggered (or am I just being >>>>> > daft)? >>>>> > >>>>> > On Wed, Oct 26, 2016 at 6:27 PM, Allon Mureinik >>>>> > <amureini(a)redhat.com&gt; wrote: >>>>> >> >>>>> >> Yipes. >>>>> >> [1] should fix that, waiting for the CI to run to merge. >>>>> >> >>>>> >> [1] https://gerrit.ovirt.org/#/c/65768/ >>>>> >> >>>>> >> On Wed, Oct 26, 2016 at 3:42 PM, Nadav Goldin <ngoldin(a)redhat.com&gt; >>>>> >> wrote: >>>>> >>> >>>>> >>> Unfortunately it is still failing, see[1], the repository used was >>>>> >>> built from commit [2]. If you want to check the logs same links >>>>> >>> apply(just replace build number 2759->2782) >>>>> >>> >>>>> >>> >>>>> >>> >>>>> >>> [1] >>>>> >>> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2782 >>>>> >>> [2] https://gerrit.ovirt.org/#/c/65740/ >>>>> >>> >>>>> >>> On Wed, Oct 26, 2016 at 11:33 AM, Tal Nisan <tnisan(a)redhat.com&gt; >>>>> >>> wrote: >>>>> >>> > Should be fixed now on master as those patches were just merged: >>>>> >>> > >>>>> >>> > https://gerrit.ovirt.org/#/c/65738/ - "Move InjectorRule to >>>>> >>> > VdsBroker": >>>>> >>> > aligns the InjectorRule's package with the Injector so it can >>>>> >>> > essentially be >>>>> >>> > used wherever the Injector is used [+12, -4] >>>>> >>> > https://gerrit.ovirt.org/#/c/65739 - "InjectorRule: override >>>>> >>> > injector >>>>> >>> > anyway": Fixes a bug in InjectorRule where the Injector is only >>>>> >>> > mocked >>>>> >>> > if >>>>> >>> > you call InjectorRule.bind [+6, -1] >>>>> >>> > https://gerrit.ovirt.org/#/c/65740 - "core: InjectorRule for >>>>> >>> > injecting >>>>> >>> > members": Fixes a bug in InjectorRule to allow using >>>>> >>> > Injector.injectMembers >>>>> >>> > when using it [+18, -5] >>>>> >>> > https://gerrit.ovirt.org/#/c/65725 - "core: Fix AuditLogging": >>>>> >>> > The >>>>> >>> > actual >>>>> >>> > fix. Basically, goes over all the places that create an >>>>> >>> > AuditLoggableBase >>>>> >>> > that needs injecting and take care of it [+155, -160] >>>>> >>> > >>>>> >>> > >>>>> >>> > On Wed, Oct 26, 2016 at 10:04 AM, Nadav Goldin >>>>> >>> > <ngoldin(a)redhat.com&gt; >>>>> >>> > wrote: >>>>> >>> >> >>>>> >>> >> Hi, >>>>> >>> >> We have new failure on OST from patches merged to master >>>>> >>> >> yesterday, >>>>> >>> >> the failure started after the merge of [1], but as there were >>>>> >>> >> quite a >>>>> >>> >> few patches merged quickly I can't make sure it is the one >>>>> >>> >> causing >>>>> >>> >> it(OST aren't ran per-patch). >>>>> >>> >> The test that fails is [2] when attempting to start the VM. >>>>> >>> >> >>>>> >>> >> The error from the API side: >>>>> >>> >> >>>>> >>> >> RequestError: >>>>> >>> >> status: 500 >>>>> >>> >> reason: Internal Server Error >>>>> >>> >> detail: javax.ejb.EJBException: java.lang.NullPointerException >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInNoTx(CMTTxInterceptor.java:213) >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:265) >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:374) >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:243) >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:340) >>>>> >>> >> .... >>>>> >>> >> >>>>> >>> >> In the engine logs there are a few >>>>> >>> >> 'java.lang.NullPointerException' >>>>> >>> >> errors: >>>>> >>> >> >>>>> >>> >> 2016-10-25 11:53:52,845 INFO >>>>> >>> >> >>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase] >>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Failed to get vds >>>>> >>> >> 'd60db21f-95f0-487b-9f17-44861e2610a7', error: null >>>>> >>> >> 2016-10-25 11:53:52,864 DEBUG >>>>> >>> >> [org.ovirt.engine.core.utils.timer.FixedDelayJobListener] >>>>> >>> >> (DefaultQuartzScheduler5) [] Rescheduling >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> DEFAULT.org.ovirt.engine.core.bll.tasks.AsyncTaskManager.timerElapsed#-9223372036854775787 >>>>> >>> >> as there is no unfired trigger. >>>>> >>> >> ... >>>>> >>> >> 2016-10-25 11:53:52,845 DEBUG >>>>> >>> >> >>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase] >>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Exception: >>>>> >>> >> java.lang.NullPointerException >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase.getVdsStatic(AuditLogableBase.java:633) >>>>> >>> >> [dal.jar:] >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase.getVdsName(AuditLogableBase.java:504) >>>>> >>> >> [dal.jar:] >>>>> >>> >> ... >>>>> >>> >> 2016-10-25 11:53:52,837 INFO >>>>> >>> >> >>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase] >>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Failed to get vds >>>>> >>> >> 'd60db21f-95f0-487b-9f17-44861e2610a7', error: null >>>>> >>> >> 2016-10-25 11:53:52,837 DEBUG >>>>> >>> >> >>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase] >>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Exception: >>>>> >>> >> java.lang.NullPointerException >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase.getVdsStatic(AuditLogableBase.java:633) >>>>> >>> >> [dal.jar:] >>>>> >>> >> at >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogableBase.getVdsName(AuditLogableBase.java:504) >>>>> >>> >> [dal.jar:] >>>>> >>> >> ... >>>>> >>> >> >>>>> >>> >> The full engine logs can be found here[3] and the entire test >>>>> >>> >> suite >>>>> >>> >> logs here[4]. >>>>> >>> >> >>>>> >>> >> Can anyone have a look? >>>>> >>> >> >>>>> >>> >> Thanks, >>>>> >>> >> Nadav. >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> [1] https://gerrit.ovirt.org/#/c/65198/ >>>>> >>> >> [2] >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> https://github.com/oVirt/ovirt-system-tests/blob/master/basic_suite_maste... >>>>> >>> >> [3] >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2759/art... >>>>> >>> >> [4] >>>>> >>> >> >>>>> >>> >> >>>>> >>> >> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_master/2759/art... >>>>> >>> >> _______________________________________________ >>>>> >>> >> Devel mailing list >>>>> >>> >> Devel(a)ovirt.org >>>>> >>> >> http://lists.ovirt.org/mailman/listinfo/devel >>>>> >>> > >>>>> >>> > >>>>> >> >>>>> >> >>>>> > >>>> >>>> >>>> >>>> _______________________________________________ >>>> Devel mailing list >>>> Devel(a)ovirt.org >>>> http://lists.ovirt.org/mailman/listinfo/devel >>> >>> >> >