NetBSD Problem Report #29942

From shamardin@theory.sinp.msu.ru  Mon Apr 11 09:26:32 2005
Return-Path: <shamardin@theory.sinp.msu.ru>
Received: from theory.sinp.msu.ru (theory.sinp.msu.ru [213.131.4.66])
	by narn.netbsd.org (Postfix) with ESMTP id 23EF563B116
	for <gnats-bugs@gnats.NetBSD.org>; Mon, 11 Apr 2005 09:26:31 +0000 (UTC)
Message-Id: <200504110909.j3B99KkA025641@theory.sinp.msu.ru>
Date: Mon, 11 Apr 2005 13:09:20 +0400
From: shamardin@theory.sinp.msu.ru
Reply-To: shamardin@theory.sinp.msu.ru
To: gnats-bugs@netbsd.org
Subject: pppoe fails to connect to a server running FreeBSD
X-Send-Pr-Version: 3.95

>Number:         29942
>Category:       kern
>Synopsis:       pppoe fails to connect to a server running FreeBSD
>Confidential:   no
>Severity:       critical
>Priority:       high
>Responsible:    martin
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Apr 11 09:27:00 +0000 2005
>Last-Modified:  Mon Apr 11 09:51:49 +0000 2005
>Originator:     shamardin@theory.sinp.msu.ru
>Release:        NetBSD 2.0.2_STABLE
>Organization:
>Environment:
System: NetBSD sentinel 2.0.2_STABLE NetBSD 2.0.2_STABLE (SENTINEL) #1: Sun Apr 10 22:17:10 MSD 2005 root@sentinel:/usr/src/sys/arch/i386/compile/SENTINEL i386
Architecture: i386
Machine: i386
>Description:

pppoe fails to connect to the server running FreeBSD with pppoed & pppd. The
logs from the client and the server sides are in the end of the description.
The server is running FreeBSD virgin.v.gz.ru 4.11-RELEASE FreeBSD 4.11-RELEASE
#14: Tue Jan 25 23:16:32 MSK 2005 with pppoed and pppd. There were no problems
with other pppoe clients (all windows, Linuxes, FreeBSD) so this seams to be
the NetBSD pppoe implementation bug.

Apr 11 13:04:02 sentinel /netbsd: pppoe0: lcp close(initial)
Apr 11 13:04:02 sentinel /netbsd: pppoe0: lcp open(initial)
Apr 11 13:04:02 sentinel /netbsd: pppoe0: phase establish
Apr 11 13:04:02 sentinel /netbsd: pppoe0: session 0x9074 connected
Apr 11 13:04:02 sentinel /netbsd: pppoe0: lcp up(starting)
Apr 11 13:04:02 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xb7 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(req-sent): <conf-req id=0x1 len=27 01-04-05-78-05-06-17-8f-21-97-04-08-c0-25-00-00-0b-b8-03-05-c2-23-05-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp parse opts: mru magic qual-proto [rej] auth-proto send conf-rej
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-rej id=0x1 len=12 04-08-c0-25-00-00-0b-b8>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(req-sent): <conf-nak id=0xb7 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xb8 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(req-sent): <conf-req id=0x2 len=19 01-04-05-78-05-06-17-8f-21-97-03-05-c2-23-05-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp parse opts: mru magic auth-proto
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp parse opt values:  mru 1400 magic 0x178f2197 auth-proto send conf-ack
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-ack id=0x2 len=19 01-04-05-78-05-06-17-8f-21-97-03-05-c2-23-05>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xb8 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xb9 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xb9 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xba len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xba len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xbb len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xbb len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xbc len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xbc len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xbd len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xbd len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xbe len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xbe len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xbf len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xbf len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc0 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc0 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc1 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc1 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc2 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc2 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc3 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc3 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc4 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc4 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc5 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <conf-nak id=0xc5 len=8 01-04-05-d4-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc6 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp input(ack-sent): <term-req id=0x3 len=4 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00>
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp send terminate-ack
Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp output <term-ack id=0x3 len=4>
Apr 11 13:04:03 sentinel /netbsd: pppoe*: GENERIC ERROR: session closed
Apr 11 13:04:04 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 10
Apr 11 13:04:04 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc7 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:05 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 9
Apr 11 13:04:05 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc8 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:06 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 8
Apr 11 13:04:06 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xc9 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:07 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 7
Apr 11 13:04:07 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xca len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:08 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 6
Apr 11 13:04:08 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xcb len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:09 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 5
Apr 11 13:04:09 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xcc len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:10 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 4
Apr 11 13:04:10 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xcd len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:11 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 3
Apr 11 13:04:11 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xce len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:12 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 2
Apr 11 13:04:12 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xcf len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:13 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 1
Apr 11 13:04:13 sentinel /netbsd: pppoe0: lcp output <conf-req id=0xd0 len=14 05-06-2b-03-88-26-01-04-05-dc>
Apr 11 13:04:14 sentinel /netbsd: pppoe0: lcp TO(req-sent) rst_counter = 0
Apr 11 13:04:14 sentinel /netbsd: pppoe0: phase dead
Apr 11 13:04:14 sentinel /netbsd: pppoe0: disconnecting
Apr 11 13:04:14 sentinel /netbsd: pppoe0: lcp down(stopped)

