ModemManager allows connection before modem fully enabled

Submitted by Ladislav Michl

Assigned to ModemManager bug user

Link to original bug (#106468)

Description

Created attachment 139480 Complete journal with debug enabled for ModemManager and NetworkManager

SimpleConnect does not block until the modem is actually done enabling itself leading to endless loop - see attached log.

Attachment 139480, "Complete journal with debug enabled for ModemManager and NetworkManager":
journal.log

Version: git master

Aleksander Morgado said:

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

Dan Williams @dcbw said:

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.

Ladislav Michl uploaded an attachment:

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.

Attachment 139588, "Complete journal with debug enabled for ModemManager and NetworkManager and patch applied":
xxx

Ladislav Michl uploaded an attachment:

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

Attachment 139589, "nm-1.11.3, mm-git":
log

Dan Williams @dcbw said:

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.'

mentioned in commit 746cf54b

mentioned in commit 1f1fb47c

mentioned in commit a77beaa2

What's the progress on this? Do you need help? I have this modem and ubuntu 18.04 installed. I can test stuff if you point me in the right direction.

As Dan said, this issue seems to be a race condition on the enabling phase. Looks like if two Enable() operations are queued one after the other, it may happen that both are run and the port flashing step fails. I was thinking in fix the actual race condition, but maybe the good fix is to allow multiple Enable() operations in parallel (i.e. just have the first one run and all the other ones scheduled a the same time wait for the result of the first one). Will try to prepare a fix in the following weeks.

mentioned in commit 5e53cd0a

@dansta could you try the branch in this MR? !19 (merged)

Here's a quick test of both ModemManager-1.8.0 (k1_log) and aleksander/parallel-enable git branch (k2_log). k1_log.txtk2_log.txt

mentioned in commit c4766122

Branch was merged already to git master

closed

mentioned in commit e67e6a52

mentioned in commit 48d2fa39

mentioned in commit 2e6bcd31

mentioned in commit 63c8f509

mentioned in commit ef942ca5

mentioned in commit bb0820d0

mentioned in commit 50fc46c1

mentioned in commit fae089b7

mentioned in commit f1a781f5

mentioned in merge request !145 (closed)

mentioned in commit 6e8f36a6

mentioned in commit f3f05f39

mentioned in commit 3d5a994c

mentioned in commit 2ed8ee52

mentioned in merge request !525 (merged)

mentioned in commit ace5d2db

mentioned in commit 293c2c40