test: wait for interfaces online

[yuwata]

Prompted by #19811 (comment).

[yuwata]

(I do not check this work or not.)

cc @bluca.

[bluca]

Thanks, looks good in principle, given the failure does not happen often let's see if this helps

[bluca]

SemaphoreCI's unhappy:

======================================================================
ERROR: test_bridge_init (__main__.BridgeTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest-lxc.rk05cu7n/downtmp/build.0dp/src/test/networkd-test.py", line 230, in setUp
    subprocess.check_call([NETWORKD_WAIT_ONLINE, '--timeout=5',
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--timeout=5', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_bridge_port_priority (__main__.BridgeTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest-lxc.rk05cu7n/downtmp/build.0dp/src/test/networkd-test.py", line 230, in setUp
    subprocess.check_call([NETWORKD_WAIT_ONLINE, '--timeout=5',
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--timeout=5', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_bridge_port_property (__main__.BridgeTest)
Test the "[Bridge]" section keys
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest-lxc.rk05cu7n/downtmp/build.0dp/src/test/networkd-test.py", line 230, in setUp
    subprocess.check_call([NETWORKD_WAIT_ONLINE, '--timeout=5',
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--timeout=5', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_coldplug_dhcp_ip4_only (__main__.DnsmasqClientTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest-lxc.rk05cu7n/downtmp/build.0dp/src/test/networkd-test.py", line 477, in test_coldplug_dhcp_ip4_only
    self.do_test(coldplug=True, ipv6=False, dhcp_mode='ipv4',
  File "/tmp/autopkgtest-lxc.rk05cu7n/downtmp/build.0dp/src/test/networkd-test.py", line 392, in do_test
    subprocess.check_call([NETWORKD_WAIT_ONLINE, '--interface',
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'test_eth42', '--timeout=15']' returned non-zero exit status 1.

----------------------------------------------------------------------
Ran 35 tests in 162.406s

FAILED (errors=4, skipped=2)

[yuwata]

Now, semaphore is green. Setting the green label again.

[keszybz]

bionic-s390x: looks possibly related:

Verify link states with Unmanaged= settings, cold-plug. ... ok

======================================================================
ERROR: test_bridge_init (__main__.BridgeTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 233, in setUp
    '--interface', 'port2'])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_bridge_port_priority (__main__.BridgeTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 233, in setUp
    '--interface', 'port2'])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_bridge_port_priority_set_zero (__main__.BridgeTest)
It should be possible to set the bridge port priority to 0
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 233, in setUp
    '--interface', 'port2'])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_bridge_port_property (__main__.BridgeTest)
Test the "[Bridge]" section keys
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 233, in setUp
    '--interface', 'port2'])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'mybridge', '--interface', 'port1', '--interface', 'port2']' returned non-zero exit status 1.

======================================================================
ERROR: test_coldplug_dhcp_ip4_only (__main__.DnsmasqClientTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 478, in test_coldplug_dhcp_ip4_only
    online_timeout=15)
  File "/tmp/autopkgtest.KYHTbl/build.CRU/systemd/test/networkd-test.py", line 393, in do_test
    self.iface, '--timeout=%i' % online_timeout])
  File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/lib/systemd/systemd-networkd-wait-online', '--interface', 'test_eth42', '--timeout=15']' returned non-zero exit status 1.

----------------------------------------------------------------------
Ran 35 tests in 629.189s

FAILED (errors=5, skipped=2)
autopkgtest [11:54:35]: test networkd-test.py: -----------------------]
networkd-test.py     FAIL non-zero exit status 1

About the commit message: please say why the change is done, instead of just linking to an online discussion.

[yuwata]

@bluca How can I get the journal of the failed CI results??

[bluca]

it's documented in the README in the test/ subfolder - get the link from the CI status here, and change log.gz with artifacts.tar.gz
in this case:

https://autopkgtest.ubuntu.com/results/autopkgtest-bionic-upstream-systemd-ci-systemd-ci/bionic/s390x/s/systemd-upstream/20210610_124704_acadd@/artifacts.tar.gz

[yuwata]

@bluca Oh, it is documented!? I did not know that. Thanks!

[yuwata]

Hmm, it does not contain anything about networkd-test.py failure...

[bluca]

Ah yes you are indeed right - that's because we don't collect any info about that test. For the "upstream" suite for example, we explicitly extract the journal files (you can see them in the "artifacts" directory of the tarball".

test/networkd-test.py would need to change to collect what needs to be collected, and copy it to $AUTOPKGTEST_ARTIFACTS if it is set (then it gets collected by autopkgtest automatically, and included in the tarball).

[yuwata]

Hmm, I noticed that the issue can be found only on s390x... So, the issue is not a simple(?) timing issue.

[yuwata]

Hmm,
#19815 -- ok
#19837 -- failed with some infra issue.
#19835 -- failed with networkd-test.py.

Is this a kernel issue??