Port forced closed after DEACT

[Aleksander Morgado]

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