Project

General

Profile

Bug #2941

ofono: SierraW sometimes crashing while deactivating a context.

Added by pespin 6 days ago. Updated 6 days ago.

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

trial-5267-run.tgz (5.56 MB) pespin, 02/13/2018 04:14 PM

History

#1 Updated by pespin 6 days ago

And indeed, after the crash, the device is reassigned a new name, that's why we cannot find it anymore without restarting ofono (/sierra_5):

# mdbus2 -s org.ofono
/
/bluetooth
/bluetooth/profile
/bluetooth/profile/dun_gw
/bluetooth/profile/hfp_ag
/bluetooth/profile/hfp_hf
/gobi_0
/gobi_4
/sierra_3
/sierra_5

Also available in: Atom PDF