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
diff --git a/src/mm-broadband-modem.c b/src/mm-broadband-modem.c
index b480255..dee67df 100644
--- a/src/mm-broadband-modem.c
+++ b/src/mm-broadband-modem.c
@@ -9444,11 +9444,45 @@ enabling_started_ready (MMBroadbandModem *self,
}
static void
+enabling_wait_for_final_state_ready2 (MMIfaceModem *self,
+ GAsyncResult *res,
+ EnablingContext *ctx)
+{
+ GError *error = NULL;
+ MMModemState state = MM_MODEM_STATE_UNKNOWN;
+
+ ctx->previous_state = mm_iface_modem_wait_for_final_state_finish (self, res, &error);
+ if (error) {
+ g_simple_async_result_take_error (ctx->result, error);
+ enabling_context_complete_and_free (ctx);
+ return;
+ }
+
+ g_object_get (self,
+ MM_IFACE_MODEM_STATE, &state,
+ NULL);
+
+ if (state != MM_MODEM_STATE_ENABLED) {
+ g_simple_async_result_take_error (ctx->result,
+ g_error_new_literal (MM_CORE_ERROR,
+ MM_CORE_ERROR_FAILED,
+ "waited longer, still not enabled"));
+ enabling_context_complete_and_free (ctx);
+ return;
+ }
+
+ /* We're enabled now, go on */
+ g_simple_async_result_set_op_res_gboolean (ctx->result, TRUE);
+ enabling_context_complete_and_free (ctx);
+}
+
+static void
enabling_wait_for_final_state_ready (MMIfaceModem *self,
GAsyncResult *res,
EnablingContext *ctx)
{
GError *error = NULL;
+ MMModemState state = MM_MODEM_STATE_UNKNOWN;
ctx->previous_state = mm_iface_modem_wait_for_final_state_finish (self, res, &error);
if (error) {
@@ -9457,6 +9491,20 @@ enabling_wait_for_final_state_ready (MMIfaceModem *self,
return;
}
+ g_object_get (self,
+ MM_IFACE_MODEM_STATE, &state,
+ NULL);
+ if (state == MM_MODEM_STATE_ENABLING) {
+ g_message ("######## parallel enables!");
+
+ mm_iface_modem_wait_for_final_state (MM_IFACE_MODEM (ctx->self),
+ MM_MODEM_STATE_UNKNOWN, /* just any */
+ (GAsyncReadyCallback)enabling_wait_for_final_state_ready2,
+ ctx);
+ return;
+ }
+
+
if (ctx->previous_state >= MM_MODEM_STATE_ENABLED) {
/* Just return success, don't relaunch enabling */
g_simple_async_result_set_op_res_gboolean (ctx->result, TRUE);
_______________________________________________
networkmanager-list mailing list
[email protected]
https://mail.gnome.org/mailman/listinfo/networkmanager-list
