> On 19 April 2017 at 19:06 Dan Williams <[email protected]> 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 <[email protected]> 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)
_______________________________________________
networkmanager-list mailing list
[email protected]
https://mail.gnome.org/mailman/listinfo/networkmanager-list
