On Thu, Aug 9, 2018 at 11:09 PM Nir Soffer <nsoffer@redhat.com> wrote:
We did not update the Fedora rawhide for few month since a package
was missing. Now that this issue was solved, we have new errors,


1. async is a keywoard in python 3.7


Compiling './tests/storage/fakesanlock.py'...
*** File "./tests/storage/fakesanlock.py", line 65
async=False):
^
SyntaxError: invalid syntax

We have many of these. The issue is sanlock api uses the kwarg "async", and
python 3.7 made this invalid syntax.

$ ./python
Python 3.7.0+ (heads/3.7:426135b674, Aug  9 2018, 22:50:16) 
[GCC 8.1.1 20180712 (Red Hat 8.1.1-5)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> def foo(async=False):
  File "<stdin>", line 1
    def foo(async=False):
                ^
SyntaxError: invalid syntax
>>> async = True
  File "<stdin>", line 1
    async = True
          ^
SyntaxError: invalid syntax

Thank you python developers for making our life more interesting :-)

So we will have to change sanlock python binding to replace "async"
with something else.

I'll file sanlock bug for this.


2. test_sourceroute_add_remove_and_read fails

No idea why it fails, hopefully Dan or Edward have a clue.


FAIL: test_sourceroute_add_remove_and_read (network.sourceroute_test.TestSourceRoute)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/vdsm/tests/testValidation.py", line 193, in wrapper
return f(*args, **kwargs)
File "/vdsm/tests/network/sourceroute_test.py", line 80, in test_sourceroute_add_remove_and_read
self.assertEqual(2, len(routes), routes)
AssertionError: 2 != 0
-------------------- >> begin captured logging << --------------------
2018-08-09 19:36:31,446 DEBUG (MainThread) [root] /sbin/ip link add name dummy_UTpMy type dummy (cwd None) (cmdutils:151)
2018-08-09 19:36:31,455 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,456 DEBUG (netlink/events) [root] START thread <Thread(netlink/events, started daemon 140332374083328)> (func=<bound method Monitor._scan of <vdsm.network.netlink.monitor.Monitor object at 0x7fa1b18dc6d0>>, args=(), kwargs={}) (concurrent:193)
2018-08-09 19:36:31,456 DEBUG (MainThread) [root] /sbin/ip link set dev dummy_UTpMy up (cwd None) (cmdutils:151)
2018-08-09 19:36:31,463 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,464 DEBUG (netlink/events) [root] FINISH thread <Thread(netlink/events, started daemon 140332374083328)> (concurrent:196)
2018-08-09 19:36:31,471 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,471 DEBUG (MainThread) [root] Adding source route for device dummy_UTpMy (sourceroute:195)
2018-08-09 19:36:31,472 DEBUG (MainThread) [root] /sbin/ip -4 route add 0.0.0.0/0 via 192.168.99.2 dev dummy_UTpMy table 3232260865 (cwd None) (cmdutils:151)
2018-08-09 19:36:31,478 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,479 DEBUG (MainThread) [root] /sbin/ip -4 route add 192.168.99.0/29 via 192.168.99.1 dev dummy_UTpMy table 3232260865 (cwd None) (cmdutils:151)
2018-08-09 19:36:31,485 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,485 DEBUG (MainThread) [root] /sbin/ip rule add from 192.168.99.0/29 prio 32000 table 3232260865 (cwd None) (cmdutils:151)
2018-08-09 19:36:31,492 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,492 DEBUG (MainThread) [root] /sbin/ip rule add from all to 192.168.99.0/29 dev dummy_UTpMy prio 32000 table 3232260865 (cwd None) (cmdutils:151)
2018-08-09 19:36:31,498 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,499 DEBUG (MainThread) [root] /sbin/ip rule (cwd None) (cmdutils:151)
2018-08-09 19:36:31,505 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,505 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_d3SHQ [detached] lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,505 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_d3SHQ [detached] lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,505 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_UTpMy lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,506 DEBUG (MainThread) [root] /sbin/ip rule (cwd None) (cmdutils:151)
2018-08-09 19:36:31,512 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)
2018-08-09 19:36:31,512 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_d3SHQ [detached] lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,512 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_d3SHQ [detached] lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,513 WARNING (MainThread) [root] Could not parse rule 32000: from all to 192.168.99.0 /29 iif dummy_UTpMy lookup 3232260865 (iproute2:60)
2018-08-09 19:36:31,513 DEBUG (MainThread) [root] Removing source route for device dummy_UTpMy (sourceroute:215)
2018-08-09 19:36:31,513 DEBUG (MainThread) [root] /sbin/ip link del dev dummy_UTpMy (cwd None) (cmdutils:151)
2018-08-09 19:36:31,532 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (cmdutils:159)

