ModemManager - connect/disconnect loop on modem startup

Product support
1

Hey guys.

I have a weird behavior in one of my modems where it stays in a connect/disconnect cycle for a couple minutes before it finally connects, and I need it to connect as fast as possible, 30s tops.

Eventually the loop stops and the modem stays connected, I just need to make it faster on connection.

This is the loop it gets stuck in journalctl:

ModemManager[1388]: [modem1] simple connect started...
ModemManager[1388]: [modem1] simple connect state (4/8): wait to get fully enabled
ModemManager[1388]: [modem1] state changed (disconnecting -> registered)
ModemManager[1388]: [modem1] simple connect state (5/8): register
ModemManager[1388]: [modem1/bearer233] connection #12 finished: duration 1s, tx: 0 bytes, rx :0 bytes
ModemManager[1388]: [modem1] simple connect state (6/8): bearer
ModemManager[1388]: [modem1] simple connect state (7/8): connect
Nmmodem state changed, 'disconnecting' --> 'registered' (reason: user-requested)
ModemManager[1388]: [modem1] state changed (registered -> connecting)
Nmmodem state changed, 'registered' --> 'connecting' (reason: user-requested)
ModemManager[1388]: [modem1/bearer233] QMI IPv4 Settings:
ModemManager[1388]: [modem1/bearer233]     address: 100.65.81.178/30
ModemManager[1388]: [modem1/bearer233]     gateway: 100.65.81.177
ModemManager[1388]: [modem1/bearer233]     DNS #1: 201.10.128.2
ModemManager[1388]: [modem1/bearer233]     DNS #2: 201.10.120.2
MMTU: 1500
MnMnmessage
ModemManager[1388]: [modem1] state changed (connecting -> connected)
ModemManager[1388]: [modem1] simple connect state (8/8): all done
Nmmodem state changed, 'connecting' --> 'connected' (reason: user-requested)
Nmmmethods
NetworkManager[1484]: <info>  [1631109707.2367] device (cdc-wdm1): state change: prepare -> failed (reason 'config-failed', sys-iface-state: 'managed')
NetworkManager[1484]: <warn>  [1631109707.2426] device (cdc-wdm1): Activation: failed for connection 'BRA-BrTCelular-d8a338232cefff166e10be70b28cdf24371041dc'
NetworkManager[1484]: <info>  [1631109707.2450] device (cdc-wdm1): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
NetworkManager[1484]: <info>  [1631109707.2476] policy: auto-activating connection 'BRA-BrTCelular-d8a338232cefff166e10be70b28cdf24371041dc' (11322719-6aad-4000-9f32-948ed62c910e)
ModemManager[1388]: [modem1] state changed (connected -> disconnecting)

There is a little bit of NetworkManager logs in there, I left to just in case it’s relevant.

The above log repeats for about 10-20 times. You can see the modem reaches the state connected in here:

Sep 08 14:01:47 3182c51 ModemManager[1388]: [modem1] state changed (connecting -> connected)
Sep 08 14:01:47 3182c51 ModemManager[1388]: [modem1] simple connect state (8/8): all done

And then, suddenly:

ModemManager[1388]: [modem1] state changed (connected -> disconnecting)

These couple lines caught my attention:

ModemManager[1388]: [modem1/bearer233] failed to read IPv4 netmask: Field 'IPv4 Gateway Subnet Mask' was not found in the message

And:

NetworkManager[1484]: <warn>  [1631109707.2366] modem-broadband[cdc-wdm1]: failed to connect modem: invalid ip methods

These are the only lines that does NOT show up when the modem successful connects. When finally the modem connects and stops the loop, this the successful log:

