Re: NetworkManager invalid bearer IP configuration
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]: Auto-activating connection 'Verizon'. Sep 16 21:33:37 localhost NetworkManager[224]: (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:37 localhost NetworkManager[224]: (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): disconnecting connection 'Verizon' for new activation request. Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): device state change: prepare -> deactivating (reason 'new-activation') [40 110 60] Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): disconnecting for new activation request. Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): device state change: deactivating -> disconnected (reason 'new-activation') [110 30 60] Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): Activation: starting connection 'Verizon' (8868b767-a938-4096-9b90-9a1bebb398f9) Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0] Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'enabling' --> 'registered' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'registered' --> 'connecting' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'connecting' --> 'registered' (reason: user-requested) Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'registered' --> 'connecting' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'connecting' --> 'connected' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): failed to connect modem: invalid bearer IP configuration Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): device state change: prepare -> failed (reason 'config-failed') [40 120 4] Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): Activation: failed for connection 'Verizon' Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): modem state changed, 'connected' --> 'disconnecting' (reason: user-requested) Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0] Sep 16 21:33:39 localhost NetworkManager[224]: (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]: Auto-activating connection 'Verizon'. Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1):
Re: NetworkManager invalid bearer IP configuration
On Fri, 2016-09-16 at 22:04 -0500, 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. ModemManager is sending the wrong bearer object path for the disconnected/failed bearer which is what's messing up NM here. Is there any chance you have (or can get?) ModemManager --debug logs from when the problem happens? Dan > > --- > --- > NetworkManager Logs > --- > --- > > Sep 16 21:33:37 localhost NetworkManager[224]: Auto- > activating > connection 'Verizon'. > Sep 16 21:33:37 localhost NetworkManager[224]: (cdc-wdm1): > Activation: starting connection 'Verizon' > (8868b767-a938-4096-9b90-9a1bebb398f9) > Sep 16 21:33:37 localhost NetworkManager[224]: (cdc-wdm1): > device state change: disconnected -> prepare (reason 'none') [30 40 > 0] > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > disconnecting connection 'Verizon' for new activation request. > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > device state change: prepare -> deactivating (reason 'new- > activation') > [40 110 60] > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > disconnecting for new activation request. > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > device state change: deactivating -> disconnected (reason > 'new-activation') [110 30 60] > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > Activation: starting connection 'Verizon' > (8868b767-a938-4096-9b90-9a1bebb398f9) > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > device state change: disconnected -> prepare (reason 'none') [30 40 > 0] > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'enabling' --> 'registered' (reason: user-requested) > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'registered' --> 'connecting' (reason: user-requested) > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'connecting' --> 'registered' (reason: user-requested) > Sep 16 21:33:38 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'registered' --> 'connecting' (reason: user-requested) > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'connecting' --> 'connected' (reason: user-requested) > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > failed to connect modem: invalid bearer IP configuration > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > device state change: prepare -> failed (reason 'config-failed') [40 > 120 4] > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > Activation: failed for connection 'Verizon' > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > modem > state changed, 'connected' --> 'disconnecting' (reason: user- > requested) > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > device state change: failed -> disconnected (reason 'none') [120 30 > 0] > Sep 16 21:33:39 localhost NetworkManager[224]: (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]: Auto- > activating > connection 'Verizon'. > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > Activation: starting connection 'Verizon' > (8868b767-a938-4096-9b90-9a1bebb398f9) > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > device state change: disconnected -> prepare (reason 'none') [30 40 > 0] > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > failed to connect modem: invalid bearer IP configuration > Sep 16 21:33:39 localhost NetworkManager[224]: (cdc-wdm1): > device state change: prepare ->