3. qemu-io returns now non-zero code on failures, breaking our tests

This command use to return 0 on failures, and the only way to detect failures was
to check the output. Now it was fixed to return non-zero code, and this breaks our
tests.

I think this should be an easy fix.

Here is an example:


1m
_____________________________ test_no_match[qcow2] _____________________________
tmpdir = local('/var/tmp/vdsm/test_no_match_qcow2_0'), image_format = 'qcow2'
def test_no_match(tmpdir, image_format):
path = str(tmpdir.join('test.' + image_format))
op = qemuimg.create(path, '1m', image_format)
op.run()
qemuio.write_pattern(path, image_format, pattern=2)
with pytest.raises(qemuio.VerificationError):
> qemuio.verify_pattern(path, image_format, pattern=4)
storage/qemuio_test.py:59:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
path = '/var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2', format = 'qcow2'
offset = 512, len = 1024, pattern = 4
def verify_pattern(path, format, offset=512, len=1024, pattern=5):
read_cmd = 'read -P %d -s 0 -l %d %d %d' % (pattern, len, offset, len)
cmd = ['qemu-io', '-f', format, '-c', read_cmd, path]
rc, out, err = commands.execCmd(cmd, raw=True)
if rc != 0 or err != b"":
> raise cmdutils.Error(cmd, rc, out, err)
E Error: Command ['qemu-io', '-f', 'qcow2', '-c', 'read -P 4 -s 0 -l 1024 512 1024', '/var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2'] failed with rc=1 out='Pattern verification failed at offset 512, 1024 bytes\nread 1024/1024 bytes at offset 512\n1 KiB, 1 ops; 0.0001 sec (7.570 MiB/sec and 7751.9380 ops/sec)\n' err=''
storage/qemuio.py:50: Error
----------------------------- Captured stderr call -----------------------------
2018-08-09 19:37:32,126 DEBUG (MainThread) [storage.operation] /usr/bin/taskset --cpu-list 0-1 /usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/qemu-img create -f qcow2 -o compat=0.10 /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 1m (cwd None) (operation:150)
2018-08-09 19:37:32,148 DEBUG (MainThread) [storage.operation] SUCCESS: <err> = ''; <rc> = 0 (operation:169)
2018-08-09 19:37:32,148 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-1 qemu-io -f qcow2 -c 'write -P 2 512 1024' /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 (cwd None) (commands:66)
2018-08-09 19:37:32,170 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:87)
2018-08-09 19:37:32,171 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-1 qemu-io -f qcow2 -c 'read -P 4 -s 0 -l 1024 512 1024' /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 (cwd None) (commands:66)
2018-08-09 19:37:32,181 DEBUG (MainThread) [root] FAILED: <err> = ''; <rc> = 1 (commands:87)
------------------------------ Captured log call -------------------------------
operation.py 150 DEBUG /usr/bin/taskset --cpu-list 0-1 /usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/qemu-img create -f qcow2 -o compat=0.10 /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 1m (cwd None)
operation.py 169 DEBUG SUCCESS: <err> = ''; <rc> = 0
commands.py 66 DEBUG /usr/bin/taskset --cpu-list 0-1 qemu-io -f qcow2 -c 'write -P 2 512 1024' /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 (cwd None)
commands.py 87 DEBUG SUCCESS: <err> = ''; <rc> = 0
commands.py 66 DEBUG /usr/bin/taskset --cpu-list 0-1 qemu-io -f qcow2 -c 'read -P 4 -s 0 -l 1024 512 1024' /var/tmp/vdsm/test_no_match_qcow2_0/test.qcow2 (cwd None)
commands.py 87 DEBUG FAILED: <err> = ''; <rc> = 1

