After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 696703 - [MM 0.8] mbm: +CPIN not being retried?
[MM 0.8] mbm: +CPIN not being retried?
Status: RESOLVED DUPLICATE of bug 696702
Product: NetworkManager
Classification: Platform
Component: ModemManager
unspecified
Other Linux
: Normal normal
: ---
Assigned To: NetworkManager maintainer(s)
NetworkManager maintainer(s)
Depends on:
Blocks:
 
 
Reported: 2013-03-27 15:33 UTC by Dan Williams
Modified: 2013-03-27 15:38 UTC
See Also:
GNOME target: ---
GNOME version: ---


Description Dan Williams 2013-03-27 15:33:30 UTC 
I thought we had code to retry +CPIN a few times after entering the PIN to wait for the modem to be unlocked, but it seems like that's not getting executed:

ModemManager[1867]: <debug> [1364397820.309183] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0) opening serial port...
ModemManager[1867]: <debug> [1364397820.311773] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 1 (open)
ModemManager[1867]: <debug> [1364397820.311838] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CPIN="1234"<CR>'
ModemManager[1867]: <debug> [1364397820.402874] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1867]: <debug> [1364397820.403093] [mm-broadband-modem.c:1137] modem_load_unlock_required(): checking if unlock required...
ModemManager[1867]: <debug> [1364397820.403164] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
ModemManager[1867]: <debug> [1364397820.403238] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
ModemManager[1867]: <debug> [1364397820.403304] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CPIN?<CR>'
ModemManager[1867]: <debug> [1364397820.422841] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>+CPIN: SIM PIN<CR><LF>'
ModemManager[1867]: <debug> [1364397820.424801] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1867]: <debug> [1364397820.424944] [mbm/mm-broadband-modem-mbm.c:687] load_unlock_retries(): loading unlock retries (mbm)...
ModemManager[1867]: <debug> [1364397820.425015] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
ModemManager[1867]: <debug> [1364397820.425093] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
ModemManager[1867]: <debug> [1364397820.425159] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT*EPIN?<CR>'
ModemManager[1867]: <warn>  [1364397824.019494] [mm-iface-modem.c:2527] load_unlock_retries_ready(): Couldn't load unlock retries: 'Serial command timed out'
ModemManager[1867]: <debug> [1364397824.019764] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 0 (close)
ModemManager[1867]: <debug> [1364397824.019847] [mm-serial-port.c:1019] mm_serial_port_close(): (ttyACM0) closing serial port...
ModemManager[1867]: <debug> [1364397824.040034] [mm-serial-port.c:1050] mm_serial_port_close(): (ttyACM0) serial port closed

<resend PIN code via mmcli --pin>

ModemManager[1867]: <debug> [1364398065.533072] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0) opening serial port...
ModemManager[1867]: <debug> [1364398065.535706] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 1 (open)
ModemManager[1867]: <debug> [1364398065.535774] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CPIN="1234"<CR>'
ModemManager[1867]: <debug> [1364398065.549953] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>*EPIN: 3,10,3,10,5,5,5,5<CR><LF><CR><LF>OK<CR><LF>'
ModemManager[1867]: <debug> [1364398065.550780] [mm-broadband-modem.c:1137] modem_load_unlock_required(): checking if unlock required...
ModemManager[1867]: <debug> [1364398065.551350] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
ModemManager[1867]: <debug> [1364398065.551961] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
ModemManager[1867]: <debug> [1364398065.552578] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CPIN?<CR>'
ModemManager[1867]: <debug> [1364398065.565705] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>+CME ERROR: 3<CR><LF>'
ModemManager[1867]: <debug> [1364398065.565768] [mm-serial-parsers.c:316] mm_serial_parser_v1_parse(): Got failure code 3: Operation not allowed
ModemManager[1867]: <debug> [1364398065.565800] [mm-iface-modem.c:2597] load_unlock_required_ready(): Couldn't check if unlock required: 'Operation not allowed'
ModemManager[1867]: <debug> [1364398065.565830] [mm-iface-modem.c:2603] load_unlock_required_ready(): Retrying (1) unlock required check
ModemManager[1867]: <debug> [1364398065.565851] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 0 (close)
ModemManager[1867]: <debug> [1364398065.565869] [mm-serial-port.c:1019] mm_serial_port_close(): (ttyACM0) closing serial port...
ModemManager[1867]: <debug> [1364398065.583987] [mm-serial-port.c:1050] mm_serial_port_close(): (ttyACM0) serial port closed
ModemManager[1867]: <debug> [1364398068.017055] [mm-broadband-modem.c:1137] modem_load_unlock_required(): checking if unlock required...
ModemManager[1867]: <debug> [1364398068.017227] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0) opening serial port...
ModemManager[1867]: <debug> [1364398068.019793] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 1 (open)
ModemManager[1867]: <debug> [1364398068.019928] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT+CPIN?<CR>'
ModemManager[1867]: <debug> [1364398068.038727] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>+CPIN: READY<CR><LF>'
ModemManager[1867]: <debug> [1364398068.040703] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1867]: <debug> [1364398068.040784] [mbm/mm-broadband-modem-mbm.c:687] load_unlock_retries(): loading unlock retries (mbm)...
ModemManager[1867]: <debug> [1364398068.040822] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
ModemManager[1867]: <debug> [1364398068.040863] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
ModemManager[1867]: <debug> [1364398068.040898] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): --> 'AT*EPIN?<CR>'
ModemManager[1867]: <debug> [1364398070.681079] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>*EPIN: 3,10,3,10,5,5,5,5<CR><LF>'
ModemManager[1867]: <debug> [1364398070.682885] [mm-at-serial-port.c:397] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1867]: <debug> [1364398070.683176] [mm-iface-modem.c:2683] update_lock_info_context_step(): SIM is ready, running after SIM unlock step...
ModemManager[1867]: <debug> [1364398070.683245] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 0 (close)
ModemManager[1867]: <debug> [1364398070.683289] [mm-serial-port.c:1019] mm_serial_port_close(): (ttyACM0) closing serial port...
ModemManager[1867]: <debug> [1364398070.701701] [mm-serial-port.c:1050] mm_serial_port_close(): (ttyACM0) serial port closed
ModemManager[1867]: <info>  [1364398071.185678] [mm-iface-modem.c:1201] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/1: state changed (locked -> initializing)

Also, oddly, the *EPIN response times out, but if you re-unlock with mmcli, you'll see the response.
Comment 1 Dan Williams 2013-03-27 15:38:05 UTC 

*** This bug has been marked as a duplicate of bug 696702 ***