*** Bug 696703 has been marked as a duplicate of this bug. ***

*** Bug 696704 has been marked as a duplicate of this bug. ***

> 
> Also, oddly, the *EPIN response times out, but if you re-unlock with mmcli,
> you'll see the response.

The port gets fully closed (open_count = 0) after our timeout, so we get the reply once we re-open it again. We should probably increase the timeout in the *EPIN command.

(In reply to comment #0)
> 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:
> 


Not sure what you exactly mean here. We do retry CPIN? unlock check after having sent the PIN, don't we?

Oh, so it's just that the command timeout closes the port down completely?  I guess I'd expected it to just give up on that command and try with the next one.

I did try the *EPIN timeout increased to 5 seconds, but that didn't help anything, I presume because it was angry that the SIM was still busy.  Here's what I think should be happening:

+CPIN=1234
OK
+CPIN?
SIM PIN
+CPIN?
SIM PIN
+CPIN?
READY
<load unlock retries>

whereas right now it appears that we're loading unlock retries before the modem is actually ready:

--> 'AT+CPIN="1234"<CR>'
<-- '<CR><LF>OK<CR><LF>'
modem_load_unlock_required(): checking if unlock required...
--> 'AT+CPIN?<CR>'
<-- '<CR><LF>+CPIN: SIM PIN<CR><LF>'
<-- '<CR><LF>OK<CR><LF>'
load_unlock_retries(): loading unlock retries (mbm)...
--> 'AT*EPIN?<CR>'
load_unlock_retries_ready(): Couldn't load unlock retries: 'Serial command timed out'

The retries in CPIN? are *only* when a non-fatal error is returned. If the modem replies "SIM PIN" to +CPIN? after having sent the correct PIN, we don't retry it.

I'll write a MBM-specific SIM handling to support this behaviour.

The 'aleksander/fix-mbm-unlock' branch upstream adds a new MMSimMbm object with a custom implementation of PIN/PUK sending, which explicitly waits for the READY state.

Dan, could you review and test it?

(In reply to comment #6)
> The retries in CPIN? are *only* when a non-fatal error is returned. If the
> modem replies "SIM PIN" to +CPIN? after having sent the correct PIN, we don't
> retry it.
> 
> I'll write a MBM-specific SIM handling to support this behaviour.

I seem to recall that some devices took some time to unlock the PIN here, not just MBM.  Perhaps it would be good to just retry a few times unconditionally in the future?  At least I think that's what we did for 0.6 and it seemed to work out OK.

Anyway, it works:

[1364564747.607675] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0) opening serial port...
[1364564747.611019] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 1 (open)
[1364564747.611148] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): --> 'AT+CPIN="1234"<CR>'
[1364564747.694308] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
[1364564747.694545] [mbm/mm-sim-mbm.c:111] wait_for_unlocked_status(): Scheduling lock state check...
[1364564747.694649] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 0 (close)
[1364564747.694714] [mm-serial-port.c:1019] mm_serial_port_close(): (ttyACM0) closing serial port...
[1364564747.712978] [mm-serial-port.c:1050] mm_serial_port_close(): (ttyACM0) serial port closed
[1364564749.017599] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0) opening serial port...
[1364564749.019009] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 1 (open)
[1364564749.019123] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): --> 'AT+CPIN?<CR>'
[1364564755.501340] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>+CPIN: READY<CR><LF>'
[1364564755.505045] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
[1364564755.505305] [mm-broadband-modem.c:1139] modem_load_unlock_required(): checking if unlock required...
[1364564755.505383] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
[1364564755.505457] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
[1364564755.505526] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): --> 'AT+CPIN?<CR>'
[1364564755.521008] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>+CPIN: READY<CR><LF>'
[1364564755.522959] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
[1364564755.523104] [mbm/mm-broadband-modem-mbm.c:711] load_unlock_retries(): loading unlock retries (mbm)...
[1364564755.523173] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0) device open count is 2 (open)
[1364564755.523248] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0) device open count is 1 (close)
[1364564755.523315] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): --> 'AT*EPIN?<CR>'
[1364564758.425332] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>*EPIN: 3,10,3,10,5,5,5,5<CR><LF>'
[1364564758.427007] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <-- '<CR><LF>OK<CR><LF>'
[1364564758.427286] [mm-iface-modem.c:2683] update_lock_info_context_step(): SIM is ready, running after SIM unlock step...

