12:26 p.m.
Hi,
I have been seeing random failures of tests in different projects caused by
vdsm monitoring.
I need someone from vdsm to please help debug this issue.
From what I can see, the test suspend/resume vm failed because we could not
query the status of the vm on the host.
you can see full log from failed tests here:
https://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/10208/arti...
Here are the errors that I can see in the vdsm which seem to suggest that
there is an issue getting stats on the vm which was suspended and caused
the failure of the test:
2018-09-11 00:40:05,896-0400 INFO (monitor/c1fe6e6)
[storage.StorageDomain] Removing remnants of deleted images [] (fileSD:734)
2018-09-11 00:40:07,957-0400 DEBUG (qgapoller/1) [vds] Not sending QEMU-GA
command 'guest-get-users' to
vm_id='8214433a-f233-4aaa-aeda-2ce1d31c78dc',
command is not supported (qemuguestagent:192)
2018-09-11 00:40:08,068-0400 DEBUG (periodic/3)
[virt.sampling.VMBulkstatsMonitor] sampled timestamp 4296118.49 elapsed
0.010 acquired True domains all (sampling:443)
2018-09-11 00:40:08,271-0400 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer]
Calling 'Image.prepare' in bridge with {u'allowIllegal': True,
u'storagepoolID': u'e80a56d9-74da-498a-b010-4a9df287f11d',
u'imageID':
u'd4c831e6-02d2-4d89-b516-0ec4597
5e024', u'volumeID': u'15b07af1-625b-42e3-b62a-8e7c7a120a56',
u'storagedomainID': u'f1744940-41b6-4d35-b7bf-870c4e07d995'}
(__init__:329)
2018-09-11 00:40:10,846-0400 DEBUG (vmchannels) [virt.vm]
(vmId='8214433a-f233-4aaa-aeda-2ce1d31c78dc') Guest connection timed out
(guestagent:556)
2018-09-11 00:40:11,637-0400 DEBUG (jsonrpc/5) [jsonrpc.JsonRpcServer]
Calling 'Host.getStats' in bridge with {} (__init__:329)
2018-09-11 00:40:11,637-0400 INFO (jsonrpc/5) [api.host] START getStats()
from=::ffff:192.168.201.4,49184 (api:47)
2018-09-11 00:40:11,643-0400 DEBUG (jsonrpc/5) [root] cannot read eth0
speed (nic:42)
2018-09-11 00:40:11,645-0400 DEBUG (jsonrpc/5) [root] cannot read eth1
speed (nic:42)
2018-09-11 00:40:11,647-0400 DEBUG (jsonrpc/5) [root] cannot read eth2
speed (nic:42)
2018-09-11 00:40:11,649-0400 DEBUG (jsonrpc/5) [root] cannot read eth3
speed (nic:42)
2018-09-11 00:40:11,667-0400 INFO (jsonrpc/5) [api.host] FINISH getStats
error=[Errno 22] Invalid argument from=::ffff:192.168.201.4,49184 (api:51)
2018-09-11 00:40:11,667-0400 ERROR (jsonrpc/5) [jsonrpc.JsonRpcServer]
Internal server error (__init__:350)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 345,
in _handle_request
res = method(**params)
File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 202, in
_dynamicMethod
result = fn(*methodArgs)
File "<string>", line 2, in getStats
File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 49, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 1407, in
getStats
multipath=True)}
File "/usr/lib/python2.7/site-packages/vdsm/host/api.py", line 49, in
get_stats
decStats = stats.produce(first_sample, last_sample)
File "/usr/lib/python2.7/site-packages/vdsm/host/stats.py", line 71, in
produce
stats.update(get_interfaces_stats())
File "/usr/lib/python2.7/site-packages/vdsm/host/stats.py", line 153, in
get_interfaces_stats
return net_api.network_stats()
File "/usr/lib/python2.7/site-packages/vdsm/network/api.py", line 63, in
network_stats
return netstats.report()
File "/usr/lib/python2.7/site-packages/vdsm/network/netstats.py", line
31, in report
stats = link_stats.report()
File "/usr/lib/python2.7/site-packages/vdsm/network/link/stats.py", line
41, in report
speed = vlan.speed(i.device)
File "/usr/lib/python2.7/site-packages/vdsm/network/link/vlan.py", line
36, in speed
dev_speed = nic.read_speed_using_sysfs(dev_name)
File "/usr/lib/python2.7/site-packages/vdsm/network/link/nic.py", line
48, in read_speed_using_sysfs
s = int(f.read())
IOError: [Errno 22] Invalid argument
2018-09-11 00:40:11,669-0400 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC
call Host.getStats failed (error -32603) in 0.03 seconds (__init__:312)
2018-09-11 00:40:14,656-0400 DEBUG (jsonrpc/2) [jsonrpc.JsonRpcServer]
Calling 'Host.getAllVmStats' in bridge with {} (__init__:329)
2018-09-11 00:40:14,657-0400 INFO (jsonrpc/2) [api.host] START
getAllVmStats() from=::1,46772 (api:47)
2018-09-11 00:40:14,659-0400 INFO (jsonrpc/2) [api.host] FINISH
getAllVmStats return={'status': {'message': 'Done',
'code': 0},
'statsList': (suppressed)} from=::1,46772 (api:53)
2018-09-11 00:40:14,660-0400 DEBUG (jsonrpc/2) [jsonrpc.JsonRpcServer]
Return 'Host.getAllVmStats' in bridge with (suppressed) (__init__:356)
2018-09-11 00:40:14,661-0400 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC
call Host.getAllVmStats succeeded in 0.00 seconds (__init__:312)
2018-09-11 00:40:14,674-0400 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer]
Calling 'Host.getAllVmIoTunePolicies' in bridge with {} (__init__:329)
2018-09-11 00:40:14,675-0400 INFO (jsonrpc/1) [api.host] START
getAllVmIoTunePolicies() from=::1,46772 (api:47)
2018-09-11 00:40:14,675-0400 INFO (jsonrpc/1) [api.host] FINISH
getAllVmIoTunePolicies return={'status': {'message': 'Done',
'code': 0},
'io_tune_policies_dict': {'8214433a-f233-4aaa-aeda-2ce1d31c78dc':
{'policy': [], 'current_values': [{'ioTune':
{'write_bytes_sec': 0L,
'total_iops_sec': 0L, 'read_iops_sec': 0L, 'read_bytes_sec': 0L,
'write_iops_sec': 0L, 'total_bytes_sec': 0L}, 'path':
'/rhev/data-center/mnt/blockSD/f1744940-41b6-4d35-b7bf-870c4e07d995/images/9a3659dc-339e-4b3f-a1d1-6ee3debb6168/e2570635-a798-4e9e-a0ea-88436d5b296f',
'name': 'vda'}]}}} from=::1,46772 (api:53)
2018-09-11 00:40:14,675-0400 DEBUG (jsonrpc/1) [jsonrpc.JsonRpcServer]
Return 'Host.getAllVmIoTunePolicies' in bridge with
{'8214433a-f233-4aaa-aeda-2ce1d31c78dc': {'policy': [],
'current_values':
[{'ioTune': {'write_bytes_sec': 0L, 'total_iops_sec': 0L,
'read_iops_sec':
0L, 'read_bytes_sec': 0L, 'write_iops_sec': 0L, 'total_bytes_sec':
0L},
'path':
'/rhev/data-center/mnt/blockSD/f1744940-41b6-4d35-b7bf-870c4e07d995/images/9a3659dc-339e-4b3f-a1d1-6ee3debb6168/e2570635-a798-4e9e-a0ea-88436d5b296f',
'name': 'vda'}]}} (__init__:356)
2018-09-11 00:40:14,675-0400 INFO (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC
call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:312)
2018-09-11 00:40:16,118-0400 DEBUG (jsonrpc/7) [jsonrpc.JsonRpcServer]
Calling 'Host.getAllVmStats' in bridge with {} (__init__:329)
2018-09-11 00:40:16,119-0400 INFO (jsonrpc/7) [api.host] START
getAllVmStats() from=::ffff:192.168.201.4,49184 (api:47)
2018-09-11 00:40:16,121-0400 INFO (jsonrpc/7) [api.host] FINISH
getAllVmStats return={'status': {'message': 'Done',
'code': 0},
'statsList': (suppressed)} from=::ffff:192.168.201.4,49184 (api:53)
2018-09-11 00:40:16,122-0400 DEBUG (jsonrpc/7) [jsonrpc.JsonRpcServer]
Return 'Host.getAllVmStats' in bridge with (suppressed) (__init__:356)
2018-09-11 00:40:16,122-0400 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC
call Host.getAllVmStats succeeded in 0.01 seconds (__init__:312)
2018-09-11 00:40:17,956-0400 DEBUG (qgapoller/2) [vds] Not sending QEMU-GA
command 'guest-get-users' to
vm_id='8214433a-f233-4aaa-aeda-2ce1d31c78dc',
command is not supported (qemuguestagent:192)
2018-09-11 00:40:18,025-0400 DEBUG (periodic/3) [virt.periodic] Looking for
stale paused VMs (periodic:388)
I can also see this in Super vdsm which may be related but I an not 100%
sure its related to current issue:
MainProcess|jsonrpc/2::DEBUG::2018-09-11
00:33:20,012::cmdutils::159::root::(exec_cmd) SUCCESS: <err> = '';
<rc> = 0
ifup/on039d2d88d8ee4::DEBUG::2018-09-11
00:33:20,238::cmdutils::159::root::(exec_cmd) FAILED: <err> = 'Running
scope as unit
2f1f417d-85b9-46c0-b7d7-6082836daaae.scope.\n/etc/sysconfig/network-scripts/ifup-eth:
line 321: 20715 Terminated
/sbin/dhclient ${DHCLIENTARGS} ${DEVICE}\nDevice
"on039d2d88d8ee4" does not exist.\nCannot find device
"on039d2d88d8ee4"\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d
8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevic
e "on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does
not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d
8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevic
e "on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does
not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d
8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevic
e "on039d2d88d8ee4" does not exist.\nDevice "on039d2d88d8ee4" does
not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4" does not
exist.\nDevice "on039d2d88d8ee4" does not exist.\nDevice
"on039d2d88d8ee4"
does not exist.\nDevice "on039d2d88d8ee4" does not exist.\n'; <rc> =
1
ifup/on039d2d88d8ee4::ERROR::2018-09-11
00:33:20,238::concurrent::202::root::(run) FINISH thread
<Thread(ifup/on039d2d88d8ee4, stopped daemon 140281550731008)> failed
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/common/concurrent.py", line
195, in run
ret = func(*args, **kwargs)
File
"/usr/lib/python2.7/site-packages/vdsm/network/configurators/ifcfg.py",
line 948, in _exec_ifup
_exec_ifup_by_name(iface.name, cgroup)
File
"/usr/lib/python2.7/site-packages/vdsm/network/configurators/ifcfg.py",
line 934, in _exec_ifup_by_name
raise ConfigNetworkError(ERR_FAILED_IFUP, out[-1] if out else '')
ConfigNetworkError: (29, '\n')
thanks,
Dafna