ModemManager[1388]: [modem1] simple connect started...
ModemManager[1388]: [modem1] simple connect state (4/8): wait to get fully enabled
ModemManager[1388]: [modem1] state changed (disconnecting -> registered)
ModemManager[1388]: [modem1] simple connect state (5/8): register
ModemManager[1388]: [modem1/bearer233] connection #13 finished: duration 1s, tx: 0 bytes, rx :0 bytes
ModemManager[1388]: [modem1] simple connect state (6/8): bearer
ModemManager[1388]: [modem1] simple connect state (7/8): connect
ModemManager[1388]: [modem1] state changed (registered -> connecting)
NetworkManager[1484]: <info>  [1631109708.5788] modem["cdc-wdm1"]: modem state changed, 'disconnecting' --> 'registered' (reason: user-requested)
ModemManager[1388]: [modem1/bearer233] bearer call end reason (1): 'generic-unspecified'
ModemManager[1388]: transaction 0x222f aborted, but message is not abortable
ModemManager[1388]: [modem1] state changed (connecting -> registered)
NetworkManager[1484]: <info>  [1631109708.5817] modem["cdc-wdm1"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
ModemManager[1388]: [modem1/bearer233] connection #14 finished: duration 0s, tx: 0 bytes, rx :0 bytes
ModemManager[1388]: [modem1/bearer233] connection attempt #14 failed: aborted by the network
ModemManager[1388]: [/dev/cdc-wdm1] No transaction matched in received message
NetworkManager[1484]: <info>  [1631109708.5889] modem["cdc-wdm1"]: modem state changed, 'connecting' --> 'registered' (reason: user-requested)
ModemManager[1388]: [modem1] simple connect started...
ModemManager[1388]: [modem1] simple connect state (4/8): wait to get fully enabled
ModemManager[1388]: [modem1] simple connect state (5/8): register
ModemManager[1388]: [modem1] simple connect state (6/8): bearer
ModemManager[1388]: [modem1] simple connect state (7/8): connect
ModemManager[1388]: [modem1] state changed (registered -> connecting)
NetworkManager[1484]: <info>  [1631109708.5978] modem["cdc-wdm1"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
ef330e08e204[1500]: [ssh] keepalive at
ModemManager[1388]: [modem1/bearer234] QMI IPv4 Settings:
ModemManager[1388]: [modem1/bearer234]     address: 100.73.120.56/30
ModemManager[1388]: [modem1/bearer234]     gateway: 100.73.120.57
ModemManager[1388]: [modem1/bearer234]     DNS #1: 201.10.128.2
ModemManager[1388]: [modem1/bearer234]     DNS #2: 201.10.120.2
ModemManager[1388]: [modem1/bearer234]        MTU: 1500
ModemManager[1388]: [modem1] state changed (connecting -> connected)
ModemManager[1388]: [modem1] simple connect state (8/8): all done
NetworkManager[1484]: <info>  [1631109712.0919] modem["cdc-wdm1"]: modem state changed, 'connecting' --> 'connected' (reason: user-requested)
NetworkManager[1484]: <info>  [1631109712.1047] device (cdc-wdm1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
NetworkManager[1484]: <info>  [1631109712.1069] device (cdc-wdm1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
NetworkManager[1484]: <info>  [1631109712.1086] dhcp4 (wwan1): activation: beginning transaction (no timeout)
NetworkManager[1484]: <info>  [1631109712.1093] modem["cdc-wdm1"]: IPv6 configuration disabled
NetworkManager[1484]: <info>  [1631109712.1137] dhcp4 (wwan1): state changed unknown -> expire
NetworkManager[1484]: <info>  [1631109712.1351] dhcp4 (wwan1): option dhcp_lease_time      => '7200'
NetworkManager[1484]: <info>  [1631109712.1352] dhcp4 (wwan1): option domain_name_servers  => '201.10.128.2 201.10.120.2'
NetworkManager[1484]: <info>  [1631109712.1353] dhcp4 (wwan1): option expiry               => '1631116912'
NetworkManager[1484]: <info>  [1631109712.1353] dhcp4 (wwan1): option host_name            => '3182c51'
NetworkManager[1484]: <info>  [1631109712.1354] dhcp4 (wwan1): option ip_address           => '100.73.120.56'
NetworkManager[1484]: <info>  [1631109712.1354] dhcp4 (wwan1): option next_server          => '100.73.120.57'
NetworkManager[1484]: <info>  [1631109712.1355] dhcp4 (wwan1): option requested_broadcast_address => '1'
NetworkManager[1484]: <info>  [1631109712.1355] dhcp4 (wwan1): option requested_domain_name => '1'
NetworkManager[1484]: <info>  [1631109712.1356] dhcp4 (wwan1): option requested_domain_name_servers => '1'
NetworkManager[1484]: <info>  [1631109712.1356] dhcp4 (wwan1): option requested_domain_search => '1'
NetworkManager[1484]: <info>  [1631109712.1357] dhcp4 (wwan1): option requested_host_name  => '1'
NetworkManager[1484]: <info>  [1631109712.1357] dhcp4 (wwan1): option requested_interface_mtu => '1'
NetworkManager[1484]: <info>  [1631109712.1358] dhcp4 (wwan1): option requested_ms_classless_static_routes => '1'
NetworkManager[1484]: <info>  [1631109712.1359] dhcp4 (wwan1): option requested_nis_domain => '1'
NetworkManager[1484]: <info>  [1631109712.1359] dhcp4 (wwan1): option requested_nis_servers => '1'
NetworkManager[1484]: <info>  [1631109712.1360] dhcp4 (wwan1): option requested_ntp_servers => '1'
NetworkManager[1484]: <info>  [1631109712.1360] dhcp4 (wwan1): option requested_rfc3442_classless_static_routes => '1'
NetworkManager[1484]: <info>  [1631109712.1361] dhcp4 (wwan1): option requested_root_path  => '1'
NetworkManager[1484]: <info>  [1631109712.1362] dhcp4 (wwan1): option requested_routers    => '1'
NetworkManager[1484]: <info>  [1631109712.1362] dhcp4 (wwan1): option requested_static_routes => '1'
avahi-daemon[1541]: Joining mDNS multicast group on interface wwan1.IPv4 with address 100.73.120.56.
avahi-daemon[1541]: New relevant interface wwan1.IPv4 for mDNS.
avahi-daemon[1541]: Registering new address record for 100.73.120.56 on wwan1.IPv4.
NetworkManager[1484]: <info>  [1631109712.1363] dhcp4 (wwan1): option requested_subnet_mask => '1'
NetworkManager[1484]: <info>  [1631109712.1363] dhcp4 (wwan1): option requested_time_offset => '1'
NetworkManager[1484]: <info>  [1631109712.1364] dhcp4 (wwan1): option requested_wpad       => '1'
NetworkManager[1484]: <info>  [1631109712.1365] dhcp4 (wwan1): option routers              => '100.73.120.57'
NetworkManager[1484]: <info>  [1631109712.1365] dhcp4 (wwan1): option subnet_mask          => '255.255.255.252'
NetworkManager[1484]: <info>  [1631109712.1366] dhcp4 (wwan1): state changed expire -> bound
NetworkManager[1484]: <info>  [1631109712.1421] device (cdc-wdm1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
dbus-daemon[1392]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.3' (uid=0 pid=1484 comm="/usr/sbin/NetworkManager --no-daemon ")
dbus-daemon[1392]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
NetworkManager[1484]: <info>  [1631109712.1981] device (cdc-wdm1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
NetworkManager[1484]: <info>  [1631109712.1991] device (cdc-wdm1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
NetworkManager[1484]: <info>  [1631109712.2061] dns-mgr: Writing DNS information to /sbin/resolvconf
dnsmasq[1498]: dnsmasq[1498]: reading /etc/resolv.dnsmasq
dnsmasq[1498]: dnsmasq[1498]: using nameserver 8.8.8.8#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 189.7.72.72#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 189.7.72.62#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 2804:14c:7510:672:189:7:72:72#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 2804:14c:7510:672:189:7:72:62#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 189.40.198.96#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 189.40.198.81#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 201.10.128.2#53
dnsmasq[1498]: dnsmasq[1498]: using nameserver 201.10.120.2#53
NetworkManager[1484]: <info>  [1631109712.2575] device (cdc-wdm1): Activation: successful, device activated.

Any ideas?

2

Hi,

First thought:
I recall seeing similar behavior when NetworkManager/ModemManager wasn’t the only one trying to connect a modem.
Have you tried connecting the modem using qmicli or similar?

Second thought:
I’m also not 100% sure what happens when there are multiple system-connections that can use the same device (ex. system-connections with same type, but no interface-name defined).
Did you double check which connections are defined in NetworkManager?

3

I tried with qmicli:

qmicli --device=/dev/cdc-wdm1 --device-open-proxy --wds-start-network="ip-type=4,apn=gprs.oi.com.br,username=oi,password=oi" --client-no-release-cid --wds-follow-network -v

I get the following loop:


[/dev/cdc-wdm1] Network started
	Packet data handle: '28062296'

Ctrl+C will stop the network
[/dev/cdc-wdm1] Connection status: 'connected'
[/dev/cdc-wdm1] Connection status: 'connected'
[/dev/cdc-wdm1] Connection status: 'connected'
[/dev/cdc-wdm1] Connection status: 'connected'
[/dev/cdc-wdm1] Connection status: 'connected'
[/dev/cdc-wdm1] Connection status: 'connected'

[/dev/cdc-wdm1] Connection status: 'disconnected'
[/dev/cdc-wdm1] Stopping after detecting disconnection
Network cancelled... releasing resources
error: couldn't stop network: QMI protocol error (26): 'NoEffect'
[/dev/cdc-wdm1] Client ID not released:
	Service: 'wds'
	    CID: '4'

Connection never comes up in this case, this is different from when I let ModemManager/NetworkManager handle it, that eventually the connection comes up.

This is the full verbose log:

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] Opening device with flags 'proxy, auto'...
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] automatically selecting QMI mode
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] created endpoint
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 28
<<<<<<   data   = 01:1B:00:00:00:00:00:01:00:FF:10:00:01:0D:00:2F:64:65:76:2F:63:64:63:2D:77:64:6D:31

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 27
<<<<<<   flags   = 0x00
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 1
<<<<<<   tlv_length  = 16
<<<<<<   message     = "Internal Proxy Open" (0xFF00)
<<<<<< TLV:
<<<<<<   type       = "Device Path" (0x01)
<<<<<<   length     = 13
<<<<<<   value      = 2F:64:65:76:2F:63:64:63:2D:77:64:6D:31
<<<<<<   translated = /dev/cdc-wdm1

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 19
<<<<<<   data   = 01:12:00:80:00:00:01:01:00:FF:07:00:02:04:00:00:00:00:00

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 18
<<<<<<   flags   = 0x80
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 1
<<<<<<   tlv_length  = 7
<<<<<<   message     = "Internal Proxy Open" (0xFF00)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS

[08 Sep 2021, 18:55:31] [Debug] QMI Device at '/dev/cdc-wdm1' ready
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] Assuming service 'wds' is supported...
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] Allocating new client ID...
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 16
<<<<<<   data   = 01:0F:00:00:00:00:00:02:22:00:04:00:01:01:00:01

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 15
<<<<<<   flags   = 0x00
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 2
<<<<<<   tlv_length  = 4
<<<<<<   message     = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Service" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 01
<<<<<<   translated = wds

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:00:00:01:02:22:00:0C:00:02:04:00:00:00:00:00:01:02:00:01:06

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 2
<<<<<<   tlv_length  = 12
<<<<<<   message     = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Allocation Info" (0x01)
<<<<<<   length     = 2
<<<<<<   value      = 01:06
<<<<<<   translated = [ service = 'wds' cid = '6' ]

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] Registered 'wds' (version unknown) client with ID '6'
[08 Sep 2021, 18:55:31] [Debug] Network start parameters set (apn: 'gprs.oi.com.br', 3gpp_profile: '0', 3gpp2_profile: '0', auth: 'unspecified', ip-type: '4', username: 'oi', password: 'oi', autoconnect: 'unspecified')
[08 Sep 2021, 18:55:31] [Debug] Asynchronously starting network...
[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 44
<<<<<<   data   = 01:2B:00:00:01:06:00:01:00:20:00:1F:00:19:01:00:04:18:02:00:6F:69:17:02:00:6F:69:14:0E:00:67:70:72:73:2E:6F:69:2E:63:6F:6D:2E:62:72

[08 Sep 2021, 18:55:31] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 43
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 1
<<<<<<   tlv_length  = 31
<<<<<<   message     = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<<   type       = "IP Family Preference" (0x19)
<<<<<<   length     = 1
<<<<<<   value      = 04
<<<<<<   translated = ipv4
<<<<<< TLV:
<<<<<<   type       = "Password" (0x18)
<<<<<<   length     = 2
<<<<<<   value      = 6F:69
<<<<<<   translated = oi
<<<<<< TLV:
<<<<<<   type       = "Username" (0x17)
<<<<<<   length     = 2
<<<<<<   value      = 6F:69
<<<<<<   translated = oi
<<<<<< TLV:
<<<<<<   type       = "APN" (0x14)
<<<<<<   length     = 14
<<<<<<   value      = 67:70:72:73:2E:6F:69:2E:63:6F:6D:2E:62:72
<<<<<<   translated = gprs.oi.com.br

[08 Sep 2021, 18:55:37] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 27
<<<<<<   data   = 01:1A:00:80:01:06:02:01:00:20:00:0E:00:02:04:00:00:00:00:00:01:04:00:F8:35:AC:01

[08 Sep 2021, 18:55:37] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 26
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 1
<<<<<<   tlv_length  = 14
<<<<<<   message     = "Start Network" (0x0020)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Packet Data Handle" (0x01)
<<<<<<   length     = 4
<<<<<<   value      = F8:35:AC:01
<<<<<<   translated = 28063224

[/dev/cdc-wdm1] Network started
	Packet data handle: '28063224'

Ctrl+C will stop the network
[08 Sep 2021, 18:55:37] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 22
<<<<<<   data   = 01:15:00:80:01:FF:04:00:00:22:00:09:00:01:02:00:02:00:12:01:00:04

[08 Sep 2021, 18:55:37] [Debug] [/dev/cdc-wdm1] received generic indication (translated)...
<<<<<< QMUX:
<<<<<<   length  = 21
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 255
<<<<<< QMI:
<<<<<<   flags       = "indication"
<<<<<<   transaction = 0
<<<<<<   tlv_length  = 9
<<<<<<   message     = "Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 2
<<<<<<   value      = 02:00
<<<<<<   translated = [ status = 'connected' reconfiguration_required = 'no' ]
<<<<<< TLV:
<<<<<<   type       = "IP Family" (0x12)
<<<<<<   length     = 1
<<<<<<   value      = 04
<<<<<<   translated = ipv4


[08 Sep 2021, 18:55:58] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:02:00:22:00:00:00

[08 Sep 2021, 18:55:58] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 2
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:55:58] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:02:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:55:58] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 2
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:56:18] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:03:00:22:00:00:00

