Aleksander, This is the exact same issue I reported a couple months ago: https://lists.freedesktop.org/archives/modemmanager-devel/2018-August/006593.html
I am currently working around it by adding a NetworkManager dispatcher script that on ppp0 going down, I restart ModemManager. I never did find a solution to the issue even after trying some modifications to the serial force close code (src/mm-port-serial.c) in ModemManager. It looks like the force_closed boolean gets set and is never reset, which causes the serial port to never retry communications over the serial port again. Regards, Matthew Starr > Date: Mon, 22 Oct 2018 11:39:37 +0200 > From: Sven Schwermer <s...@svenschwermer.de> > To: Aleksander Morgado <aleksan...@aleksander.es> > Cc: modemmanager-devel@lists.freedesktop.org > Subject: Re: Infinite connection loop > Message-ID: <41689DBE-1755-4F85-BFA7- > 97cf6e588...@svenschwermer.de> > Content-Type: text/plain; charset="utf-8" > > I looked a little closer into this now. > > Here’s what I think is happening: > 1. My cell operator terminates the LCP after some time of inactivity. This is > confirmed by my operator. > 2. pppd receives the termination request, acknowledges it and the modem > hangs up the connection. > 3. ModemManager fails to re-acquire serial port lock because of the hangup. > 4. ModemManager sets the connection state to ‘registered’. > 5. ModemManager force-closes the serial port. > 6. NetworkManager registers the lost connection and tries to re-establish it. > 7. The ModemManager fails to re-open serial port because it had been force- > closed. > > pppd doesn’t appear to be re-launched. How is this all supposed to work? > I’m sure the software stack should be able to handle a terminated > connection and re-dial it? > > Please find attached the debug-level log. The LCP termination happens at Oct > 21 14:53:51. > > Best regards, > Sven > > -------------- next part -------------- > A non-text attachment was scrubbed... > Name: excerpt.long.gz > Type: application/x-gzip > Size: 53662 bytes > Desc: not available > URL: <https://lists.freedesktop.org/archives/modemmanager- > devel/attachments/20181022/1e9e348d/attachment.bin> > -------------- next part -------------- > > > > On 20 Oct 2018, at 16:26, Sven Schwermer <s...@svenschwermer.de> > wrote: > > > > 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> > > > >> 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