Sixfab LTE hat - no modems were found

Product support balenaOS
1

Hi,

I got a Sixfab LTE hat with Quectel modem connected to my Pi3. It´s connected both trough GPIO and USB cable. The thing is that the modem is not found when booted up:

root@4838211:~# mmcli -L
No modems were found

Shortly after I have scan for devices (mmcli -S) it appears in the list …

root@4838211:~# mmcli -L
/org/freedesktop/ModemManager1/Modem/0 [QUALCOMM INCORPORATED] QUECTEL Mobile Broadband Module

… and a few seconds later it receive an IP address from the mobile network and is good to go.

Is this a common issue?

Thanks,
Mikael

4

Hello @nosslrak

Which Quectel modem are you using?

Could you also try only plugging the USB cable to the HAT? By this I mean without connecting the header. With this setup you should be able to see the modem listed with lsusb and on mmcli.

Let us know how that test goes.
Cheers,
Nico.

6

Hey @nosslrak

Does the modem not get automatically exposed on boot even if you wait a long time?

If you really require a manual scan request (mmcli -S) it could be because the port probing done when the ports are exposed in the system are not waiting long enough for the modem system to boot. Ideally, we can know this by looking at the ModemManager debug log; could you update its init script so that it runs with --debug and then post the full MM log for analysis while you reproduce the issue?

8

Hi
@ntzovanis

I’m using Quectel EC25-E. I tried your suggestion but the modem is still not in the list (mmcli -L) until I scan for it, mmcli -S.

@aleksander0m

No, I have waited for like 30-40 minutes. I’m not sure how to update the script since I can’t write to modemmanager.conf. Please have a look at attached file regarding logs.

modemmanger.log (15.2 KB)

10

Hi @nosslrak,

I do not think ModemManager was running in debug mode.

This is the systemd unit file for starting the ModemManager service - https://github.com/balena-os/meta-balena/blob/master/meta-balena-common/recipes-connectivity/modemmanager/balena-files/ModemManager.conf.systemd. You need to add --debug as a parameter.

You may find where it is located on the filesystem with find / -name ModemManager.*. After this you can edit it with vi. Since the root partition is mounted as read-only by default, you can remount it as rw before editing the file: mount -o remount, rw /. After you reboot the device ModemManager should be running in debug mode.

12

@majorz You are correct. I was not able to enable debug in the beginning.

Log with debug attached.

modemmanager_debug.log (155.8 KB)

Thanks,
Mikael

13

Hi @nosslrak,

Can you please reboot the device and upload the ModemManager logs again? Just to have another set of logs to double check something.

Thanks,
Zahari

15

modemmanager_debug2.log (157.0 KB)

Thanks,
Mikael

17

Thanks for providing the logs. I see ModemManager is able to establish communication with the modem successfully, but then the ports gets added again for some reason. Let’s see whether @aleksander0m has some insights about the logs as he is actually the ModemManager author.

19

@nosslrak not sure I’ve ever seen a sequence like that one, it’s very strange, I’m now wondering whether the udev events are being processed correctly or not, because that “cancelled probing” doesn’t make much sense, unless the device is going away during the port probing phase.

Would it be too much to ask to get both MM debug logs and dmesg (kernel logs) while reproducing the issue? We need to confirm whether the device is truly going away or whether this is a bug in MM when processing the udev events.

21

kernel and mm logs
journalctl-k.log (28.4 KB)
journalctl-u_modemmanager.log (154.1 KB)

Thanks,
Mikael

23

Ok, this doesn’t make any sense:

