Hey All,I solved my problem. I have a d-bus client application that identifies the correct carrier, and thus the correct connection to activate. There was a race condition where my client was trying to activate the connection while NetworkManager was already setting up the bearer, and the first bearer was only half configured. I have modified my client to avoid the conflict, and I hope to eventually upgrade my devices to a newer version of NetworkManager that will handle this for me, but I feel obligated to suggest making NetworkManager clean up after itself better when going from "prepare" to "deactivating" with a cellular modem. This state change can be seen in the first few lines of my logs below, caused by a "new activation".
Alex Ferm PetroPower, LLC. 3003 E. 37th Street N. Suite 100 Wichita, KS 67219 Phone: (316) 361-0222 Toll Free: (877) 265-6581 Fax: (316) 361-0967 On 09/16/2016 10:04 PM, Alex Ferm wrote:
Hello all,I have run into a problem with NetworkManager and ModemManager, where NetworkManager fails to complete the connection due to an "invalid bearer IP configuration". In this state, ModemManager shows the modem as connected with 2 bearers, and one of them has an unknown IPv4 configuration. I have many devices running the same configuration, and I have seen this multiple times. I don't know what is causing this, but it appears to happen most frequently when the RTC of the device is set improperly, or doesn't keep time without power. I can fairly regularly reproduce the issue by setting the hardware clock to a time in the past and rebooting or power-cycling the host. I have devices with the same software configuration using a different modem (an MC7750) and I have never seen, or been able to cause this issue with that modem. Logs and some digging from the command-line are shown below.------------------------------------------------------------------------------ NetworkManager Logs ------------------------------------------------------------------------------Sep 16 21:33:37 localhost NetworkManager[224]: <info> Auto-activating connection 'Verizon'. Sep 16 21:33:37 localhost NetworkManager[224]: <info> (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:37 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:38 localhost NetworkManager[224]: <warn> (cdc-wdm1): disconnecting connection 'Verizon' for new activation request. Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: prepare -> deactivating (reason 'new-activation') [40 110 60] Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): disconnecting for new activation request. Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: deactivating -> disconnected (reason 'new-activation') [110 30 60] Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'enabling' --> 'registered' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'registered' --> 'connecting' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'connecting' --> 'registered' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'registered' --> 'connecting' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'connecting' --> 'connected' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): failed to connect modem: invalid bearer IP configuration Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'config-failed') [40 120 4] Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): Activation: failed for connection 'Verizon' Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0] Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): modem state changed, 'disconnecting' --> 'connected' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: (NetworkManager:224): NetworkManager-wwan-CRITICAL **: modem_prepare_result: assertion 'state == NM_DEVICE_STATE_PREPARE' failed Sep 16 21:33:39 localhost NetworkManager[224]: <info> Auto-activating connection 'Verizon'. Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): failed to connect modem: invalid bearer IP configuration Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'config-failed') [40 120 4] Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): Activation: failed for connection 'Verizon' Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0] Sep 16 21:33:39 localhost NetworkManager[224]: <info> Auto-activating connection 'Verizon'. Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): failed to connect modem: invalid bearer IP configuration Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'config-failed') [40 120 4] Sep 16 21:33:39 localhost NetworkManager[224]: <warn> (cdc-wdm1): Activation: failed for connection 'Verizon' Sep 16 21:33:39 localhost NetworkManager[224]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0]------------------------------------------------------------------------------ Command Line Introspection ------------------------------------------------------------------------------console@localhost:~$ nmcli d DEVICE TYPE STATE CONNECTION eth0 ethernet connected eth0-DHCP cdc-wdm1 gsm disconnected -- lo loopback unmanaged -- console@localhost:~$ mmcli -m 0/org/freedesktop/ModemManager1/Modem/0 (device id 'dba163d88766f89690dde112e66dd89239d2af9d')------------------------- Hardware | manufacturer: 'Sierra Wireless, Incorporated' | model: 'MC7354'| revision: 'SWI9X15C_05.05.58.01 r27044 carmd-fwbuild1 2015/03/05 00:02:40'| supported: 'gsm-umts | cdma-evdo | lte | cdma-evdo, gsm-umts | gsm-umts, lte | cdma-evdo, lte | cdma-evdo, gsm-umts, lte' | current: 'cdma-evdo, gsm-umts, lte' | equipment id: 'XXXXXXXXXXXXXXX' -------------------------System | device: '/sys/devices/platform/ocp/47400000.usb/47401c00.usb/musb-hdrc.1.auto/usb1/1-1'| drivers: 'qmi_wwan, option1' | plugin: 'Generic' | primary port: 'cdc-wdm1'| ports: 'ttyUSB0 (qcdm), uplink0 (net), ttyUSB2 (at), cdc-wdm1 (qmi), wwan1 (net), cdc-wdm0 (qmi)'------------------------- Numbers | own : 'XXXXXXXXXX' ------------------------- Status | lock: 'sim-pin2'| unlock retries: 'sim-pin (3), sim-pin2 (3), sim-puk (10), sim-puk2 (10)'| state: 'connected' | power state: 'on' | access tech: 'lte' | signal quality: '55' (recent) ------------------------- Modes | supported: 'allowed: 2g, 3g, 4g; preferred: none' | current: 'allowed: 2g, 3g, 4g; preferred: none' -------------------------Bands | supported: 'cdma-bc0-cellular-800, cdma-bc1-pcs-1900, cdma-bc10-secondary-800, cdma-bc15-aws, dcs, egsm, pcs, g850, u2100, u1900, u17iv, u850, u900, eutran-ii, eutran-iv, eutran-v, eutran-xiii, eutran-xvii, eutran-xxv' | current: 'cdma-bc0-cellular-800, cdma-bc1-pcs-1900, cdma-bc15-aws, dcs, egsm, pcs, g850, u2100, u1900, u850, u900, eutran-iv, eutran-xiii'------------------------- IP | supported: 'ipv4, ipv6, ipv4v6' ------------------------- 3GPP | imei: 'XXXXXXXXXXXXXXX' | enabled locks: 'none' | operator id: '311480' | operator name: 'VZW' | subscription: 'unknown' | registration: 'home' ------------------------- CDMA | meid: 'XXXXXXXXXXXXXXX' | esn: 'XXXXXXXX' | sid: 'unknown' | nid: 'unknown' | registration: CDMA1x 'unknown' | EV-DO 'unknown' | activation: 'activated' ------------------------- SIM | path: '/org/freedesktop/ModemManager1/SIM/0' -------------------------Bearers | paths: '/org/freedesktop/ModemManager1/Bearer/2, /org/freedesktop/ModemManager1/Bearer/0'console@localhost:~$ mmcli -b 2 Bearer '/org/freedesktop/ModemManager1/Bearer/2' ------------------------- Status | connected: 'yes' | suspended: 'no' | interface: 'uplink0' | IP timeout: '20' ------------------------- Properties | apn: 'mw01.vzwstatic' | roaming: 'allowed' | IP type: 'ipv4' | user: 'none' | password: 'none' | number: '*99#' | Rm protocol: 'unknown' ------------------------- IPv4 configuration | method: 'dhcp' | address: 'unknown' | prefix: '0' | gateway: 'unknown' | DNS: none | MTU: '1428' ------------------------- IPv6 configuration | method: 'unknown' console@localhost:~$ mmcli -b 0 Bearer '/org/freedesktop/ModemManager1/Bearer/0' ------------------------- Status | connected: 'yes' | suspended: 'no' | interface: 'uplink0' | IP timeout: '20' ------------------------- Properties | apn: 'mw01.vzwstatic' | roaming: 'allowed' | IP type: 'ipv4v6' | user: 'none' | password: 'none' | number: '*99#' | Rm protocol: 'unknown' ------------------------- IPv4 configuration | method: 'unknown' ------------------------- IPv6 configuration | method: 'unknown' rer 0le@localhost:~$ sudo mmcli -m 0 --delete-bear console@localhost:~$ sudo nmcli c up VerizonConnection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/6)console@localhost:~$ nmcli d DEVICE TYPE STATE CONNECTION eth0 ethernet connected eth0-DHCP cdc-wdm1 gsm connected Verizon lo loopback unmanaged -- _______________________________________________ networkmanager-list mailing list networkmanager-list gnome org https://mail.gnome.org/mailman/listinfo/networkmanager-list
Attachment:
aferm.vcf
Description: Vcard