[08 Sep 2021, 18:56:18] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 3
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:56:18] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:03:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:56:18] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 3
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:56:38] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:04:00:22:00:00:00

[08 Sep 2021, 18:56:38] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 4
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:56:38] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:04:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:56:38] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 4
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:56:58] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:05:00:22:00:00:00

[08 Sep 2021, 18:56:58] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 5
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:56:58] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:05:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:56:58] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 5
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:57:18] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:06:00:22:00:00:00

[08 Sep 2021, 18:57:18] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 6
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:57:18] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:06:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:57:18] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 6
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:57:38] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:07:00:22:00:00:00

[08 Sep 2021, 18:57:38] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 7
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:57:38] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:07:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:02

[08 Sep 2021, 18:57:38] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 7
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 02
<<<<<<   translated = connected

[/dev/cdc-wdm1] Connection status: 'connected'
[08 Sep 2021, 18:57:39] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 27
<<<<<<   data   = 01:1A:00:80:01:FF:04:00:00:22:00:0E:00:01:02:00:01:00:10:02:00:01:00:12:01:00:04

[08 Sep 2021, 18:57:39] [Debug] [/dev/cdc-wdm1] received generic indication (translated)...
<<<<<< QMUX:
<<<<<<   length  = 26
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 255
<<<<<< QMI:
<<<<<<   flags       = "indication"
<<<<<<   transaction = 0
<<<<<<   tlv_length  = 14
<<<<<<   message     = "Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 2
<<<<<<   value      = 01:00
<<<<<<   translated = [ status = 'disconnected' reconfiguration_required = 'no' ]
<<<<<< TLV:
<<<<<<   type       = "Call End Reason" (0x10)
<<<<<<   length     = 2
<<<<<<   value      = 01:00
<<<<<<   translated = generic-unspecified
<<<<<< TLV:
<<<<<<   type       = "IP Family" (0x12)
<<<<<<   length     = 1
<<<<<<   value      = 04
<<<<<<   translated = ipv4

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 13
<<<<<<   data   = 01:0C:00:00:01:06:00:08:00:22:00:00:00

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 12
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 8
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Packet Service Status" (0x0022)

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 24
<<<<<<   data   = 01:17:00:80:01:06:02:08:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:01

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 23
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 8
<<<<<<   tlv_length  = 11
<<<<<<   message     = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 00:00:00:00
<<<<<<   translated = SUCCESS
<<<<<< TLV:
<<<<<<   type       = "Connection Status" (0x01)
<<<<<<   length     = 1
<<<<<<   value      = 01
<<<<<<   translated = disconnected

