Bug #2510
closedexception in ofono_client for tests calling connect() more than once
100%
Description
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]
Updated by pespin over 6 years ago
- Status changed from New to Feedback
- % Done changed from 0 to 90
Issue was found in build https://jenkins.osmocom.org/jenkins/view/osmo-gsm-tester/job/osmo-gsm-tester_run/2820/
Patch available in https://gerrit.osmocom.org/#/c/3901/1
Updated by pespin over 6 years ago
- Status changed from Feedback to Resolved
- % Done changed from 90 to 100