Hi again, I now managed to capture the event in the journal. I limited the auto connect retried to 4 in order to keep the log size manageable. I didn’t have debug-level logging active for NetworkManager at the time. I’ll enable that now and try to reproduce. Please find the log attached. The error seems to be happening at Oct 20 07:44:26.
Best regards, Sven
ed6e56cf2ac5b6bdb2e3ca97276ebd6d.journal.log
Description: Binary data
> On 20 Oct 2018, at 13:47, Aleksander Morgado <aleksan...@aleksander.es> wrote: > > Hey, > >> 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. >> > > Do you have a full log of when this issue happens? If you can > reproduce this more or less frequently, could you setup both > ModemManager and NetworkManager to dump debug logs and try to get it > reproduced? This issue could be to a wrong synchronization between MM > and NM/pppd, in particular related to the CLOCAL settings in each case > (i.e. MM shouldn't get HUPs in the serial port unless for the cases > where the port is going away). > > -- > Aleksander > https://aleksander.es
_______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
