[ OST Failure Report ] [ oVirt Master (log-collector/engine/vdsm) ] [ 23/25/26-03-2018 ] [004_basic_sanity.hotplug_cpu ]

[Milan Zamazal]

Dafna Ron <dron at redhat.com> writes:

> We have a failure that seems to be random and happening in several
> projects.

Does this failure occur only recently or has it been present for ages?

> from what I can see, we are failing due to a timing issue in the test
> itself because we are querying the vm after its been destroyed in engine.
> looking at engine, I can see that the vm was actually shut down,

No, the VM was shut down in another test.  It's already running again in
hotplug_cpu.

> I would like to disable this test until we can fix the issue since it
> already failed about 7 different patches from different projects.

I can see that Gal has already increased the timeout.  I think the test
could be split to reduce the waiting delay, I'll post a patch for that.

> *Link to
> Job:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/
> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/>Link
> to all
> logs:http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/
> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-004_basic_sanity.py/>(Relevant)
> error snippet from the log: <error>*
>
>
>
>
>
>
>
>
>
>
>
>
> *engine: 018-03-23 14:44:14,156-04 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-5) [] Failed to destroy VM
> '7020944f-cd26-4c31-b381-0ce6be733fd7' because VM does not exist,
> ignoring2018-03-23 14:44:14,156-04 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand]
> (ForkJoinPool-1-worker-5) [] FINISH, DestroyVDSCommand, log id:
> 646766a2018-03-23 14:44:14,156-04 DEBUG
> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
> (ForkJoinPool-1-worker-5) [] method: runVdsCommand, params: [Destroy,
> DestroyVmVDSCommandParameters:{hostId='c40b11df-7053-437e-8acc-c5e91c1694bc',
> vmId='7020944f-cd26-4c31-b381-0ce6be733fd7', secondsToWait='0',
> gracefully='false', reason='', ignoreNoVm='true'}], timeElapsed:
> 14ms2018-03-23 14:44:14,156-04 DEBUG
> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
> (ForkJoinPool-1-worker-5) [] method: getVmManager, params:
> [7020944f-cd26-4c31-b381-0ce6be733fd7], timeElapsed: 0ms2018-03-23
> 14:44:14,156-04 INFO
> [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer]
> (ForkJoinPool-1-worker-5) [] VM '7020944f-cd26-4c31-b381-0ce6be733fd7'(vm2)
> moved from 'Up' --> 'Down'2018-03-23 14:44:14,156-04 DEBUG
> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
> (ForkJoinPool-1-worker-5) [] method: getVmManager, params:
> [7020944f-cd26-4c31-b381-0ce6be733fd7], timeElapsed: 0ms2018-03-23
> 14:44:14,177-04 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (default task-4) [a463501f-f01a-4048-93ca-02647308394b] EVENT_ID:
> USER_STOP_VM(33), VM vm2 powered off by admin at internal-authz (Host:
> lago-basic-suite-master-host-0).*
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> *vdsm: 2018-03-23 14:44:14,024-0400 INFO  (libvirt/events) [virt.vm]
> (vmId='7020944f-cd26-4c31-b381-0ce6be733fd7') Changed state to Down: Admin
> shut down from the engine (code=6) (vm:1684)2018-03-23 14:44:14,028-0400
> INFO  (jsonrpc/1) [api.virt] FINISH destroy return={'status': {'message':
> 'Machine destroyed', 'code': 0}} from=::ffff:192.168.201.4,53454,
> flow_id=a463501f-f01a-4048-93ca-02647308394b,
> vmId=7020944f-cd26-4c31-b381-0ce6be733fd7 (api:52)2018-03-23
> 14:44:14,028-0400 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call
> VM.destroy succeeded in 1.72 seconds (__init__:311)2018-03-23
> 14:44:14,031-0400 INFO  (periodic/2) [Executor] Worker was discarded
> (executor:305)2018-03-23 14:44:14,033-0400 INFO  (libvirt/events) [virt.vm]
> (vmId='7020944f-cd26-4c31-b381-0ce6be733fd7') Stopping connection
> (guestagent:440)2018-03-23 14:44:14,033-0400 ERROR (libvirt/events) [vds]
> Error running VM callback (clientIF:666)Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 629, in
> dispatchLibvirtEvents    v.onLibvirtLifecycleEvent(event, detail,
> None)AttributeError: 'NoneType' object has no attribute
> 'onLibvirtLifecycleEvent'2018-03-23 14:44:14,078-0400 INFO  (jsonrpc/4)
> [api.virt] START destroy(gracefulAttempts=1)
> from=::ffff:192.168.201.4,53454, vmId=7020944f-cd26-4c31-b381-0ce6be733fd7
> (api:46)2018-03-23 14:44:14,078-0400 INFO  (jsonrpc/4) [api] FINISH destroy
> error=Virtual machine does not exist: {'vmId':
> u'7020944f-cd26-4c31-b381-0ce6be733fd7'} (api:127)2018-03-23
> 14:44:14,079-0400 INFO  (jsonrpc/4) [api.virt] FINISH destroy
> return={'status': {'message': "Virtual machine does not exist: {'vmId':
> u'7020944f-cd26-4c31-b381-0ce6be733fd7'}", 'code': 1}}
> from=::ffff:192.168.201.4,53454, vmId=7020944f-cd26-4c31-b381-0ce6be733fd7
> (api:52)*
>
> *</error>*
> _______________________________________________
> Devel mailing list
> Devel at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel