GNOME.org
 

Re: GSM conn up fails first time with SIM PIN



On 19 April 2017 at 19:06 Dan Williams <dcbw redhat com> wrote:

On Wed, 2017-04-19 at 14:47 +0100, Colin Helliwell wrote:


On 19 April 2017 at 14:01 Colin Helliwell <colin.helliwell@ln-syste ms.com> wrote:


On 18 April 2017 at 14:36 Colin Helliwell <colin.helliwell@ln-sys tems.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 also notice that at 12:51:36, "enabling_started(): Flashing primary
AT port before enabling..." is occurring *twice*..?


I think that's a problem. Might not be the problem, but certainly
could be involved. Here's what I think is happening:

1) NM notices the modem is finally all initialized and in the
'disabled' state. Since your rfkill switch (or if you don't have one,
the NM WWAN Enabled property) allows WWAN, so NM sends the 'enable this
modem' request to MM.

2) MM authorizes the Enable() request, which hits up polkit and thus
might take a few mainloop iterations

3) While the authorize is waiting, something (perhaps NM) triggers the
Simple.Connect() request now that the modem is initialized and unlocked

4) MM authorizes the Simple.Connect() request, which hits up polkit and
thus might take a few mainloop iterations.

5) The Enable() authorize completes and calls mm_base_modem_enable().
That gets to mm-broadband-modem.c::enable(). That sees the modem is
MM_MODEM_STATE_DISABLED and falls through to
ENABLING_STEP_WAIT_FOR_FINAL_STATE. That sees the modem is already in
a final state, and schedules a completion from an idle handler.

6) While #5's idle handler is scheduled, the authorize from #4
completes and sees MM_MODEM_STATE_DISABLED and jumps to
CONNECTION_STEP_ENABLE which also calls mm_base_modem_enable(). That
sees the modem is MM_MODEM_STATE_DISABLED and falls through to
ENABLING_STEP_WAIT_FOR_FINAL_STATE. That sees the modem is already in
a final state, and schedules a completion from an idle handler.

So now we have two callchains trying to enable the modem. I don't know
how that could actually trigger the enabling -> disabled bug, but I
don't doubt something could be involved there. If this is all correct,
it's clearly an MM race bug.

Could you try the attached patch and see if you get the message and if
that fixes the issue?

Dan


