Hello!
I am currently using my EM7565 mostly as a backup link, connected to a
Linksys WRT1900ACv1 running a recent OpenWrt build, using the current
ModemManager package there. I find this setup very convenient for
occasional testing of QMI or ModemManager stuff, whether it is OpenWrt
related or not.
My modem testing is spurious nowadays, so there are often long periods
where I don't look at this modem link at all.
But when I did yesterday, I was surprised to learn that it had been down
for a couple of weeks. ModemManager was still running and the netdev was
up and running, and still configured with the IP config it had when the
link went down. This was therefore hard to notice without actually
looking at mmcli output or trying to use the link.
So I had
root@wrt1900ac-1:~# ifconfig -a
..
wwan0 Link encap:UNSPEC HWaddr
00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
inet addr:46.66.177.154 P-t-P:46.66.177.154 Mask:255.255.255.252
inet6 addr: fe80::7a7d:7a05:fe59:c843/64 Scope:Link
UP POINTOPOINT RUNNING NOARP MULTICAST MTU:1500 Metric:1
RX packets:67346 errors:0 dropped:0 overruns:0 frame:0
TX packets:55018 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 txqueuelen:1000
RX bytes:3178928 (3.0 MiB) TX bytes:2319172 (2.2 MiB)
and
root@wrt1900ac-1:~# uptime
20:00:01 up 39 days, 1:43, load average: 0.00, 0.00, 0.00
root@wrt1900ac-1:~# ps w|grep Modem
2234 root 12380 S /usr/sbin/ModemManager
22729 root 1072 S grep Modem
But there was no modem, according to ModemManager (this was what made me
notice the problem):
root@wrt1900ac-1:~# mmcli -L
No modems were found
If the modem was diconnected from the bus, then there obviously wouldn't
have been any wwan0 netdev either. Anyway, lsusb confirmed that it was
still there:
root@wrt1900ac-1:~# lsusb
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 1608:0001 Inside Out Networks [hex] EdgePort/4 Serial
Port
Bus 003 Device 002: ID 1199:9091 Sierra Wireless, Inc.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Looking in the log I found part of the explanation. This started
happening once a day or so, but not periodical, on April 4th:
Apr 4 12:00:10 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home
-> idle)
Apr 4 12:00:10 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connected -> enabled)
Apr 4 12:00:11 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle
-> registering)
Apr 4 12:00:11 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(registering -> home)
Apr 4 12:00:11 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
Then on April 13th, this happeed:
Apr 13 23:50:37 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home
-> idle)
Apr 13 23:50:37 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered -> enabled)
Apr 13 23:50:37 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle
-> registering)
Apr 13 23:50:37 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(registering -> home)
Apr 13 23:50:37 wrt1900ac-1.mork.no [2234]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
Apr 13 23:50:45 wrt1900ac-1.mork.no [2234]: <error> (tty/ttyUSB6) at port timed
out 10 consecutive times, marking modem
'/org/freedesktop/ModemManager1/Modem/0' as invalid
And that was it. No more messages from ModemManager at all, except for
a series of wlan hotplug events when I restarted the wifi for some other
changes.
Restarting made ModemManager rediscover the modem and reconnect without
any complaints:
Apr 24 20:16:20 wrt1900ac-1.mork.no [2234]: <info> ModemManager is shut down
Apr 24 20:16:20 wrt1900ac-1.mork.no netifd: mm (23140): error: couldn't find
the ModemManager process in the bus
Apr 24 20:16:20 wrt1900ac-1.mork.no [23186]: <info> ModemManager (version
1.12.6) starting in system bus...
..
Apr 24 20:16:24 wrt1900ac-1.mork.no [23186]: <info> Modem for device
'/sys/devices/platform/soc/soc:pcie@82000000/pci0000:00/0000:00:01.0/0000:01:00.0/usb3/3-2'
successfully created
Apr 24 20:16:27 wrt1900ac-1.mork.no ModemManager: hotplug: error: modem not
detected at sysfs path
Apr 24 20:16:27 wrt1900ac-1.mork.no [23186]: <info> Modem: state changed
(unknown -> disabled)
Apr 24 20:16:32 wrt1900ac-1.mork.no ModemManager: hotplug: modem exported
successfully at
/sys/devices/platform/soc/soc:pcie@82000000/pci0000:00/0000:00:01.0/0000:01:00.0/usb3/3-2
Apr 24 20:16:32 wrt1900ac-1.mork.no ModemManager: hotplug: setting interface
'mm' as available
Apr 24 20:16:32 wrt1900ac-1.mork.no netifd: mm (23971): modem available at
/org/freedesktop/ModemManager1/Modem/0
Apr 24 20:16:32 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Apr 24 20:16:38 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> enabled)
Apr 24 20:16:38 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(unknown -> registering)
Apr 24 20:16:38 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(registering -> home)
Apr 24 20:16:38 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
Apr 24 20:16:39 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Apr 24 20:16:39 wrt1900ac-1.mork.no [23186]: <info> Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
I haven't yet seen any of those "Registration state changed" messages
after this, but that might be because I haven't waited long enough.
It's only been 16 hours since the restart, and there were sometimes more
than 2 days between those events.
I wonder what really happened here, and if this is how it should work?
I assume the "(tty/ttyUSB6) at port timed out 10 consecutive times" is a
real error, for unknown reasons. What's worrying me is how it is
handled. I do not expect the modem to disconnect and disappear from
ModemManager due to an error like this, which seems to be related to the
optional at port only. Giving up seems excessive. Restart is fine as a
last resort. Stop is not.
The error could of course be a symptom of even more serious modem
issues, causing the modem to disconnect by itself. But it definitely did
not crash. In fact, it has been up twice as long as the OpenWrt system
(and now I learned that this system doesn't cut USB power on reboot):
root@wrt1900ac-1:~# adb shell
* daemon not running. starting it now on port 5037 *
* daemon started successfully *
/ # uptime
10:42:41 up 83 days, 22:01, load average: 1.15, 1.07, 1.11
/ # uname -a
Linux mdm9650-perf 3.18.31 #1 PREEMPT Fri Jun 28 15:38:03 UTC 2019 armv7l
GNU/Linux
There is no indication that it did any USB device controller reset or
anything as such either. These are the last kernel messages from the
modem:
[ 34.011694] random: nonblocking pool is initialized
[ 60.640187] sierra_startup_monitor
[1905553.592945] msm-dwc3 8a00000.ssusb: Avail curr from USB = 0
[1905553.592997] diag: USB channel diag disconnected
[1905553.593840] dwc3 8a00000.dwc3: request c6068b00 was not queued to ep0out
[1905553.598936] android_work: android_work: sent uevent USB_STATE=DISCONNECTED
[1905553.648641] dwc3 8a00000.dwc3: failed to stop controller
[1905553.648920] read descriptors
[1905553.648938] read strings
[1905553.648971] Match for Function Name: diag, Int #0
[1905553.648979] name:diag, interface id:0, id:0
[1905553.649016] Match for Function Name: Function FS Gadget, Int #1
[1905553.649024] name:Function FS Gadget, interface id:1, id:1
[1905553.649038] Match for Function Name: nmea, Int #2
[1905553.649045] name:nmea, interface id:2, id:2
[1905553.649066] Match for Function Name: modem, Int #3
[1905553.649073] name:modem, interface id:3, id:3
[1905553.649097] Match for Function Name: rmnet, Int #8
[1905553.649103] name:rmnet, interface id:8, id:4
[1905553.649124] msm-dwc3 8a00000.ssusb: ep [gsi-epin,29] already configured as
msm endpoint
[1905553.649135] msm-dwc3 8a00000.ssusb: ep [gsi-epout,30] already configured
as msm endpoint
[1905553.701059] android_work: android_work: did not send uevent (0 0 00000000)
[1905553.972467] android_work: android_work: did not send uevent (0 0 00000000)
[1905554.193501] android_work: android_work: sent uevent USB_STATE=CONNECTED
[1905554.208277] android_usb gadget: super-speed config #1: 86000c8.android_usb
[1905554.208335] diag: USB channel diag connected
[1905554.208515] msm-dwc3 8a00000.ssusb: Avail curr from USB = 900
[1905554.209780] alloc_contig_range: [87080, 870b8) PFNs busy
[1905554.259837] ipa_usb_notify_cb: ipa_usb_notify_cb: Set net_ready_trigger
[1905554.266918] android_work: android_work: sent uevent USB_STATE=CONFIGURED
[1905566.697683] QTI:USB tethered modem SMD port opened
[3814545.835176] msm-dwc3 8a00000.ssusb: Avail curr from USB = 0
[3814545.835227] diag: USB channel diag disconnected
[3814545.837942] dwc3 8a00000.dwc3: request c6068b00 was not queued to ep0out
[3814545.841076] android_work: android_work: sent uevent USB_STATE=DISCONNECTED
[3814545.885185] dwc3 8a00000.dwc3: failed to stop controller
[3814545.885496] read descriptors
[3814545.885513] read strings
[3814545.885546] Match for Function Name: diag, Int #0
[3814545.885554] name:diag, interface id:0, id:0
[3814545.885592] Match for Function Name: Function FS Gadget, Int #1
[3814545.885599] name:Function FS Gadget, interface id:1, id:1
[3814545.885613] Match for Function Name: nmea, Int #2
[3814545.885620] name:nmea, interface id:2, id:2
[3814545.885640] Match for Function Name: modem, Int #3
[3814545.885648] name:modem, interface id:3, id:3
[3814545.885671] Match for Function Name: rmnet, Int #8
[3814545.885678] name:rmnet, interface id:8, id:4
[3814545.885697] msm-dwc3 8a00000.ssusb: ep [gsi-epin,29] already configured as
msm endpoint
[3814545.885709] msm-dwc3 8a00000.ssusb: ep [gsi-epout,30] already configured
as msm endpoint
[3814545.937592] android_work: android_work: did not send uevent (0 0 00000000)
[3814546.214778] android_work: android_work: did not send uevent (0 0 00000000)
[3814546.426566] android_work: android_work: sent uevent USB_STATE=CONNECTED
[3814546.446362] android_usb gadget: super-speed config #1: 86000c8.android_usb
[3814546.446421] diag: USB channel diag connected
[3814546.446604] msm-dwc3 8a00000.ssusb: Avail curr from USB = 900
[3814546.496699] ipa_usb_notify_cb: ipa_usb_notify_cb: Set net_ready_trigger
[3814546.503792] android_work: android_work: sent uevent USB_STATE=CONFIGURED
[3814559.375063] QTI:USB tethered modem SMD port opened
This is busybox dmesg, so no human readable timestamps. But those last
ones are at around 44 days uptime. Which put them right with the last
OpenWrt host system reboot. There are no modem kernel events logged
after this. So I think we can rule out any major modem firmware issue
or crash.
The root cause seems to be either a network or an internal ModemManager
problem. But either way, it was obviously temporary and easily worked
around with a simple MM restart. That is something which should have
been resolved automatically IMHO.
Bjørn
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