And for the server side:

Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: Phase: Using interface: tun97
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: Phase: deflink: Created in closed state
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set radius /etc/radius.conf
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set ifaddr 192.168.129.1 192.168.129.2-192.168.135.254
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: IPCP: Selected IP address 192.168.135.118
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set speed sync
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set timeout 3600
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set ctsrts off
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set accmap 000a0000
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: enable lqr
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set cd 5
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: accept dns
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set dns 192.168.129.1
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set mtu 1400
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: set mru 1400
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: disable deflate pred1 acfcomp protocomp pap vjcomp
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: deny deflate pred1 acfcomp pap protocomp vjcomp
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: enable chap
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Command: pppoe: accept chap
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: PPP Started (direct mode).
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: bundle: Establish
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: closed -> opening
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: Link is a netgraph node
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: Connected!
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: opening -> carrier
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: carrier -> lcp
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: Too many LCP NAKs sent - abandoning negotiation
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: Disconnected!
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: Connect time: 0 secs: 297 octets in, 206 octets out
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: 19 packets in, 18 packets out
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase:  total 503 bytes/sec, peak 0 bytes/sec on Mon Apr 11 13:04:03 2005
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: deflink: lcp -> closed
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: bundle: Dead
Apr 11 13:04:03 <daemon.info> virgin ppp[10733]: tun97: Phase: PPP Terminated (normal).

>How-To-Repeat:

Configuration for the client side:

/etc/ifconfig.pppoe0:

create
! /sbin/ifconfig ex0 up
! /sbin/pppoectl -e ex0 $int
! /sbin/pppoectl $int myauthproto=chap myauthname=leo myauthsecret=asecret
inet 0.0.0.0 0.0.0.1 netmask 0xffffffff
debug up

Configuration for the server side running FreeBSD:

pppoed is started with

/usr/libexec/pppoed -P /var/run/pppoed.pid -l -minunit 1 pppoe -p * fxp1

/etc/ppp/ppp.conf:

pppoe:
  set radius /etc/radius.conf
  set ifaddr 192.168.129.1 192.168.129.2-192.168.135.254
  set speed sync
  set timeout 3600
  set ctsrts off
  set accmap 000a0000
  enable lqr
  set cd 5
  accept dns
  set dns 192.168.129.1
  set mtu 1400
  set mru 1400
  disable deflate pred1 acfcomp protocomp pap vjcomp
  deny deflate pred1 acfcomp pap protocomp vjcomp
  enable chap
  accept chap

>Fix:
	unknown

>Release-Note:

>Audit-Trail:
From: Martin Husemann <martin@duskware.de>
To: gnats-bugs@netbsd.org
Cc: 
Subject: Re: kern/29942: pppoe fails to connect to a server running FreeBSD
Date: Mon, 11 Apr 2005 11:48:00 +0200

 On Mon, Apr 11, 2005 at 09:27:00AM +0000, shamardin@theory.sinp.msu.ru wrote:
 > Apr 11 13:04:03 sentinel /netbsd: pppoe0: lcp nak opts: mru 1492

 Try to configure the MTU of pppoe0 to 1400 beforehand and let us know
 if this fixes the problem, please.

 >   set mtu 1400
 >   set mru 1400

 Is there any good reason for this atypical values?

 Martin

Responsible-Changed-From-To: kern-bug-people->martin
Responsible-Changed-By: martin@netbsd.org
Responsible-Changed-When: Mon, 11 Apr 2005 09:51:49 +0000
Responsible-Changed-Why:
I'll handle it.


>Unformatted:

Home	PR Database Search