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. DanAttached.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
Attachment:
parallel-enable-debug.patch
Description: Text Data