pppd failures

To: <netbsd-users%netbsd.org@localhost>
Subject: pppd failures
From: "CK" <un_x%earthlink.net@localhost>
Date: Tue, 11 Oct 2016 23:37:08 -0800
This regards a NetBSD pppd problem in connecting to a
national ISP in the USA via dial-up.  First, the log
showing FreeBSD successfully establishing a PPP
connection with its user-ppp.  Then 3 types of NetBSD
pppd attempts, which all fail (and many more types of
options were attempted - but the 3 listed serve to
demonstrate the same problem which is in need of some
kind of resolution).  Potential trivial mistakes such
as bad user/password information in PAP configurations
were double-checked 10x over, as well as swapping the
login name with the local host name, and many other
possible option adjustments to establish a PPP connection.

FBSD=11.0-RC3 NBSD=7.0.1

Basically, it appears that when a login-only attempt
is done with pppd, there is a failure+disconnect due
to not agreeing with PAP authentication, yet when PAP
authentication is done, both with and without a login
and password prompt, the ISP disconnects with a
REQUEST DENIED.  However, the FreeBSD user-ppp never
gets any request to do PAP authentication, and isn't
disconnected even after receiving Terminate Requests.
=========================================================
FreeBSD user-ppp log (logs in and functions without PAP).
=========================================================
Command: isp: enable lqr echo
Command: isp: disable ipv6cp
Command: isp: disable mppe
Phase: PPP Started (ddial mode).
Phase: bundle: Establish
Phase: deflink: closed -> opening
Phase: deflink: Connected!
Phase: deflink: opening -> dial
Phase: deflink: login -> lcp
LCP: FSM: Using "deflink" as a transport
LCP: deflink: State change Initial --> Closed
LCP: deflink: State change Closed --> Stopped
LCP: deflink: LayerStart
LCP: deflink: SendConfigReq(1) state = Stopped
LCP:  ACFCOMP[2]
LCP:  PROTOCOMP[2]
LCP:  ACCMAP[6] 0x00000000
LCP:  MRU[4] 1500
LCP:  MAGICNUM[6] 0xcf3614cc
LCP:  QUALPROTO[8] proto c025, interval 30000ms
LCP: deflink: State change Stopped --> Req-Sent
LCP: deflink: RecvConfigReq(1) state = Req-Sent
LCP:  MRU[4] 1524
LCP:  ACCMAP[6] 0x000a0000
LCP:  PROTOCOMP[2]
LCP:  ACFCOMP[2]
LCP: deflink: SendConfigAck(1) state = Req-Sent
LCP:  MRU[4] 1524
LCP:  ACCMAP[6] 0x000a0000
LCP:  PROTOCOMP[2]
LCP:  ACFCOMP[2]
LCP: deflink: State change Req-Sent --> Ack-Sent
LCP: deflink: SendConfigReq(1) state = Ack-Sent
LCP:  ACFCOMP[2]
LCP:  PROTOCOMP[2]
LCP:  ACCMAP[6] 0x00000000
LCP:  MRU[4] 1500
LCP:  MAGICNUM[6] 0xcf3614cc
LCP:  QUALPROTO[8] proto c025, interval 30000ms
LCP: deflink: RecvConfigRej(1) state = Ack-Sent
LCP:  QUALPROTO[8] proto c025, interval 30000ms
LCP: deflink: SendConfigReq(2) state = Ack-Sent
LCP:  ACFCOMP[2]
LCP:  PROTOCOMP[2]
LCP:  ACCMAP[6] 0x00000000
LCP:  MRU[4] 1500
LCP:  MAGICNUM[6] 0xcf3614cc
LCP: deflink: RecvConfigAck(2) state = Ack-Sent
LCP:  ACFCOMP[2]
LCP:  PROTOCOMP[2]
LCP:  ACCMAP[6] 0x00000000
LCP:  MRU[4] 1500
LCP:  MAGICNUM[6] 0xcf3614cc
LCP: deflink: State change Ack-Sent --> Opened
LCP: deflink: LayerUp
LCP: deflink: SendEchoRequest(0) state = Opened
CCP: FSM: Using "deflink" as a transport
CCP: deflink: State change Initial --> Closed
CCP: deflink: LayerStart.
CCP: deflink: SendConfigReq(1) state = Closed
CCP:  DEFLATE[4] win 15
CCP:  PRED1[2]
CCP: deflink: State change Closed --> Req-Sent
Phase: deflink: lcp -> open
Phase: bundle: Network
IPCP: FSM: Using "deflink" as a transport
IPCP: deflink: State change Initial --> Closed
IPCP: deflink: LayerStart.
IPCP: deflink: SendConfigReq(1) state = Closed
IPCP:  IPADDR[6] 72.251.118.0
IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
IPCP: deflink: State change Closed --> Req-Sent
IPCP: deflink: RecvConfigReq(1) state = Req-Sent
IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
IPCP:  IPADDR[6] 4.34.24.78
IPCP: deflink: SendConfigAck(1) state = Req-Sent
IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
IPCP:  IPADDR[6] 4.34.24.78
IPCP: deflink: State change Req-Sent --> Ack-Sent
CCP: deflink: RecvConfigReq(1) state = Req-Sent
CCP:  MPPE[6] value 0x00000001 (0 bits, stateful, compressed)
CCP: MPPE: Not usable without CHAP81
CCP: deflink: SendConfigRej(1) state = Req-Sent
CCP:  MPPE[6] value 0x00000001 (0 bits, stateful, compressed)
LCP: deflink: RecvEchoReply(0) state = Opened
CCP: deflink: RecvConfigRej(1) state = Req-Sent
CCP:  DEFLATE[4] win 15
CCP:  PRED1[2]
CCP: deflink: SendConfigReq(2) state = Req-Sent
CCP:   [EMPTY]
IPCP: deflink: RecvConfigNak(1) state = Ack-Sent
IPCP:  IPADDR[6] 72.251.111.152
IPCP:  IPADDR[6] changing address: xxx.xxx.xxx.xxx --> yyy.yyy.yyy.yyy
IPCP: deflink: SendConfigReq(2) state = Ack-Sent
IPCP:  IPADDR[6] 72.251.111.152
IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
CCP: deflink: RecvConfigReq(2) state = Req-Sent
CCP:  STAC[5]
CCP: deflink: SendConfigRej(2) state = Req-Sent
CCP:  STAC[5]
CCP: deflink: RecvConfigRej(2) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(3) state = Req-Sent
CCP:   [EMPTY]
IPCP: deflink: RecvConfigAck(2) state = Ack-Sent
IPCP:  IPADDR[6] 72.251.111.152
IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
IPCP: deflink: State change Ack-Sent --> Opened
IPCP: deflink: LayerUp.
IPCP: myaddr 72.251.111.152 hisaddr = 4.34.24.78
Command: isp: add default HISADDR
Warning: ff02::: Change route failed: errno: Value too large to be stored in data type
CCP: deflink: RecvConfigReq(3) state = Req-Sent
CCP:  STAC[5]
CCP: deflink: SendConfigRej(3) state = Req-Sent
CCP:  STAC[5]
CCP: deflink: RecvConfigRej(3) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(4) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: RecvConfigReq(4) state = Req-Sent
CCP:  STAC[6]
CCP: deflink: SendConfigRej(4) state = Req-Sent
CCP:  STAC[6]
CCP: deflink: RecvConfigRej(4) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(5) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: RecvConfigRej(5) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(6) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: RecvTerminateReq(5) state = Req-Sent
CCP: deflink: SendTerminateAck(5) state = Req-Sent
CCP: deflink: RecvTerminateReq(6) state = Req-Sent
CCP: deflink: SendTerminateAck(6) state = Req-Sent
CCP: deflink: SendConfigReq(6) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(6) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(6) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: SendConfigReq(6) state = Req-Sent
CCP:   [EMPTY]
CCP: deflink: LayerFinish.
CCP: deflink: State change Req-Sent --> Stopped
LCP: deflink: SendEchoRequest(1) state = Opened
LCP: deflink: RecvEchoReply(1) state = Opened
=======================================
NetBSD pppd logs ... pppd always fails.
=======================================
lock debug kdebug 4
tty00 57600 crtscts
connect '/usr/sbin/chat -vf /etc/ppp/chat'
defaultroute
=======================================
'chat' LOGIN + NO pppd-option: user/PAP
=======================================
Script /usr/sbin/chat -vf /etc/ppp/chat finished (pid 2271), status = 0x0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x419fcd5a> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x419fcd5a> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x1 < 00 04 00 00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <mrru 1524> <endpoint [MAC:00:d0:52:04:23:6d]>]
No auth is possible
sent [LCP ConfRej id=0x1 < 00 04 00 00> <auth pap> <mrru 1524>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x419fcd5a> <pcomp> <accomp>]
rcvd [LCP TermReq id=0x2]
sent [LCP TermAck id=0x2]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x419fcd5a> <pcomp> <accomp>]
DISCONNECTED
====================================
'chat' LOGIN + pppd-option: user/PAP
====================================
Script /usr/sbin/chat -vf /etc/ppp/chat finished (pid 1485), status = 0x0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xc2e3b4da> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xc2e3b4da> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x1 < 00 04 00 00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <mrru 1524> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [LCP ConfRej id=0x1 < 00 04 00 00> <mrru 1524>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xc2e3b4da> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x2 <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [LCP ConfAck id=0x2 <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [PAP AuthReq id=0x1 user="myloginname" password=<hidden>]
rcvd [PAP AuthNak id=0x1 "Request Denied"]
sent [LCP TermReq id=0x2 "Failed to authenticate ourselves to peer"]
rcvd [LCP TermAck id=0x2]
DISCONNECTED
=======================================
NO 'chat' LOGIN + pppd-option: user/PAP
=======================================
Script /usr/sbin/chat -vf /etc/ppp/chat finished (pid 1897), status = 0x0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x6fd1ce2e> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x1 < 00 04 00 00> <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <mrru 1524> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [LCP ConfRej id=0x1 < 00 04 00 00> <mrru 1524>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x6fd1ce2e> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x2 <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [LCP ConfAck id=0x2 <mru 1524> <asyncmap 0xa0000> <auth pap> <pcomp> <accomp> <endpoint [MAC:00:d0:52:04:23:6d]>]
sent [PAP AuthReq id=0x1 user="myloginname" password=<hidden>]
rcvd [PAP AuthNak id=0x1 "Request Denied"]
sent [LCP TermReq id=0x2 "Failed to authenticate ourselves to peer"]
rcvd [LCP TermAck id=0x2]
DISCONNECTED
Follow-Ups:
- Re: pppd failures
  - From: Michael van Elst
Prev by Date: Re: GPT missing after controller swap (wd to ld)
Next by Date: Re: pppd failures
Previous by Thread: GPT missing after controller swap (wd to ld)
Next by Thread: Re: pppd failures
Indexes:
Home | Main Index | Thread Index | Old Index