Yes, I get the message - seemingly consistently. 
It fixed the double enable, but still not connecting. Based on what I saw in the log (below) I took a bit of 
a stab in the dark and changed your
    if (state != MM_MODEM_STATE_ENABLED) {
to
    if ((state < MM_MODEM_STATE_ENABLED) || (state > MM_MODEM_STATE_REGISTERED)) {

This was a bit of a semi-educated guess, and may not the the correct/best mod. But it does then successfully 
complete the connection.

Tail end of log without the above mod:

Apr 20 07:39:57 wg2xx-tx6s ModemManager[1187]: <debug> [1492670397.997985] [src/mm-broadband-modem.c:6423] 
modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sr'
Apr 20 07:39:57 wg2xx-tx6s ModemManager[1187]: <debug> [1492670397.998137] [src/mm-broadband-modem.c:5533] 
mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SR), mem2 (none)...
Apr 20 07:39:57 wg2xx-tx6s ModemManager[1187]: <debug> [1492670397.998334] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 3 (open)
Apr 20 07:39:57 wg2xx-tx6s ModemManager[1187]: <debug> [1492670397.998590] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 2 (close)
Apr 20 07:39:57 wg2xx-tx6s ModemManager[1187]: <debug> [1492670397.998839] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CPMS="SR"<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.029293] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CPMS: 0,4,2,4,2,4<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.031883] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.032365] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.032704] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.033028] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CMGL=4<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.063921] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.064684] [src/mm-broadband-modem.c:5954] 
set_messaging_unsolicited_events_handlers(): (ttyMux1) Setting messaging unsolicited events handlers
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.064910] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.065346] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.065682] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CNMI=2,1,2,2,1<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.100938] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.101546] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.101816] [src/mm-broadband-modem.c:9609] 
enabling_step(): Modem has voice capabilities, enabling the Voice interface...
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.102550] [src/mm-broadband-modem.c:6591] 
set_voice_unsolicited_events_handlers(): (ttyMux1) Setting voice unsolicited events handlers
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.102913] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.103233] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CLIP=1<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.133054] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.133676] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CRC=1<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.164866] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.165371] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.165630] [src/mm-broadband-modem.c:9622] 
enabling_step(): Modem has time capabilities, enabling the Time interface...

Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: <info>  [1492670398.1759] (ttyMux1): modem state changed, 
'enabling' --> 'registered' (reason: user-requested)

Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <info>  [1492670398.166099] [src/mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling 
-> registered)

Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: <warn>  [1492670398.1861] modem-broadband[ttyMux1]: failed 
to connect modem: waited longer, still not enabled

Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.176956] [src/mm-iface-modem.c:1357] 
periodic_signal_quality_check_enable(): Periodic signal quality checks enabled (interval = 3s)
Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: <info>  [1492670398.1864] device (ttyMux1): state change: 
prepare -> failed (reason 'unknown') [40 120 1]
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.177162] [src/mm-broadband-modem.c:2065] 
modem_load_signal_quality(): loading signal quality...
Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: <warn>  [1492670398.2237] device (ttyMux1): Activation: 
failed for connection 'Vodafone'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.177367] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.177601] [src/mm-iface-modem.c:1077] 
periodic_access_technologies_check_enable(): Periodic access technology checks enabled
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.177818] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 3 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.196459] [src/mm-iface-modem-3gpp.c:798] 
mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 'yes', PS: 'yes', EPS: 'no')
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.196744] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 4 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.197003] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CSQ<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.226659] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CSQ: 13,99<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.237775] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.238415] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 3 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.239119] [src/mm-iface-modem.c:1206] 
update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (41)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.239290] [src/mm-iface-modem.c:1276] 
signal_quality_check_ready(): Periodic signal quality checks rescheduled (interval = 30s)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.245464] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT^SIND?<CR>'
Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: <info>  [1492670398.3443] device (ttyMux1): state change: 
failed -> disconnected (reason 'none') [120 30 0]
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.329535] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>^SIND: service,0,1<CR><LF>^SIND: message,0,0<CR><LF>^SIND: 
call,0,0<CR><LF>^SIND: roam,0,0<CR><LF>^SIND: smsfull,0,0<CR><LF>^SIND: rssi,0,2<CR><LF>^SIND: 
ciphcall,0,0<CR><LF>^SIND: simdata,0<CR><LF>^SIND: 
eons,0,4,"0076006F006400610066006F006E006500200055004B",""<CR><LF>^SIND: 
nitz,0,"00310037002F00300034002F00320030002C00300036003A00330039003A00340032",+04,1<CR><LF>^SIND: 
psinfo,0,10<CR><LF>^SIND: pacsp,0,99<CR><LF>^SIND: simtray,0,1<CR><LF>^SIND: vmwait,0,0<CR><LF>^SIND: 
lsta,0,0<CR><LF>^SIND: dtmf,0,1,0,0,0<CR><LF>^SIND: ecallco,0,0<CR><LF>^SIND: ecallda,0,0<CR><LF>^SIND: 
ecaller,0,0<CR><LF><CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.331229] [src/mm-iface-modem.c:935] 
mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology 
changed (unknown -> hsdpa, hsupa)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.331416] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 2 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.333821] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CREG?<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.364232] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CREG: 2,1,"037C","0288FCD9",6<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.375629] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.376127] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 3 (open)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.376377] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 2 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.376639] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CGREG?<CR>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.403635] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CGREG: 2,1,"037C","0288FCD9",6,"02"<CR><LF><CR><LF>OK<CR><LF>'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.404498] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: <debug> [1492670398.404783] [src/mm-broadband-modem.c:8871] 
modem_3gpp_run_registration_checks_ready(): Initial 3GPP registration checks finished
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: <debug> [1492670403.045901] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: <debug> [1492670403.046290] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT+CCLK?<CR>'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: <debug> [1492670403.076232] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>+CCLK: "04/01/01,00:07:30"<CR><LF>'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: <debug> [1492670403.081289] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: <debug> [1492670403.082500] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 1 (close)
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.051291] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.051670] [src/mm-broadband-modem.c:2065] 
modem_load_signal_quality(): loading signal quality...
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.051859] [src/mm-port-serial.c:1222] 
mm_port_serial_open(): (ttyMux1) device open count is 3 (open)
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.052128] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): --> 'AT^SIND?<CR>'
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.132368] [src/mm-port-serial-at.c:459] 
debug_log(): (ttyMux1): <-- '<CR><LF>^SIND: service,0,1<CR><LF>^SIND: message,0,0<CR><LF>^SIND: 
call,0,0<CR><LF>^SIND: roam,0,0<CR><LF>^SIND: smsfull,0,0<CR><LF>^SIND: rssi,0,2<CR><LF>^SIND: 
ciphcall,0,0<CR><LF>^SIND: simdata,0<CR><LF>^SIND: 
eons,0,4,"0076006F006400610066006F006E006500200055004B",""<CR><LF>^SIND: 
nitz,0,"00310037002F00300034002F00320030002C00300036003A00330039003A00340032",+04,1<CR><LF>^SIND: 
psinfo,0,10<CR><LF>^SIND: pacsp,0,99<CR><LF>^SIND: simtray,0,1<CR><LF>^SIND: vmwait,0,0<CR><LF>^SIND: 
lsta,0,0<CR><LF>^SIND: dtmf,0,1,0,0,0<CR><LF>^SIND: ecallco,0,0<CR><LF>^SIND: ecallda,0,0<CR><LF>^SIND: 
ecaller,0,0<CR><LF><CR><LF>OK<CR><LF>'
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: <debug> [1492670428.133620] [src/mm-port-serial.c:1279] 
_close_internal(): (ttyMux1) device open count is 2 (close)
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]