Actions
Bug #2941
openofono: SierraW sometimes crashing while deactivating a context.
Status:
New
Priority:
Normal
Assignee:
-
Target version:
-
Start date:
02/13/2018
Due date:
% Done:
0%
Spec Reference:
Description
I am looking at all the crashes, and before not being able to access the modem (tests failing) there's a first different failure.
from osmo-gsm-tester:
15:02:17.133244 tst /sierra_2: DBG: 'org.ofono.ConnectionManager'.PropertyChanged() -> Attached=True [trial-5267↪gprs:octphy↪/sierra_2] [modem.py:723] 15:02:17.140183 tst /sierra_2: DBG: attached: True [trial-5267↪gprs:octphy↪/sierra_2] [modem.py:579] 15:02:17.140818 tst /sierra_2: DBG: activate_context {apn='inet46', protocol='ip', user='ogt'} [trial-5267↪gprs:octphy↪/sierra_2] [modem.py:599] 15:02:21.038076 tst /sierra_2: context activated {apn='inet46', path='/sierra_2/context2', properties={AccessPointName='inet46', Active=True, AuthenticationMethod='chap', IPv6.Settings={}, Name='Internet', Password='', Protocol='ip', Settings={Address='176.16.46.1', DomainNameServers=['8.8.8.8', '8.8.8.8'], Gateway='176.16.46.2', Interface='wwan1', Method='static', Netmask='255.255.255.252'}, Type='internet', Username='ogt'}, user='ogt'} [trial-5267↪gprs:octphy↪/sierra_2] [modem.py:613] 15:02:26.049407 tst /sierra_2: DBG: deactivate_context {path='/sierra_2/context2'} [trial-5267↪gprs:octphy↪/sierra_2] [modem.py:617] 15:03:03.295353 tst ping.py:53: ERR: Error: g-io-error-quark: GDBus.Error:org.ofono.Error.Failed: Operation failed (36) [trial-5267↪gprs:octphy↪ping.py:53] [proxy_method.py:75: 0, timeout_to_glib(timeout), None).unpack()] 15:03:03.298508 tst ping.py:53: TRACEBACK: Traceback (most recent call last): File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/test.py", line 61, in run self.path) File "/home/jenkins/workspace/osmo-gsm-tester_run/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/osmo-gsm-tester/suites/gprs/ping.py", line 53, in <module> ms.deactivate_context(ctx_id_v4) File "/home/jenkins/workspace/osmo-gsm-tester_run/osmo-gsm-tester/src/osmo_gsm_tester/modem.py", line 619, in deactivate_context ctx.SetProperty('Active', Variant('b', False)) 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-io-error-quark: GDBus.Error:org.ofono.Error.Failed: Operation failed (36) [trial-5267↪gprs:octphy↪ping.py:53] [test.py:104] [17:07:27] <pespin> so the test basically waits until the context is activated (15:02:21), then waits for 5 seconds, and then deactives it (15:02:26) [17:08:01] <pespin> but deactivating it fails after the call is stuck for a few seconds (15:03:03) with Error.Failed: Operation failed (36) [17:08:11] <pespin> Then, looking at ofono trace: [17:08:45] <pespin> eb 13 15:02:21.016686 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() Feb 13 15:02:21.016714 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() APN: inet46 Feb 13 15:02:21.016740 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() PDP type 3 Feb 13 15:02:21.016771 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() IP addr: 176.16.46.1 Feb 13 15:02:21.016800 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() Gateway: 176.16.46.2 Feb 13 15:02:21.016828 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() Gateway netmask: 255.255.255.252 Feb 13 15:02:21.016856 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() Primary DNS: 192.168.100.1 Feb 13 15:02:21.016882 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:get_settings_cb() Secondary DNS: 8.8.8.8 Feb 13 15:02:21.016914 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:get_modem_property() modem 0x55d391490920 property NetworkInterface Feb 13 15:02:21.016945 osmo-gsm-tester-prod ofonod[18915]: src/gprs.c:pri_activate_callback() 0x55d3914a02f0 Feb 13 15:02:26.058379 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:qmi_deactivate_primary() cid 1 Feb 13 15:02:26.058639 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/qmibridge.c:ask_qmi() _REQ: QMI QMUX: QMI length = 19 QMI flags = 0x00 QMI service = "wds" QMI client = 9 QMI QMI: QMI flags = "none" QMI transaction = 344 QMI tlv_length = 7 QMI message = "Stop Network" (0x0021) QMI TLV: QMI type = "Packet Data Handle" (0x01) QMI length = 4 QMI value = F8:6C:D5:43 QMI translated = 1138060536 Feb 13 15:03:03.281453 osmo-gsm-tester-prod ofonod[18915]: plugins/udevng.c:remove_device() /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.7/1-1.7.2/1-1.7.2:1.0/ttyUSB10/tty/ttyUSB10 Feb 13 15:03:03.281497 osmo-gsm-tester-prod ofonod[18915]: plugins/udevng.c:destroy_modem() /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.7/1-1.7.2 Feb 13 15:03:03.281524 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:ofono_modem_remove() 0x55d391490920 Feb 13 15:03:03.281549 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:modem_unregister() 0x55d391490920 Feb 13 15:03:03.281576 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:modem_change_state() old state: 3, new state: 0 Feb 13 15:03:03.281599 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:flush_atoms() Feb 13 15:03:03.281648 osmo-gsm-tester-prod ofonod[18915]: src/gprs.c:gprs_context_unregister() 0x55d391536b20, 0x55d3914e7fe0 Feb 13 15:03:03.286171 osmo-gsm-tester-prod ofonod[18915]: src/gprs.c:gprs_context_remove() atom: 0x55d3914f3520 Feb 13 15:03:03.286196 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs-context.c:qmi_gprs_context_remove() Feb 13 15:03:03.286290 osmo-gsm-tester-prod ofonod[18915]: plugins/bluez5.c:bt_unregister_profile() Bluetooth: Unregistering profile /bluetooth/profile/dun_gw Feb 13 15:03:03.286414 osmo-gsm-tester-prod ofonod[18915]: src/gprs.c:gprs_unregister() 0x55d3914e7fe0 Feb 13 15:03:03.312084 osmo-gsm-tester-prod ofonod[18915]: src/network.c:__ofono_netreg_remove_status_watch() 0x55d3915007d0 Feb 13 15:03:03.312158 osmo-gsm-tester-prod ofonod[18915]: src/gprs.c:gprs_remove() atom: 0x55d3914e8090 Feb 13 15:03:03.312181 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/gprs.c:qmi_gprs_remove() Feb 13 15:03:03.312250 osmo-gsm-tester-prod ofonod[18915]: src/ussd.c:ussd_remove() atom: 0x55d391500720 Feb 13 15:03:03.312270 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/ussd.c:qmi_ussd_remove() Feb 13 15:03:03.317890 osmo-gsm-tester-prod ofonod[18915]: src/sim.c:ofono_sim_remove_spn_watch() 0x55d3914ab790 Feb 13 15:03:03.317964 osmo-gsm-tester-prod ofonod[18915]: src/network.c:netreg_remove() atom: 0x55d391500880 Feb 13 15:03:03.317985 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/network-registration.c:qmi_netreg_remove() Feb 13 15:03:03.318052 osmo-gsm-tester-prod ofonod[18915]: plugins/push-notification.c:push_notification_cleanup() 0x55d391438320 Feb 13 15:03:03.318098 osmo-gsm-tester-prod ofonod[18915]: plugins/smart-messaging.c:smart_messaging_cleanup() 0x55d391538e70 Feb 13 15:03:03.318143 osmo-gsm-tester-prod ofonod[18915]: src/sms.c:sms_remove() atom: 0x55d3914a0920 Feb 13 15:03:03.318163 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/sms.c:qmi_sms_remove() Feb 13 15:03:03.330613 osmo-gsm-tester-prod ofonod[18915]: src/radio-settings.c:radio_settings_remove() atom: 0x55d3915374f0 Feb 13 15:03:03.330640 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/radio-settings.c:qmi_radio_settings_remove() Feb 13 15:03:03.330683 osmo-gsm-tester-prod ofonod[18915]: src/phonebook.c:phonebook_remove() atom: 0x55d3914ffad0 Feb 13 15:03:03.330708 osmo-gsm-tester-prod ofonod[18915]: src/stk.c:stk_remove() atom: 0x55d391539b70 Feb 13 15:03:03.330784 osmo-gsm-tester-prod ofonod[18915]: src/location-reporting.c:location_reporting_remove() atom: 0x55d39153a4b0 Feb 13 15:03:03.330805 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/location-reporting.c:qmi_location_reporting_remove() Feb 13 15:03:03.337816 osmo-gsm-tester-prod ofonod[18915]: src/voicecall.c:voicecall_remove() atom: 0x55d3914aaee0 Feb 13 15:03:03.337841 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/voicecall.c:qmi_voicecall_remove() Feb 13 15:03:03.337953 osmo-gsm-tester-prod ofonod[18915]: plugins/bluez5.c:bt_unregister_profile() Bluetooth: Unregistering profile /bluetooth/profile/hfp_ag Feb 13 15:03:03.338178 osmo-gsm-tester-prod ofonod[18915]: src/sim.c:sim_remove() atom: 0x55d391435610 Feb 13 15:03:03.338216 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/sim.c:qmi_sim_remove() Feb 13 15:03:03.338270 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:devinfo_remove() atom: 0x55d3914eb0f0 Feb 13 15:03:03.338290 osmo-gsm-tester-prod ofonod[18915]: drivers/qmimodem/devinfo.c:qmi_devinfo_remove() Feb 13 15:03:03.338313 osmo-gsm-tester-prod ofonod[18915]: plugins/gobi.c:gobi_disable() 0x55d391490920 Feb 13 15:03:03.338336 osmo-gsm-tester-prod ofonod[18915]: src/modem.c:get_modem_property() modem 0x55d391490920 property AlwaysOnline Feb 13 15:03:03.339583 osmo-gsm-tester-prod ofonod[18915]: plugins/gobi.c:gobi_remove() 0x55d391490920
It correctly sends the QMI message to the modem, and then after a few seconds we see udev asking us to remove the device ? that looks like a modem crash right?
And then indeed starting from that point all tests fail because they cannot find the object with the modem path...
I attach full test output
Files
Actions