[ OST Failure Report ] [ oVirt Master (log-collector/engine/vdsm) ] [ 23/25/26-03-2018 ] [004_basic_sanity.hotplug_cpu ]
7:02 p.m.
Hi,
We have a failure that seems to be random and happening in several
projects.
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,
I would like to disable this test until we can fix the issue since it
already failed about 7 different patches from different projects.
*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/a...
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/artifa...
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@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>*
11:18 a.m.
Dafna Ron <dron(a)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/a...
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/6521/artifa...
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@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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
11:23 a.m.
Milan Zamazal <mzamazal(a)redhat.com> writes:
Dafna Ron <dron(a)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.
BTW I think the primary cause of the trouble are the infamous Cirros
networking recovery problems.
12:01 p.m.
Thanks Milan,
Can you post the fix that you added on the mail?
Thanks,
Dafna
On Wed, Mar 28, 2018 at 9:23 AM, Milan Zamazal <mzamazal(a)redhat.com> wrote:
Milan Zamazal <mzamazal(a)redhat.com> writes:
> Dafna Ron <dron(a)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.
BTW I think the primary cause of the trouble are the infamous Cirros
networking recovery problems.
2:52 p.m.
Dafna Ron <dron(a)redhat.com> writes:
Can you post the fix that you added on the mail?
I split hotplug_cpu test in https://gerrit.ovirt.org/89551
We'll see whether it is actually useful once the disk_operations failure
is fixed. If it still causes problem then hotplug_cpu_guest_check
introduced by the patch should be disabled until we can log into the
guest OS reliably.
On Wed, Mar 28, 2018 at 9:23 AM, Milan Zamazal
<mzamazal(a)redhat.com> wrote:
> Milan Zamazal <mzamazal(a)redhat.com> writes:
>
> > Dafna Ron <dron(a)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.
>
> BTW I think the primary cause of the trouble are the infamous Cirros
> networking recovery problems.
>
3:34 p.m.
Milan Zamazal <mzamazal(a)redhat.com> writes:
Dafna Ron <dron(a)redhat.com> writes:
> Can you post the fix that you added on the mail?
I split hotplug_cpu test in https://gerrit.ovirt.org/89551
After some thought, I have a different fix:
https://gerrit.ovirt.org/89589
This one checks whether ssh (and not only network) is available after
resume and if not then it reboots the VM as if network wasn't available.
We'll see whether it is actually useful once the disk_operations
failure
is fixed. If it still causes problem then hotplug_cpu_guest_check
introduced by the patch should be disabled until we can log into the
guest OS reliably.
> On Wed, Mar 28, 2018 at 9:23 AM, Milan Zamazal <mzamazal(a)redhat.com> wrote:
>
>> Milan Zamazal <mzamazal(a)redhat.com> writes:
>>
>> > Dafna Ron <dron(a)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.
>>
>> BTW I think the primary cause of the trouble are the infamous Cirros
>> networking recovery problems.
>>
2426
days inactive
2429
days old
5 comments
2 participants
participants (2)
-
Dafna Ron -
Milan Zamazal