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 _______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
