'port forced close' after failed ppp

Tue Mar 7 10:13:05 UTC 2017

> On 07 March 2017 at 09:43 Colin Helliwell <colin.helliwell at ln-systems.com> wrote:
> 
> (Sorry - misformatted that last one)
> 
> > On 06 March 2017 at 16:47 Dan Williams <dcbw at redhat.com> wrote:
> > 
> > On Mon, 2017-03-06 at 15:35 +0000, colin.helliwell at ln-systems.com
> > wrote:
> > 
> > > I have MM hooked into a Mux driver which is presenting two virtual
> > > ports:
> > > one as the Primary, one for PPP. I'm attempting to fire up the
> > > data/PPP with
> > > --enable and --simple-connect=.
> > > 
> > > The PPP is failing, no doubt a problem with the config in that
> > > itself, but I
> > > have a couple of puzzlements:
> > > 
> > > MM is getting a "[src/mm-port-serial.c:942] common_input_available():
> > > (ttyMux1) unexpected port hangup!" . But I can't see in the source
> > > where the
> > > G_IO_HUP [?] would be originating - maybe a handshake signal on the
> > > port?
> > 
> > Correct. Something (driver? modem? MM?) cleared DTR or RTS and caused
> > a serial port hangup. Any chance you can instrument the MUX driver to
> > see if/when it calls tty_hangup() or tty_port_tty_hangup()?
> > 
> > To figure out if MM is involved, you can strace MM and see what
> > termio/tty operations it's doing, but usually this message is caused by
> > external things.
> 
> It looks like this is pppd (which is configured with the 'modem' parameter) which is clearing DTR with a tty_operations->tiocmset. Changing 'modem' to 'local' however still causes a port hangup - I can see the driver ioctl handler getting a TCFLSH and a TCSETSF.
> 
> But since the ppp negotiation *is* failing (tho I don't yet know why), I guess the 'hangup' *is* probably correct. Which comes back to why the port is then 'dead' and unretry-able (+ see below). Especially since it is ppp's use of the port which has been hung up, not MM's own use of it.
> Just wondering about a) the "When connected ignore let PPP have all the data" in port_connected(); and b) that data_watch_enable(false) doesn't seem to take much 'disabling' actions?
> 
> (Thought I'd got all of this, even the ppp, working right a few weeks ago :( maybe that was before I'd got the two ports going on the modem)

