ofono_client: Implement network registration during connect()

A new mcc_mnc parameter is now optionally passed to connect() in order
to manually register to a specific network with a given MCC+MNC pair.
If no parameter is passed (or None), then the modem will be instructed
to attempt an automatic registration with any available network which
permits it.

We get the MCC+MNC parameter from the MSC/NITB and we pass it to the
modem object at connect time as shown in the modified tests. Two new
simple tests to check network registration is working are added in this
commit.

Ofono modems seem to be automatically registering at some point after
they are set Online=true, and we were actually using that 'feature'
before this patch. Thus, it is possible that a modem quickly becomes
registered, and we then check so before starting the scan+registration
process, which can take a few seconds.

The scanning method can take a few seconds to complete. To avoid
blocking in the dbus ofono Scan() method, this commit adds some code to
make use of glib/gdbus async methods, which are not yet supported
directly by pydbus. This way, we can continue polling while waiting for
the scan process to complete and we can register several modems in
parallel. When scan completes, a callback is run which attempts to
register. If no MCC+MNC was passed, as we just finished scanning the
modem should have enough fresh operator information to take good and
quick decisions on where to connect. If we have an MCC+MNC, then we check
the operator list received by Scan() method. If operator with desired
MCC+MNC is there, we register with it. If it's not there, we start
scanning() again asynchronously hoping the operator will show up in next
scan.

As scanning() and registration is done in the background, tests are
expected to call connect(), and then later on wait for the modem to
register by waiting/polling the method "modem.is_connected()". Tests
first check for the modem being connected and after with MSC
subscriber_attached(). The order is intentional because the later has to
poll through network and adds unneeded garbage to the pcap files bein
recorded.

Change-Id: I8d9eb47eac1044550d3885adb55105c304b0c15c

src/osmo_gsm_tester/ofono_client.py

@@ -22,6 +22,7 @@ from . import log, test, util, event_loop, sms
 from pydbus import SystemBus, Variant
 import time
 import pprint
+import sys
 
 from gi.repository import GLib
 glib_main_loop = GLib.MainLoop()
@@ -32,6 +33,12 @@ I_MODEM = 'org.ofono.Modem'
 I_NETREG = 'org.ofono.NetworkRegistration'
 I_SMS = 'org.ofono.MessageManager'
 
+# See https://github.com/intgr/ofono/blob/master/doc/network-api.txt#L78
+NETREG_ST_REGISTERED = 'registered'
+NETREG_ST_ROAMING = 'roaming'
+
+NETREG_MAX_REGISTER_ATTEMPTS = 3
+
 class DeferredHandling:
     defer_queue = []
 
@@ -48,6 +55,9 @@ class DeferredHandling:
             handler, args, kwargs = DeferredHandling.defer_queue.pop(0)
             handler(*args, **kwargs)
 
+def defer(handler, *args, **kwargs):
+    DeferredHandling.defer_queue.append((handler, args, kwargs))
+
 def dbus_connect(dbus_iface, handler):
     '''This function shall be used instead of directly connecting DBus signals.
     It ensures that we don't nest a glib main loop within another, and also
@@ -73,6 +83,53 @@ def list_modems():
     root = systembus_get('/')
     return sorted(root.GetModems())
 
+def _async_result_handler(obj, result, user_data):
+    '''Generic callback dispatcher called from glib loop when an async method
+    call has returned. This callback is set up by method dbus_async_call.'''
+    (result_callback, error_callback, real_user_data) = user_data
+    try:
+        ret = obj.call_finish(result)
+    except Exception as e:
+        # return exception as value
+        if error_callback:
+            error_callback(obj, e, real_user_data)
+        else:
+            result_callback(obj, e, real_user_data)
+        return
+
+    ret = ret.unpack()
+    # to be compatible with standard Python behaviour, unbox
+    # single-element tuples and return None for empty result tuples
+    if len(ret) == 1:
+        ret = ret[0]
+    elif len(ret) == 0:
+        ret = None
+    result_callback(obj, ret, real_user_data)
+
+def dbus_async_call(instance, proxymethod, *proxymethod_args,
+                    result_handler=None, error_handler=None,
+                    user_data=None, timeout=30,
+                    **proxymethod_kwargs):
+    '''pydbus doesn't support asynchronous methods. This method adds support for
+    it until pydbus implements it'''
+
+    argdiff = len(proxymethod_args) - len(proxymethod._inargs)
+    if argdiff < 0:
+        raise TypeError(proxymethod.__qualname__ + " missing {} required positional argument(s)".format(-argdiff))
+    elif argdiff > 0:
+        raise TypeError(proxymethod.__qualname__ + " takes {} positional argument(s) but {} was/were given".format(len(proxymethod._inargs), len(proxymethod_args)))
+
+    timeout = timeout * 1000
+    user_data = (result_handler, error_handler, user_data)
+
+    ret = instance._bus.con.call(
+        instance._bus_name, instance._path,
+        proxymethod._iface_name, proxymethod.__name__,
+        GLib.Variant(proxymethod._sinargs, proxymethod_args),
+        GLib.VariantType.new(proxymethod._soutargs),
+        0, timeout, None,
+        _async_result_handler, user_data)
+
 class ModemDbusInteraction(log.Origin):
     '''Work around inconveniences specific to pydbus and ofono.
     ofono adds and removes DBus interfaces and notifies about them.
