On Mon, 2017-04-24 at 14:08 +0100, Colin Helliwell wrote: > Does this look like one which should be punted over to MM mailing > list?
Most definitely. Dan > > On 20 April 2017 at 09:23 Colin Helliwell <colin.helliwell@ln- > > systems.com> 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,"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 > > [email protected] > > https://mail.gnome.org/mailman/listinfo/networkmanager-list _______________________________________________ networkmanager-list mailing list [email protected] https://mail.gnome.org/mailman/listinfo/networkmanager-list
