Userland ppp stopped working between Mar24 and Apr8
I originally sent this message to misc@ on April 17/2011, but I never
got a response and I can't find it in the archives. (I found this copy
in my sent mail).
I guess it never went through. Since I never heard anything back, I
figured I'd wait a while and see if the problem got corrected after the
kernel hackathon finished. (It didn't.)
I gave the most recent snapshot (June 29) a try, and the problem
remains, so I'll try sending this again. I haven't seen anything
about this on the list since; surely I can't be the only person who has
run into this.
My original message:
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
Re: Userland ppp stopped working between Mar24 and Apr8
I don't see anything really wrong with your configuration. When I used
userland PPP, I had the mtu and mru set to 1492 but you took a known working
configuration from a previous setup. Is there a good reason why you couldn't
use kernel PPP? It is really easy:
cat /etc/hostname.pppoe0:
inet 0.0.0.0
255.255.255.255 NONE pppoedev interface authproto pap authname
isp_username authkey isp_password
dest 0.0.0.1
!/sbin/route add default
-ifp pppoe0 0.0.0.1
cat /etc/hostname.interface:
up
add a rule to your
pf.conf:
match on pppoe0 scrub (max-mss 1440)
I have found performance to be
much better using OpenBSD's implementation of kernel PPPoE
I originally sent this message to misc@ on
April 17/2011, but I never got a response and I can't find it in the
archives. (I found this copy in my sent mail).
I guess it never went
through. Since I never heard anything back, I figured I'd wait a while and
see if the problem got corrected after the kernel hackathon finished. (It
didn't.)
I gave the most recent snapshot (June 29) a try, and the problem
remains, so I'll try sending this again. I haven't seen anything about this
on the list since; surely I can't be the only person who has run into this.
My original message:
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:
Re: Userland ppp stopped working between Mar24 and Apr8
2011/7/4 Matt S maschwa...@yahoo.com: configuration from a previous setup. Is there a good reason why you couldn't use kernel PPP? It is really easy: You're not helping.
Re: Userland ppp stopped working between Mar24 and Apr8
On 2011-07-04, Matt S maschwa...@yahoo.com wrote: I don't see anything really wrong with your configuration. When I used userland PPP, I had the mtu and mru set to 1492 but you took a known working configuration from a previous setup. Is there a good reason why you couldn't use kernel PPP? It is really easy: It doesn't support mlppp.
Re: Userland ppp stopped working between Mar24 and Apr8
On 2011-07-04, Scott McEachern sc...@blackstaff.ca wrote:
I gave the most recent snapshot (June 29) a try, and the problem
remains, so I'll try sending this again. I haven't seen anything
about this on the list since; surely I can't be the only person who has
run into this.
does this help?
Index: client.c
===
RCS file: /cvs/src/usr.sbin/pppoe/client.c,v
retrieving revision 1.22
diff -u -p -r1.22 client.c
--- client.c31 Mar 2011 09:19:35 - 1.22
+++ client.c4 Jul 2011 14:56:05 -
@@ -274,6 +274,7 @@ send_padr(int bfd, u_int8_t *srv, struct
}
ph-len = htons(ph-len);
+ tag_hton(tl);
client_state = STATE_EXPECT_PADS;
return (writev(bfd, iov, idx));
Index: pppoe.h
===
RCS file: /cvs/src/usr.sbin/pppoe/pppoe.h,v
retrieving revision 1.8
diff -u -p -r1.8 pppoe.h
--- pppoe.h 31 Mar 2011 09:19:35 - 1.8
+++ pppoe.h 4 Jul 2011 14:56:05 -
@@ -103,6 +103,7 @@ void tag_destroy(struct tag_list *);
struct tag_node *tag_lookup(struct tag_list *, u_int16_t, int);
int tag_add(struct tag_list *, u_int16_t, u_int16_t, u_int8_t *);
int tag_pkt(struct tag_list *, u_long, u_int8_t *);
+void tag_hton(struct tag_list *);
struct pppoe_session {
LIST_ENTRY(pppoe_session) s_next;
Index: tag.c
===
RCS file: /cvs/src/usr.sbin/pppoe/tag.c,v
retrieving revision 1.3
diff -u -p -r1.3 tag.c
--- tag.c 31 Mar 2011 09:19:35 - 1.3
+++ tag.c 4 Jul 2011 14:56:05 -
@@ -143,3 +143,14 @@ tag_pkt(struct tag_list *l, u_long pktle
return (-1);
return (0);
}
+
+void
+tag_hton(struct tag_list *l)
+{
+ struct tag_node *p;
+
+ for (p = LIST_FIRST(l-thelist); p; p = LIST_NEXT(p, next)) {
+ p-len = htons(p-len);
+ p-type = htons(p-type);
+ }
+}
Re: Userland ppp stopped working between Mar24 and Apr8
On Mon, 4 Jul 2011 14:56:55 + (UTC) Stuart Henderson s...@spacehopper.org wrote: On 2011-07-04, Scott McEachern sc...@blackstaff.ca wrote: I gave the most recent snapshot (June 29) a try, and the problem remains, so I'll try sending this again. I haven't seen anything about this on the list since; surely I can't be the only person who has run into this. The problem seems to be caused by my mistake on March. I'm sorry. does this help? This will fix the problem. --yasuoka
Re: Userland ppp stopped working between Mar24 and Apr8
On 07/04/11 10:56, Stuart Henderson wrote: On 2011-07-04, Scott McEachernsc...@blackstaff.ca wrote: I gave the most recent snapshot (June 29) a try, and the problem remains, so I'll try sending this again. I haven't seen anything about this on the list since; surely I can't be the only person who has run into this. does this help? It is now working perfectly, thank-you very much Stuart! (Truth be told, I saw your commit on src, so I just did a cvs update vs. applying the patches by hand.) They were applied against the known bad Apr 8th snapshot, but I'll confirm with -current when a new snap is released. - Scott
Userland ppp stopped working between Mar24 and Apr8
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
