#374698 pppd exits despite 'persist' option

Package:
ppp
Source:
ppp
Description:
Point-to-Point Protocol (PPP) - daemon
Submitter:
Claus Fischer
Date:
2023-11-04 00:00:03 UTC
Severity:
normal
#374698#5
Date:
2006-06-20 18:05:13 UTC
From:
To:
Summary: The persist option does not work properly.


Scenario
********

I tried to use the pppd daemon as a child of the pptp daemon,
which gets started by an init script. (The init script is by
Klaus Triendl). A combination of pptp and pppd is required for
ADSL in Austria.

While the pptp connection is generally stable, a disconnect
of the phone cable (simulating a fall-off of the connection)
or a switch-off of the modem will lead to eventual death of
pppd, and consequently death of the controlling pptp daemon.

This is not good. On one hand, the phone line quality will
sometimes lead to similar disconnects, on the other hand,
the internet provider will typically disconnect after some
period of time.

I have tried to get things to work the other way around
(pppd calling pptp in a pty-keyword-setup) but that also
proved unstable.


How pppd dies
*************


Apparently pppd does not die immediately with the dead
connection; it dies while the next attempt to restart
the connection is made.


Here's an excerpt of the log:

<Switching off the modem>
Jun 15 22:39:41 hostname kernel: eth0: link down
Jun 15 22:40:14 hostname pptp[8340]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 5 'Echo-Request'
Jun 15 22:40:36 hostname pppd[8341]: No response to 5 echo-requests
Jun 15 22:40:36 hostname pppd[8341]: Serial link appears to be disconnected.
Jun 15 22:40:36 hostname pppd[8341]: Connect time 1.4 minutes.
Jun 15 22:40:36 hostname pppd[8341]: Sent 1412 bytes, received 328 bytes.
Jun 15 22:40:37 hostname postfix/postfix-script: refreshing the Postfix mail system
Jun 15 22:40:37 hostname postfix/master[4033]: reload configuration
Jun 15 22:40:42 hostname pppd[8341]: Connection terminated.
Jun 15 22:40:43 hostname pppd[8341]: Modem hangup
Jun 15 22:40:53 hostname ovpn-hostname[3486]: write UDPv4 []: Network is unreachable (code=101)
Jun 15 22:40:58 hostname pppd[8341]: Using interface ppp0
Jun 15 22:40:58 hostname pppd[8341]: Connect: ppp0 <--> /dev/pts/0
Jun 15 22:41:14 hostname pptp[8340]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 12 'Call-Clear-Request'
Jun 15 22:41:14 hostname pptp[8340]: anon log[pptp_conn_close:pptp_ctrl.c:425]: Closing PPTP connection
Jun 15 22:41:14 hostname pptp[8340]: anon log[ctrlp_rep:pptp_ctrl.c:243]: Sent control packet type is 3 'Stop-Control-Connection-Request'
Jun 15 22:41:14 hostname pptp[8340]: anon log[call_callback:pptp_callmgr.c:77]: Closing connection
Jun 15 22:41:28 hostname pppd[8341]: LCP: timeout sending Config-Requests
Jun 15 22:41:28 hostname pppd[8341]: Connection terminated.
Jun 15 22:41:28 hostname pppd[8341]: Using interface ppp0
Jun 15 22:41:28 hostname pppd[8341]: Connect: ppp0 <--> /dev/pts/0
Jun 15 22:41:29 hostname ntpd[4272]: sendto(131.130.253.2): Network is unreachable
Jun 15 22:41:34 hostname pppd[8341]: Connection terminated.
Jun 15 22:41:34 hostname pppd[8341]: tcflush failed: Bad file descriptor
Jun 15 22:41:34 hostname pppd[8341]: tcsetattr: Invalid argument (line 971)
Jun 15 22:41:35 hostname pppd[8341]: tcsetattr: Invalid argument (line 1010)
Jun 15 22:41:35 hostname pppd[8341]: Exit.
Jun 15 22:41:35 hostname pptp[8348]: anon warn[decaps_hdlc:pptp_gre.c:197]: short read (-1): Input/output error
Jun 15 22:41:35 hostname pptp[8348]: anon warn[decaps_hdlc:pptp_gre.c:209]: pppd may have shutdown, see pppd log
Jun 15 22:42:11 hostname ntpd[4272]: sendto(212.17.99.45): Network is unreachable
Jun 15 22:42:53 hostname kernel: eth0: link up, 100Mbps, full-duplex, lpa 0x41E1
Jun 15 22:42:55 hostname pptp[8511]: anon log[main:pptp.c:243]: The synchronous pptp option is NOT activated
Jun 15 22:42:56 hostname kernel: eth0: link down
Jun 15 22:42:58 hostname pptp[8513]: anon warn[open_inetsock:pptp_callmgr.c:311]: connect: No route to host
Jun 15 22:42:58 hostname pptp[8513]: anon fatal[callmgr_main:pptp_callmgr.c:123]: Could not open control connection to 10.0.0.138
Jun 15 22:42:58 hostname pptp[8512]: anon fatal[open_callmgr:pptp.c:402]: Call manager exited with error 256
Jun 15 22:42:58 hostname pptp[8511]: anon fatal[main:pptp.c:286]: Child process died
<Here, pptp is apparently dead>


