Actions
Bug #2323
closedofono network registration makes tester runs unstable
Start date:
06/12/2017
Due date:
% Done:
100%
Spec Reference:
Description
mo_mt_sms.py:24: ERR: Error: Scan() failed: g-io-error-quark: GDBus.Error:org.ofono.Error.Failed: Operation failed (36)
This failure occurs sporadically, "a significant amount of times out of ten runs" so that we either fix or revert it (as much as I'd like to have this patch in).
I suspect that scanning is not permitted when a modem is already scanning, and a modem may start scanning on its own accord when we set Online=true, to perform an automatic attach.
Does this need a fix in ofono? Should we just catch this error and retry? Should query the state, whether the modem is already scanning, and/or not scan if we already get a list of operators from the NetworkRegistration interface?
If you can't find a quick fix, we need to revert for the time being.
Updated by pespin almost 7 years ago
Example build with error can be found here: http://jenkins.osmocom.org/jenkins/view/osmo-gsm-tester/job/osmo-gsm-tester_run/586/
The initial error triggering the issue comes from the modem QMI layer, it's not directly caused by ofono.
When the scanning + registering works correctly, this can be seen with ofono running with debug enabled:
ofonod[18837]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 1 tech 0 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_current_operator() ofonod[18837]: src/network.c:current_operator_callback() 0x1f889e0, 0x201ef30 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_signal_strength() ofonod[18837]: src/gprs.c:netreg_status_changed() 1 ofonod[18837]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1 ofonod[18837]: drivers/qmimodem/gprs.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/gprs.c:handle_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() radio in use 4 ofonod[18837]: src/gprs.c:ofono_gprs_status_notify() /sierra_2 status 0 ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() signal with -100 dBm on 4 ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() signal with -100 dBm on 4 ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() signal with -100 dBm on 4 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() found 10 operators ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 901-70 (901:70) status 1 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() E-Plus (262:03) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() E-Plus (262:03) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() TDG (262:01) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() TDG (262:01) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() Vodafone (262:02) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() TDG (262:01) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() E-Plus (262:03) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() Vodafone (262:02) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() Vodafone (262:02) status 3 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 901:70 4 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:03 8 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:03 5 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:01 8 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:01 4 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:02 4 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:01 5 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:03 4 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:02 5 ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() 262:02 8 ofonod[18837]: drivers/qmimodem/network-registration.c:event_notify() ofonod[18837]: drivers/qmimodem/network-registration.c:event_notify() signal with -92 dBm on 4 ofonod[18837]: src/network.c:ofono_netreg_strength_notify() strength 20 ofonod[18837]: drivers/qmimodem/network-registration.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 2 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech 0 ofonod[18837]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 2 tech 0 ofonod[18837]: src/network.c:current_operator_callback() 0x1f889e0, 0x201ef30 ofonod[18837]: src/gprs.c:netreg_status_changed() 2
When the issue appears, the following can be seen when running ofono with debug enabled:
ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_current_operator() ofonod[18837]: src/network.c:current_operator_callback() 0x1f889e0, 0x201ef30 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_signal_strength() ofonod[18837]: src/gprs.c:netreg_status_changed() 1 ofonod[18837]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1 ofonod[18837]: drivers/qmimodem/gprs.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/gprs.c:handle_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() radio in use 4 ofonod[18837]: src/gprs.c:ofono_gprs_status_notify() /sierra_2 status 0 ofonod[18837]: drivers/qmimodem/gprs.c:attach_detach_cb() ofonod[18837]: src/gprs.c:gprs_attach_callback() /sierra_2 error = 0 ofonod[18837]: drivers/qmimodem/gprs.c:qmi_attached_status() ofonod[18837]: drivers/qmimodem/network-registration.c:scan_nets_cb() ofonod[18837]: src/network.c:operator_list_callback() Error occurred during operator list ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() ofonod[18837]: drivers/qmimodem/network-registration.c:get_rssi_cb() signal with -100 dBm on 4 ofonod[18837]: src/network.c:ofono_netreg_strength_notify() strength 0 ofonod[18837]: drivers/qmimodem/network-registration.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 1 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() 901-70 (901:70) ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech 0 ofonod[18837]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 1 tech 0 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_current_operator() ofonod[18837]: src/network.c:current_operator_callback() 0x1f889e0, 0x201ef30 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_signal_strength() ofonod[18837]: src/gprs.c:netreg_status_changed() 1 ofonod[18837]: src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1 ofonod[18837]: drivers/qmimodem/gprs.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/gprs.c:handle_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/gprs.c:extract_ss_info() radio in use 4 ofonod[18837]: src/gprs.c:ofono_gprs_status_notify() /sierra_2 status 0 ofonod[18837]: drivers/qmimodem/network-registration.c:ss_info_notify() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() serving system status 1 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() radio in use 4 ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() 901-70 (901:70) ofonod[18837]: drivers/qmimodem/network-registration.c:extract_ss_info() lac -1 cellid -1 tech 0 ofonod[18837]: src/network.c:ofono_netreg_status_notify() /sierra_2 status 1 tech 0 ofonod[18837]: drivers/qmimodem/network-registration.c:qmi_current_operator()
Which means the error is checked and triggered in ofono in drivers/qmimodem/network-registration.c:scan_nets_cb():
DBG("");
if (qmi_result_set_error(result, NULL)) {
CALLBACK_WITH_FAILURE(cb, 0, NULL, cbd->data);
return;
}
ptr = qmi_result_get(result, QMI_NAS_RESULT_NETWORK_LIST, &len);
if (!ptr) {
CALLBACK_WITH_FAILURE(cb, 0, NULL, cbd->data);
return;
}
netlist = ptr;
num = GUINT16_FROM_LE(netlist->count);
DBG("found %d operators", num);
Updated by pespin almost 7 years ago
I always see the following lines just before the error lines. Those are not there when the process runs correctly:
ofonod[18837]: drivers/qmimodem/gprs.c:attach_detach_cb() ofonod[18837]: src/gprs.c:gprs_attach_callback() /sierra_2 error = 0 ofonod[18837]: drivers/qmimodem/gprs.c:qmi_attached_status()
From ofono API doc:
array{object,dict} Scan()
Runs a network operator scan to discover the currently
available operators. This operation can take several
seconds, and up to several minutes on some modems.
This can be used to help the user determine what is
the best operator to use if forced to roam on a
foreign network.
NOTE: The operator scan can interfere with any active
GPRS contexts. Expect the context to be unavailable
for the duration of the operator scan.
Possible Errors: [service].Error.InProgress
[service].Error.NotImplemented
[service].Error.Failed
[service].Error.AccessDenied
So it seems GPRS can somehow be affecting too network registration.
Updated by pespin almost 7 years ago
Fixed/workaround in osmo-gsm-tester 4d63d920333c23996b4a2773aa7c363812971b37
Updated by pespin almost 7 years ago
- Status changed from New to Resolved
- % Done changed from 0 to 100
Actions
