Does this look like one which should be punted over to MM mailing list?
> On 20 April 2017 at 09:23 Colin Helliwell <[email protected]> > wrote: > > > 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]: [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,"00310037002F00300034002F00320030002C00300036003A00330039003A00340032",+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,"00310037002F00300034002F00320030002C00300036003A00330039003A00340032",+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 > [email protected] > https://mail.gnome.org/mailman/listinfo/networkmanager-list _______________________________________________ networkmanager-list mailing list [email protected] https://mail.gnome.org/mailman/listinfo/networkmanager-list
