EM120 not correctly booting up, unknown wwan control port exposed?

Sat May 22 19:13:58 UTC 2021

Hey Loic and Carl,

I wanted to test the EM120 setup I have with latest MM git master and
kernel 5.13.0-rc2, but unfortunately there is some issue, not sure if
in device or in kernel driver. These are the kernel logs I get as
output when the issue happens:

[  263.458712] mhi-pci-generic 0000:01:00.0: can't change power state
from D3cold to D0 (config space inaccessible)
[  263.458727] mhi-pci-generic 0000:01:00.0: can't change power state
from D3cold to D0 (config space inaccessible)
[  263.458736] mhi-pci-generic 0000:01:00.0: failed to resume device: -22
[  263.458742] mhi-pci-generic 0000:01:00.0: device recovery started
[  263.516090] mhi-pci-generic 0000:01:00.0: can't change power state
from D3cold to D0 (config space inaccessible)
[  263.577411] mhi-pci-generic 0000:01:00.0: reset
[  264.102575] mhi-pci-generic 0000:01:00.0: can't change power state
from D3cold to D0 (config space inaccessible)
[  264.822555] mhi-pci-generic 0000:01:00.0: timed out waiting for
pending transaction; performing function level reset anyway
[  266.049177] mhi-pci-generic 0000:01:00.0: not ready 1023ms after FLR; waiting
[  267.089191] mhi-pci-generic 0000:01:00.0: not ready 2047ms after FLR; waiting
[  269.302577] mhi-pci-generic 0000:01:00.0: not ready 4095ms after FLR; waiting
[  273.569404] mhi-pci-generic 0000:01:00.0: not ready 8191ms after FLR; waiting
[  281.889737] mhi-pci-generic 0000:01:00.0: not ready 16383ms after
FLR; waiting
[  298.743574] mhi-pci-generic 0000:01:00.0: not ready 32767ms after
FLR; waiting
[  332.224729] kauditd_printk_skb: 1 callbacks suppressed
[  332.877464] mhi-pci-generic 0000:01:00.0: not ready 65535ms after
FLR; giving up
[  333.980714] mhi-pci-generic 0000:01:00.0: reset failed

There is one interesting thing in the MM log, though, maybe it's MM
the one causing the issue.
See this list of ports and the details for each port reported via udev/sysfs.

The first port we find is the net port as we scan net subsystem first:

ModemManager[2490]: <debug> [1621709598.546715] [mhi_mbim0] port
contents loaded:
ModemManager[2490]: <debug> [1621709598.546823] [mhi_mbim0]   bus: pci
ModemManager[2490]: <debug> [1621709598.546974] [mhi_mbim0]   device:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.547071] [mhi_mbim0]   driver: mhi_net
ModemManager[2490]: <debug> [1621709598.547175] [mhi_mbim0]   vendor: 1eac
ModemManager[2490]: <debug> [1621709598.547275] [mhi_mbim0]   product: 1001
ModemManager[2490]: <debug> [1621709598.547375] [base-manager] adding
port mhi_mbim0 at sysfs path:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0/mhi0/mhi0_IP_HW0_MBIM/net/mhi_mbim0
ModemManager[2490]: <debug> [1621709598.548559] [filter]
(net/mhi_mbim0) port allowed: net device
ModemManager[2490]: <debug> [1621709598.548785] [base-manager] port
mhi_mbim0 is first in device
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.549024] [plugin-manager] task
4: new support task for device:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.549359] [plugin-manager] task
4: port grabbed: mhi_mbim0
ModemManager[2490]: <debug> [1621709598.549489] [plugin-manager] task
4,mhi_mbim0: new support task for port
ModemManager[2490]: <debug> [1621709598.549585] [plugin-manager] task
4,mhi_mbim0: deferred until min wait time elapsed

Then we find all these ports in the wwan subsystem:

ModemManager[2490]: <debug> [1621709598.566894] [wwan0] port contents loaded:
ModemManager[2490]: <debug> [1621709598.567007] [wwan0]   bus: pci
ModemManager[2490]: <debug> [1621709598.567104] [wwan0]   device:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.567195] [wwan0]   driver:
mhi-pci-generic
ModemManager[2490]: <debug> [1621709598.567285] [wwan0]   vendor: 1eac
ModemManager[2490]: <debug> [1621709598.567390] [wwan0]   product: 1001
ModemManager[2490]: <debug> [1621709598.567488] [base-manager] adding
port wwan0 at sysfs path:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0/mhi0/wwan/wwan0
ModemManager[2490]: <debug> [1621709598.568261] [filter] (wwan/wwan0)
port allowed: wwan device
ModemManager[2490]: <debug> [1621709598.568542] [base-manager]
additional port wwan0 in device
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.568823] [plugin-manager] task
4: port grabbed: wwan0
ModemManager[2490]: <debug> [1621709598.568968] [plugin-manager] task
4,wwan0: new support task for port
ModemManager[2490]: <debug> [1621709598.569059] [plugin-manager] task
4,wwan0: deferred until min wait time elapsed

