Actions
Bug #3064
closedofono: crash after merging osmo-gsm-tester patch to read IMSI
Start date:
03/14/2018
Due date:
% Done:
100%
Spec Reference:
Description
ofono crashes consistenly after 2nd-3rd test in osmo-gsm-tester_prod after merging this patch in osmo-gsm-tester to read the SIM from the modem: https://gerrit.osmocom.org/#/c/7274/
osmo-gsm-tester output:
13:13:35.834710 tst /sierra_2: DBG: got SIM properties {'MobileCountryCode': '901', 'LockedPins': [], 'PinRequired': 'none', 'FixedDialing': False, 'SubscriberNumbers': [], 'Retries': {'network': 40, 'service': 0, 'corppuk': 0, 'puk2': 10, 'pin2': 3, 'phone': 24, 'networkpuk': 60, 'corp': 253, 'netsubpuk': 157, 'pin': 3, 'puk': 10, 'netsub': 48, 'firstphonepuk': 253, 'firstphone': 51, 'servicepuk': 253}, 'MobileNetworkCode': '70', 'SubscriberIdentity': '901700000015252', 'Present': True, 'BarredDialing': False, 'CardIdentifier': '8988211000000152523'} [trial-215↪ussd:sysmo↪/sierra_2] [modem.py:438]
13:13:35.835678 run osmo-nitb_10.42.42.2: Add subscriber {imsi='901700000015252', msisdn='8465'} [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2] [osmo_nitb.py:140]
13:13:35.836527 bus Ctrl(host='10.42.42.2', port=4249): DBG: Connecting [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)] [osmo_ctrl.py:54]
13:13:35.837398 bus Ctrl(host='10.42.42.2', port=4249): DBG: Sending {data='SET 0 subscriber-modify-v1 901700000015252,8465,comp128v1,EBAB63D06C3F546A16C977CB40E57C68'} [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)] [osmo_ctrl.py:65]
13:13:35.921488 bus Ctrl(host='10.42.42.2', port=4249): DBG: Receiving {data=b'\x00$\xee\x00SET_REPLY 0 subscriber-modify-v1 OK'} [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)] [osmo_ctrl.py:71]
13:13:35.922253 bus CTRL(10.42.42.2:4249): DBG: Created subscriber {imsi='901700000015252', msisdn='8465'} [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)] [osmo_nitb.py:198]
13:13:35.922719 bus Ctrl(host='10.42.42.2', port=4249): DBG: Disconnecting [trial-215↪ussd:sysmo↪osmo-nitb_10.42.42.2↪CTRL(10.42.42.2:4249)↪Ctrl(host='10.42.42.2', port=4249)] [osmo_ctrl.py:60]
13:13:35.932170 bus /sierra_2: DBG: Powered == True [trial-215↪ussd:sysmo↪/sierra_2↪/sierra_2] [modem.py:314]
13:13:35.932820 tst /sierra_2: DBG: Power cycling [trial-215↪ussd:sysmo↪/sierra_2] [modem.py:579]
13:13:35.933375 bus /sierra_2: DBG: has_interface(org.ofono.ConnectionManager) == False [trial-215↪ussd:sysmo↪/sierra_2↪/sierra_2] [modem.py:306]
13:13:35.934287 bus /sierra_2: Setting Online False [trial-215↪ussd:sysmo↪/sierra_2↪/sierra_2] [modem.py:322]
13:13:35.943841 bus /sierra_2: DBG: Online == False [trial-215↪ussd:sysmo↪/sierra_2↪/sierra_2] [modem.py:314]
13:13:35.944772 bus /sierra_2: Setting Powered False [trial-215↪ussd:sysmo↪/sierra_2↪/sierra_2] [modem.py:322]
13:13:36.002454 tst assert_extension.py:18: ERR: Error: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Message recipient disconnected from message bus without replying (4) [trial-215↪ussd:sysmo↪assert_extension.py:18] [proxy_method.py:75: 0, timeout_to_glib(timeout), None).unpack()]
13:13:36.005071 tst assert_extension.py:18: TRACEBACK: Traceback (most recent call last):
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/test.py", line 61, in run
self.path)
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/util.py", line 326, in run_python_file
spec.loader.exec_module( importlib.util.module_from_spec(spec) )
File "<frozen importlib._bootstrap_external>", line 673, in exec_module
File "<frozen importlib._bootstrap>", line 222, in _call_with_frames_removed
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/suites/ussd/assert_extension.py", line 18, in <module>
ms.connect(nitb.mcc_mnc())
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 593, in connect
self.power_cycle()
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 580, in power_cycle
self.power_off()
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 570, in power_off
self.set_powered(False)
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 413, in set_powered
return self.dbus.set_powered(powered=powered)
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 328, in set_powered
self.set_bool('Powered', powered)
File "/home/jenkins/workspace/osmo-gsm-tester_run-prod/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 323, in set_bool
self.interface(iface).SetProperty(name, Variant('b', val))
File "/usr/local/lib/python3.5/dist-packages/pydbus/proxy_method.py", line 75, in __call__
0, timeout_to_glib(timeout), None).unpack()
GLib.GError: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Message recipient disconnected from message bus without replying (4)
[trial-215↪ussd:sysmo↪assert_extension.py:18] [test.py:104]
13:13:36.008739 tst assert_extension.py:18: Test FAILED (41.5 sec) [trial-215↪ussd:sysmo↪assert_extension.py:18] [test.py:105]
It can be seen that ofono crashes while powering off the modem. The different in behaviour from osmo-gms-testser since the patch was applied, was that we now set Powered=true before and fetch the IMSI with SimManager.getProperties(), then when we call connect(), we call power_cycle which finds the modem ON so it turns it OFF. Before the patch, the modem was already OFF because it was not previously turned ON to read the IMSI.
ofono logs during the same time show the crash occurring:
Mar 14 13:13:35.947250 osmo-gsm-tester-prod ofonod[26036]: src/modem.c:modem_change_state() old state: 2, new state: 0 Mar 14 13:13:35.947307 osmo-gsm-tester-prod ofonod[26036]: src/modem.c:flush_atoms() Mar 14 13:13:35.947394 osmo-gsm-tester-prod ofonod[26036]: src/message-waiting.c:mw_remove() atom: 0x56188db370c0 Mar 14 13:13:35.947438 osmo-gsm-tester-prod ofonod[26036]: plugins/push-notification.c:push_notification_cleanup() 0x56188dbff1c0 Mar 14 13:13:35.947483 osmo-gsm-tester-prod ofonod[26036]: plugins/smart-messaging.c:smart_messaging_cleanup() 0x56188dbff160 Mar 14 13:13:35.947988 osmo-gsm-tester-prod ofonod[26036]: src/sms.c:sms_remove() atom: 0x56188dba71a0 Mar 14 13:13:35.948017 osmo-gsm-tester-prod ofonod[26036]: drivers/qmimodem/sms.c:qmi_sms_remove() Mar 14 13:13:35.962295 osmo-gsm-tester-prod ofonod[26036]: src/radio-settings.c:radio_settings_remove() atom: 0x56188db67370 Mar 14 13:13:35.962345 osmo-gsm-tester-prod ofonod[26036]: drivers/qmimodem/radio-settings.c:qmi_radio_settings_remove() Mar 14 13:13:35.962385 osmo-gsm-tester-prod ofonod[26036]: src/phonebook.c:phonebook_remove() atom: 0x56188db67340 Mar 14 13:13:35.962408 osmo-gsm-tester-prod ofonod[26036]: src/stk.c:stk_remove() atom: 0x56188db41a10 Mar 14 13:13:35.962470 osmo-gsm-tester-prod ofonod[26036]: src/location-reporting.c:location_reporting_remove() atom: 0x56188dc2eb70 Mar 14 13:13:35.962490 osmo-gsm-tester-prod ofonod[26036]: drivers/qmimodem/location-reporting.c:qmi_location_reporting_remove() Mar 14 13:13:35.967282 osmo-gsm-tester-prod ofonod[26036]: src/voicecall.c:voicecall_remove() atom: 0x56188db3bcd0 Mar 14 13:13:35.967313 osmo-gsm-tester-prod ofonod[26036]: drivers/qmimodem/voicecall.c:qmi_voicecall_remove() Mar 14 13:13:35.967590 osmo-gsm-tester-prod ofonod[26036]: plugins/bluez5.c:bt_unregister_profile() Bluetooth: Unregistering profile /bluetooth/profile/hfp_ag Mar 14 13:13:35.968854 osmo-gsm-tester-prod ofonod[26036]: src/sim.c:sim_remove() atom: 0x56188db66930 Mar 14 13:13:35.968883 osmo-gsm-tester-prod ofonod[26036]: drivers/qmimodem/sim.c:qmi_sim_remove() Mar 14 13:13:35.969121 osmo-gsm-tester-prod ofonod[26036]: Aborting (signal 11) [/usr/local/sbin/ofonod] Mar 14 13:13:35.972237 osmo-gsm-tester-prod ofonod[26036]: ++++++++ backtrace ++++++++ Mar 14 13:13:35.987586 osmo-gsm-tester-prod ofonod[26036]: #0 0x7f76371ff060 in /lib/x86_64-linux-gnu/libc.so.6 Mar 14 13:13:35.987831 osmo-gsm-tester-prod ofonod[26036]: #1 0x7f7637dda517 in /lib/x86_64-linux-gnu/libglib-2.0.so.0 Mar 14 13:13:35.988221 osmo-gsm-tester-prod ofonod[26036]: #2 0x56188d571ea0 in /usr/local/sbin/ofonod Mar 14 13:13:36.006677 osmo-gsm-tester-prod systemd[1]: ofono.service: Main process exited, code=exited, status=1/FAILURE Mar 14 13:13:36.008039 osmo-gsm-tester-prod systemd[1]: ofono.service: Unit entered failed state. Mar 14 13:13:36.008154 osmo-gsm-tester-prod systemd[1]: ofono.service: Failed with result 'exit-code'. Mar 14 13:13:38.236776 osmo-gsm-tester-prod systemd[1]: ofono.service: Service hold-off time over, scheduling restart. Mar 14 13:13:38.238182 osmo-gsm-tester-prod systemd[1]: Stopped Telephony service. Mar 14 13:13:38.242292 osmo-gsm-tester-prod systemd[1]: Starting Telephony service...
Files
Actions
