On 20 April 2017 at 09:23 Colin Helliwell <colin.helliwell@ln-
systems.com> wrote:
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]: [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]: [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]: [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]: [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]: [1492670397.998839]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CPMS="SR"'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.029293]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '+CPMS:
0,4,2,4,2,4'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.031883]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [1492670398.033028]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CMGL=4'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.063921]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [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]: [1492670398.065682]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CNMI=2,1,2,2,1'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.100938]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [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]: [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]: [1492670398.103233]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CLIP=1'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.133054]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.133676]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CRC=1'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.164866]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [1492670398.1759]
(ttyMux1): modem state changed, 'enabling' --> 'registered'
(reason: user-requested)
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [1492670398.1861]
modem-broadband[ttyMux1]: failed to connect modem: waited longer,
still not enabled
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [1492670398.1864]
device (ttyMux1): state change: prepare -> failed (reason
'unknown') [40 120 1]
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.177162]
[src/mm-broadband-modem.c:2065] modem_load_signal_quality():
loading signal quality...
Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: [1492670398.2237]
device (ttyMux1): Activation: failed for connection 'Vodafone'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [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]: [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]: [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]: [1492670398.197003]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'AT+CSQ'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.226659]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '+CSQ:
13,99'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.237775]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [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]: [1492670398.245464]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT^SIND?'
Apr 20 07:39:58 wg2xx-tx6s NetworkManager[1154]: [1492670398.3443]
device (ttyMux1): state change: failed -> disconnected (reason
'none') [120 30 0]
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.329535]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '^SIND:
service,0,1^SIND: message,0,0^SIND: call,0,0^SIND: roam,0,0^SIND:
smsfull,0,0^SIND: rssi,0,2^SIND: ciphcall,0,0^SIND: simdata,0^SIND:
eons,0,4,"0076006F006400610066006F006E006500200055004B",""^SIND:
nitz,0,"00310037002F00300034002F00320030002C00300036003A00330039003
A00340032",+04,1^SIND: psinfo,0,10^SIND: pacsp,0,99^SIND:
simtray,0,1^SIND: vmwait,0,0^SIND: lsta,0,0^SIND:
dtmf,0,1,0,0,0^SIND: ecallco,0,0^SIND: ecallda,0,0^SIND:
ecaller,0,0OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [1492670398.333821]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CREG?'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.364232]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '+CREG:
2,1,"037C","0288FCD9",6'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.375629]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [1492670398.376639]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CGREG?'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [1492670398.403635]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '+CGREG:
2,1,"037C","0288FCD9",6,"02"OK'
Apr 20 07:39:58 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [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]: [1492670403.046290]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT+CCLK?'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: [1492670403.076232]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '+CCLK:
"04/01/01,00:07:30"'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: [1492670403.081289]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'OK'
Apr 20 07:40:03 wg2xx-tx6s ModemManager[1187]: [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]: [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]: [1492670428.051670]
[src/mm-broadband-modem.c:2065] modem_load_signal_quality():
loading signal quality...
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: [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]: [1492670428.052128]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
'AT^SIND?'
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: [1492670428.132368]
[src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '^SIND:
service,0,1^SIND: message,0,0^SIND: call,0,0^SIND: roam,0,0^SIND:
smsfull,0,0^SIND: rssi,0,2^SIND: ciphcall,0,0^SIND: simdata,0^SIND:
eons,0,4,"0076006F006400610066006F006E006500200055004B",""^SIND:
nitz,0,"00310037002F00300034002F00320030002C00300036003A00330039003
A00340032",+04,1^SIND: psinfo,0,10^SIND: pacsp,0,99^SIND:
simtray,0,1^SIND: vmwait,0,0^SIND: lsta,0,0^SIND:
dtmf,0,1,0,0,0^SIND: ecallco,0,0^SIND: ecallda,0,0^SIND:
ecaller,0,0OK'
Apr 20 07:40:28 wg2xx-tx6s ModemManager[1187]: [1492670428.133620]
[src/mm-port-serial.c:1279] _close_internal(): (ttyMux1) device
open count is 2 (close)
_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
