ANN: ModemManager 1.18.4 released / Avoiding PPP

[Aleksander Morgado]

Hey Peter,

On Thu, Jan 13, 2022 at 3:22 PM Peter Naulls <peter at chocky.org> wrote:
>
> On 1/13/22 5:08 AM, Aleksander Morgado wrote:
> > Hey Peter,
> >
>
> >
> > Unfortunately this log is missing the port notifications and the port
> > probing phase; so we cannot investigate why the QMI port was not
> > included in the modem object :/
> > We need the log including the port addition events until the modem
> > object is created; the connection attempt itself is really not needed
> > to debug this problem.
> >
>
> Ok, I think I got it.
>

Yes, this log is perfect to understand what happened, see the flow of
events below:

Wed Jan 12 19:32:35 2022 user.notice ModemManager: hotplug: add
network interface wwan0: event processed
Wed Jan 12 19:32:35 2022 user.notice ModemManager: hotplug: add cdc
interface cdc-wdm0: custom event processed
Wed Jan 12 19:32:36 2022 user.notice ModemManager: hotplug: add serial
interface ttyUSB0: event processed

// These 3 previous events for wwan0, cdc-wdm0 and ttyUSB0 go directly
to the cache exclusively, because MM is not running

Wed Jan 12 19:32:36 2022 daemon.info [2709]: <info>
[1642015956.367284] ModemManager (version 1.18.4) starting in system
bus...

// MM is already running now, and the next events for tty USB1,
ttyUSB2 and ttyUSB3 are notified to the daemon right away, and also
added in the cache

Wed Jan 12 19:32:37 2022 user.notice ModemManager: hotplug: add serial
interface ttyUSB1: event processed
Wed Jan 12 19:32:37 2022 daemon.debug [2709]: <debug>
[1642015957.539903] [base-manager] adding port ttyUSB1 at sysfs path:
/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.1/ttyUSB1/tty/ttyUSB1
Wed Jan 12 19:32:38 2022 user.notice ModemManager: hotplug: add serial
interface ttyUSB2: event processed
Wed Jan 12 19:32:38 2022 daemon.debug [2709]: <debug>
[1642015958.580584] [base-manager] adding port ttyUSB2 at sysfs path:
/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.2/ttyUSB2/tty/ttyUSB2

Wed Jan 12 19:32:39 2022 daemon.debug [2709]: <debug>
[1642015959.106244] [ttyUSB1/probe] GPS port detected
Wed Jan 12 19:32:39 2022 daemon.debug [2709]: <debug>
[1642015959.648717] [ttyUSB2/probe] port is AT-capable
Wed Jan 12 19:32:39 2022 daemon.debug [2709]: <debug>
[1642015959.651858] [plugin-manager] task 0: all port probings
completed, but not reached min probing time yet

// 2 full seconds elapsed since the last event reported for ttyUSB2,
so ModemManager thinks no more ports will be notified in the modem,
and ends up creating the modem object with only these 2 ttyUSB1 and
ttyUSB2 ports

Wed Jan 12 19:32:40 2022 daemon.info [2709]: <info>
[1642015960.093395] [device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1] creating modem with
plugin 'quectel' and '2' ports

// A bit later, we still receive the event for ttyUSB3, notified
directly to the daemon

Wed Jan 12 19:32:40 2022 user.notice ModemManager: hotplug: add serial
interface ttyUSB3: event processed

// And some short time later on we start receiving the events from the
cache for wwan0, cdc-wdm0 and ttyUSB0

Wed Jan 12 19:32:40 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
Wed Jan 12 19:32:41 2022 daemon.debug [2709]: <debug>
[1642015961.010150] [base-manager] additional port ttyUSB3 in device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1
Wed Jan 12 19:32:41 2022 daemon.debug [2709]: <debug>
[1642015961.049996] [base-manager] additional port wwan0 in device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1
Wed Jan 12 19:32:41 2022 user.notice ModemManager: hotplug: cached
event found: action=add, name=ttyUSB0, subsystem=tty,
sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.0/ttyUSB0/tty/ttyUSB0
Wed Jan 12 19:32:41 2022 daemon.debug [2709]: <debug>
[1642015961.121626] [base-manager] additional port cdc-wdm0 in device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1
Wed Jan 12 19:32:41 2022 daemon.debug [2709]: <debug>
[1642015961.314655] [base-manager] additional port ttyUSB0 in device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1

So, the problem is the timing here exclusively, there is no failed QMI
protocol probing. This system you're running seems to be a bit slow,
and the events reported are taking a lot of time to complete before
the next one can be processed; we should definitely fix this in
ModemManager so that we can handle these type of systems as well.

For a quick workaround in your case, can you try modifying
EXTRA_PROBING_TIME_MSECS in mm-plugin-manager.c and change it from
1500 to something bigger like e.g. 3000 or 4000?

There's one thing clear though; the longer timeout should not be
applied by default, as that would impose an extra wait time that is
not needed in most cases. I think we can make this more specific to
setups like yours, e.g. making the longer timeout happen only for
openwrt setups (when udev is not available) and also maybe applicable
only during MM daemon startup (e.g. if the port addition happened in
the first 10s of the MM daemon startup, allow a bigger extra probing
time). What do you think?

-- 
Aleksander
https://aleksander.es