IPCP received before authentification success
Gilles Espinasse
When it is not good, the authentification server don't ack CHAP
authentification answer and answer with IPCP messages
(192.168.254.254 is the default gateway address always received)
Is the ISP authentification server broken?
May 25 23:23:11 ipcop pppd[1106]: Plugin /usr/lib/pppd/2.4.2/pppoatm.so
loaded.
May 25 23:23:11 ipcop pppd[1106]: PPPoATM plugin_init
May 25 23:23:11 ipcop pppd[1106]: PPPoATM setdevname - remove unwanted
options
May 25 23:23:11 ipcop pppd[1106]: PPPoATM setdevname_pppoatm - SUCCESS:8.35
May 25 23:23:11 ipcop pppd[1107]: pppd 2.4.2 started by root, uid 0
May 25 23:23:11 ipcop pppd[1107]: using channel 6
May 25 23:23:11 ipcop pppd[1107]: Using interface ppp0
May 25 23:23:11 ipcop pppd[1107]: Connect: ppp0 <--> 8.35
May 25 23:23:11 ipcop pppd[1107]: sent [LCP ConfReq id=0x1 <magic
0x8f83ade9>]
May 25 23:23:11 ipcop pppd[1107]: rcvd [LCP ConfReq id=0x63 <mru 9178> <auth
chap MD5> <magic 0x73476a40>]
May 25 23:23:11 ipcop pppd[1107]: sent [LCP ConfAck id=0x63 <mru 9178> <auth
chap MD5> <magic 0x73476a40>]
May 25 23:23:14 ipcop pppd[1107]: sent [LCP ConfReq id=0x1 <magic
0x8f83ade9>]
May 25 23:23:14 ipcop pppd[1107]: rcvd [LCP ConfAck id=0x1 <magic
0x8f83ade9>]
May 25 23:23:14 ipcop pppd[1107]: sent [LCP EchoReq id=0x0 magic=0x8f83ade9]
May 25 23:23:14 ipcop pppd[1107]: rcvd [CHAP Challenge id=0xa2
<b196c718fffecfc26c5f170e4d86989b>, name = "BSSGW113"]
May 25 23:23:14 ipcop pppd[1107]: sent [CHAP Response id=0xa2
<e19caea9e3939d8611b649b96b880ec1>, name = "mylogin@freeadsl"]
May 25 23:23:14 ipcop pppd[1107]: rcvd [LCP EchoRep id=0x0 magic=0x73476a40]
May 25 23:23:15 ipcop pppd[1107]: rcvd [LCP EchoReq id=0x1 magic=0x73476a40
c2 6c 5f 17]
May 25 23:23:15 ipcop pppd[1107]: sent [LCP EchoRep id=0x1 magic=0x8f83ade9
05 05 06 73]
May 25 23:23:16 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x2 <addr
192.168.254.254>]
May 25 23:23:16 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:18 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x3 <addr
192.168.254.254>]
May 25 23:23:18 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:20 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x4 <addr
192.168.254.254>]
May 25 23:23:20 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:22 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x5 <addr
192.168.254.254>]
May 25 23:23:22 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:24 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x6 <addr
192.168.254.254>]
May 25 23:23:24 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:26 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x7 <addr
192.168.254.254>]
May 25 23:23:26 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:28 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x8 <addr
192.168.254.254>]
May 25 23:23:28 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:30 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x9 <addr
192.168.254.254>]
May 25 23:23:30 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:32 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xa <addr
192.168.254.254>]
May 25 23:23:32 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:23:34 ipcop pppd[1107]: sent [LCP EchoReq id=0x1 magic=0x8f83ade9]
May 25 23:23:34 ipcop pppd[1107]: rcvd [LCP EchoRep id=0x1 magic=0x73476a40]
May 25 23:23:54 ipcop pppd[1107]: sent [LCP EchoReq id=0x2 magic=0x8f83ade9]
May 25 23:23:54 ipcop pppd[1107]: rcvd [LCP EchoRep id=0x2 magic=0x73476a40]
May 25 23:24:04 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xb <addr
192.168.254.254>]
May 25 23:24:04 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:24:06 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xc <addr
192.168.254.254>]
May 25 23:24:06 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:24:08 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xd <addr
192.168.254.254>]
May 25 23:24:08 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:24:10 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xe <addr
192.168.254.254>]
May 25 23:24:10 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:24:12 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0xf <addr
192.168.254.254>]
May 25 23:24:12 ipcop pppd[1107]: discarding proto 0x8021 in phase 5
May 25 23:24:14 ipcop pppd[1107]: sent [LCP EchoReq id=0x3 magic=0x8f83ade9]
What is curious is that sometime the server ask for CHAP but some other
times directly with PAP.
Everytime attempt with PAP is successfull like that:
May 25 23:10:50 ipcop pppd[809]: Plugin /usr/lib/pppd/2.4.2/pppoatm.so
loaded.
May 25 23:10:50 ipcop pppd[809]: PPPoATM plugin_init
May 25 23:10:50 ipcop pppd[809]: PPPoATM setdevname - remove unwanted
options
May 25 23:10:50 ipcop pppd[809]: PPPoATM setdevname_pppoatm - SUCCESS:8.35
May 25 23:10:50 ipcop pppd[810]: pppd 2.4.2 started by root, uid 0
May 25 23:10:50 ipcop pppd[810]: using channel 3
May 25 23:10:50 ipcop pppd[810]: Using interface ppp0
May 25 23:10:50 ipcop pppd[810]: Connect: ppp0 <--> 8.35
May 25 23:10:50 ipcop pppd[810]: sent [LCP ConfReq id=0x1 <magic
0x109bc42f>]
May 25 23:10:52 ipcop pppd[810]: rcvd [LCP ConfReq id=0x1 <auth pap> <magic
0x3348be54>]
May 25 23:10:52 ipcop pppd[810]: sent [LCP ConfAck id=0x1 <auth pap> <magic
0x3348be54>]
May 25 23:10:53 ipcop pppd[810]: sent [LCP ConfReq id=0x1 <magic
0x109bc42f>]
May 25 23:10:53 ipcop pppd[810]: rcvd [LCP ConfAck id=0x1 <magic
0x109bc42f>]
May 25 23:10:53 ipcop pppd[810]: sent [LCP EchoReq id=0x0 magic=0x109bc42f]
May 25 23:10:53 ipcop pppd[810]: sent [PAP AuthReq id=0x1
user="mylogin@freeadsl" password=<hidden>]
May 25 23:10:53 ipcop pppd[810]: rcvd [LCP EchoRep id=0x0 magic=0x3348be54]
May 25 23:10:53 ipcop pppd[810]: rcvd [PAP AuthAck id=0x1 ""]
May 25 23:10:53 ipcop pppd[810]: PAP authentication succeeded
May 25 23:10:53 ipcop pppd[810]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 25 23:10:53 ipcop pppd[810]: rcvd [IPCP ConfReq id=0x1 <addr
192.168.254.254>]
May 25 23:10:53 ipcop pppd[810]: sent [IPCP ConfAck id=0x1 <addr 192.168.254
.254>]
May 25 23:10:53 ipcop pppd[810]: rcvd [IPCP ConfNak id=0x1 <addr
82.64.150.218>]
May 25 23:10:53 ipcop pppd[810]: sent [IPCP ConfReq id=0x2 <addr
82.64.150.218>]
May 25 23:10:53 ipcop pppd[810]: rcvd [IPCP ConfAck id=0x2 <addr
82.64.150.218>]
What is more curious is that with PPPoE protocol, the server ask first with
CHAP, and later with PAP and it's work reliable.
Every answer from the server look padded with many 00 00...
May 25 23:40:30 ipcop RFC1483/2684 bridge: Interface "nas0" created
sucessfully
May 25 23:40:30 ipcop RFC1483/2684 bridge: Communicating over ATM 0.8.35,
encapsulation: LLC
May 25 23:40:30 ipcop RFC1483/2684 bridge: Interface configured
May 25 23:40:30 ipcop RFC1483/2684 bridge: RFC 1483/2684 bridge daemon
started
May 25 23:40:31 ipcop ipcop: PPPoE bridge success
May 25 23:40:35 ipcop pppd[1349]: Plugin /usr/lib/pppd/2.4.2/rp-pppoe.so
loaded.
May 25 23:40:35 ipcop pppd[1349]: RP-PPPoE plugin version 3.3 compiled
against pppd 2.4.2
May 25 23:40:35 ipcop pppd[1350]: pppd 2.4.2 started by root, uid 0
May 25 23:40:35 ipcop pppd[1350]: PADS: Service-Name: ''
May 25 23:40:35 ipcop pppd[1350]: PPP session is 7713
May 25 23:40:35 ipcop pppd[1350]: using channel 8
May 25 23:40:35 ipcop pppd[1350]: Using interface ppp0
May 25 23:40:35 ipcop pppd[1350]: Connect: ppp0 <--> nas0
May 25 23:40:35 ipcop pppd[1350]: Couldn't increase MTU to 1500
May 25 23:40:35 ipcop pppd[1350]: Couldn't increase MRU to 1500
May 25 23:40:35 ipcop pppd[1350]: sent [LCP ConfReq id=0x1 <magic
0x7ef23857>]
May 25 23:40:35 ipcop pppd[1350]: rcvd [LCP ConfReq id=0x53 <mru 1492> <auth
chap MD5> <magic 0x51231eba>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00
May 25 23:40:35 ipcop pppd[1350]: sent [LCP ConfAck id=0x53 <mru 1492> <auth
chap MD5> <magic 0x51231eba>]
May 25 23:40:35 ipcop pppd[1350]: rcvd [LCP ConfAck id=0x1 <magic
0x7ef23857>] 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
May 25 23:40:35 ipcop pppd[1350]: Couldn't increase MRU to 1500
May 25 23:40:35 ipcop pppd[1350]: sent [LCP EchoReq id=0x0 magic=0x7ef23857]
May 25 23:40:35 ipcop pppd[1350]: rcvd [CHAP Challenge id=0x61
<39c097a76ebac560ccf649b47e2fe75e>, name = "BSSGW113"] 00 00 00 00 00 00 00
00 00
May 25 23:40:35 ipcop pppd[1350]: sent [CHAP Response id=0x61
<6fafb10299bf999f8e2ec34accf0e2d4>, name = "mylogin@freeadsl"]
May 25 23:40:35 ipcop pppd[1350]: rcvd [LCP EchoRep id=0x0 magic=0x51231eba]
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
May 25 23:40:37 ipcop pppd[1350]: rcvd [LCP ConfReq id=0x2 <auth pap> <magic
0x12ca1733>] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
May 25 23:40:37 ipcop pppd[1350]: Couldn't increase MTU to 1500
May 25 23:40:37 ipcop pppd[1350]: Couldn't increase MRU to 1500
May 25 23:40:37 ipcop pppd[1350]: sent [LCP ConfReq id=0x2 <magic
0x55ea4333>]
May 25 23:40:37 ipcop pppd[1350]: sent [LCP ConfAck id=0x2 <auth pap> <magic
0x12ca1733>]
May 25 23:40:37 ipcop pppd[1350]: rcvd [LCP ConfAck id=0x2 <magic
0x55ea4333>] 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
May 25 23:40:37 ipcop pppd[1350]: Couldn't increase MTU to 1500
May 25 23:40:37 ipcop pppd[1350]: Couldn't increase MRU to 1500
May 25 23:40:37 ipcop pppd[1350]: sent [LCP EchoReq id=0x0 magic=0x55ea4333]
May 25 23:40:37 ipcop pppd[1350]: sent [PAP AuthReq id=0x1
user="mylogin@freeadsl" password=<hidden>]
May 25 23:40:37 ipcop pppd[1350]: rcvd [LCP EchoRep id=0x0 magic=0x12ca1733]
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
May 25 23:40:37 ipcop pppd[1350]: rcvd [PAP AuthAck id=0x1 ""] 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 ...
May 25 23:40:37 ipcop pppd[1350]: PAP authentication succeeded
May 25 23:40:37 ipcop pppd[1350]: peer from calling number 00:90:1A:40:44:17
authorized
May 25 23:40:38 ipcop pppd[1350]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 25 23:40:38 ipcop pppd[1350]: rcvd [IPCP ConfReq id=0x1 <addr
192.168.254.254>] 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
May 25 23:40:38 ipcop pppd[1350]: sent [IPCP ConfAck id=0x1 <addr
192.168.254.254>]
May 25 23:40:38 ipcop pppd[1350]: rcvd [IPCP ConfNak id=0x1 <addr
82.65.42.88>] 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
May 25 23:40:38 ipcop pppd[1350]: sent [IPCP ConfReq id=0x2 <addr
82.65.42.88>]
May 25 23:40:38 ipcop pppd[1350]: rcvd [IPCP ConfAck id=0x2 <addr
82.65.42.88>] 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
May 25 23:40:38 ipcop pppd[1350]: local IP address 82.65.42.88
May 25 23:40:38 ipcop pppd[1350]: remote IP address 192.168.254.254
May 25 23:40:38 ipcop pppd[1350]: Script /etc/ppp/ip-up started (pid 1354)
May 25 23:40:45 ipcop ipcop: PPP has gone up on ppp0
James Carlson
> I have sometime (but not always) now problem to connect with PPPoA protocol.
> When it is not good, the authentification server don't ack CHAP
> authentification answer and answer with IPCP messages
> (192.168.254.254 is the default gateway address always received)
> Is the ISP authentification server broken?
The CHAP Success message isn't acknowledged, so it's remotely possible
for it to be lost and for the peer to run on to IPCP (or other NCPs).
This is a known but exceedingly rare problem -- I can't say I'd seen
it before, though I knew of it in theory. In any event, the fix is
relatively simple. An implementation can assume that receipt of any
NCP negotiation messages is equivalent to reception of CHAP Success,
and since those negotiation messages are on a timer, that's reliable.
The same is true, for what it's worth, for PAP Authenticate-Ack. No,
I don't think that pppd supports this mechanism though. It sounds
like a fair idea to add it.
(I'm not convinced, though, that this is what's happening in your
case. See below.)
> What is curious is that sometime the server ask for CHAP but some other
> times directly with PAP.
That's a clear indication that you're not just talking to one server.
I see at least two possibilities, and I suspect that both are
happening:
1. You may be connecting through some sort of load balancer.
Such a device would either pick a lightly-loaded server
(stupid) or an arbitrary one (better) to handle your PPP
session. If those servers are configured differently (an
unfortunately *very* common error with ISPs), then you'll
see varying behavior every time you connect.
2. If the first hop is using L2TP or some other tunneling
protocol to backhaul your connection to a separate ISP
(very likely so, given that this is PPPoA), then you'll
get an LCP negotiation and initial (partial!)
authentication that's instigated by the LAC (access
server), followed by further PPP negotiation by the LNS
(ISP). There are warts in such a scenario, and the LAC's
initial authentication configuration might not be in sync
with what the LNS decides to do.
A combination of (1) and (2) above would explain the symptoms you see.
> May 25 23:23:14 ipcop pppd[1107]: rcvd [CHAP Challenge id=0xa2
> <b196c718fffecfc26c5f170e4d86989b>, name = "BSSGW113"]
> May 25 23:23:14 ipcop pppd[1107]: sent [CHAP Response id=0xa2
> <e19caea9e3939d8611b649b96b880ec1>, name = "mylogin@freeadsl"]
> May 25 23:23:16 ipcop pppd[1107]: rcvd [IPCP ConfReq id=0x2 <addr
> 192.168.254.254>]
This looks like a case of (2) above. I'm guessing that the LAC
insisted on CHAP, then (perhaps without actually verifying the CHAP
Response) used the 'name' you provided to locate an L2TP tunnel to the
LNS for "freeadsl." The LNS, though, was configured to work with *NO*
authentication, so it didn't even bother to complete the CHAP
sequence.
That's mostly guesswork, and only someone clueful who worked for the
ISP could verify the situation.
Based on the guess, it sounds like there are a couple of bugs there:
the ISP's server should probably be set to do authentication (and not
just ignore it) and the implementation they're using should inspect
the information provided by L2TP to know that even when authentication
isn't required, they still need to go through the motions so the peer
doesn't get confused.
(There's a deeper architectural flaw with L2TP here ... but I guess
that's beside the point.)
Just at a guess, removing entries from /etc/ppp/chap-secrets (so that
you respond with PAP *only*) might help. It probably won't, though.
> May 25 23:10:52 ipcop pppd[810]: rcvd [LCP ConfReq id=0x1 <auth pap> <magic
> 0x3348be54>]
This looks like a case of (1) above. You landed on an access server
that's configured to use PAP first. Complaining to the company that
owns the first hop might help ... assuming you can locate someone with
a clue.
(Having spent a fair amount of time arguing the nearly impenetrable
front line "support" used by companies that have to support the
typical 'doze user, I'd say that it's worthwhile to find a different
ISP instead.)
> What is more curious is that with PPPoE protocol, the server ask first with
> CHAP, and later with PAP and it's work reliable.
Are you switching tunneling protocols here? It may well be that the
servers for PPPoA and PPPoE are separate. Showing that one works and
the other doesn't might not be helpful.
> Every answer from the server look padded with many 00 00...
Don't worry about it. It's a "feature" of PPPoE.
--
James Carlson, IP Systems Group <james.d...@sun.com>
Sun Microsystems / 1 Network Drive 71.234W Vox +1 781 442 2084
MS UBUR02-212 / Burlington MA 01803-2757 42.497N Fax +1 781 442 1677
Gilles Espinasse
efficient to discribe the problem.
You are right in many of your suppositions. I appologize to give not more
clues.
There is a L2TP tunnel. In previous month, I had sometime rcvd [CHAP
Failure id=0x2d "Tunnel startup failure"]
The first server is run by the historical operator. The name of the ISP in
the login after the @ is used to switch to this ISP.
Previously I was always authenticated with CHAP. In those times when CHAP
authentification was working, it was often that twice chap authentifications
were necessary wich make think that the first was used to switch to the ISP
and the second to authenticate.
There is other french people complaining about the same problem with various
ISP but probably the same infrastructure of the historical operator :
http://lists.debian.org/debian-user-french/2004/03/msg04247.html
I test the solution to disallow chap (I add -chap) and PPPoA connection is
now reliable (but not direct : need to send twice PAP login/password).
May 26 23:47:38 ipcop pppd[10269]: Connect: ppp0 <--> 8.35
May 26 23:47:38 ipcop pppd[10269]: sent [LCP ConfReq id=0x1 <magic
0x8f9d9489>]
May 26 23:47:39 ipcop pppd[10269]: rcvd [LCP ConfReq id=0x73 <mru 9178>
<auth chap MD5> <magic 0x56cd911c>]
May 26 23:47:39 ipcop pppd[10269]: sent [LCP ConfNak id=0x73 <auth chap
MS-v2>]
May 26 23:47:39 ipcop pppd[10269]: rcvd [LCP ConfReq id=0x74 <mru 9178>
<auth pap> <magic 0x56cd911c>]
May 26 23:47:39 ipcop pppd[10269]: sent [LCP ConfAck id=0x74 <mru 9178>
<auth pap> <magic 0x56cd911c>]
May 26 23:47:41 ipcop pppd[10269]: sent [LCP ConfReq id=0x1 <magic
0x8f9d9489>]
May 26 23:47:41 ipcop pppd[10269]: rcvd [LCP ConfAck id=0x1 <magic
0x8f9d9489>]
May 26 23:47:41 ipcop pppd[10269]: sent [LCP EchoReq id=0x0
magic=0x8f9d9489]
May 26 23:47:41 ipcop pppd[10269]: sent [PAP AuthReq id=0x1
user="mylogin@freeadsl" password=<hidden>]
May 26 23:47:42 ipcop pppd[10269]: rcvd [LCP EchoRep id=0x0
magic=0x56cd911c]
May 26 23:47:43 ipcop pppd[10269]: rcvd [LCP EchoReq id=0x1 magic=0x56cd911c
05 06 56 cd]
May 26 23:47:43 ipcop pppd[10269]: sent [LCP EchoRep id=0x1 magic=0x8f9d9489
39 34 33 40]
May 26 23:47:44 ipcop pppd[10269]: rcvd [IPCP ConfReq id=0x2 <addr
192.168.254.254>]
May 26 23:47:44 ipcop pppd[10269]: discarding proto 0x8021 in phase 5
May 26 23:47:45 ipcop pppd[10269]: sent [PAP AuthReq id=0x2
user="mylogin@freeadsl" password=<hidden>]
May 26 23:47:45 ipcop pppd[10269]: rcvd [PAP AuthAck id=0x2 ""]
May 26 23:47:45 ipcop pppd[10269]: PAP authentication succeeded
May 26 23:47:45 ipcop pppd[10269]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0>]
May 26 23:47:45 ipcop pppd[10269]: rcvd [IPCP ConfNak id=0x1 <addr
62.147.154.30>]
May 26 23:47:45 ipcop pppd[10269]: sent [IPCP ConfReq id=0x2 <addr
62.147.154.30>]
May 26 23:47:45 ipcop pppd[10269]: rcvd [IPCP ConfAck id=0x2 <addr
62.147.154.30>]
May 26 23:47:46 ipcop pppd[10269]: rcvd [IPCP ConfReq id=0x3 <addr
192.168.254.254>]
May 26 23:47:46 ipcop pppd[10269]: sent [IPCP ConfAck id=0x3 <addr
192.168.254.254>]
May 26 23:47:46 ipcop pppd[10269]: local IP address 62.147.154.30
May 26 23:47:46 ipcop pppd[10269]: remote IP address 192.168.254.254