'port forced close' after failed ppp

[Dan Williams]

On Thu, 2017-03-16 at 13:36 +0000, Colin Helliwell wrote:
> > On 14 March 2017 at 14:18 Colin Helliwell <colin.helliwell at ln-syste
> > ms.com> wrote:
> > 
> > > On 13 March 2017 at 09:53 Colin Helliwell <colin.helliwell at ln-sys
> > > tems.com> wrote:
> > > 
> > > > On 13 March 2017 at 09:06 Colin Helliwell <colin.helliwell at ln-s
> > > > ystems.com> wrote:
> > > > 
> > > > > On 10 March 2017 at 16:54 Aleksander Morgado <aleksander at alek
> > > > > sander.es> wrote:
> > > > > 
> > > > > On Fri, Mar 10, 2017 at 5:43 PM, Aleksander Morgado
> > > > > <aleksander at aleksander.es> wrote:
> > > > > 
> > > > > > > > > mmcli -m 0 --enable
> > > > > > > > >  mmcli -m 0 --simple-connect="apn=wap.vodafone.co.uk"
> > > > > > > > >  pon
> > > > > > > > >  ... success ...
> > > > > > > > >  poff
> > > > > > > > >  mmcli -m 0 --simple-disconnect
> > > > > > > > > 
> > > > > > > > > Then trying again to connect fails with 'forced
> > > > > > > > > close'
> > > > > > > > 
> > > > > > > > I'd consider this an MM bug then. But as a workaround,
> > > > > > > > try passing the
> > > > > > > > "local" option to pppd, which disables its munging of
> > > > > > > > modem control
> > > > > > > > lines and thus prevents a port hangup. Does that help?
> > > > > > > 
> > > > > > > No, changing 'modem' to 'local' doesn't help.
> > > > > > > I'm not sure where this hangup is coming from - is it
> > > > > > > being signalled from the pppd process to MM, or is it
> > > > > > > that MM is seeing a change on the port lines via the
> > > > > > > driver? (Would it help if I tried to find out?)
> > > > > > 
> > > > > > Just to confirm it, could you trace pppd to see if it re-
> > > > > > sets CLOCAL
> > > > > > before exiting?
> > > > > 
> > > > > Some more context...
> > > > > 
> > > > > pppd will by default, unless configured otherwise, unset
> > > > > CLOCAL, which
> > > > > in turn enables the carrier detect modem control line. pppd
> > > > > uses this
> > > > > to e.g. detect disconnections reported by the other end. When
> > > > > pppd
> > > > > exits, it re-sets the serial port configuration to what was
> > > > > found when
> > > > > the daemon was called. If CLOCAL was set before, pppd will
> > > > > re-set
> > > > > CLOCAL again.
> > > > > 
> > > > > ModemManager needs to work always with the ports with CLOCAL
> > > > > set (i.e.
> > > > > ignoring carrier detect).
> > > > > 
> > > > > Some years ago I fixed a bug in NetworkManager which was
> > > > > triggered by
> > > > > this logic; NM was telling MM that the port was disconnected
> > > > > as soon
> > > > > as pppd reported "PHASE_DISCONNECT", and MM was taking
> > > > > control of the
> > > > > port at that time. The problem was that at that time, pppd
> > > > > didn't yet
> > > > > recover the original serial port configuration, including
> > > > > CLOCAL, so
> > > > > MM was actually getting the HUP in the TTY right away as
> > > > > carrier
> > > > > detect was enabled (CLOCAL unset). The fix was to update NM
> > > > > so that it
> > > > > reports the disconnection to MM only after the DEAD state was
> > > > > reported
> > > > > by pppd.
> > > > > 
> > > > > So, following what the CLOCAL setting is in the different
> > > > > steps should
> > > > > definitely help I think.
> > > > 
> > > > Tracing in the driver, I can see the TCSETFS ioctl being called
> > > > at the 'pon' and at the 'poff'. Presumably this *is* from pppd
> > > > - nothing else is using the port except MM.
> > > > The respective c_cflag values in the args seem to be
> > > >  pon 020000012267
> > > >  poff 016261
> > > > So, yes, it appears that CLOCAL [04000] is being set? (and
> > > > CRTSCTS cleared)
> > > 
> > > Using 'local' instead of 'modem' in the ppp settings:
> > > pon 20000014267
> > > poff 016261
> > > i.e. CLOCAL *staying* set, and setting HUPCL?
> 
> Made an interesting discovery this morning. I wanted to use strace to
> try to track down the sequence of events. This didn't show much
> [without -f] because pppd forks, so instead I added nodetach
> ('/usr/sbin/pppd nodetach call provider') and... it worked!
> On running poff, I see
>   ModemManager[979]: <debug> [1489668966.638001] [src/mm-port-serial-
> at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>NO CARRIER<CR><LF>'
>   ModemManager[979]: <debug> [1489668966.638554] [src/mm-serial-
> parsers.c:364] mm_serial_parser_v1_parse(): Got failure code 1: No
> carrier
> 
> but no 'unexpected hangup'! ...?

Aha!  Good catch.  NetworkManager sends "nodetach" when it controls
pppd, so perhaps that's why we haven't seen it in NM cases.  And this
could make sense, because some of the in-kernel HUP cases depend on the
"session leader" and when that process exits then the port is hung up. 
"nodetach" says "Don't detach from the controlling terminal." which
would prevent pppd from creating a new session and thus prevent it from
becoming the session leader of a new session, thus perhaps prevent the
port from being closed when the leader exits (because the leader is
still ModemManager).  At least, in theory :)

Dan