'port forced close' after failed ppp

[Colin Helliwell]

> On 16 March 2017 at 16:23 Dan Williams <dcbw at redhat.com> wrote:
> 
> 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]:  [1489668966.638001] [src/mm-port-serial-
> > at.c:459] debug_log(): (ttyMux0): <-- 'NO CARRIER'
> >  ModemManager[979]:  [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 :)
> 

Theory sounds plausible! Presumably though, others use MM in the same way (ppp via pon/poff), so there's still something 'unusual' about my driver?