[/dev/cdc-wdm1] Connection status: 'disconnected'
[/dev/cdc-wdm1] Stopping after detecting disconnection
Network cancelled... releasing resources
[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] sent message...
<<<<<< RAW:
<<<<<<   length = 20
<<<<<<   data   = 01:13:00:00:01:06:00:09:00:21:00:07:00:01:04:00:F8:35:AC:01

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] sent generic request (translated)...
<<<<<< QMUX:
<<<<<<   length  = 19
<<<<<<   flags   = 0x00
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 9
<<<<<<   tlv_length  = 7
<<<<<<   message     = "Stop Network" (0x0021)
<<<<<< TLV:
<<<<<<   type       = "Packet Data Handle" (0x01)
<<<<<<   length     = 4
<<<<<<   value      = F8:35:AC:01
<<<<<<   translated = 28063224

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] received message...
<<<<<< RAW:
<<<<<<   length = 20
<<<<<<   data   = 01:13:00:80:01:06:02:09:00:21:00:07:00:02:04:00:01:00:1A:00

[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] received generic response (translated)...
<<<<<< QMUX:
<<<<<<   length  = 19
<<<<<<   flags   = 0x80
<<<<<<   service = "wds"
<<<<<<   client  = 6
<<<<<< QMI:
<<<<<<   flags       = "response"
<<<<<<   transaction = 9
<<<<<<   tlv_length  = 7
<<<<<<   message     = "Stop Network" (0x0021)
<<<<<< TLV:
<<<<<<   type       = "Result" (0x02)
<<<<<<   length     = 4
<<<<<<   value      = 01:00:1A:00
<<<<<<   translated = FAILURE: NoEffect