My provisoric solution
**********************

I have resorted to run "/etc/init.d/adsl start" through
a cron-script that checks if the pptp daemon has died.

This is for various reasons undesirable:
- it is an ad hoc solution that does not help others
- it produces unnecessary log entries
- it causes an unnecessary delay
- it cannot be nicely configured and parametrized
- it doesn't take into account whether adsl should
  run in the current run-level


This is a set-top machine (VIA processor) at my parents' place
and they have hardly a clue about computers, so it is imperative
that the ADSL daemons keep running under any circumstances.



Regards,

Claus

#374698#10
Date:
2006-06-20 18:27:32 UTC
From:
To:
This is an hard error. Looks like you will have to debug it, sorry.
#374698#15
Date:
2006-06-20 18:27:32 UTC
From:
To:
This is an hard error. Looks like you will have to debug it, sorry.
#374698#20
Date:
2007-02-05 09:23:23 UTC
From:
To:
I confirm the same bug.
I use an analog modem, and if I unplug the phone cable, pppd exits:

Feb  5 09:47:49 localhost pppd[9733]: Hangup (SIGHUP)
Feb  5 09:47:49 localhost pppd[9733]: Connect time 2.5 minutes.
Feb  5 09:47:49 localhost pppd[9733]: Sent 78902 bytes, received 261814 bytes.
Feb  5 09:47:49 localhost pppd[9733]: Script /etc/ppp/ip-down started (pid 10699)
Feb  5 09:47:49 localhost pppd[9733]: sent [LCP TermReq id=0x2 "User request"]
Feb  5 09:47:50 localhost pppd[9733]: Script /etc/ppp/ip-down finished (pid 10699), status = 0x1
Feb  5 09:47:52 localhost pppd[9733]: sent [LCP TermReq id=0x3 "User request"]
Feb  5 09:47:55 localhost pppd[9733]: Connection terminated.
Feb  5 09:47:55 localhost pppd[9733]: tcflush failed: Input/output error
Feb  5 09:47:55 localhost pppd[9733]: Modem hangup
Feb  5 09:48:25 localhost pppd[9733]: tcsetattr: Invalid argument (line971)
Feb  5 09:48:26 localhost pppd[9733]: tcsetattr: Invalid argument (line1010)
Feb  5 09:48:26 localhost pppd[9733]: Exit.

Here is the option file of teh connection:

sudo cat /etc/ppp/peers/libero

hide-password
noauth
connect "/usr/sbin/chat -v -f /etc/chatscripts/libero"
debug
/dev/ttyS0
115200
defaultroute
noipdefault
user "xxxxxxxxxxxx@libero.it"
remotename libero
replacedefaultroute
persist
maxfail 0

#374698#25
Date:
2007-07-07 00:09:39 UTC
From:
To:
I've had the 'persist' option fail for me similarly, but without the strange 'tcsetattr' bug. This is with PPPoE (for an ADSL connection), and has occurred in the past when the PPP connection has been terminated at the ISP end (during faults, or sometimes load balancing).

Jul  4 01:10:01 bluesky pppd[32014]: No response to 3 echo-requests
Jul  4 01:10:01 bluesky pppd[32014]: Serial link appears to be disconnected.
Jul  4 01:10:01 bluesky pppd[32014]: Connect time 4271.3 minutes.
Jul  4 01:10:01 bluesky pppd[32014]: Sent 366052693 bytes, received 1306815812 bytes.
Jul  4 01:10:01 bluesky pppd[32014]: Script /etc/ppp/ip-down started (pid 7523)
Jul  4 01:10:01 bluesky pppd[32014]: sent [LCP TermReq id=0x2 "Peer not responding"]
Jul  4 01:10:01 bluesky pppd[32014]: Script /etc/ppp/ip-down finished (pid 7523), status = 0x0
Jul  4 01:10:04 bluesky pppd[32014]: sent [LCP TermReq id=0x3 "Peer not responding"]
Jul  4 01:10:07 bluesky pppd[32014]: Connection terminated.
Jul  4 01:10:07 bluesky pppd[32014]: Modem hangup
Jul  4 01:10:32 bluesky pppd[32014]: Terminating on signal 15
Jul  4 01:10:32 bluesky pppd[32014]: Exit.

'debug' is set to on, as is 'persist' and 'maxfail 0'

After these log entries turn up, there is no pppd process to be found.

Richard

#374698#30
Date:
2008-03-26 03:58:50 UTC
From:
To:
2.6.23 ppp* modules and it made no difference.
#374698#35
Date:
2023-11-03 23:56:49 UTC
From:
To:
Are you still able to reproduce this issue?