What is this "wwan0" port exposed by the wwan subsystem? It doesn't
have a protocol reported, still, it's exposed in the system. Due to
this, we attempt to probe with all known protocols we may have in the
subsystem:

ModemManager[2490]: <debug> [1621709600.082522] [plugin/generic]
probes required for port wwan0: 'at, qcdm, qmi, mbim'

Maybe this port probing is the one causing the crash, as it seems the
timing could explain it.

Not sure I understand what this port is, I thought it was assumed all
ports to be known modem control protocol ports?

The next list of ports is expected:

ModemManager[2490]: <debug> [1621709598.570470] [wwan0p1QCDM] port
contents loaded:
ModemManager[2490]: <debug> [1621709598.570583] [wwan0p1QCDM]   bus: pci
ModemManager[2490]: <debug> [1621709598.570678] [wwan0p1QCDM]
device: /sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.570778] [wwan0p1QCDM]
driver: mhi-pci-generic
ModemManager[2490]: <debug> [1621709598.570882] [wwan0p1QCDM]   vendor: 1eac
ModemManager[2490]: <debug> [1621709598.570971] [wwan0p1QCDM]   product: 1001
ModemManager[2490]: <debug> [1621709598.571068] [base-manager] adding
port wwan0p1QCDM at sysfs path:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0/mhi0/wwan/wwan0/wwan0p1QCDM
ModemManager[2490]: <debug> [1621709598.571850] [filter]
(wwan/wwan0p1QCDM) port allowed: wwan device
ModemManager[2490]: <debug> [1621709598.572139] [base-manager]
additional port wwan0p1QCDM in device
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.572411] [plugin-manager] task
4: port grabbed: wwan0p1QCDM
ModemManager[2490]: <debug> [1621709598.572572] [plugin-manager] task
4,wwan0p1QCDM: new support task for port
ModemManager[2490]: <debug> [1621709598.572662] [plugin-manager] task
4,wwan0p1QCDM: deferred until min wait time elapsed
ModemManager[2490]: <debug> [1621709598.574070] [wwan0p2MBIM] port
contents loaded:
ModemManager[2490]: <debug> [1621709598.574182] [wwan0p2MBIM]   bus: pci
ModemManager[2490]: <debug> [1621709598.574295] [wwan0p2MBIM]
device: /sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.574387] [wwan0p2MBIM]
driver: mhi-pci-generic
ModemManager[2490]: <debug> [1621709598.574479] [wwan0p2MBIM]   vendor: 1eac
ModemManager[2490]: <debug> [1621709598.574569] [wwan0p2MBIM]   product: 1001
ModemManager[2490]: <debug> [1621709598.574679] [base-manager] adding
port wwan0p2MBIM at sysfs path:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0/mhi0/wwan/wwan0/wwan0p2MBIM
ModemManager[2490]: <debug> [1621709598.575501] [filter]
(wwan/wwan0p2MBIM) port allowed: wwan device
ModemManager[2490]: <debug> [1621709598.575782] [base-manager]
additional port wwan0p2MBIM in device
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.576076] [plugin-manager] task
4: port grabbed: wwan0p2MBIM
ModemManager[2490]: <debug> [1621709598.576231] [plugin-manager] task
4,wwan0p2MBIM: new support task for port
ModemManager[2490]: <debug> [1621709598.576320] [plugin-manager] task
4,wwan0p2MBIM: deferred until min wait time elapsed
ModemManager[2490]: <debug> [1621709598.577736] [wwan0p3AT] port
contents loaded:
ModemManager[2490]: <debug> [1621709598.577848] [wwan0p3AT]   bus: pci
ModemManager[2490]: <debug> [1621709598.577945] [wwan0p3AT]   device:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0
ModemManager[2490]: <debug> [1621709598.578034] [wwan0p3AT]   driver:
mhi-pci-generic
ModemManager[2490]: <debug> [1621709598.578121] [wwan0p3AT]   vendor: 1eac
ModemManager[2490]: <debug> [1621709598.578209] [wwan0p3AT]   product: 1001
ModemManager[2490]: <debug> [1621709598.578305] [base-manager] adding
port wwan0p3AT at sysfs path:
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0/mhi0/wwan/wwan0/wwan0p3AT
ModemManager[2490]: <debug> [1621709598.579113] [filter]
(wwan/wwan0p3AT) port allowed: wwan device
ModemManager[2490]: <debug> [1621709598.579402] [base-manager]
additional port wwan0p3AT in device
/sys/devices/pci0000:00/0000:00:1b.0/0000:01:00.0

-- 
Aleksander
https://aleksander.es