Hi Matthew, Thanks for chiming in. I hadn’t found your thread before. Would you mind sharing that dispatcher script? Is that working out satisfactory as a workaround?
Best regards, Sven > On 22 Oct 2018, at 16:52, Matthew Starr <mst...@hedonline.com> wrote: > > Aleksander, > > This is the exact same issue I reported a couple months ago: > https://lists.freedesktop.org/archives/modemmanager-devel/2018-August/006593.html > > <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 <mailto:s...@svenschwermer.de>> >> To: Aleksander Morgado <aleksan...@aleksander.es >> <mailto:aleksan...@aleksander.es>> >> Cc: modemmanager-devel@lists.freedesktop.org >> <mailto:modemmanager-devel@lists.freedesktop.org> >> Subject: Re: Infinite connection loop >> Message-ID: <41689DBE-1755-4F85-BFA7- >> 97cf6e588...@svenschwermer.de <mailto: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- >> <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