ModemManager consuming 100% CPU while refreshing 3GPP registration

[Torsten Hilbrich]

Hello,

I recently had some problems with my Lenovo T450s. The ModemManager and mbim-proxy processes were generating a lot of CPU activity.

ModemManager: 1.8.0
libmbim: 1.16.0
libqmi: 1.20.0
Kernel: v4.14.65

The modem is a:

usb 2-4: New USB device found, idVendor=1199, idProduct=a001
usb 2-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 2-4: Product: Sierra Wireless EM7345 4G LTE
usb 2-4: Manufacturer: Sierra Wireless Inc.
usb 2-4: SerialNumber: 013937003907084

I ran strace on both the ModemManager and the mbim-proxy, there were sending the same command over and over again to the kernel driver and were receiving an -EAGAIN:

modem-manager:
13:00:26.252810 write(9, "\3\0\0\0000\0\0\0=\1\0\0\1\0\0\0\0\0\0\0\242\211\3143\274\273\213O\266\260\23>"..., 48) = -1 EAGAIN (Resource temporarily unavailable)
13:00:26.252877 write(9, "\3\0\0\0000\0\0\0=\1\0\0\1\0\0\0\0\0\0\0\242\211\3143\274\273\213O\266\260\23>"..., 48) = -1 EAGAIN (Resource temporarily unavailable)
...

mbim-proxy:
13:00:48.228085 write(7, "\3\0\0\0000\0\0\0\23\0\0\0\1\0\0\0\0\0\0\0\242\211\3143\274\273\213O\266\260\23>"..., 48) = -1 EAGAIN (Resource temporarily unavailable)
13:00:48.228172 write(7, "\3\0\0\0000\0\0\0\23\0\0\0\1\0\0\0\0\0\0\0\242\211\3143\274\273\213O\266\260\23>"..., 48) = -1 EAGAIN (Resource temporarily unavailable)
...

I also ran gdb on the ModemManager to get some context:

#0  0x000074db7c29815d in write () from /lib/libpthread.so.0
#1  0x000074db7c53333c in g_io_unix_write () from /usr/lib/libglib-2.0.so.0
#2  0x000074db7c4e3c01 in g_io_channel_write_chars () from /usr/lib/libglib-2.0.so.0
#3  0x000074db7cdacf2e in device_write () from /usr/lib/libmbim-glib.so.4
#4  0x000074db7cdad206 in device_send () from /usr/lib/libmbim-glib.so.4
#5  0x000074db7cdaea48 in mbim_device_command () from /usr/lib/libmbim-glib.so.4
#6  0x000008d1680e77fb in modem_3gpp_run_registration_checks ()
#7  0x000008d16809bdaa in mm_iface_modem_3gpp_run_registration_checks ()
#8  0x000008d16809be42 in periodic_registration_check ()
#9  0x000074db7c4ef233 in g_timeout_dispatch () from /usr/lib/libglib-2.0.so.0
#10 0x000074db7c4ee7fa in g_main_context_dispatch () from /usr/lib/libglib-2.0.so.0
#11 0x000074db7c4eeb78 in g_main_context_iterate.isra () from /usr/lib/libglib-2.0.so.0
#12 0x000074db7c4eee92 in g_main_loop_run () from /usr/lib/libglib-2.0.so.0
#13 0x000008d16807580e in main ()
Detaching from program: /usr/bin/ModemManager, process 4020

The logs from the kernel and the ModemManager were too large to attach here, I uploaded them to pastebin:

- ModemManager: https://pastebin.com/7NbUmmde
- kernel: https://pastebin.com/tRdb5fDe

In the kernel I only found some throttling messages which should be related to the high CPU activity. Otherwise, I found no relevant messages from the kernel.

In the ModemManager log file the problem seems to start with the following messages, about 3 minutes after starting the ModemManager:

<warn>  [1542959070.991422] Initial 3GPP registration check failed: Transaction timed out
<debug> [1542959080.961091] Couldn't refresh 3GPP registration status: 'Transaction timed out'
<debug> [1542959100.961091] Running registration checks (CS: 'yes', PS: 'yes', EPS: 'yes')
[/dev/cdc-wdm0] Sent message...
[/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<<   length = 48
<<<<<<   data   = 03:00:00:00:30:00:00:00:23:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:09:00:00:00:00:00:00:00:00:00:00:00
[/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<<   length      = 48
<<<<<<   type        = command (0x00000003)
<<<<<<   transaction = 35
<<<<<< Fragment header:
<<<<<<   total   = 1
<<<<<<   current = 0
<<<<<< Contents:
<<<<<<   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<<   cid     = 'register-state' (0x00000009)
<<<<<<   type    = 'query' (0x00000000)

The problem only occured one time so far. After rebooting the system the LTE modem resumed normal operation.
Has anyone any idea, what was happening here?