Re: GSM conn up fails first time with SIM PIN

[Colin Helliwell <colin helliwell ln-systems com>]

> On 18 April 2017 at 14:36 Colin Helliwell <colin helliwell ln-systems com> wrote:
>
> > On 17 April 2017 at 18:32 Dan Williams <dcbw redhat com> wrote:
> >
> > On Sat, 2017-04-15 at 13:11 +0100, Colin Helliwell wrote:
> >
> > > I have NM setup with ModemManager and GSM modem, and can bring up the
> > > connection. But when I enable a SIM PIN lock, the first 'nmcli conn
> > > up' from reboot fails.
> > > I can see that the modem is being unlocked ok, and is indeed
> > > registered afterwards. And a retry of the 'conn up' also works.
> > > I wonder if there's some sequence/timing issue on the first time,
> > > when the modem has to be brought out of locked state. (I leave the
> > > enabling to NM/MM; with the PIN in the NM connection settings).
> > >
> > > NM log is below. I *think* the point at which it goes awry is
> > > indicated by the
> > >  'enabling' --> 'disabled' (reason: unknown) @ 12:51:37
> > > Unable to spot at the MM end of things [these logs omitted here]
> > > what's triggering this change. Could it just be a timeout? (circa
> > > 20secs)
> >
> > Can you grab MM debug logs for this sequence too? I can't see what it
> > would be from the NM side, maybe having both together would help.
> >
> > Dan
>
> Attached.

I've been taking another look at this, and I wonder if the problem is more in MM. I suspect it may be these 
operations:

Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.806784] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CESQ=?<CR>'
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.833437] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CME ERROR: 100<CR><LF>'
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.833833] [src/mm-serial-parsers.c:364] 
mm_serial_parser_v1_parse(): Got failure code 100: Unknown error
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.834030] [src/mm-iface-modem-signal.c:428] 
check_support_ready(): Extended signal support check failed: 'Unknown error'
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.834206] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.834436] [src/mm-broadband-modem.c:9931] 
iface_modem_signal_initialize_ready(): Couldn't initialize interface: 'Extended Signal information not 
supported'
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.836278] [src/mm-broadband-modem.c:9932] 
iface_modem_oma_initialize_ready(): Couldn't initialize interface: 'OMA not supported'
Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <debug> [1492257094.836804] [src/mm-broadband-modem.c:9933] 
iface_modem_firmware_initialize_ready(): Couldn't initialize interface: 'Firmware interface not available'

which are then triggering:

Apr 15 12:51:34 wg2xx-tx6s ModemManager[1186]: <info>  [1492257094.837136] [src/mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed 
(initializing -> disabled)

and hence causing NM to fail the Up.

Without the PIN enabled, this set of commands occurs towards the end of the initial modem 'scanning'. After 
which the modem would be left disabled anyway, so there's no problem.
With the PIN enabled, that section of operations is deferred until, after PIN entry, where NM/MM *are* trying 
to enable the modem.
Maybe it may not be the above 3 items which cause the "(initializing -> disabled)", but maybe something prior 
to that - I'm not sure what this part of MM tries to do.
Either that or NM isn't waiting long enough for MM to get the modem from locked to initialised before trying 
to enable it?