Infinite connection loop

Tue Oct 23 06:22:25 UTC 2018

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 <mstarr at 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 <sven at svenschwermer.de <mailto:sven at svenschwermer.de>>
>> To: Aleksander Morgado <aleksander at aleksander.es <mailto:aleksander at aleksander.es>>
>> Cc: modemmanager-devel at lists.freedesktop.org <mailto:modemmanager-devel at lists.freedesktop.org>
>> Subject: Re: Infinite connection loop
>> Message-ID: <41689DBE-1755-4F85-BFA7-
>> 97CF6E588F41 at svenschwermer.de <mailto:97CF6E588F41 at 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 <sven at 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
>> <aleksander at 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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20181023/e8c49664/attachment-0001.html>