Bug 106468

Oh wow, how unfortunate this is, yes, this is not good.

The specific issue is that:

1) modem begins enabling due to SimpleConnect request (state -> enabling)
2) modem has Location capabilities, enables the Location interface
3) Location enable explicitly runs mm_iface_modem_3gpp_run_registration_checks() to get LAC/CI
4) mm-broadband-modem.c::run_registration_checks_context_step() calls AT+CREG?
5) CREG indicates modem is registered and valid MCC/MNC; mm-broadband-modem.c::registration_status_check_ready() calls mm-iface-modem-3gpp.c::mm_iface_modem_3gpp_update_ps_registration_state()
6) mm-iface-modem-3gpp.c::update_registration_state() has this code:

        if (modem_state < MM_MODEM_STATE_ENABLING) {
            mm_dbg ("Modem %s: 3GPP Registration state change ignored as modem isn't enabled",
                    g_dbus_object_get_object_path (G_DBUS_OBJECT (self)));
            return;
        }

which came from Ben Chan's recent commit "iface-modem-3gpp: ignore initial registration check result when appropriate", which was an attempt to handle this case, but only for state < ENABLING.  Unfortunately here, our state is ENABLING so this check doesn't trigger.

Could we adjust that < ENABLING check to be < ENABLED?  We already have a schedule_initial_registration_checks() call for ENABLING_STEP_LAST.

Created attachment 139588 [details]
Complete journal with debug enabled for ModemManager and NetworkManager and patch applied

Tested with today's git version of both mm and nm with patch applied:
--- a/src/mm-iface-modem-3gpp.c
+++ b/src/mm-iface-modem-3gpp.c
@@ -1342,7 +1342,7 @@ update_registration_state (MMIfaceModem3gpp *self,
         g_object_get (self,
                       MM_IFACE_MODEM_STATE, &modem_state,
                       NULL);
-        if (modem_state < MM_MODEM_STATE_ENABLING) {
+        if (modem_state < MM_MODEM_STATE_ENABLED) {
             mm_dbg ("Modem %s: 3GPP Registration state change ignored as modem isn't enabled",
                     g_dbus_object_get_object_path (G_DBUS_OBJECT (self)));
             return;

Does not even unlock modem, but given that I do not see above mm_dbg line in the log, it is probably not related to the proposed change. Debug log provided just for completeness, I will retest with latest development snapshots.

Created attachment 139589 [details]
nm-1.11.3, mm-git

Retested with nm-1.11.3, mm version is the same (including patch)
Again, condition < ENABLED is not triggered.

$ mmcli -m 0 --location-get

/org/freedesktop/ModemManager1/Modem/0                                                                                   
  -------------------------                                                                                              
  3GPP location   | Mobile country code: '230'                                                                           
                  | Mobile network code: '2'                                                                             
                  |  Location area code: '1621'                                                                          
                  |             Cell ID: '265500017'
  -------------------------
  GPS NMEA traces | Not available
  -------------------------
  Raw GPS         | Not available
  -------------------------
  CDMA BS         | Not available

The problem in the latest logs appears to be a double-flash on enable, which could only occur if there is a race where two enable processes occur in parallel:

Apr 01 02:01:54 simear ModemManager[304]: <info>  Simple connect started...
Apr 01 02:01:54 simear ModemManager[304]: <debug>    PIN: 8888
Apr 01 02:01:54 simear ModemManager[304]: <debug>    Operator ID: unspecified
Apr 01 02:01:54 simear ModemManager[304]: <debug>    Allowed roaming: yes
Apr 01 02:01:54 simear ModemManager[304]: <debug>    APN: op.mediaresearch
Apr 01 02:01:54 simear ModemManager[304]: <debug>    IP family: ipv4
Apr 01 02:01:54 simear ModemManager[304]: <debug>    Allowed authentication: unspecified
Apr 01 02:01:54 simear ModemManager[304]: <debug>    User: unspecified
Apr 01 02:01:54 simear ModemManager[304]: <debug>    Password: unspecified
Apr 01 02:01:54 simear ModemManager[304]: <debug>    Number: unspecified
Apr 01 02:01:54 simear ModemManager[304]: <info>  Simple connect state (3/8): Enable
Apr 01 02:01:54 simear ModemManager[304]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2) opening serial port...
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2): setting up baudrate: 57600
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2): port attributes not fully set
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2) device open count is 1 (open)
Apr 01 02:01:54 simear ModemManager[304]: <debug> Flashing primary AT port before enabling...
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2): port attributes not fully set
Apr 01 02:01:54 simear ModemManager[304]: <debug> (ttyUSB2) device open count is 2 (open)
Apr 01 02:01:54 simear ModemManager[304]: <debug> Flashing primary AT port before enabling...
Apr 01 02:01:54 simear NetworkManager[320]: <warn>  [1522540914.6677] modem-broadband[ttyUSB2]: failed to connect modem: Primary port flashing failed: Modem is already being flashed.
Apr 01 02:01:54 simear ModemManager[304]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> disabled)
Apr 01 02:01:54 simear NetworkManager[320]: <debug> [1522540914.6680] modem-broadband[ttyUSB2]: unmapped error detected: 'Primary port flashing failed: Modem is already being flashed.'

-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/mobile-broadband/ModemManager/issues/8.