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

Allon Mureinik amureini at redhat.com
Thu Oct 27 15:40:21 UTC 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 at redhat.com> 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 at redhat.com>
> 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 at redhat.com> 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.getConstraintValidatorInstanceForAutomaticUn
>>> wrapping(ConstraintTree.java:266) [hibernate-validator-5.2.4.Fin
>>> al.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.MetaConstrain
>>> t.validateConstraint(MetaConstraint.java:73)
>>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teConstraintsForGroup(ValidatorImpl.java:1488)
>>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teReturnValueForSingleGroup(ValidatorImpl.java:1459)
>>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teReturnValueForGroup(ValidatorImpl.java:1422)
>>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teReturnValueInContext(ValidatorImpl.java:1338)
>>> [hibernate-validator-5.2.4.Final.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teReturnValue(ValidatorImpl.java:317) [hibernate-validator-5.2.4.Fin
>>> al.jar:5.2.4.Final]
>>>         at org.hibernate.validator.internal.engine.ValidatorImpl.valida
>>> teReturnValue(ValidatorImpl.java:277) [hibernate-validator-5.2.4.Fin
>>> al.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$976
>>> 505265$Proxy$_$$_WeldClientProxy.validateReturnValue(Unknown Source)
>>>         at org.hibernate.validator.internal.cdi.interceptor.ValidationI
>>> nterceptor.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.SimpleInterceptorInvocatio
>>> n$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)
>>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final]
>>>         at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.ex
>>> ecuteAroundInvoke(InterceptorMethodHandler.java:84)
>>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final]
>>>         at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.ex
>>> ecuteInterception(InterceptorMethodHandler.java:72)
>>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final]
>>>         at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.in
>>> voke(InterceptorMethodHandler.java:56) [weld-core-impl-2.3.5.Final.ja
>>> r:2.3.5.Final]
>>>         at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorSta
>>> ckMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
>>> [weld-core-impl-2.3.5.Final.jar:2.3.5.Final]
>>>         at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorSta
>>> ckMethodHandler.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 at redhat.com>
>>> 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 at redhat.com>
>>>> wrote:
>>>>
>>>>> Its running now:
>>>>> http://jenkins.ovirt.org/job/ovirt-engine_master_build-artif
>>>>> acts-fc24-x86_64/1037/,
>>>>> 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 at redhat.com>
>>>>> 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 at redhat.com>
>>>>> 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 at redhat.com>
>>>>> 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_ma
>>>>> ster/2782
>>>>> >>> [2] https://gerrit.ovirt.org/#/c/65740/
>>>>> >>>
>>>>> >>> On Wed, Oct 26, 2016 at 11:33 AM, Tal Nisan <tnisan at redhat.com>
>>>>> 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 at redhat.com>
>>>>> >>> > 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(CMTTxInte
>>>>> rceptor.java:265)
>>>>> >>> >>     at
>>>>> >>> >>
>>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxIntercep
>>>>> tor.java:374)
>>>>> >>> >>     at
>>>>> >>> >>
>>>>> >>> >> org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTT
>>>>> xInterceptor.java:243)
>>>>> >>> >>     at
>>>>> >>> >>
>>>>> >>> >> org.jboss.invocation.InterceptorContext.proceed(InterceptorC
>>>>> ontext.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.AuditLo
>>>>> gableBase]
>>>>> >>> >> (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.tim
>>>>> erElapsed#-9223372036854775787
>>>>> >>> >> as there is no unfired trigger.
>>>>> >>> >> ...
>>>>> >>> >> 2016-10-25 11:53:52,845 DEBUG
>>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLo
>>>>> gableBase]
>>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Exception:
>>>>> >>> >> java.lang.NullPointerException
>>>>> >>> >>         at
>>>>> >>> >>
>>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLog
>>>>> ableBase.getVdsStatic(AuditLogableBase.java:633)
>>>>> >>> >> [dal.jar:]
>>>>> >>> >>         at
>>>>> >>> >>
>>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLog
>>>>> ableBase.getVdsName(AuditLogableBase.java:504)
>>>>> >>> >> [dal.jar:]
>>>>> >>> >> ...
>>>>> >>> >> 2016-10-25 11:53:52,837 INFO
>>>>> >>> >> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLo
>>>>> gableBase]
>>>>> >>> >> (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.AuditLo
>>>>> gableBase]
>>>>> >>> >> (org.ovirt.thread.pool-6-thread-2) [5e6a88be] Exception:
>>>>> >>> >> java.lang.NullPointerException
>>>>> >>> >>         at
>>>>> >>> >>
>>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLog
>>>>> ableBase.getVdsStatic(AuditLogableBase.java:633)
>>>>> >>> >> [dal.jar:]
>>>>> >>> >>         at
>>>>> >>> >>
>>>>> >>> >> org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLog
>>>>> ableBase.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/basi
>>>>> c_suite_master/test-scenarios/004_basic_sanity.py#L322
>>>>> >>> >> [3]
>>>>> >>> >>
>>>>> >>> >> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_ma
>>>>> ster/2759/artifact/exported-artifacts/basic_suite_master.sh-
>>>>> fc24/exported-artifacts/test_logs/basic_suite_master/post-00
>>>>> 4_basic_sanity.py/*zip*/post-004_basic_sanity.py.zip
>>>>> >>> >> [4]
>>>>> >>> >>
>>>>> >>> >> http://jenkins.ovirt.org/job/test-repo_ovirt_experimental_ma
>>>>> ster/2759/artifact/exported-artifacts/basic_suite_master.sh-
>>>>> fc24/exported-artifacts/
>>>>> >>> >> _______________________________________________
>>>>> >>> >> Devel mailing list
>>>>> >>> >> Devel at ovirt.org
>>>>> >>> >> http://lists.ovirt.org/mailman/listinfo/devel
>>>>> >>> >
>>>>> >>> >
>>>>> >>
>>>>> >>
>>>>> >
>>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Devel mailing list
>>>> Devel at ovirt.org
>>>> http://lists.ovirt.org/mailman/listinfo/devel
>>>>
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/devel/attachments/20161027/f6d7e0d6/attachment-0001.html>

More information about the Devel mailing list