Issues with modem reset

Wed Jun 28 09:59:26 UTC 2017

Hi,

2017-06-28 10:41 GMT+02:00 Aleksander Morgado <aleksander at aleksander.es>:
> Can you retry but before running the reset operation, do an explicit
> disconnection and/or disable?

I checked with nmcli d disconnect prior to mmcli -r and I'm not able
to reproduce this. Though once mmcli -r failed because of timeout on
AT commands interface (it took over 5s for modem to reply with OK). It
looks like the timeout in telit plugin may be too short.

I'm checking the logs and if my understanding is correct it looks like
some logic from bearer disconnect from the connection before the modem
reset happens still executes after modem was lost and when "new" modem
is probed, it looks like it may get in the way of AT ports probing.
Especially this happens and afterwards it seems PORTCFG reply fails to
parse (or it's retried 3 times for other reason)

<debug> [1719500205.463624]
[../../ModemManager-1.6.6/src/mm-device.c:399] unexport_modem():
Unexported modem
'/sys/devices/soc0/soc.1/2100000.aips-bus/2184200.usb/ci_hdrc.1/usb1/1-1/1-1.4'
from path '/org/freedesktop/ModemManager1/Modem/7'
<debug> [1719500206.439252]
[../../ModemManager-1.6.6/src/mm-port-serial.c:1162]
mm_port_serial_open(): (ttyACM0) opening serial port...
<debug> [1719500206.495430]
[../../ModemManager-1.6.6/src/mm-port-serial.c:1292]
mm_port_serial_open(): (ttyACM0) device open count is 1 (open)
<debug> [1719500206.500921]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:495]
mm_port_serial_at_run_init_sequence(): (ttyACM0): running init
sequence...
<debug> [1719500206.504403]
[../../ModemManager-1.6.6/src/mm-port-serial.c:1292]
mm_port_serial_open(): (ttyACM0) device open count is 2 (open)
<debug> [1719500206.509531]
[../../ModemManager-1.6.6/src/mm-broadband-bearer.c:1559]
data_reopen_3gpp_ready(): Flashing data port (ttyACM0)...
<debug> [1719500206.513330]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'ATE0<CR>'
<debug> [1719500206.601027]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1442]
mm_plugin_manager_device_support_check(): [plugin manager] task 9: new
support task for device:
/sys/devices/soc0/soc.1/2100000.aips-bus/2184200.usb/ci_hdrc.1/usb1/1-1/1-1.4
<debug> [1719500206.606393]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1167]
device_context_port_grabbed(): [plugin manager] task 9: port grabbed:
ttyACM3
<debug> [1719500206.611529]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1192]
device_context_port_grabbed(): [plugin manager] task 9,ttyACM3: new
support task for port
<debug> [1719500206.614495]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1197]
device_context_port_grabbed(): [plugin manager) task 9,ttyACM3:
deferred until min wait time elapsed
<debug> [1719500206.621993]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1167]
device_context_port_grabbed(): [plugin manager] task 9: port grabbed:
ttyACM0
<debug> [1719500206.624972]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1192]
device_context_port_grabbed(): [plugin manager] task 9,ttyACM0: new
support task for port
<debug> [1719500206.629888]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1197]
device_context_port_grabbed(): [plugin manager) task 9,ttyACM0:
deferred until min wait time elapsed
<debug> [1719500206.636271]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1167]
device_context_port_grabbed(): [plugin manager] task 9: port grabbed:
ttyACM1
<debug> [1719500206.641412]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1192]
device_context_port_grabbed(): [plugin manager] task 9,ttyACM1: new
support task for port
<debug> [1719500206.644427]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1197]
device_context_port_grabbed(): [plugin manager) task 9,ttyACM1:
deferred until min wait time elapsed
<debug> [1719500206.651976]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1167]
device_context_port_grabbed(): [plugin manager] task 9: port grabbed:
ttyACM2
<debug> [1719500206.654983]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1192]
device_context_port_grabbed(): [plugin manager] task 9,ttyACM2: new
support task for port
<debug> [1719500206.659860]
[../../ModemManager-1.6.6/src/mm-plugin-manager.c:1197]
device_context_port_grabbed(): [plugin manager) task 9,ttyACM2:
deferred until min wait time elapsed
<debug> [1719500207.515959]
[../../ModemManager-1.6.6/src/mm-port-serial.c:1349]
_close_internal(): (ttyACM0) device open count is 1 (close)
<debug> [1719500207.520868]
[../../ModemManager-1.6.6/src/mm-broadband-bearer.c:1529]
data_flash_3gpp_ready(): Sending PDP context deactivation in
primary/data port...
<debug> [1719500207.524547]
[../../ModemManager-1.6.6/src/mm-port-serial.c:1292]
mm_port_serial_open(): (ttyACM0) device open count is 2 (open)
<debug> [1719500207.528404]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- 'ATE0<CR><CR><LF>OK<CR><LF>'
<debug> [1719500207.532292]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'ATV1<CR>'
<debug> [1719500207.548781]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- '<CR><LF>OK<CR><LF>'
<debug> [1719500207.552620]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'AT+CMEE=1<CR>'
<debug> [1719500207.580402]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- '<CR><LF>OK<CR><LF>'
<debug> [1719500207.584507]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'ATX4<CR>'
<debug> [1719500207.600529]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- '<CR><LF>OK<CR><LF>'
<debug> [1719500207.604388]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'AT&C1<CR>'
<debug> [1719500207.620653]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- '<CR><LF>OK<CR><LF>'
<debug> [1719500207.624527]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): --> 'AT+CGACT=0,2<CR>'
<debug> [1719500207.652159]
[../../ModemManager-1.6.6/src/mm-port-serial-at.c:459] debug_log():
(ttyACM0): <-- '<CR><LF>+CME ERROR: 555<CR><LF>'
<debug> [1719500207.655999]
[../../ModemManager-1.6.6/src/mm-error-helpers.c:131]
mm_mobile_equipment_error_for_code(): Invalid mobile equipment error
code: 555

Best regards, Piotr.