@@ -257,6 +314,7 @@ class Modem(log.Origin):
         self.set_log_category(log.C_TST)
         self.sms_received_list = []
         self.dbus = ModemDbusInteraction(self.path)
+        self.register_attempts = 0
         self.dbus.required_signals = {
                 I_SMS: ( ('IncomingMessage', self._on_incoming_message), ),
                 I_NETREG: ( ('PropertyChanged', self._on_netreg_property_changed), ),
@@ -323,18 +381,95 @@ class Modem(log.Origin):
     def _on_netreg_property_changed(self, name, value):
         self.dbg('%r.PropertyChanged() -> %s=%s' % (I_NETREG, name, value))
 
-    def connect(self, nitb):
-        'set the modem up to connect to MCC+MNC from NITB config'
-        self.log('connect to', nitb)
+    def is_connected(self, mcc_mnc=None):
+        netreg = self.dbus.interface(I_NETREG)
+        prop = netreg.GetProperties()
+        status = prop.get('Status')
+        if not (status == NETREG_ST_REGISTERED or status == NETREG_ST_ROAMING):
+            return False
+        if mcc_mnc is None: # Any network is fine and we are registered.
+            return True
+        mcc = prop.get('MobileCountryCode')
+        mnc = prop.get('MobileNetworkCode')
+        if (mcc, mnc) == mcc_mnc:
+            return True
+        return False
+
+    def schedule_scan_register(self, mcc_mnc):
+        if self.register_attempts > NETREG_MAX_REGISTER_ATTEMPTS:
+            self.raise_exn('Failed to find Network Operator', mcc_mnc=mcc_mnc, attempts=self.register_attempts)
+        self.register_attempts += 1
+        netreg = self.dbus.interface(I_NETREG)
+        self.dbg('Scanning for operators...')
+        # Scan method can take several seconds, and we don't want to block
+        # waiting for that. Make it async and try to register when the scan is
+        # finished.
+        register_func = self.scan_cb_register_automatic if mcc_mnc is None else self.scan_cb_register
+        result_handler = lambda obj, result, user_data: defer(register_func, result, user_data)
+        error_handler = lambda obj, e, user_data: defer(self.raise_exn, 'Scan() failed:', e)
+        dbus_async_call(netreg, netreg.Scan, timeout=30, result_handler=result_handler,
+                        error_handler=error_handler, user_data=mcc_mnc)
+
+    def scan_cb_register_automatic(self, scanned_operators, mcc_mnc):
+        self.dbg('scanned operators: ', scanned_operators);
+        for op_path, op_prop in scanned_operators:
+            if op_prop.get('Status') == 'current':
+                mcc = op_prop.get('MobileCountryCode')
+                mnc = op_prop.get('MobileNetworkCode')
+                self.log('Already registered with network', (mcc, mnc))
+                return
+        self.log('Registering with the default network')
+        netreg = self.dbus.interface(I_NETREG)
+        netreg.Register()
+
+    def scan_cb_register(self, scanned_operators, mcc_mnc):
+        self.dbg('scanned operators: ', scanned_operators);
+        matching_op_path = None
+        for op_path, op_prop in scanned_operators:
+            mcc = op_prop.get('MobileCountryCode')
+            mnc = op_prop.get('MobileNetworkCode')
+            if (mcc, mnc) == mcc_mnc:
+                if op_prop.get('Status') == 'current':
+                    self.log('Already registered with network', mcc_mnc)
+                    # We discovered the network and we are already registered
+                    # with it. Avoid calling op.Register() in this case (it
+                    # won't act as a NO-OP, it actually returns an error).
+                    return
+                matching_op_path = op_path
+                break
+        if matching_op_path is None:
+            self.dbg('Failed to find Network Operator', mcc_mnc=mcc_mnc, attempts=self.register_attempts)
+            self.schedule_scan_register(mcc_mnc)
+            return
+        dbus_op = systembus_get(matching_op_path)
+        self.log('Registering with operator', matching_op_path, mcc_mnc)
+        dbus_op.Register()
+
+    def power_cycle(self):
+        'Power the modem and put it online, power cycle it if it was already on'
         if self.is_powered():
-            self.dbg('is powered')
+            self.dbg('Power cycling')
             self.set_online(False)
             self.set_powered(False)
             event_loop.wait(self, lambda: not self.dbus.has_interface(I_NETREG, I_SMS), timeout=10)
+        else:
+            self.dbg('Powering on')
         self.set_powered()
         self.set_online()
         event_loop.wait(self, self.dbus.has_interface, I_NETREG, I_SMS, timeout=10)
 
+    def connect(self, mcc_mnc=None):
+        'Connect to MCC+MNC'
+        if (mcc_mnc is not None) and (len(mcc_mnc) != 2 or None in mcc_mnc):
+            self.raise_exn('mcc_mnc value is invalid. It should be None or contain both valid mcc and mnc values:', mcc_mnc=mcc_mnc)
+        self.power_cycle()
+        self.register_attempts = 0
+        if self.is_connected(mcc_mnc):
+            self.log('Already registered with', mcc_mnc if mcc_mnc else 'default network')
+        else:
+            self.log('Connect to', mcc_mnc if mcc_mnc else 'default network')
+            self.schedule_scan_register(mcc_mnc)
+
     def sms_send(self, to_msisdn_or_modem, *tokens):
         if isinstance(to_msisdn_or_modem, Modem):
             to_msisdn = to_msisdn_or_modem.msisdn

src/osmo_gsm_tester/osmo_msc.py

@@ -29,6 +29,7 @@ class OsmoMsc(log.Origin):
     config_file = None
     process = None
     hlr = None
+    config = None
 
     def __init__(self, suite_run, hlr, mgcpgw, ip_address):
         self.suite_run = suite_run
@@ -73,6 +74,7 @@ class OsmoMsc(log.Origin):
         config.overlay(values, dict(msc=dict(ip_address=self.ip_address)))
         config.overlay(values, self.mgcpgw.conf_for_msc())
         config.overlay(values, self.hlr.conf_for_msc())
+        self.config = values
 
         self.dbg('MSC CONFIG:\n' + pprint.pformat(values))
 
@@ -84,6 +86,15 @@ class OsmoMsc(log.Origin):
     def addr(self):
         return self.ip_address.get('addr')
 
+    def mcc(self):
+        return self.config['msc']['net']['mcc']
+
+    def mnc(self):
+        return self.config['msc']['net']['mnc']
+
+    def mcc_mnc(self):
+        return (self.mcc(), self.mnc())
+
     def subscriber_attached(self, *modems):
         return self.imsi_attached(*[m.imsi() for m in modems])
 

src/osmo_gsm_tester/osmo_nitb.py

@@ -76,6 +76,7 @@ class OsmoNitb(log.Origin):
         for bts in self.bts:
             bts_list.append(bts.conf_for_bsc())
         config.overlay(values, dict(nitb=dict(net=dict(bts_list=bts_list))))
+        self.config = values
 
         self.dbg('NITB CONFIG:\n' + pprint.pformat(values))
 
@@ -91,6 +92,15 @@ class OsmoNitb(log.Origin):
         self.bts.append(bts)
         bts.set_bsc(self)
 
+    def mcc(self):
+        return self.config['nitb']['net']['mcc']
+
+    def mnc(self):
+        return self.config['nitb']['net']['mnc']
+
+    def mcc_mnc(self):
+        return (self.mcc(), self.mnc())
+
     def subscriber_add(self, modem, msisdn=None):
         if msisdn is None:
             msisdn = self.suite_run.resources_pool.next_msisdn(modem)

suites/aoip_debug/interactive.py

@@ -18,7 +18,7 @@ bts.start()
 
 for m in modems:
   hlr.subscriber_add(m)
-  m.connect(bsc)
+  m.connect(msc.mcc_mnc())
 
 while True:
   cmd = prompt('Enter command: (q)uit (s)ms (g)et-registered (w)ait-registered')
@@ -30,6 +30,8 @@ while True:
     break
   elif 'wait-registered'.startswith(cmd):
     try:
+      for m in modems:
+          wait(m.is_connected, msc.mcc_mnc())
       wait(msc.subscriber_attached, *modems)
     except Timeout:
       print('Timeout while waiting for registration.')

suites/aoip_sms/mo_mt_sms.py

@@ -21,13 +21,15 @@ bts.start()
 hlr.subscriber_add(ms_mo)
 hlr.subscriber_add(ms_mt)
 
-ms_mo.connect(bsc)
-ms_mt.connect(bsc)
+ms_mo.connect(msc.mcc_mnc())
+ms_mt.connect(msc.mcc_mnc())
 
 ms_mo.log_info()
 ms_mt.log_info()
 
 print('waiting for modems to attach...')
+wait(ms_mo.is_connected, msc.mcc_mnc())
+wait(ms_mt.is_connected, msc.mcc_mnc())
 wait(msc.subscriber_attached, ms_mo, ms_mt)
 
 sms = ms_mo.sms_send(ms_mt)

suites/debug/interactive.py

@@ -13,7 +13,7 @@ bts.start()
 
 for m in modems:
   nitb.subscriber_add(m)
-  m.connect(nitb)
+  m.connect(nitb.mcc_mnc())
 
 while True:
   cmd = prompt('Enter command: (q)uit (s)ms (g)et-registered (w)ait-registered')
@@ -25,6 +25,8 @@ while True:
     break
   elif 'wait-registered'.startswith(cmd):
     try:
+      for m in modems:
+         wait(m.is_connected, nitb.mcc_mnc())
       wait(nitb.subscriber_attached, *modems)
     except Timeout:
       print('Timeout while waiting for registration.')

suites/netreg/register.py

@@ -0,0 +1,21 @@
+#!/usr/bin/env python3
+from osmo_gsm_tester.test import *
+
+print('use resources...')
+nitb = suite.nitb()
+bts = suite.bts()
+ms = suite.modem()
+
+print('start nitb and bts...')
+nitb.bts_add(bts)
+nitb.start()
+bts.start()
+
+nitb.subscriber_add(ms)
+
+ms.connect(nitb.mcc_mnc())
+
+print(ms.info())
+
+wait(ms.is_connected, nitb.mcc_mnc())
+wait(nitb.subscriber_attached, ms)

suites/netreg/register_default.py

@@ -0,0 +1,21 @@
+#!/usr/bin/env python3
+from osmo_gsm_tester.test import *
+
+print('use resources...')
+nitb = suite.nitb()
+bts = suite.bts()
+ms = suite.modem()
+
+print('start nitb and bts...')
+nitb.bts_add(bts)
+nitb.start()
+bts.start()
+
+nitb.subscriber_add(ms)
+
+ms.connect()
+
+print(ms.info())
+
+wait(ms.is_connected)
+wait(nitb.subscriber_attached, ms)

suites/netreg/suite.conf

@@ -0,0 +1,10 @@
+resources:
+  ip_address:
+  - times: 1
+  bts:
+  - times: 1
+  modem:
+  - times: 1
+
+defaults:
+  timeout: 40s

suites/sms/mo_mt_sms.py

@@ -14,13 +14,15 @@ bts.start()
 nitb.subscriber_add(ms_mo)
 nitb.subscriber_add(ms_mt)
 
-ms_mo.connect(nitb)
-ms_mt.connect(nitb)
+ms_mo.connect(nitb.mcc_mnc())
+ms_mt.connect(nitb.mcc_mnc())
 
 ms_mo.log_info()
 ms_mt.log_info()
 
 print('waiting for modems to attach...')
+wait(ms_mo.is_connected, nitb.mcc_mnc())
+wait(ms_mt.is_connected, nitb.mcc_mnc())
 wait(nitb.subscriber_attached, ms_mo, ms_mt)
 
 sms = ms_mo.sms_send(ms_mt)