modem: Fix race condition when connect() is called more than once

An issue was spotted recently in tests run in production which call
modem.connect() twice, first time to check that we are unable to connect
with a wrong KI, then that we can connect with the correct KI.

As there's no current easy way to wait for "rejected" signal, we
basically wait for some time before checking if we were unable to
connect. It seems that sometimes waiting for 30 seconds is not enough,
and then a scan() async method is still in progress when we decide to
call connect() again, which will powercycle the modem. If the scan()
method returns at that time, then we try to access interfaces of the
modem which are no longer available because the modem is powered off at
that time. This triggers an exception and test fails.

To correct way to fix this is to make sure we disable pending Scan()
dbus method before powercycling the modem and starting a new Scan()
method.

The sleep time is also increased to make sure we let enough time to
register. It seems it can take about 15 seconds to do a full scan, and
sometimes during first scan iteration the BTS is still not found,
probably because it's still starting.

Related: OS#2510

Change-Id: Ic4bb1c6b72c23cd860c33bee7851bca3d0ac0e1b

src/osmo_gsm_tester/ofono_client.py

@@ -349,10 +349,7 @@ class Modem(log.Origin):
     def cleanup(self):
         self.dbg('cleanup')
         if self.cancellable:
-            self.cancellable.cancel()
-            # Cancel op is applied as a signal coming from glib mainloop, so we
-            # need to run it and wait for the callbacks to handle cancellations.
-            poll_glib()
+            self.cancel_pending_dbus_methods()
             self.cancellable = None
         self.dbus.cleanup()
         self.dbus = None
@@ -500,6 +497,12 @@ class Modem(log.Origin):
         self.log('Registering with operator', matching_op_path, mcc_mnc)
         dbus_call_dismiss_error(self, 'org.ofono.Error.InProgress', dbus_op.Register)
 
+    def cancel_pending_dbus_methods(self):
+        self.cancellable.cancel()
+        # Cancel op is applied as a signal coming from glib mainloop, so we
+        # need to run it and wait for the callbacks to handle cancellations.
+        poll_glib()
+
     def power_cycle(self):
         'Power the modem and put it online, power cycle it if it was already on'
         if self.is_powered():
@@ -517,6 +520,8 @@ class Modem(log.Origin):
         'Connect to MCC+MNC'
         if (mcc_mnc is not None) and (len(mcc_mnc) != 2 or None in mcc_mnc):
             raise log.Error('mcc_mnc value is invalid. It should be None or contain both valid mcc and mnc values:', mcc_mnc=mcc_mnc)
+        # if test called connect() before and async scanning has not finished, we need to get rid of it:
+        self.cancel_pending_dbus_methods()
         self.power_cycle()
         self.register_attempts = 0
         if self.is_connected(mcc_mnc):

suites/aoip_encryption/register_a5_0_authreq.py

@@ -31,7 +31,7 @@ hlr.subscriber_add(ms)
 print('Attempt connection with wrong KI...')
 ms.connect(msc.mcc_mnc())
 
-sleep(30) # TODO: read pcap or CTRL interface and look for Rejected? (gsm_a.dtap.msg_mm_type == 0x04)
+sleep(40) # TODO: read pcap or CTRL interface and look for Rejected? (gsm_a.dtap.msg_mm_type == 0x04)
 print('Asserting modem did not register')
 # FIXME: this can fail because ofono qmi signals registered before being accepted by network. See OS#2458
 # assert not ms.is_connected(msc.mcc_mnc())

suites/aoip_encryption/register_a5_1_authreq.py

@@ -31,7 +31,7 @@ hlr.subscriber_add(ms)
 print('Attempt connection with wrong KI...')
 ms.connect(msc.mcc_mnc())
 
-sleep(30) # TODO: read pcap or CTRL interface and look for Rejected? (gsm_a.dtap.msg_mm_type == 0x04)
+sleep(40) # TODO: read pcap or CTRL interface and look for Rejected? (gsm_a.dtap.msg_mm_type == 0x04)
 print('Asserting modem did not register')
 # FIXME: this can fail because ofono qmi signals registered before being accepted by network. See OS#2458
 # assert not ms.is_connected(msc.mcc_mnc())