ANN: ModemManager 1.18.4 released / Avoiding PPP

[Aleksander Morgado]

Hey

> > Also, please note that if you fully disable the PPP usage (maybe
> > making sure that data_at_primary is always NULL in
> > mm_base_modem_organize_ports()), what you will achieve is that the
> > modem ends up not usable ("Failed to find a data port in the modem").
> > You need to decide whether that's better than falling back to PPP. As
> > said in an earlier email, the key would be to understand why you don't
> > have a valid QMI+NET pair, not really to disable the PPP usage (IMO).
>
> Well, it took me a while to get this; it requires a specific setup.  What I can
> say is that it most often happens at OpenWrt boot, but by no means always.
>

There's a problem in that log, and the problem is exclusively
happening on system boots. When the system boots, modem ports may be
detected BEFORE ModemManager has even started; what we do in the
hotplug script is to add these events in a "cache" of events that will
be processed by the ModemManager init script upon boot. The init
script will run the daemon, and right away run
"mm_report_events_from_cache" which should go over all the events in
the cache and report them one by one again to MM, as if they had just
happened. This is a bit weird, but it fits very well with the logic
applied by the normal usecase when using udev.

Now, what I can see in your logs is that the cdc-wdm port and net port
are detected way before MM has started, so they're added to the cache.
But then, MM starts, and some of the ttyUSB events don't reach the
cache because MM has already started, so they're reported to MM right
away. The final outcome is that MM creates the modem with the ttyUSB
ports that were detected during runtime and we miss all the ports that
had hit the cache, which are reported later on:

> Tue Jan 11 18:08:55 2022 daemon.info [2757]: <info>  [1641924535.408371] [device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1] creating modem with plugin
'quectel' and '2' ports
...
Tue Jan 11 18:08:56 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=wwan0, subsystem=net,
sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.4/net/wwan0
Tue Jan 11 18:08:56 2022 daemon.info [2757]: <info>  [1641924536.122148]
[base-manager] modem for device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
successfully created
Tue Jan 11 18:08:56 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=cdc-wdm0, subsystem=usbmisc,
sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.4/net/wwan0

I believe this is a regression in the openwrt packaging. In the
original implementation I did some time ago, we call
mm_report_events_from_cache BEFORE MM even starts, and that function
will make sure to emit the events as soon as MM is ready to receive
them (so the events in the cache are reported at the same time as
realtime events happening). This logic is the one available in the
openwrt-21.02 branch, if you want to look at it.

In the openwrt git master branch (which I believe it's what you're
using) that logic was updated to use a new wrapper script in
/usr/sbin/ModemManager-wrapper, and this scripts introduces a bogus
"sleep 2" in between the MM start and the call to
mm_report_events_from_cache:

        /usr/sbin/ModemManager "$@" 1>/dev/null 2>/dev/null &
        CHILD="$!"
        sleep 2
        mm_report_events_from_cache

I think that sleep is breaking the modem detection here, because the
realtime events are reported as soon as MM is detected, and the cached
ones are reported more than 2s later, and MM has a strict timing of
how long to wait for new port events since the last port event has
happened.

Can you edit your /usr/sbin/ModemManager-wrapper and remove that
"sleep 2" completely?

-- 
Aleksander
https://aleksander.es