Hey Peter, On Thu, Jan 13, 2022 at 3:22 PM Peter Naulls <pe...@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
