Bug 84993

Summary: icera: retry AT%IPSYS? probing several times if it returns ERROR
Product: ModemManager Reporter: Aleksander Morgado <aleksander>
Component: pluginsAssignee: ModemManager bug user <modemmanager>
Status: RESOLVED FIXED QA Contact:
Severity: major    
Priority: medium CC: tore
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: Patch.
Log from hotplugging 21M-02 with patch applied

Description Aleksander Morgado 2014-10-14 12:26:45 UTC
Originally reported at:
  https://bugzilla.gnome.org/show_bug.cgi?id=725294
  https://mail.gnome.org/archives/networkmanager-list/2014-February/msg00064.html

The Icera probing needs some fixes to correctly handle the Nokia 21M-02. It
needs to extend the AT timeout of the command, plus add some retry logic as the
device may initially return ERROR to the AT%IPSYS? command, especially when the device is hotplugged while ModemManager is already running.
Comment 1 Dan Williams 2014-11-24 21:18:23 UTC
Just ran into this again.

1949] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): --> 'ATE1 E0<CR>'
4555] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): --> 'ATE1 E0<CR>'
4604] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): --> 'ATE1 E0<CR>'
4902] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): <-- 'E0'
5755] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): <-- '<CR><CR><LF>ERROR<CR><LF>'
6250] [mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got failure code 100: Unknown error
6657] [mm-port-probe-at.c:43] mm_port_probe_response_processor_is_at(): Parsing AT got: 'Unknown error'
7093] [mm-port-probe.c:155] mm_port_probe_set_result_at(): (tty/ttyACM0) port is AT-capable
7549] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): <-- 'ATE1 E0'
7968] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): <-- ' E0'
8387] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): <-- '<CR>'
8814] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): <-- '<CR><CR><LF>ERROR<CR><LF>'
9209] [mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got failure code 100: Unknown error
9603] [mm-port-probe-at.c:43] mm_port_probe_response_processor_is_at(): Parsing AT got: 'Unknown error'
9996] [mm-port-probe.c:155] mm_port_probe_set_result_at(): (tty/ttyACM1) port is AT-capable
0426] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): <-- '<CR><LF>OK<CR><LF>'
0842] [mm-port-probe.c:155] mm_port_probe_set_result_at(): (tty/ttyACM2) port is AT-capable
1272] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): --> 'AT%IPSYS?<CR>'
1668] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): --> 'AT%IPSYS?<CR>'
1707] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): --> 'AT%IPSYS?<CR>'
1854] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): <-- 'AT%IPSYS?'
2472] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): <-- '<CR>'
2517] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): <-- 'AT%IPSYS?'
4850] [mm-port-serial-at.c:440] debug_log(): (ttyACM1): <-- '<CR><CR><LF>ERROR<CR><LF>'
4900] [mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got failure code 100: Unknown error
4942] [mm-port-probe.c:227] mm_port_probe_set_result_at_icera(): (tty/ttyACM1) Modem is probably not Icera-based
4996] [mm-port-serial.c:1294] _close_internal(): (ttyACM1) device open count is 0 (close)
5027] [mm-port-serial.c:1310] _close_internal(): (ttyACM1) closing serial port...
2190] [mm-port-serial.c:1359] _close_internal(): (ttyACM1) serial port closed
2245] [mm-port-serial.c:1421] port_serial_close_force(): (ttyACM1) forced to close port
2295] [mm-port-probe.c:1249] mm_port_probe_run_cancel_at_probing(): (tty/ttyACM2) requested to cancel all AT probing
2355] [mm-port-probe.c:881] serial_probe_at_parse_response(): (tty/ttyACM2) no need to keep on probing the port for AT support
2385] [mm-port-probe.c:227] mm_port_probe_set_result_at_icera(): (tty/ttyACM2) Modem is probably not Icera-based
2426] [mm-port-probe.c:1249] mm_port_probe_run_cancel_at_probing(): (tty/ttyACM0) requested to cancel all AT probing
2461] [mm-port-probe.c:881] serial_probe_at_parse_response(): (tty/ttyACM0) no need to keep on probing the port for AT support
2488] [mm-port-probe.c:227] mm_port_probe_set_result_at_icera(): (tty/ttyACM0) Modem is probably not Icera-based
2554] [mm-port-serial-at.c:440] debug_log(): (ttyACM0): <-- '<CR><LF>%IPSYS: 5,2<CR><LF><CR><LF>OK<CR><LF>'
2606] [mm-port-serial-at.c:440] debug_log(): (ttyACM2): <-- '<CR><LF>ERROR<CR><LF>'
2646] [mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got failure code 100: Unknown error
2680] [mm-port-serial.c:1294] _close_internal(): (ttyACM2) device open count is 0 (close)
Comment 2 Aleksander Morgado 2014-12-03 18:56:50 UTC
Created attachment 110421 [details] [review]
Patch.
Comment 3 Tore Anderson 2014-12-03 21:17:07 UTC
Created attachment 110423 [details]
Log from hotplugging 21M-02 with patch applied

I applied the patch on top of ModemManager-1.4.0-1.fc21.src.rpm and rebuilt, and it now works beautifully. My Nokia 21M-02 was detected as Icera-capable 10 times out of 10 when I did some repeated testing. So thumbs up from me!

I'm attaching debugging output from one of the hot-pluggings, for your reference.
Comment 4 Aleksander Morgado 2014-12-03 21:20:52 UTC
(In reply to Tore Anderson from comment #3)
> Created attachment 110423 [details]
> Log from hotplugging 21M-02 with patch applied
> 
> I applied the patch on top of ModemManager-1.4.0-1.fc21.src.rpm and rebuilt,
> and it now works beautifully. My Nokia 21M-02 was detected as Icera-capable
> 10 times out of 10 when I did some repeated testing. So thumbs up from me!
> 
> I'm attaching debugging output from one of the hot-pluggings, for your
> reference.

Superb! thanks for the tests
Comment 5 Aleksander Morgado 2014-12-03 22:02:19 UTC
Patch pushed to git master and mm-1-4

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.