gsm connection failure in network-manager snap (1.22.10-15 rev 754)

[Paul Larson]

On one of the systems in our test lab, we're getting the following error when running one of the gsm tests. This passed fine in the stable version of network-manager:

10:12:18 ---------------------------[ Running job 123 / 155 ]----------------------------
10:12:18 ---------[ Verify a GSM broadband modem can create a data connection ]----------
10:12:18 ID: com.canonical.certification::wwan/gsm-connection-QUALCOMM INCORPORATED-QUECTEL Mobile Broadband Module-867698040190756-auto
10:12:18 Category: Wireless Wide Area Network
10:12:18 --------------------------------------------------------------------------------
10:12:18 ## Creating 3GPP Connection
10:12:18 + nmcli c add con-name GSMCONN type gsm ifname cdc-wdm0 apn internet.iot
10:12:30 Connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f) successfully added.
10:12:30
10:12:30 ## Turn radio on
10:12:30 + nmcli r wwan on
10:12:42
10:12:42 ## Perfrom ping test
10:12:42 + ip route add 8.8.8.8 dev wwan0
10:12:42 Error: Device for nexthop is not up.
10:12:42
10:12:42 ## Destroy 3GPP Connection
10:12:42 + nmcli c delete GSMCONN
10:13:05 Connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f) successfully deleted.
10:13:05
10:13:05 ## Turn radio off
10:13:05 + nmcli r wwan off
10:13:05
10:13:05 ==== Service units logs ====
10:13:05 <info> [1667488329.5270] audit: op="connection-add" uuid="231b5162-f226-4b50-8896-b13bef8ccc8f" name="GSMCONN" pid=16416 uid=0 result="success"
10:13:05 <info> [1667488330.1445] manager: rfkill: WWAN hardware radio set enabled
10:13:05 <info> [1667488330.1733] modem["cdc-wdm0"]: modem state changed, 'disabled' --> 'enabling' (reason: user preference)
10:13:05 <info> [1667488330.1884] audit: op="radio-control" arg="wwan-enabled" pid=16444 uid=0 result="success"
10:13:05 <info> [1667488330.1952] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'modem-available', sys-iface-state: 'managed')
10:13:05 <info> [1667488330.2183] policy: auto-activating connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.2286] device (cdc-wdm0): Activation: starting connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.2304] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
10:13:05 <info> [modem0] state changed (disabled -> enabling)
10:13:05 <warn> [1667488330.4805] modem-broadband[cdc-wdm0]: failed to connect modem: Invalid properties dictionary, unexpected key 'profile-id'
10:13:05 <info> [1667488330.4806] device (cdc-wdm0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.4987] device (cdc-wdm0): Activation: failed for connection 'GSMCONN'
10:13:05 <info> [1667488330.5044] device (cdc-wdm0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
10:13:05 <info> [1667488330.5240] policy: auto-activating connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.5373] device (cdc-wdm0): Activation: starting connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.5404] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.5783] modem-broadband[cdc-wdm0]: failed to connect modem: Invalid properties dictionary, unexpected key 'profile-id'
10:13:05 <info> [1667488330.5787] device (cdc-wdm0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.5934] device (cdc-wdm0): Activation: failed for connection 'GSMCONN'
10:13:05 <info> [1667488330.5971] device (cdc-wdm0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
10:13:05 <info> [modem0] power state updated: on
10:13:05 <info> [1667488330.6137] policy: auto-activating connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.6253] device (cdc-wdm0): Activation: starting connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.6271] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.6483] modem-broadband[cdc-wdm0]: failed to connect modem: Invalid properties dictionary, unexpected key 'profile-id'
10:13:05 <info> [1667488330.6488] device (cdc-wdm0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.6728] device (cdc-wdm0): Activation: failed for connection 'GSMCONN'
10:13:05 <info> [1667488330.6844] device (cdc-wdm0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
10:13:05 <info> [1667488330.6904] policy: auto-activating connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.6939] device (cdc-wdm0): Activation: starting connection 'GSMCONN' (231b5162-f226-4b50-8896-b13bef8ccc8f)
10:13:05 <info> [1667488330.6967] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.7130] modem-broadband[cdc-wdm0]: failed to connect modem: Invalid properties dictionary, unexpected key 'profile-id'
10:13:05 <info> [1667488330.7134] device (cdc-wdm0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
10:13:05 <warn> [1667488330.7363] device (cdc-wdm0): Activation: failed for connection 'GSMCONN'
10:13:05 <info> [1667488330.7481] device (cdc-wdm0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
10:13:05 <warn> [modem0] couldn't load operator code: Current operator MCC/MNC is still unknown
10:13:05 <warn> [modem0] couldn't load operator name: Current operator description is still unknown
10:13:05 <info> [modem0] 3GPP registration state changed (unknown -> idle)
10:13:05 <info> [modem0] state changed (enabling -> enabled)
10:13:05 <info> [1667488332.4338] modem["cdc-wdm0"]: modem state changed, 'enabling' --> 'enabled' (reason: user-requested)
10:13:05 <info> [modem0] 3GPP registration state changed (idle -> registering)
10:13:05 <info> [modem0] 3GPP registration state changed (registering -> home)
10:13:05 <info> [modem0] state changed (enabled -> registered)
10:13:05 <info> [1667488332.4609] modem["cdc-wdm0"]: modem state changed, 'enabled' --> 'registered' (reason: unknown)
10:13:05 <info> [1667488360.6960] keyfile: deleting netplan connection: NM-231b5162-f226-4b50-8896-b13bef8ccc8f
10:13:05 <info> [1667488362.4231] audit: op="connection-delete" uuid="231b5162-f226-4b50-8896-b13bef8ccc8f" name="GSMCONN" pid=16478 uid=0 result="success"
10:13:05 <info> [1667488363.0184] manager: rfkill: WWAN hardware radio set disabled
10:13:05 <info> [modem0] state changed (registered -> disabling)
10:13:05 <info> [1667488363.0287] modem["cdc-wdm0"]: modem state changed, 'registered' --> 'disabling' (reason: user preference)
10:13:05 <info> [1667488363.0289] device (cdc-wdm0): state change: disconnected -> unavailable (reason 'none', sys-iface-state: 'managed')
10:13:05 <info> [1667488363.0394] audit: op="radio-control" arg="wwan-enabled" pid=16520 uid=0 result="success"
10:13:05 <info> [modem0] 3GPP registration state changed (home -> unknown)
10:13:05 <info> [modem0] state changed (disabling -> disabled)
10:13:05 <info> [1667488363.1873] modem["cdc-wdm0"]: modem state changed, 'disabling' --> 'disabled' (reason: user-requested)
10:13:05 <info> [modem0] power state updated: low
10:13:05 --------------------------------------------------------------------------------
10:13:05 Outcome: job failed

Here are the snaps that were installed at the time of the test:

bluez Version: 5.53-7-334
checkbox-newparis Version: 1.3-28
checkbox20 Version: 1.30-1037
core20 Version: 20220919-1634
kmc-commander-bx Version: 20-3.2.2.1433.28132-180
kmc-uno-420-gadget Version: 20-0.6-81
modem-manager Version: 1.16.6-2-470
network-manager Version: 1.22.10-15-754
pc-kernel Version: 5.4.0-131.147.2-1127
snapd Version: 2.57.4-17336
undying-sentinel Version: 20-1.2.8.9-88