4. pywatch tests still fail

Looks like our on_fedora() helper is broken, so this test is not marked as xfail.


______________________ TestPyWatch.test_timeout_backtrace ______________________
self = <pywatch_test.TestPyWatch object at 0x7f5cf42899d0>
@pytest.mark.xfail(on_fedora(), reason="py-bt is broken on Fedora 27")
@pytest.mark.xfail(on_ovirt_ci(),
reason="py-bt randomly unavailable on EL7 nodes")
def test_timeout_backtrace(self):
script = '''
import time
def outer():
inner()
def inner():
time.sleep(10)
outer()
'''
rc, out, err = exec_cmd(['./py-watch', '0.1', 'python', '-c', script])
> assert b'in inner ()' in out
E AssertionError: assert 'in inner ()' in '=============================================================\n= Watched process timed out ... Terminating watched process =\n=============================================================\n'
pywatch_test.py:74: AssertionError
------------------------------ Captured log call -------------------------------
cmdutils.py 151 DEBUG ./py-watch 0.1 python -c '
import time
def outer():
inner()
def inner():
time.sleep(10)
outer()
' (cwd None)
cmdutils.py 159 DEBUG FAILED: <err> = '\nwarning: Loadable section ".note.gnu.property" outside of ELF segments\n\nwarning: Loadable section ".note.gnu.property" outside of ELF segments\n'; <rc> = 143

5. ovs tests that pass on Fedora 28 fail on rawhide

Not sure how why the tests pass on Fedora 28 and fail on CentOS and Fedora rawhide.


________ ERROR at setup of TestOvsApiBase.test_execute_a_single_command ________
@pytest.fixture(scope='session', autouse=True)
def ovs_service():
service = OvsService()
with xfail_when_running_on_travis_with_centos():
> service.setup()
network/integration/ovs/conftest.py:37:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <network.ovsnettestlib.OvsService object at 0x7f79737589d0>
def setup(self):
if not self.ovs_init_state_is_up:
cmd.exec_sync([OVS_CTL, '--system-id=random', 'start'])
> assert self.is_service_running()
E AssertionError
network/ovsnettestlib.py:39: AssertionError
------------------------------ Captured log setup ------------------------------
cmdutils.py 151 DEBUG /usr/share/openvswitch/scripts/ovs-ctl status (cwd None)
cmdutils.py 159 DEBUG FAILED: <err> = ''; <rc> = 1
cmdutils.py 151 DEBUG /usr/share/openvswitch/scripts/ovs-ctl --system-id=random start (cwd None)
cmdutils.py 159 DEBUG FAILED: <err> = 'modprobe: FATAL: Module openvswitch not found in directory /lib/modules/4.4.0-104-generic\nrmmod: ERROR: Module bridge is in use by: br_netfilter\n'; <rc> = 1
cmdutils.py 151 DEBUG /usr/share/openvswitch/scripts/ovs-ctl status (cwd None)
cmdutils.py 159 DEBUG FAILED: <err> = ''; <rc> = 1

Otherwise all tests pass, so we are in pretty good shape :-)

Since we don't have a quick way to fix all the issues now, I marked
the rawhide build as allowed failure. Please review:
https://gerrit.ovirt.org/c/93638/

The build is green again:
https://travis-ci.org/nirs/vdsm/builds/414218779

Thanks,
Nir