error: couldn't stop network: QMI protocol error (26): 'NoEffect'
[/dev/cdc-wdm1] Client ID not released:
	Service: 'wds'
	    CID: '6'
[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] Releasing 'wds' client with flags 'none'...
[08 Sep 2021, 18:57:58] [Debug] [/dev/cdc-wdm1] Unregistered 'wds' client with ID '6'
[08 Sep 2021, 18:57:58] [Debug] Client released
[08 Sep 2021, 18:57:58] [Debug] Closed
4

@TJvV About the other question " Did you double check which connections are defined in NetworkManager?", I’m pretty sure is not it, since I do have two system-connections, but one is already in use, so that leaves a single connection to ModemManager/NetworkManager to try it.

5

It sounds like your settings do not match what your operator expects?
If you’ve hit a data cap or your device needs to be registered first, connections can act weird.
Have you tried your SIM in a different device (ex. a phone)?

Can you share your system-connection(s)?
You can always try removing the system-connection(s) and only adding the simplest configuration.
i.e. nmcli connection add type gsm ifname '*' con-name <name> apn <apn>

6

Hey @TJvV, I understand what you are saying, but the fact that the connection eventually works, doesn’t rule these options out?
I just don’t know WHY I couldn’t get it working with qmicli tho…

This is my system-connection:

[connection]
id=BRA-BrTCelular-d8a338232cefff166e10be70b28cdf24371041dc
uuid=86f36138-3cd9-4cea-8064-8cffed843f49
type=gsm
permissions=

[gsm]
apn=gprs.oi.com.br
device-id=d8a338232cefff166e10be70b28cdf24371041dc
number=*99#
password=oi
username=oi

[ipv4]
dns-search=
method=auto
never-default=true

[ipv6]
addr-gen-mode=stable-privacy
dns-search=
method=auto

[proxy]

It’s pretty simple. The only difference is I have set the ‘device-id’, which I already tested without.

Yes, it does work on a phone, but I didn’t test the connection speed on it yet, I might test this soon.

7

You need to setup ModemManager with verbose logging (--debug), or via mmcli -G DEBUG, and then we’ll now in detail what happened.

I recall a very old similar issue that was already fixed, but cannot find the exact commit right now.

8

@aleksander0m This is the loop log with debug on: https://gist.github.com/lucaswxp/56c6a8b71b984865fa84e788027f1739

I had a hard time isolating only one iteration of the loop so I didn’t had to post 5K lines log, but if needed I can send the full log of the loop.

9

The modem does IPv4-only + IPv6-only setups with different WDS clients when IPv4v6 is requested. In the IPv6 case, though, the IP family isn’t returned and ModemManager wrongly assumes IPv4:

Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/bearer0]  IP Family: failed (Field 'IP Family' was not found in the message); assuming IPv4
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/bearer0]  IP Family: IPv4
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/bearer0] failed to read IPv4 netmask: Field 'IPv4 Gateway Subnet Mask' was not found in the message
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/bearer0]    domains: failed (Field 'Domain Name List' was not found in the message)
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/wwan1/net] port now connected
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0/bearer0] connected
Sep 10 13:42:51 3182c51 ModemManager[1389]: [modem0] state changed (connecting -> connected)

