After some experimenting, I've discovered that userland ppp stopped
working normally at some point between the March 24th and April 8th
snapshots.
I've been using the same ppp.{conf,linkup,linkdown} files for 6 months
now with 4.8-stable without any problems. This weekend I decided to
change firewall hardware and use -current, and the same configuration fails.
It's not the hardware: 4.8-stable and snapshots up to Mar. 24th work
just fine. The next snap I have in my collection is Apr. 8th, and
everything since then including Apr. 17th, fails.
Replication is simple:
- clean install, not an upgrade. No customizing/tweaking anything.
- copy my known-good ppp.* files over
- "up" the interface my DSL modem is on
- adjust syslog.conf to allow ppp logging to /var/log/ppp.log
# ppp -ddial mlppp (config file below; normally this done from rc.local)
- with anything <= Mar 24th, the connection works straight away
- with anything >= Apr. 8th, the ppp process loops continuously trying
to establish the connection
Looking at the log, the old version shows "LCP: 2: RecvConfigReq", after
which my MRU drops from 1500 to 1492, and the connection ultimately
succeeds. The new version only shows "LCP: 2: SendConfigReq" and the
redial process loops until manually stopped.
Does anyone have any idea if my config needs adjusting, or have I found
a bug? The only variable is the version of -current I use, and the
ppp(8) man page is the same. Nothing to indicate that my config needs
adjusting.
I'm not sure if the following log snippets show the proper information,
so I'll wait for requests for full logs instead of spamming the list
with a hugely long post.
Thanks,
- Scott
Log snippet from successful connection:
Apr 17 21:09:22 fw0 ppp[30518]: tun0: Chat: 2: Reconnect try 2 of 3
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Chat: 2: Redial timer expired.
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Warning: Carrier settings ignored
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Phase: 2: Connected!
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Phase: 2: opening -> dial
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Phase: 2: dial -> carrier
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Phase: 2: carrier -> login
Apr 17 21:09:25 fw0 ppp[30518]: tun0: Phase: 2: login -> lcp
Apr 17 21:09:25 fw0 ppp[30518]: tun0: LCP: FSM: Using "2" as a transport
Apr 17 21:09:25 fw0 ppp[30518]: tun0: LCP: 2: State change Initial -->
Closed
Apr 17 21:09:25 fw0 ppp[30518]: tun0: LCP: 2: State change Closed -->
Stopped
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: LayerStart
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: SendConfigReq(6) state =
Stopped
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MRU[4] 1500
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MAGICNUM[6] 0x48a3693d
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MRRU[4] 1485
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: State change Stopped -->
Req-Sent
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: RecvConfigReq(138) state =
Req-Sent
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MRU[4] 1492
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MAGICNUM[6] 0x4a64ebd8
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: SendConfigAck(138) state =
Req-Sent
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MRU[4] 1492
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MAGICNUM[6] 0x4a64ebd8
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: State change Req-Sent -->
Ack-Sent
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: RecvConfigRej(6) state =
Ack-Sent
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: MRRU[4] 1485
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:09:26 fw0 ppp[30518]: tun0: LCP: 2: SendConfigReq(7) state =
Ack-Sent
Log snippet from unsuccessful connection:
Apr 17 21:07:29 hellgate ppp[30239]: tun0: Chat: 2: Reconnect try 2 of 3
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Chat: 1: Redial timer expired.
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Chat: 2: Redial timer expired.
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Warning: Carrier settings ignored
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 1: Connected!
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 1: opening -> dial
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 1: dial -> carrier
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 1: carrier -> login
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 1: login -> lcp
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: FSM: Using "1" as a
transport
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: 1: State change Initial
--> Closed
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: 1: State change Closed
--> Stopped
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Warning: Carrier settings ignored
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 2: Connected!
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 2: opening -> dial
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 2: dial -> carrier
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 2: carrier -> login
Apr 17 21:07:32 hellgate ppp[30239]: tun0: Phase: 2: login -> lcp
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: FSM: Using "2" as a
transport
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: 2: State change Initial
--> Closed
Apr 17 21:07:32 hellgate ppp[30239]: tun0: LCP: 2: State change Closed
--> Stopped
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 1: LayerStart
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 1: SendConfigReq(1)
state = Stopped
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MRU[4] 1500
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MAGICNUM[6] 0x19df081a
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MRRU[4] 1485
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 1: State change Stopped
--> Req-Sent
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 2: LayerStart
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 2: SendConfigReq(1)
state = Stopped
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MRU[4] 1500
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MAGICNUM[6] 0x58de90cd
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: MRRU[4] 1485
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:07:33 hellgate ppp[30239]: tun0: LCP: 2: State change Stopped
--> Req-Sent
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: 1: SendConfigReq(1)
state = Req-Sent
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MRU[4] 1500
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MAGICNUM[6] 0x19df081a
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MRRU[4] 1485
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: 2: SendConfigReq(1)
state = Req-Sent
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MRU[4] 1500
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MAGICNUM[6] 0x58de90cd
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: MRRU[4] 1485
Apr 17 21:07:36 hellgate ppp[30239]: tun0: LCP: SHORTSEQ[2]
Apr 17 21:07:37 hellgate ppp[30239]: tun0: Phase: 1: read (0):
Connection reset by peer
Apr 17 21:07:37 hellgate ppp[30239]: tun0: LCP: 1: State change Req-Sent
--> Starting
Apr 17 21:07:37 hellgate ppp[30239]: tun0: LCP: 1: LayerFinish
Apr 17 21:07:37 hellgate ppp[30239]: tun0: LCP: 1: State change Starting
--> Initial
Apr 17 21:07:37 hellgate ppp[30239]: tun0: Phase: 1: Disconnected!
Apr 17 21:07:37 hellgate ppp[30239]: tun0: Phase: 1: lcp -> logout
The ppp.conf file:
default:
set log Phase Chat LCP IPCP CCP tun command
set reconnect 3 3
enable mssfixup
disable ipv6cp
mlppp:
set log Phase Chat LCP IPCP CCP tun command
set mtu 1486
set mrru 1485
set speed sync
set cd 5
set dial
set hangup
set login
set timeout 0
set authname xxxxx
set authkey xxxxx
set server /var/run/ppp=tun%d 0177
set mode ddial
clone 1,2
link deflink remove
link 1,2 set mode ddial
link 1 set device "!/usr/sbin/pppoe -i xl0"
link 2 set device "!/usr/sbin/pppoe -i xl0"
add! default HISADDR
