Cellular Network Infrastructure » OsmoGSMTester

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.

00:27:52.552034 tst      register_a5_0_authreq.py:31: Attempt connection with wrong KI...  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:31]  [register_a5_0_authreq.py:31]
00:27:52.756576 bus                        /sierra_2: DBG: Powered == False  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:301]
00:27:52.794985 tst                        /sierra_2: DBG: Powering on  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:511]
00:27:52.834668 bus                        /sierra_2: Setting Powered True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:309]
00:27:53.113187 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Powered=True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.156820 bus                        /sierra_2: DBG: Powered == True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:301]
00:27:53.197594 bus                        /sierra_2: DBG: interface enabled: org.ofono.VoiceCallManager  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:53.235296 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=[]  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.273659 bus                        /sierra_2: Setting Online True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:309]
00:27:53.428400 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Manufacturer=Sierra Wireless, Incorporated  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.468348 bus                        /sierra_2: DBG: interface enabled: org.ofono.LocationReporting  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:53.506741 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.546343 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Model=MC7304  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.584741 bus                        /sierra_2: DBG: interface enabled: org.ofono.SimManager  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:53.623136 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.661288 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Online=True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.717267 bus                        /sierra_2: DBG: Online == True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:301]
00:27:53.756811 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Revision=SWI9X15C_05.05.66.00 r29972 CARMD-EV-FRMWR1 2015/10/08 08:36:28  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.794740 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Serial=356853054228053  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:53.832473 bus                        /sierra_2: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == False  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:293]
00:27:54.881681 bus                        /sierra_2: DBG: interface enabled: org.ofono.AllowedAccessPoints  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:54.919593 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:54.957867 bus                        /sierra_2: DBG: interface enabled: org.ofono.RadioSettings  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:54.995576 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['rat', 'sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:55.032707 bus                        /sierra_2: DBG: interface enabled: org.ofono.SupplementaryServices  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:55.069260 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['ussd', 'rat', 'sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:55.106130 bus                        /sierra_2: DBG: interface enabled: org.ofono.ConnectionManager  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:55.142776 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['gprs', 'ussd', 'rat', 'sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:55.180494 bus                        /sierra_2: DBG: interface enabled: org.ofono.NetworkRegistration  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:55.217484 bus                        /sierra_2: DBG: Connecting 1 signals for org.ofono.NetworkRegistration  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:281]
00:27:55.289891 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['net', 'gprs', 'ussd', 'rat', 'sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:55.327149 bus                        /sierra_2: DBG: interface enabled: org.ofono.MessageManager, org.ofono.PushNotification, org.ofono.SmartMessaging  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:241]
00:27:55.364845 bus                        /sierra_2: DBG: Connecting 1 signals for org.ofono.MessageManager  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:281]
00:27:55.425229 bus                        /sierra_2: DBG: 'org.ofono.Modem'.PropertyChanged() -> Features=['sms', 'net', 'gprs', 'ussd', 'rat', 'sim', 'gps']  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:228]
00:27:55.462149 bus                        /sierra_2: DBG: has_interface(org.ofono.NetworkRegistration, org.ofono.MessageManager) == True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:293]
00:27:55.502495 tst                        /sierra_2: DBG: status: searching  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:427]
00:27:55.538413 tst                        /sierra_2: Connect to ('901', '70')  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:525]
00:27:55.574220 tst                        /sierra_2: DBG: Scanning for operators...  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:443]
00:28:10.645179 tst                        /sierra_2: DBG: scanned operators:  [('/sierra_2/operator/26201', {'Name': 'TDG', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '01'}), ('/sierra_2/operator/26202', {'Name': 'Vodafone', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '02'}), ('/sierra_2/operator/26203', {'Name': 'E-Plus', 'Status': 'forbidden', 'Technologies': ['umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '03'})]  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:481]
00:28:10.681842 tst                        /sierra_2: DBG: Failed to find Network Operator {attempts=1, mcc_mnc=('901', '70')}  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:496]
00:28:10.719042 tst                        /sierra_2: DBG: Scanning for operators...  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:443]
00:28:25.909903 tst      register_a5_0_authreq.py:35: Asserting modem did not register  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:35]  [register_a5_0_authreq.py:35]
00:28:26.189733 bus Ctrl(host='10.42.42.4', port=4255): DBG: Connecting  [trial-2820↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:54]
00:28:26.246030 bus Ctrl(host='10.42.42.4', port=4255): DBG: Sending {data='GET 0 subscriber-list-active-v1'}  [trial-2820↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:65]
00:28:26.301963 bus Ctrl(host='10.42.42.4', port=4255): DBG: Receiving {data=b"\x00'\xee\x00GET_REPLY 0 subscriber-list-active-v1 "}  [trial-2820↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:71]
00:28:26.358802 bus Ctrl(host='10.42.42.4', port=4255): DBG: Disconnecting  [trial-2820↪aoip_encryption↪osmo-msc_10.42.42.4↪CTRL(10.42.42.4:4255)↪Ctrl(host='10.42.42.4', port=4255)]  [osmo_ctrl.py:60]
00:28:26.413116 run              osmo-msc_10.42.42.4: DBG: attached: GET_REPLY 0 subscriber-list-active-v1   [trial-2820↪aoip_encryption↪osmo-msc_10.42.42.4]  [osmo_msc.py:124]
00:28:26.468879 run              osmo-hlr_10.42.42.2: Add subscriber {imsi='901700000015252'}  [trial-2820↪aoip_encryption↪osmo-hlr_10.42.42.2]  [osmo_hlr.py:143]
00:28:26.675588 tst      register_a5_0_authreq.py:41: KI changed: FBAB63D06C3F546A16C977CB40E57C68 => EBAB63D06C3F546A16C977CB40E57C68  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:41]  [register_a5_0_authreq.py:41]
00:28:26.960650 run              osmo-hlr_10.42.42.2: Add subscriber {algo=1, imsi='901700000015252', msisdn='19632', subscriber_id=2}  [trial-2820↪aoip_encryption↪osmo-hlr_10.42.42.2]  [osmo_hlr.py:129]
00:28:27.155851 tst      register_a5_0_authreq.py:44: Attempt connection with correct KI...  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:44]  [register_a5_0_authreq.py:44]
00:28:27.465855 bus                        /sierra_2: DBG: Powered == True  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:301]
00:28:27.556294 tst                        /sierra_2: DBG: Power cycling  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:506]
00:28:27.640734 bus                        /sierra_2: Setting Online False  [trial-2820↪aoip_encryption↪/sierra_2↪/sierra_2]  [ofono_client.py:309]
00:28:27.708247 tst                        /sierra_2: DBG: scanned operators:  [('/sierra_2/operator/90170', {'Name': 'osmo-gsm-tester-nitb', 'Status': 'available', 'Technologies': ['gsm'], 'MobileCountryCode': '901', 'MobileNetworkCode': '70'}), ('/sierra_2/operator/26201', {'Name': 'TDG', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '01'}), ('/sierra_2/operator/26202', {'Name': 'Vodafone', 'Status': 'forbidden', 'Technologies': ['gsm', 'umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '02'}), ('/sierra_2/operator/26203', {'Name': 'E-Plus', 'Status': 'forbidden', 'Technologies': ['umts', 'lte'], 'MobileCountryCode': '262', 'MobileNetworkCode': '03'})]  [trial-2820↪aoip_encryption↪/sierra_2]  [ofono_client.py:481]
00:28:27.717117 tst      register_a5_0_authreq.py:45: ERR: KeyError: 'object does not export any interfaces; you might need to pass object path as the 2nd argument for get()'  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:45]  [proxy.py:118: raise KeyError("object does not export any interfaces; you might need to pass object path as the 2nd argument for get()")]
00:28:27.723729 tst      register_a5_0_authreq.py:45: TRACEBACK: Traceback (most recent call last):
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/suite.py", line 105, in run
    self.path)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/util.py", line 282, in run_python_file
    SourceFileLoader(module_name, path).load_module()
  File "<frozen importlib._bootstrap>", line 539, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 1614, in load_module
  File "<frozen importlib._bootstrap>", line 596, in _load_module_shim
  File "<frozen importlib._bootstrap>", line 1220, in load
  File "<frozen importlib._bootstrap>", line 1200, in _load_unlocked
  File "<frozen importlib._bootstrap>", line 1129, in _exec
  File "<frozen importlib._bootstrap>", line 1471, in exec_module
  File "<frozen importlib._bootstrap>", line 321, in _call_with_frames_removed
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/suites/aoip_encryption/register_a5_0_authreq.py", line 45, in <module>
    ms.connect(msc.mcc_mnc())
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 520, in connect
    self.power_cycle()
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 507, in power_cycle
    self.set_online(False)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 392, in set_online
    return self.dbus.set_online(online=online)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 318, in set_online
    self.set_bool('Online', online)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 312, in set_bool
    event_loop.wait(self, self.property_is, name, bool_val)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/event_loop.py", line 59, in wait
    if not wait_no_raise(log_obj, condition, condition_args, condition_kwargs, timeout, timestep):
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/event_loop.py", line 50, in wait_no_raise
    poll()
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/event_loop.py", line 39, in poll
    func()
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 79, in poll_glib
    DeferredHandling.handle_queue()
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 61, in handle_queue
    handler(*args, **kwargs)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 499, in scan_cb_register
    dbus_op = systembus_get(matching_op_path)
  File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/ofono_client.py", line 85, in systembus_get
    return bus.get('org.ofono', path)
  File "/usr/local/lib/python3.4/dist-packages/pydbus/proxy.py", line 59, in get
    return CompositeInterface(introspection)(self, bus_name, object_path)
  File "/usr/local/lib/python3.4/dist-packages/pydbus/proxy.py", line 118, in CompositeInterface
    raise KeyError("object does not export any interfaces; you might need to pass object path as the 2nd argument for get()")
KeyError: 'object does not export any interfaces; you might need to pass object path as the 2nd argument for get()'
  [trial-2820↪aoip_encryption↪register_a5_0_authreq.py:45]  [suite.py:148]