But the modem takes about 6 seconds after the CPIN to really respond.  Not a problem though because the MBM SIM timeout for +CPIN is 20 seconds.

Branch looks good, though a commit to mm-iface-modem.c snuck in which I've fixed with a fixup! commit.

(In reply to comment #8)
> (In reply to comment #6)
> > The retries in CPIN? are *only* when a non-fatal error is returned. If the
> > modem replies "SIM PIN" to +CPIN? after having sent the correct PIN, we don't
> > retry it.
> > 
> > I'll write a MBM-specific SIM handling to support this behaviour.
> 
> I seem to recall that some devices took some time to unlock the PIN here, not
> just MBM.  Perhaps it would be good to just retry a few times unconditionally
> in the future?  At least I think that's what we did for 0.6 and it seemed to
> work out OK.
> 

We do retry also in git master when CPIN? returns an ERROR, IIRC, but I'm not sure we do it for the case where the modem just lies and reports SIM-PIN lock even after we have unlocked it.

> Anyway, it works:
> 

Nice!

> [1364564747.607675] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0)
> opening serial port...
> [1364564747.611019] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0)
> device open count is 1 (open)
> [1364564747.611148] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): -->
> 'AT+CPIN="1234"<CR>'
> [1364564747.694308] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>OK<CR><LF>'
> [1364564747.694545] [mbm/mm-sim-mbm.c:111] wait_for_unlocked_status():
> Scheduling lock state check...
> [1364564747.694649] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0)
> device open count is 0 (close)
> [1364564747.694714] [mm-serial-port.c:1019] mm_serial_port_close(): (ttyACM0)
> closing serial port...
> [1364564747.712978] [mm-serial-port.c:1050] mm_serial_port_close(): (ttyACM0)
> serial port closed
> [1364564749.017599] [mm-serial-port.c:891] mm_serial_port_open(): (ttyACM0)
> opening serial port...
> [1364564749.019009] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0)
> device open count is 1 (open)
> [1364564749.019123] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): -->
> 'AT+CPIN?<CR>'
> [1364564755.501340] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>+CPIN: READY<CR><LF>'
> [1364564755.505045] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>OK<CR><LF>'
> [1364564755.505305] [mm-broadband-modem.c:1139] modem_load_unlock_required():
> checking if unlock required...
> [1364564755.505383] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0)
> device open count is 2 (open)
> [1364564755.505457] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0)
> device open count is 1 (close)
> [1364564755.505526] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): -->
> 'AT+CPIN?<CR>'
> [1364564755.521008] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>+CPIN: READY<CR><LF>'
> [1364564755.522959] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>OK<CR><LF>'
> [1364564755.523104] [mbm/mm-broadband-modem-mbm.c:711] load_unlock_retries():
> loading unlock retries (mbm)...
> [1364564755.523173] [mm-serial-port.c:958] mm_serial_port_open(): (ttyACM0)
> device open count is 2 (open)
> [1364564755.523248] [mm-serial-port.c:1003] mm_serial_port_close(): (ttyACM0)
> device open count is 1 (close)
> [1364564755.523315] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): -->
> 'AT*EPIN?<CR>'
> [1364564758.425332] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>*EPIN: 3,10,3,10,5,5,5,5<CR><LF>'
> [1364564758.427007] [mm-at-serial-port.c:408] debug_log(): (ttyACM0): <--
> '<CR><LF>OK<CR><LF>'
> [1364564758.427286] [mm-iface-modem.c:2683] update_lock_info_context_step():
> SIM is ready, running after SIM unlock step...
> 
> But the modem takes about 6 seconds after the CPIN to really respond.  Not a
> problem though because the MBM SIM timeout for +CPIN is 20 seconds.
> 

I wonder if we need the after-sim-unlock timeout after all this.

> Branch looks good, though a commit to mm-iface-modem.c snuck in which I've
> fixed with a fixup! commit.

Oops... :)

I'll merge the branch for now, and keep this in mind. If we see more modems doing this, we can just try to cover the lie in the generic implementation.

Merged the branch.