I would definitely test this with a newer ModemManager; I totally recall having fixed this; but don’t have time to look for the exact commit now I’m afraid.

10

Damn… I don’t think I can upgrade ModemManager easily in BalenaOS, anyone here knows how can I create a image with a newer ModemManager version?

@aleksander0m Is there a temporary fix? Could I somehow disable IPv6 altogether?

11

So, disabling IPv6 solved the loop issue:

nmcli con mod BRA-BrTCelular-d8a338232cefff166e10be70b28cdf24371041dc  ipv6.method "disabled"

But its a shame I had to do this, since @aleksander0m mentioned newer versions of ModemManager has this fixed. Is there any kind of release cycle? He asked it here Which versions of ModemManager and NetworkManager does BalenaOS runs? - #16 by aleksander0m but didn’t get any response.

12

Hey @lucaswxp, we use upstream Yocto OpenEmbedded branches for most of our packages, you can see the branches and corresponding versions for ModemManager here:
https://layers.openembedded.org/layerindex/recipe/1188/

For most active devices like Raspberry Pi, we are using the Dunfell branch which is pinned to ModemManager 1.12.12.
However, we actually pushed a little beyond that release manually to pick up some bug fixes so we are running 1.14.2.

It’s unlikely we would push to anything newer until we migrate fully to the next Yocto branch like Hardknott, but that’s not in the short term roadmap.
We want to ensure we keep compatibility across these packages like most distributions, so manually merging the latest version of each package becomes unmaintainable.

You could try building your own fork of balena-raspberrypi and substitute a newer MM to see if it works for you?
You could also open a PR against meta-balena to merge the latest version but it needs to be tested against a number of different modems.

It looks like you already have a workaround for now, let us know if we can help with anything else!

14

@klutchell I understand the need to keep compatibility across packages, thank you for your good work.

If I need a newer version and there no workaround I’ll take your suggestions into account :slight_smile:

15

ModemManager 1.18.0 was released last week. If there is any effort to upgrade MM to a newer version, please skip 1.16.x and just jump to 1.18.0, as 1.18.x is now the stable branch, and 1.16.x will likely receive no more updates.