Skip to content

mbim-proxy at 100% load when starting ModemManager

Submitted by Christian Ehrig

Assigned to ModemManager bug user

Link to original bug (#100938)

Description

I'am on Gentoo and experiencing a critical issue. Since a system update, i cant use my internal Fibocom WWAN adapter anymore. When starting ModemManager mbim-proxy goes to high cpu load and i can not establish a connection through NetworkManager.

net-misc/modemmanager-1.6.4 net-libs/libmbim-1.14.0

I started mbim-proxy manually with verbose output, before starting ModemManager:

[05 May 2017, 00:31:29] [Debug] creating UNIX socket service... [05 May 2017, 00:31:29] [Debug] starting UNIX socket service at 'mbim-proxy'... [05 May 2017, 00:31:37] [Debug] Client (6) connection open... [05 May 2017, 00:31:37] [Debug] opening device... [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Queried max control message size: 512 [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 128 data = 03:00:00:80:80:00:00:00:10: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:50:00:00:00:00:00:00:00:03:00:00:00:01:00:00:00:20:00:00:00:01:00:00:00:30:00:00:00:0A:00:00:00:3C:00:00:00:14:00:00:00:00:00:00:00:00:00:00:00:02:00:00:00:32:00:36:00:32:00:30:00:31:00:00:00:54:00:65:00:6C:00:65:00:6B:00:6F:00:6D:00:2E:00:64:00:65:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] No transaction matched in received message [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received unexpected message (translated)...

Header: length = 128 type = command-done (0x80000003) transaction = 16 Fragment header: total = 1 current = 0 Contents: status error = 'None' (0x00000000) service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'register-state' (0x00000009)

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Sent message... <<<<<< RAW: <<<<<< length = 16 <<<<<< data = 01:00:00:00:10:00:00:00:01:00:00:00:00:02:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Sent message (translated)... <<<<<< Header: <<<<<< length = 16 <<<<<< type = open (0x00000001) <<<<<< transaction = 1 <<<<<< Contents: <<<<<< max_control_transfer = 512

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:02:00:00:00:03:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:04:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:02:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:03:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:03:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:03:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:04:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:02:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:04:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:02:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:04:00:00:00:05:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:02:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 64 data = 07:00:00:80:40:00:00:00:00: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:0B:00:00:00:14:00:00:00:03:00:00:00:04:00:00:00:3C:00:00:00:02:00:00:00:FF:FF:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message (translated)...

Header: length = 64 type = indicate-status (0x80000007) transaction = 0 Fragment header: total = 1 current = 0 Contents: service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) cid = 'signal-state' (0x0000000b)

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 64 bytes [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Received message...

RAW: length = 16 data = 01:00:00:80:10:00:00:00:01:00:00:00:00:00:00:00

[05 May 2017, 00:31:37] [Debug] Client (6) TX: 48 bytes [05 May 2017, 00:31:37] [Debug] connection to MBIM device '/dev/cdc-wdm0' established [05 May 2017, 00:31:37] [Debug] Client (6) TX: 16 bytes [05 May 2017, 00:31:37] [Debug] Client (6) TX: 16 bytes [05 May 2017, 00:31:37] [Debug] Client (6) connection closed... [05 May 2017, 00:31:37] [Debug] Client (6) connection open... [05 May 2017, 00:31:37] [Debug] checking device caps during client device open... [05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Sent message... <<<<<< RAW: <<<<<< length = 48 <<<<<< data = 03:00:00:00:30:00:00:00:02: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:01:00:00:00:00:00:00:00:00:00:00:00

[05 May 2017, 00:31:37] [Debug] [/dev/cdc-wdm0] Sent message (translated)... <<<<<< Header: <<<<<< length = 48 <<<<<< type = command (0x00000003) <<<<<< transaction = 2 <<<<<< Fragment header: <<<<<< total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid = 'device-caps' (0x00000001) <<<<<< type = 'query' (0x00000000)

[05 May 2017, 00:31:42] -Warning ** device caps query during internal open failed: Transaction timed out [05 May 2017, 00:31:42] [Debug] Client (6) TX: 48 bytes [05 May 2017, 00:31:42] [Debug] connection to MBIM device '/dev/cdc-wdm0' established [05 May 2017, 00:31:42] [Debug] Client (6) TX: 16 bytes [05 May 2017, 00:31:42] [Debug] [/dev/cdc-wdm0] Sent message... <<<<<< RAW: <<<<<< length = 48 <<<<<< data = 03:00:00:00:30:00:00:00:03: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:01:00:00:00:00:00:00:00:00:00:00:00

[05 May 2017, 00:31:42] [Debug] [/dev/cdc-wdm0] Sent message (translated)... <<<<<< Header: <<<<<< length = 48 <<<<<< type = command (0x00000003) <<<<<< transaction = 3 <<<<<< Fragment header: <<<<<< total = 1 <<<<<< current = 0 <<<<<< Contents: <<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df) <<<<<< cid = 'device-caps' (0x00000001) <<<<<< type = 'query' (0x00000000)

After that there's no more output and mbim-proxy starts to eat my cpu:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4117 root 20 0 383920 5512 5004 R 100.0 0.0 1:37.31 mbim-proxy

And this is the corresponding syslog:

May 5 00:34:38 localhost systemd[1]: Starting Modem Manager... May 5 00:34:38 localhost ModemManager[4288]: <info> ModemManager (version 1.6.4) starting in system bus... May 5 00:34:38 localhost systemd[1]: Started Modem Manager. May 5 00:34:38 localhost NetworkManager[2462]: <info> [1493937278.9958] ModemManager disappeared from bus May 5 00:34:39 localhost NetworkManager[2462]: <info> [1493937279.0080] ModemManager available in the bus May 5 00:34:40 localhost ModemManager[4288]: opening device... May 5 00:34:40 localhost ModemManager[4288]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 512 May 5 00:34:40 localhost ModemManager[4288]: <info> Creating modem with plugin 'Generic' and '2' ports May 5 00:34:40 localhost ModemManager[4288]: <info> Modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3' successfully created May 5 00:34:40 localhost ModemManager[4288]: opening device... May 5 00:34:40 localhost ModemManager[4288]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 512 May 5 00:34:40 localhost ModemManager[4288]: <info> Modem: state changed (unknown -> disabled) May 5 00:34:40 localhost NetworkManager[2462]: <info> [1493937280.7528] (cdc-wdm0): modem state changed, 'disabled' --> 'enabling' (reason: user preference) May 5 00:34:40 localhost NetworkManager[2462]: <info> [1493937280.7564] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/7) May 5 00:34:40 localhost NetworkManager[2462]: <info> [1493937280.7576] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2] May 5 00:34:40 localhost NetworkManager[2462]: <info> [1493937280.7587] device (cdc-wdm0): modem state 'enabling' May 5 00:34:40 localhost NetworkManager[2462]: <info> [1493937280.7607] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'none') [20 30 0] May 5 00:34:40 localhost ModemManager[4288]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling) May 5 00:34:40 localhost ModemManager[4288]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering) May 5 00:34:40 localhost ModemManager[4288]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home) May 5 00:34:41 localhost ModemManager[4288]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> registered) May 5 00:34:41 localhost NetworkManager[2462]: <info> [1493937281.1029] (cdc-wdm0): modem state changed, 'enabling' --> 'registered' (reason: user-requested) May 5 00:34:41 localhost ModemManager[4288]: <info> Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1c.2/0000:03:00.0': not supported by any plugin May 5 00:34:41 localhost ModemManager[4288]: <info> Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin May 5 00:34:51 localhost ModemManager[4288]: <warn> Initial 3GPP registration check failed: Transaction timed out

Thanks in advance!

Version: 1.6

To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information