Infinite connection loop

[Sven Schwermer]

Hi,

I am running an embedded system with a u-blox SARA-U270 modem and NetworkManager 1.12.2 / ModemManager 1.8.0. For some reason, the modem connection seems to break over time. I am not quite sure why that’s the case, but when I look into the journal, I see NetworkManager and ModemManager spewing out log messages at a very high rate. This actually causes significant system load (mostly by dbus-daemon). Here’s an excerpt of the messages:

Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect started...
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (4/8): Wait to get fully enabled
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (5/8): Register
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (6/8): Bearer
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect started...
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (4/8): Wait to get fully enabled
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (5/8): Register
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (6/8): Bearer
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <warn>  [1539780869.7776] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.7778] device (ttyACM0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.7807] manager: NetworkManager state is now CONNECTED_LOCAL
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <warn>  [1539780869.7840] device (ttyACM0): Activation: failed for connection 'gprsconnection'
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.7860] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.7923] policy: auto-activating connection 'gprsconnection' (14e02637-0ffb-3a28-806f-ad60904afe7f)
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.8005] device (ttyACM0): Activation: starting connection 'gprsconnection' (14e02637-0ffb-3a28-806f-ad60904afe7f)
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.8015] device (ttyACM0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.8043] manager: NetworkManager state is now CONNECTING
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect started...
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (4/8): Wait to get fully enabled
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (5/8): Register
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (6/8): Bearer
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect started...
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (4/8): Wait to get fully enabled
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (5/8): Register
Oct 17 12:54:29 cf352c1 ModemManager[1385]: Simple connect state (6/8): Bearer
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <warn>  [1539780869.9321] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9323] device (ttyACM0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9350] manager: NetworkManager state is now CONNECTED_LOCAL
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <warn>  [1539780869.9399] device (ttyACM0): Activation: failed for connection 'gprsconnection'
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9430] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9490] policy: auto-activating connection 'gprsconnection' (14e02637-0ffb-3a28-806f-ad60904afe7f)
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9569] device (ttyACM0): Activation: starting connection 'gprsconnection' (14e02637-0ffb-3a28-806f-ad60904afe7f)
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9585] device (ttyACM0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 17 12:54:29 cf352c1 NetworkManager[677]: <info>  [1539780869.9653] manager: NetworkManager state is now CONNECTING

It continues like that forever. My modem network connection config is as follows:

[connection]
id=gprsconnection
type=gsm
autoconnect=true
autoconnect-retries=0
[gsm]
number=*99#
[ipv4]
dns-search=
method=auto
may-fail=false

I have been looking through the code and what I don’t understand is why the ttyACM0 would ever be forcefully closed. What could be an explanation for this?

Any insight is appreciated.

Best regards,
Sven