Aug 31 18:45:10 4838211 ModemManager[1282]: [1598899510.133490] (usbmisc/cdc-wdm0): adding device at sysfs path: /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.4/usbmisc/cdc-wdm0
Aug 31 18:45:10 4838211 ModemManager[1282]: [1598899510.134702] [filter] (usbmisc/cdc-wdm0) port allowed: cdc-wdm device
Aug 31 18:45:10 4838211 ModemManager[1282]: [1598899510.134811] (usbmisc/cdc-wdm0): first port in device /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3
Aug 31 18:45:10 4838211 ModemManager[1282]: [1598899510.134940] [plugin manager] task 2: new support task for device: /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3
Aug 31 18:45:10 4838211 ModemManager[1282]: [1598899510.135349] [plugin manager] task 2: port grabbed: cdc-wdm0
....
Aug 31 18:45:12 4838211 ModemManager[1282]: [1598899512.278835] (usbmisc/cdc-wdm0) port is QMI-capable
Aug 31 18:45:12 4838211 ModemManager[1282]: [1598899512.279363] [plugin manager] task 2,cdc-wdm0: found best plugin for port (Quectel)
Aug 31 18:45:12 4838211 ModemManager[1282]: [1598899512.279488] [plugin manager] task 2,cdc-wdm0: finished in '2.144050' seconds
Aug 31 18:45:12 4838211 ModemManager[1282]: [1598899512.279558] [plugin manager] task 2,cdc-wdm0: best plugin matches device reported one: Quectel
...
Aug 31 18:45:16 4838211 ModemManager[1282]: [1598899516.312813] (usbmisc/cdc-wdm0): adding device at sysfs path: /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.4/usbmisc/cdc-wdm0
Aug 31 18:45:16 4838211 ModemManager[1282]: [1598899516.314205] [filter] (usbmisc/cdc-wdm0) port allowed: cdc-wdm device
Aug 31 18:45:16 4838211 ModemManager[1282]: [1598899516.314387] (usbmisc/cdc-wdm0): port already added
...
Aug 31 18:45:18 4838211 ModemManager[1282]: [1598899518.050628] (usbmisc/cdc-wdm0): adding device at sysfs path: /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.4/usbmisc/cdc-wdm0
Aug 31 18:45:18 4838211 ModemManager[1282]: [1598899518.050852] (usbmisc/cdc-wdm0): released by device '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3'
Aug 31 18:45:18 4838211 ModemManager[1282]: [1598899518.050969] [plugin manager] task 2: port released: cdc-wdm0
Aug 31 18:45:18 4838211 ModemManager[1282]: [1598899518.051021] [plugin manager] task 2: port wasn't found: cdc-wdm0

It looks as if udev is notifying over and over again the same events for the same ports (e.g. for cdc-wdm0 we are getting 3 separate notifications at 18:45:10, 18:45:16 and 18:45:18).

The first notification triggers the port probing, which is fine.
The second notification is ignored because the port is still being probed.
The third notification ends up breaking the logic because MM thinks the port is being re-notified as new while it has already been probed (but full device probing is still ongoing)

MM should definitely ignore that 3rd notification, i.e. all “add” events for a given port should be ignored if the port has already been probed and added in a device.

BUT why are we getting so many udev (add or bind) notifications for all ports? I can see multiple notifications not only for cdc-wdm0, but also for the serial ports, for wlan0, etc. It doesn’t make sense. @majorz any idea why this is happening?

Keeping track of the MM bugfix here: https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/issues/255

24

Hey @aleksander0m, thanks for looking into it! My suspicion is that the balenaEngine/Docker daemon spawns a container running another udev instance that triggers those events. I encountered similar issues in the past. I am going to run some tests today and see whether this is indeed the case.

25

Ok, analyzed the issue inside ModemManager and it is not a MM problem after all. What I can see is that the 3rd “add” event reported by udev for the cdc-wdm port ends up without the ID_MM_CANDIDATE tag applied.

This tag is applied to all cdc-wdm ports for “add”, “change”, “move” or “bind” events:

ACTION!="add|change|move|bind", GOTO="mm_candidate_end"
KERNEL=="cdc-wdm*", SUBSYSTEM=="usb", ENV{ID_MM_CANDIDATE}="1"
KERNEL=="cdc-wdm*", SUBSYSTEM=="usbmisc", ENV{ID_MM_CANDIDATE}="1"
LABEL="mm_candidate_end"

So the question now is, was there any additional event (not “add” or “change” or “move” or “bind”) that triggered the removal of the udev tags? And if so, how come we’re getting a new “add” event without those tags applied?

@nosslrak could you run udevadm monitor at the same time as all the other stuff is happening? That could give us some hints.

26

@majorz see that last comment I added, the key is to know why the ID_MM_CANDIDATE tag is suddenly gone for the port while “add” events are still being notified.

28

@aleksander0m Thanks for all the support with this! I could not reproduce the issue with the same modem model and the Sixfab hat, so my only guess is that it is an udev instance running in a container separately.

@nosslrak Can you please try connecting the modem without any application pushed (no containers)? At this point I assume it is an udev instance running in the container that is interfering with the modem - this should not happen by default unless the Dockerfile has an UDEV=on. If the bug still occurs, I would need to check a device of yours with support access enabled through the dashboard.

30

@majorz I moved it to an “clean” application without any container(s) and yes, it worked right from the start!

I’m trying to build a TTN gateway based on https://github.com/jpmeijers/ttn-resin-gateway-rpi. When checking its Dockerfile it has ENV UDEV=off.

Thanks,
Mikael

33

Hi Mikael,

I checked the sources of this quickly and nothing sticks out as a possible reason. I will try to find time early next week to run this and see what’s happening.

Thanks,
Zahari

36

Hi, I pushed the application you pointed to, but the modem is appearing after reboot.

Thanks,
Zahari

41

My application turned out to be about 2 years old. “ENV UDEV=off” was added March 2019.

Apologize for the mess @majorz and @aleksander0m and thanks for your help!

1 Like