Date: Sun, 4 Jan 1998 08:21:22 -0800 (PST) From: Thomas Unger <unger@raindrop.seaslug.org> To: FreeBSD-gnats-submit@FreeBSD.ORG Subject: bin/5424: ppp crashes on signal 10 or 11 Message-ID: <199801041621.IAA18683@raindrop.seaslug.org> Resent-Message-ID: <199801041630.IAA06025@hub.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 5424
>Category: bin
>Synopsis: ppp crashes on signal 10 or 11
>Confidential: no
>Severity: serious
>Priority: medium
>Responsible: freebsd-bugs
>State: open
>Class: sw-bug
>Submitter-Id: current-users
>Arrival-Date: Sun Jan 4 08:30:01 PST 1998
>Last-Modified:
>Originator: Thomas Unger
>Organization:
WWC
>Release: FreeBSD 2.2.5-RELEASE i386
>Environment:
I'm running ppp-971230. Previous version showed the same problem
971230unger% uname -a
FreeBSD raindrop.seaslug.org 2.2.5-RELEASE FreeBSD 2.2.5-RELEASE #0: Sun Dec 7 21:11:03 PST 1997 rootz@myname.my.domain:/usr/src/sys/compile/RAINDROP i386
I run ppp over a 28.8 modem and over isdn. ppp always runs reliably
on the modem but will crash occasionally over the isdn line. On that I have
a Motorola bitsurfer pro EZ connected to a ByteRunner serial card running at about 250 Kb.
>Description:
ppp will crash (exit on signal 10 or 11) shortly after connecting and
passing a few packets. Generally, onec the connectio has been up for
more than a minute it will stay up.
This morning I downloaded the lateset verison of ppp hoping that this
probem may have been fixed. It has not. I include two excerpts from
the ppp log.
The first one is from the new version of ppp and shows everything
from invocation to crash:
Jan 4 08:03:11 raindrop ppp[18507]: Command: default: set dial ABORT NO\sCARRIER ABORT BUSY ABORT NO\sDIALTONE TIMEOUT 5 "" ATZ OK-AT-OK \dATDT\T TIMEOUT 40 CONNECT
Jan 4 08:03:11 raindrop ppp[18507]: Phase: Using interface: tun0
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set device /dev/cuaa2
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set speed 115200
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set phone 812-2075&812-2075
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set dial ABORT NO\sCARRIER ABORT BUSY ABORT NO\sDIALTONE TIMEOUT 5 "" AT&F&c1&d2@B0=2 OK-AT-OK \dATD\T TIMEOUT 40 CONNECT
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: accept pap
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set authname tunger
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set authkey ********
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set timeout 300
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set openmode active
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: set ifaddr 0 206.63.32.245/0
Jan 4 08:03:11 raindrop ppp[18507]: Command: nwn-isdn-auto: add 0 0 206.63.32.245
Jan 4 08:03:11 raindrop ppp[18508]: Phase: PPP Started.
Jan 4 08:03:14 raindrop ppp[18508]: Phase: Connected!
Jan 4 08:03:14 raindrop ppp[18508]: Chat: Dial attempt 1 of 1
Jan 4 08:03:14 raindrop ppp[18508]: Chat: Expecting:
Jan 4 08:03:14 raindrop ppp[18508]: Chat: Sending: AT&F&c1&d2@B0=2^M
Jan 4 08:03:14 raindrop ppp[18508]: Chat: Expecting: OK-AT-OK
Jan 4 08:03:14 raindrop ppp[18508]: Chat: Wait for (5): OK
Jan 4 08:03:17 raindrop ppp[18508]: Phase: Phone: 812-2075&812-2075
Jan 4 08:03:17 raindrop ppp[18508]: Chat: Sending: ATD812-2075&812-2075^M
Jan 4 08:03:17 raindrop ppp[18508]: Chat: Expecting: CONNECT
Jan 4 08:03:17 raindrop ppp[18508]: Chat: Wait for (40): CONNECT
Jan 4 08:03:19 raindrop ppp[18508]: LCP: State change Initial --> Closed
Jan 4 08:03:19 raindrop ppp[18508]: LCP: LcpSendConfigReq
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACFCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: PROTOCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACCMAP[6] 0x00000000
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MRU[4] 1500
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MAGICNUM[6] 0x45207e92
Jan 4 08:03:19 raindrop ppp[18508]: LCP: State change Closed --> Req-Sent
Jan 4 08:03:19 raindrop ppp[18508]: LCP: Received Configure Request (215) state = Req-Sent (6)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MRU[4] 1600
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACCMAP[6] 0x00000000
Jan 4 08:03:19 raindrop ppp[18508]: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: PROTOCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACFCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: SendConfigAck(Req-Sent)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MRU[4] 1600
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACCMAP[6] 0x00000000
Jan 4 08:03:19 raindrop ppp[18508]: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: PROTOCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACFCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: State change Req-Sent --> Ack-Sent
Jan 4 08:03:19 raindrop ppp[18508]: LCP: Received Configure Reject (1) state = Ack-Sent (8)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: RecvConfigRej.
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MAGICNUM[6] 0x45207e92
Jan 4 08:03:19 raindrop ppp[18508]: LCP: Magic 0x 45207e92 is REJected!
Jan 4 08:03:19 raindrop ppp[18508]: LCP: LcpSendConfigReq
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACFCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: PROTOCOMP[2]
Jan 4 08:03:19 raindrop ppp[18508]: LCP: ACCMAP[6] 0x00000000
Jan 4 08:03:19 raindrop ppp[18508]: LCP: MRU[4] 1500
Jan 4 08:03:19 raindrop ppp[18508]: LCP: Received Configure Ack (2) state = Ack-Sent (8)
Jan 4 08:03:19 raindrop ppp[18508]: LCP: State change Ack-Sent --> Opened
Jan 4 08:03:19 raindrop ppp[18508]: LCP: LcpLayerUp
Jan 4 08:03:19 raindrop ppp[18508]: Phase: NewPhase: Authenticate
Jan 4 08:03:19 raindrop ppp[18508]: Phase: his = PAP, mine = none
Jan 4 08:03:19 raindrop ppp[18508]: Phase: PAP: tunger
Jan 4 08:03:19 raindrop ppp[18508]: Phase: PapInput: ACK
Jan 4 08:03:19 raindrop ppp[18508]: Phase: Received PAP_ACK ()
Jan 4 08:03:19 raindrop ppp[18508]: Phase: NewPhase: Network
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: State change Initial --> Closed
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: IPCP Up event!!
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: IpcpSendConfigReq
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: IPADDR[6] 0.0.0.0
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: COMPPROTO[6] 16 VJ slots with slot compres
Jan 4 08:03:19 raindrop ppp[18508]: IPCP: State change Closed --> Req-Sent
Jan 4 08:03:19 raindrop ppp[18508]: CCP: State change Initial --> Closed
Jan 4 08:03:19 raindrop ppp[18508]: CCP: CCP Up event!!
Jan 4 08:03:19 raindrop ppp[18508]: CCP: CcpSendConfigReq
Jan 4 08:03:19 raindrop ppp[18508]: CCP: DEFLATE[4] win 15
Jan 4 08:03:19 raindrop ppp[18508]: CCP: PRED1[2]
Jan 4 08:03:19 raindrop ppp[18508]: CCP: State change Closed --> Req-Sent
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: Received Configure Request (1) state = Req-Sent (6)
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: COMPPROTO[6] 16 VJ slots without slot compression
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: IPADDR[6] 206.63.40.50
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: SendConfigAck(Req-Sent)
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: COMPPROTO[6] 16 VJ slots without slot compression
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: IPADDR[6] 206.63.40.50
Jan 4 08:03:20 raindrop ppp[18508]: IPCP: State change Req-Sent --> Ack-Sent
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IpcpSendConfigReq
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IPADDR[6] 0.0.0.0
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: COMPPROTO[6] 16 VJ slots with slot compres
Jan 4 08:03:22 raindrop ppp[18508]: CCP: CcpSendConfigReq
Jan 4 08:03:22 raindrop ppp[18508]: CCP: DEFLATE[4] win 15
Jan 4 08:03:22 raindrop ppp[18508]: CCP: PRED1[2]
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: Received Configure Nak (2) state = Ack-Sent (8)
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IPADDR[6] 206.63.40.85
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IPADDR[6] changing address: 0.0.0.0 --> 206.63.40.85
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IpcpSendConfigReq
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IPADDR[6] 206.63.40.85
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: COMPPROTO[6] 16 VJ slots with slot compres
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: Received Configure Ack (3) state = Ack-Sent (8)
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: State change Ack-Sent --> Opened
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: IpcpLayerUp(9).
Jan 4 08:03:22 raindrop ppp[18508]: IPCP: myaddr = 206.63.40.85 hisaddr = 206.63.40.50
Jan 4 08:03:22 raindrop ppp[18508]: Link: OsLinkup: 206.63.40.50
Jan 4 08:03:22 raindrop ppp[18508]: Command: MYADDR: delete ALL
Jan 4 08:03:22 raindrop ppp[18508]: Command: MYADDR: add 0 0 HISADDR
Jan 4 08:03:22 raindrop ppp[18508]: Command: MYADDR: ! sh -c /etc/ppp/onconnect >>/dev/null 2>&1 &
Jan 4 08:03:23 raindrop named[81]: "halcyon.COM IN NS" points to a CNAME (tau-ceti.isc-br.com)
Jan 4 08:03:25 raindrop ppp[18508]: CCP: CcpSendConfigReq
Jan 4 08:03:25 raindrop ppp[18508]: CCP: DEFLATE[4] win 15
Jan 4 08:03:25 raindrop ppp[18508]: CCP: PRED1[2]
Jan 4 08:03:27 raindrop ntpdate[18512]: adjust time server 128.115.14.97 offset -0.247738
Jan 4 08:03:28 raindrop ppp[18508]: CCP: CcpSendConfigReq
Jan 4 08:03:28 raindrop ppp[18508]: CCP: DEFLATE[4] win 15
Jan 4 08:03:28 raindrop ppp[18508]: CCP: PRED1[2]
Jan 4 08:03:31 raindrop ppp[18508]: CCP: CcpSendConfigReq
Jan 4 08:03:31 raindrop ppp[18508]: CCP: DEFLATE[4] win 15
Jan 4 08:03:31 raindrop ppp[18508]: CCP: PRED1[2]
Jan 4 08:03:34 raindrop ppp[18508]: CCP: State change Req-Sent --> Stopped
Jan 4 08:03:34 raindrop ppp[18508]: CCP: CcpLayerFinish.
Jan 4 08:04:09 raindrop /kernel: pid 18508 (ppp), uid 0: exited on signal 10
There is another failure mode which is represented in the following log file.
This PPP process had been running for about 12 hours before it crashed. This
log is from the 2.2.5-RELEASE version of ppp.
Jan 4 07:29:53 raindrop ppp[16812]: Chat: Dial attempt 1 of 1
Jan 4 07:29:53 raindrop ppp[16812]: Chat: Expecting
Jan 4 07:29:53 raindrop ppp[16812]: Chat: sending: AT&F&c1&d2@B0=2^M
Jan 4 07:29:53 raindrop ppp[16812]: Chat: Expecting OK-AT-OK
Jan 4 07:29:53 raindrop ppp[16812]: Chat: Wait for (5): OK --> OK
Jan 4 07:29:54 raindrop ppp[16812]: Phase: Phone: 812-2075&812-2075
Jan 4 07:29:54 raindrop ppp[16812]: Chat: sending: ATD812-2075&812-2075^M
Jan 4 07:29:54 raindrop ppp[16812]: Chat: Expecting CONNECT
Jan 4 07:29:54 raindrop ppp[16812]: Chat: Wait for (40): CONNECT --> CONNECT
Jan 4 07:29:56 raindrop ppp[16812]: Phase: *Connected!
Jan 4 07:29:56 raindrop ppp[16812]: LCP: State change Initial --> Closed
Jan 4 07:29:56 raindrop ppp[16812]: LCP: LcpSendConfigReq
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACFCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: PROTOCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACCMAP [6] 00000000
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MRU [4] 1500
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MAGICNUM [6] e5dc1ed8
Jan 4 07:29:56 raindrop ppp[16812]: LCP: State change Closed --> Req-Sent
Jan 4 07:29:56 raindrop ppp[16812]: LCP: Received Configure Request (212) state = Req-Sent (6)
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MRU 1600
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACCMAP 00000000
Jan 4 07:29:56 raindrop ppp[16812]: LCP: AUTHPROTO proto = c023
Jan 4 07:29:56 raindrop ppp[16812]: LCP: PROTOCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACFCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: SendConfigAck(Req-Sent)
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MRU 1600
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACCMAP 00000000
Jan 4 07:29:56 raindrop ppp[16812]: LCP: AUTHPROTO proto = c023
Jan 4 07:29:56 raindrop ppp[16812]: LCP: PROTOCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACFCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: State change Req-Sent --> Ack-Sent
Jan 4 07:29:56 raindrop ppp[16812]: LCP: Received Configure Reject (1) state = Ack-Sent (8)
Jan 4 07:29:56 raindrop ppp[16812]: LCP: RecvConfigRej.
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MAGICNUM e5dc1ed8
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MAGICNUM magic has REJected
Jan 4 07:29:56 raindrop ppp[16812]: LCP: LcpSendConfigReq
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACFCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: PROTOCOMP
Jan 4 07:29:56 raindrop ppp[16812]: LCP: ACCMAP [6] 00000000
Jan 4 07:29:56 raindrop ppp[16812]: LCP: MRU [4] 1500
Jan 4 07:29:56 raindrop ppp[16812]: LCP: Received Configure Ack (2) state = Ack-Sent (8)
Jan 4 07:29:56 raindrop ppp[16812]: LCP: State change Ack-Sent --> Opened
Jan 4 07:29:56 raindrop ppp[16812]: LCP: LcpLayerUp
Jan 4 07:29:56 raindrop ppp[16812]: Phase: NewPhase: Authenticate
Jan 4 07:29:56 raindrop ppp[16812]: Phase: his = c023, mine = 0
Jan 4 07:29:56 raindrop ppp[16812]: Phase: PAP: tunger
Jan 4 07:29:56 raindrop ppp[16812]: Phase: PapInput: ACK
Jan 4 07:29:56 raindrop ppp[16812]: Phase: Received PAP_ACK ()
Jan 4 07:29:56 raindrop ppp[16812]: Phase: NewPhase: Network
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: State change Initial --> Closed
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: IPCP Up event!!
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: IpcpSendConfigReq
Jan 4 07:29:56 raindrop ppp[16812]: LCP: IPADDR [6] 0.0.0.0
Jan 4 07:29:56 raindrop ppp[16812]: LCP: COMPPROTO [6] 002d0f00
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: State change Closed --> Req-Sent
Jan 4 07:29:56 raindrop ppp[16812]: CCP: State change Initial --> Closed
Jan 4 07:29:56 raindrop ppp[16812]: CCP: CCP Up event!!
Jan 4 07:29:56 raindrop ppp[16812]: CCP: CcpSendConfigReq
Jan 4 07:29:56 raindrop ppp[16812]: CCP: State change Closed --> Req-Sent
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: Received Configure Request (1) state = Req-Sent (6)
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: COMPPROTO[6] 002d0f00
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: IPADDR[6] 206.63.40.50
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: SendConfigAck(Req-Sent)
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: COMPPROTO[6] 002d0f00
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: IPADDR[6] 206.63.40.50
Jan 4 07:29:56 raindrop ppp[16812]: IPCP: State change Req-Sent --> Ack-Sent
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: IpcpSendConfigReq
Jan 4 07:29:59 raindrop ppp[16812]: LCP: IPADDR [6] 0.0.0.0
Jan 4 07:29:59 raindrop ppp[16812]: LCP: COMPPROTO [6] 002d0f00
Jan 4 07:29:59 raindrop ppp[16812]: CCP: CcpSendConfigReq
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: Received Configure Nak (2) state = Ack-Sent (8)
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: IPADDR[6] 206.63.40.81
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: IPADDR[6] changing address: 0.0.0.0 --> 206.63.40.81
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: IpcpSendConfigReq
Jan 4 07:29:59 raindrop ppp[16812]: LCP: IPADDR [6] 206.63.40.81
Jan 4 07:29:59 raindrop ppp[16812]: LCP: COMPPROTO [6] 002d0f00
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: Received Configure Ack (3) state = Ack-Sent (8)
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: State change Ack-Sent --> Opened
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: IpcpLayerUp(9).
Jan 4 07:29:59 raindrop ppp[16812]: IPCP: myaddr = 206.63.40.81 hisaddr = 206.63.40.50
Jan 4 07:29:59 raindrop ppp[16812]: Link: OsLinkup: 206.63.40.50
Jan 4 07:29:59 raindrop ppp[16812]: Command: MYADDR: delete ALL
Jan 4 07:29:59 raindrop ppp[16812]: Command: MYADDR: add 0 0 HISADDR
Jan 4 07:29:59 raindrop ppp[16812]: Command: MYADDR: ! sh -c "/etc/ppp/onconnect >>/dev/null 2>&1 &"
Jan 4 07:30:00 raindrop named[81]: "halcyon.COM IN NS" points to a CNAME (tau-ceti.isc-br.com)
Jan 4 07:30:02 raindrop ppp[16812]: CCP: CcpSendConfigReq
Jan 4 07:29:58 raindrop ntpdate[17935]: step time server 128.115.14.97 offset -5.517128
Jan 4 07:29:59 raindrop ppp[16812]: CCP: CcpSendConfigReq
Jan 4 07:30:02 raindrop ppp[16812]: CCP: CcpSendConfigReq
Jan 4 07:30:05 raindrop ppp[16812]: CCP: State change Req-Sent --> Stopped
Jan 4 07:30:05 raindrop ppp[16812]: CCP: CcpLayerFinish.
Jan 4 07:30:26 raindrop ppp[16812]: Error: IpInput: Problem with IP header length
Jan 4 07:30:28 raindrop /kernel: pid 16812 (ppp), uid 0: exited on signal 11
>How-To-Repeat:
>Fix:
>Audit-Trail:
>Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?199801041621.IAA18683>