Port forced closed after DEACT

[Carlo Lobrano]

Hi Aleksander,

On Fri, 5 Jun 2020, 10:22 am Aleksander Morgado, <aleksander at aleksander.es>
wrote:

> Hey!
>
> > I am facing an unexpected - as far as I can tell - behavior with
> ModemManager 1.12.8 and network manager is 1.22.10 on Ubuntu 20.04, the
> modem is LE910 V2.
> >
> > During and ongoing connection, lasting since 38 minutes, the tty port is
> force closed after the following message
> >
> >     <debug> (ttyACM3): <-- '+CGEV: ME DEACT IP, "10.29.174.52",
> 1<CR><LF>'
> >
> > Is it normal that a deactivation leads to a port close?
> >
>
> No it isn't, this happened due to the mixup of the CLOCAL settings,
> full relevant logs:
>
> Jun  3 16:49:22 orndura ModemManager[418]: <debug> (ttyACM3): <--
> '+CGEV: ME DEACT IP, "10.29.174.52", 1<CR><LF>'
> Jun  3 16:49:22 orndura ModemManager[418]: <info>  mobile equipment
> request to deactivate context (type IP, address 10.29.174.52, cid 1)
> Jun  3 16:49:22 orndura NetworkManager[411]: <info>  [1591192162.3478]
> modem["ttyACM0"]: modem state changed, 'connected' --> 'registered'
> (reason: user-requested)
> Jun  3 16:49:22 orndura ModemManager[418]: <info>  Bearer
> /org/freedesktop/ModemManager1/Bearer/1: explicitly disconnected
>
> MM detects the disconnection and by itself reports the modem
> disconnected, it shouldn't have done that, it should have ignored the
> disconnection report detected by itself and wait for pppd to detect it
> itself.
>
> Jun  3 16:49:22 orndura NetworkManager[411]: <info>  [1591192162.3479]
> device (ttyACM0): state change: activated -> failed (reason
> 'modem-no-carrier', sys-iface-state: 'managed')
> Jun  3 16:49:22 orndura ModemManager[418]: <debug> (ttyACM0): port now
> disconnected
> Jun  3 16:49:22 orndura NetworkManager[411]: <debug> [1591192162.3501]
> active-connection[0x19bb480]: set state deactivated (was activated)
> Jun  3 16:49:22 orndura ModemManager[418]: <info>  Modem
> /org/freedesktop/ModemManager1/Modem/1: state changed (connected ->
> registered)
> Jun  3 16:49:22 orndura NetworkManager[411]: <info>  [1591192162.3508]
> manager: NetworkManager state is now DISCONNECTED
> Jun  3 16:49:22 orndura NetworkManager[411]: <debug> [1591192162.3515]
> active-connection[0x19bb480]: check-master-ready: not signalling
> (state deactivated, no master)
> Jun  3 16:49:22 orndura pppd[2774]: Modem hangup
> Jun  3 16:49:22 orndura NetworkManager[411]: Modem hangup
>
> CHUP happens in the TTY, which MM also detects because it was already
> also monitoring the port.
>
> Jun  3 16:49:22 orndura pppd[2774]: nm-ppp-plugin: (nm_phasechange):
> status 8 / phase 'network'
> Jun  3 16:49:22 orndura ModemManager[418]: <debug> (ttyACM3): <--
> '<CR><LF>'
> Jun  3 16:49:22 orndura ModemManager[418]: <debug> (ttyACM0)
> unexpected port hangup!
> Jun  3 16:49:22 orndura ModemManager[418]: <debug> (ttyACM0) forced to
> close port
>
> MM treats the HUP as a port removal, which shouldn't have happened if
> the disconnection was reported by NM after pppd exit, as CLOCAL
> settings would have been reset.
>
> I thought this should have been fixed in
> 5f29bd64de8127cb326488d68a2a2b64a45e1f45, but I don't see the relevant
> "PPP is required for connection, will ignore disconnection reports"
> message that should happen once the modem gets connected in PPP mode.
>
> If you have the setup with you, could you check why this message is
> not being logged?
>
> --
> Aleksander
> https://aleksander.es


Thanks for the analysis!
We were thinking about something related to clocal, but not this detail,
indeed.
I'll double check with the setup and keep, and report it back

Carlo

 I'll double check the setup, and

>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20200605/5c722914/attachment.htm>