testCheckpoint takes unreasonably long to fail

[martinpitt]

This rhel-8-2-distropkg test run timed out, due to

1498 not ok 149 testCheckpoint (check_networking_checkpoints.TestNetworking) # duration: 1498 # RETRY due to failure of test harness or framework
1503 not ok 149 testCheckpoint (check_networking_checkpoints.TestNetworking) # duration: 1503 # RETRY due to failure of test harness or framework
1554 not ok 149 testCheckpoint (check_networking_checkpoints.TestNetworking) # duration: 1554 # RETRY due to failure of test harness or framework
1554 not ok 149 testCheckpoint (check_networking_checkpoints.TestNetworking) # duration: 1554 # RETRY due to failure of test harness or framework

I. e. these three retries took 1½ hours. There is clearly a broken test retry loop somewhere.

Traceback (most recent call last):
  File "test/verify/check-networking-checkpoints", line 50, in testCheckpoint
    b.click("#confirm-breaking-change-popup button:contains('Keep connection')")
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 213, in click
    self.mouse(selector + ":not([disabled])", "click", 0, 0, 0)
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 209, in mouse
    self.wait_visible(selector)
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 391, in wait_visible
    self.wait_js_func('ph_is_visible', selector)
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 375, in wait_js_func
    self.wait_js_cond("%s(%s)" % (func, ','.join(map(jsquote, args))))
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 372, in wait_js_cond
    self.raise_cdp_exception("timeout\nwait_js_cond", cond, result["exceptionDetails"], trailer)
  File "/build/cockpit-project/bots/make-checkout-workdir/test/common/testlib.py", line 174, in raise_cdp_exception
    raise Error("%s(%s): %s" % (func, arg, msg))
testlib.Error: timeout
wait_js_cond(ph_is_visible("#confirm-breaking-change-popup button:contains('Keep connection'):not([disabled])")):

[martinpitt]

I can provoke this with this hack:

--- test/verify/check-networking-checkpoints
+++ test/verify/check-networking-checkpoints
@@ -43,6 +43,7 @@ class TestNetworking(NetworkCase):
         b.wait_visible("#network-interface")
 
         # Disconnect
+        m.spawn("sleep 5; systemctl stop NetworkManager", "kill-nm")
         self.wait_onoff(".panel-heading:contains('%s')" % iface, True)
         self.toggle_onoff(".panel-heading:contains('%s')" % iface)

The b.click() timeout actually does happen correctly, but it's the subsequent journalctl call which takes a long time.

The most direct way to catch this is:

--- test/verify/check-example
+++ test/verify/check-example
@@ -36,6 +36,9 @@ class TestExample(MachineCase):
     def testBasic(self):
         self.login_and_go("/system")
 
+    def testNetKaputt(self):
+        self.machine.spawn("sleep 2; ip link set eth0 down", "kill-net")
+        self.assertTrue(False)
 
 class TestPersistentExample(PersistentMachineCase):
 

This also explains why the journal logs in that test are all 0 bytes.

[martinpitt]

Hah, this is a bug in bots, SSHConnection.execute(). Transferring issue.

[martinpitt]

Fixed in #517