In case it's of use, here's the log of MM+pppd when trying (after a --enable) the --simple-connect followed by 'pon'

Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.022821] [src/mm-iface-modem-simple.c:641] connect_auth_ready(): Simple connect started...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023123] [src/mm-iface-modem-simple.c:651] connect_auth_ready():    PIN: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023257] [src/mm-iface-modem-simple.c:653] connect_auth_ready():    Operator ID: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023392] [src/mm-iface-modem-simple.c:655] connect_auth_ready():    Allowed roaming: yes
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023525] [src/mm-iface-modem-simple.c:657] connect_auth_ready():    APN: mobile.o2.co.uk
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023660] [src/mm-iface-modem-simple.c:665] connect_auth_ready():    IP family: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023786] [src/mm-iface-modem-simple.c:673] connect_auth_ready():    Allowed authentication: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.023916] [src/mm-iface-modem-simple.c:675] connect_auth_ready():    User: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.024039] [src/mm-iface-modem-simple.c:677] connect_auth_ready():    Password: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.024171] [src/mm-iface-modem-simple.c:679] connect_auth_ready():    Number: unspecified
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.024281] [src/mm-iface-modem-simple.c:469] connection_step(): Simple connect state (4/8): Wait to get fully enabled
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.024578] [src/mm-iface-modem-simple.c:478] connection_step(): Simple connect state (5/8): Register
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.026843] [src/mm-iface-modem-3gpp.c:437] mm_iface_modem_3gpp_register_in_network(): Already registered in network '23410', automatic registration not launched...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.028145] [src/mm-iface-modem-simple.c:501] connection_step(): Simple connect state (6/8): Bearer
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.029406] [src/mm-iface-modem-simple.c:521] connection_step(): Creating new bearer...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.030410] [plugins/cinterion/mm-broadband-modem-cinterion.c:1733] cinterion_modem_create_bearer(): skipping ^SWWAN check as no data port is available
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.031342] [plugins/cinterion/mm-broadband-modem-cinterion.c:1671] common_create_bearer(): ^SWWAN not supported, creating default bearer...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.034868] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.036067] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.037489] [plugins/cinterion/mm-broadband-modem-cinterion.c:1630] cinterion_modem_create_bearer_finish(): New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/0'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.042393] [src/mm-iface-modem-simple.c:583] connection_step(): Simple connect state (7/8): Connect
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.043586] [src/mm-base-bearer.c:801] mm_base_bearer_connect(): Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <info>  [1488881116.044690] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.052266] [src/mm-broadband-bearer.c:1342] connect(): Launching 3GPP connection attempt with APN 'mobile.o2.co.uk'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.054094] [src/mm-broadband-bearer.c:84] select_bearer_ip_family(): No specific IP family requested, defaulting to ipv4
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.055072] [src/mm-broadband-bearer.c:84] select_bearer_ip_family(): No specific IP family requested, defaulting to ipv4
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.056028] [src/mm-broadband-bearer.c:951] cid_selection_3gpp(): Looking for best CID...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.057001] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.058199] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CGDCONT?<CR>'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.111839] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CGDCONT: 1,"IP","mobile.o2.co.uk","",0,0<CR><LF><CR><LF>OK<CR><LF>'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.113404] [src/mm-broadband-bearer.c:867] parse_pdp_list(): Found '1' PDP contexts
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.114400] [src/mm-broadband-bearer.c:876] parse_pdp_list():   PDP context [cid=1] [type='ipv4'] [apn='mobile.o2.co.uk']
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.115352] [src/mm-broadband-bearer.c:901] parse_pdp_list(): Found PDP context with CID 1 and PDP type ipv4 for APN 'mobile.o2.co.uk'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.116265] [src/mm-port-serial.c:1164] mm_port_serial_open(): (ttyMux1) opening serial port...
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.228678] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 1 (open)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.229838] [src/mm-broadband-bearer.c:222] common_get_at_data_port(): Connection through a plain serial AT port (ttyMux1)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.230881] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.232005] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.233118] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'ATD*99***1#<CR>'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.261200] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'ATD*99***1#<CR>'
Mar  7 10:05:16 wg2 daemon.info ModemManager[896]: <debug> [1488881116.274786] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CGREG: 2<CR><LF>'
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.270515] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CGREG: 1<CR><LF>'
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.778895] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '<CR><LF>CONNECT<CR><LF>~\255}#\192!}!}#} }9}"}&} }*} } }'}"}(}"}%}&_\173\129q}#}%\194#}%},M~'
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.780328] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 1 (close)
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.781645] [src/mm-port.c:94] mm_port_set_connected(): (ttyMux1): port now connected
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.782764] [src/mm-base-bearer.c:699] connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <info>  [1488881119.784955] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <info>  [1488881119.792374] [src/mm-iface-modem-simple.c:602] connection_step(): Simple connect state (8/8): All done
Mar  7 10:05:19 wg2 user.info kernel: PPP generic driver version 2.4.2
Mar  7 10:05:19 wg2 daemon.notice pppd[944]: pppd 2.4.7 started by root, uid 0
Mar  7 10:05:19 wg2 daemon.debug pppd[944]: using channel 1
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.961557] [src/mm-base-manager.c:256] device_added(): (net/ppp0): adding device at sysfs path: /sys/devices/virtual/net/ppp0
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.961950] [src/kerneldevice/mm-kernel-device-udev.c:466] kernel_device_is_candidate(): (net/ppp0): could not get port's parent device
Mar  7 10:05:19 wg2 daemon.info ModemManager[896]: <debug> [1488881119.962129] [src/mm-base-manager.c:265] device_added(): (net/ppp0): port not candidate
Mar  7 10:05:19 wg2 daemon.info pppd[944]: Using interface ppp0
Mar  7 10:05:19 wg2 daemon.notice pppd[944]: Connect: ppp0 <--> /dev/ttyMux1
Mar  7 10:05:19 wg2 daemon.debug pppd[944]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xa0e54e1c> <pcomp> <accomp>]
Mar  7 10:05:19 wg2 daemon.debug pppd[944]: rcvd [LCP ConfNak id=0x1 <asyncmap 0xa0000>]
Mar  7 10:05:19 wg2 daemon.debug pppd[944]: sent [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0xa0e54e1c> <pcomp> <accomp>]
Mar  7 10:05:20 wg2 daemon.debug pppd[944]: rcvd [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0xa0e54e1c> <pcomp> <accomp>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x3 <asyncmap 0xa0000> <pcomp> <accomp> <magic 0x5fad8171> <auth chap MD5>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: No auth is possible
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfRej id=0x3 <auth chap MD5>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x5 <asyncmap 0xa0000> <pcomp> <accomp> <magic 0x5fad8171> <auth pap>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: No auth is possible
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfRej id=0x5 <auth pap>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x7 <asyncmap 0xa0000> <pcomp> <accomp> <magic 0x5fad8171>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfAck id=0x7 <asyncmap 0xa0000> <pcomp> <accomp> <magic 0x5fad8171>]
Mar  7 10:05:22 wg2 daemon.warn pppd[944]: kernel does not support PPP filtering
Mar  7 10:05:22 wg2 user.info kernel: PPP BSD Compression module registered
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:22 wg2 user.info kernel: PPP Deflate Compression module registered
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ProtRej id=0x8 80 fd 01 01 00 0f 1a 04]
Mar  7 10:05:22 wg2 daemon.debug pppd[944]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Mar  7 10:05:25 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.484324] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.484745] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CGACT?<CR>'
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.513270] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>OK<CR><LF>'
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.514773] [src/mm-base-bearer.c:172] load_connection_status_ready(): connection status loaded: disconnected
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.515912] [src/mm-port.c:94] mm_port_set_connected(): (ttyMux1): port now disconnected
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <info>  [1488881125.516973] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> registered)
Mar  7 10:05:25 wg2 daemon.info ModemManager[896]: <debug> [1488881125.521936] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
Mar  7 10:05:28 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:31 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:34 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:37 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:40 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:43 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.488654] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.489017] [src/mm-broadband-modem.c:2077] modem_load_signal_quality(): loading signal quality...
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.489234] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.489520] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT^SMONG<CR>'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.536387] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>GPRS Monitor<CR><LF><CR><LF>BCCH  G  PBC'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.554117] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- 'CH  PAT MCC  MNC  NOM  TA      RAC                              # Cell #<CR><LF>  40  2  -      4   234   10  2    -       92    
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.555862] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 2 (close)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.557052] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CIND?<CR>'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.585853] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CIND: 5,99,1,0,0,0,0,0,3<CR><LF><CR><LF>OK<CR><LF>'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.587382] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.588580] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 2 (close)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.589679] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CSQ<CR>'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.614250] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CSQ: 22,99<CR><LF><CR><LF>OK<CR><LF>'
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.615634] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
Mar  7 10:05:43 wg2 daemon.info ModemManager[896]: <debug> [1488881143.617096] [src/mm-iface-modem.c:1204] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (70)
Mar  7 10:05:46 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:49 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar  7 10:05:52 wg2 daemon.warn pppd[944]: IPCP: timeout sending Config-Requests
Mar  7 10:05:52 wg2 daemon.debug pppd[944]: sent [LCP TermReq id=0x3 "No network protocols running"]
Mar  7 10:05:52 wg2 daemon.debug pppd[944]: rcvd [LCP TermAck id=0x3 "No network protocols running"]
Mar  7 10:05:52 wg2 daemon.notice pppd[944]: Connection terminated.
Mar  7 10:05:52 wg2 daemon.info avahi-daemon[865]: Withdrawing workstation service for ppp0.
Mar  7 10:05:53 wg2 daemon.info pppd[944]: Exit.
Mar  7 10:05:53 wg2 daemon.info ModemManager[896]: <debug> [1488881153.411592] [src/mm-port-serial.c:942] common_input_available(): (ttyMux1) unexpected port hangup!
Mar  7 10:05:53 wg2 daemon.info ModemManager[896]: <debug> [1488881153.411812] [src/mm-port-serial.c:1477] port_serial_close_force(): (ttyMux1) forced to close port
Mar  7 10:05:53 wg2 daemon.info ModemManager[896]: <debug> [1488881153.411933] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 0 (close)
Mar  7 10:05:53 wg2 daemon.info ModemManager[896]: <debug> [1488881153.412072] [src/mm-port-serial.c:1367] _close_internal(): (ttyMux1) closing serial port...
Mar  7 10:05:53 wg2 daemon.info ModemManager[896]: <debug> [1488881153.423341] [src/mm-port-serial.c:1415] _close_internal(): (ttyMux1) serial port closed

The ppp 'provider' file is
ttyMux1
115200
lock
crtscts
modem
passive
novj
defaultroute
noipdefault
usepeerdns
noauth
hide-password
persist
holdoff 10
maxfail 1
debug