LCP negotiation problem - PPP

This is a discussion on LCP negotiation problem - PPP ; I am having a problem with negotiating LCP between two Debian hosts (operating as PPPoE client and servers). The server and client debug logs are shown below. Any insight or suggestions of how to debug would be gratefully recieved! josh. ...

+ Reply to Thread
Results 1 to 4 of 4

Thread: LCP negotiation problem

  1. LCP negotiation problem

    I am having a problem with negotiating LCP between two Debian hosts
    (operating as PPPoE client and servers). The server and client debug
    logs are shown below.

    Any insight or suggestions of how to debug would be gratefully
    recieved!

    josh.

    PPPoE server:

    Jun 14 00:49:58 concentrator pppd[31903]: pppd 2.4.3 started by root,
    uid 0
    Jun 14 00:49:58 concentrator pppd[31903]: using channel 215
    Jun 14 00:49:58 concentrator pppd[31903]: Using interface ppp0
    Jun 14 00:49:58 concentrator pppd[31903]: Connect: ppp0 <--> /dev/pts/2
    Jun 14 00:49:59 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:01 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:01 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:02 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:04 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:04 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:05 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:07 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:07 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:08 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:10 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:10 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:11 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:13 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:13 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:14 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:16 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:16 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:17 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:19 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:19 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:20 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:22 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:22 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:23 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]
    Jun 14 00:50:25 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 1000> ]
    Jun 14 00:50:25 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 1000> ]
    Jun 14 00:50:26 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    ]

    PPPoE client:

    Jun 13 16:52:44 localhost pppd[5596]: Plugin rp-pppoe.so loaded.
    Jun 13 16:52:44 localhost pppd[5597]: pppd 2.4.3 started by root, uid 0
    Jun 13 16:52:44 localhost pppd[5597]: PADS: Service-Name: ''
    Jun 13 16:52:44 localhost pppd[5597]: PPP session is 15
    Jun 13 16:52:44 localhost pppd[5597]: using channel 188
    Jun 13 16:52:44 localhost pppd[5597]: Using interface ppp0
    Jun 13 16:52:44 localhost pppd[5597]: Connect: ppp0 <--> eth0
    Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MTU to 1500
    Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MRU to 1500
    Jun 13 16:52:44 localhost pppd[5597]: sent [LCP ConfReq id=0x1 1000> ]
    Jun 13 16:53:11 localhost last message repeated 9 times
    Jun 13 16:53:14 localhost pppd[5597]: LCP: timeout sending
    Config-Requests
    Jun 13 16:53:14 localhost pppd[5597]: Connection terminated.


  2. Re: LCP negotiation problem

    In article <1150217566.258435.185560@y43g2000cwc.googlegroups. com>,
    josh.howlett@gmail.com wrote:
    >I am having a problem with negotiating LCP between two Debian hosts
    >(operating as PPPoE client and servers). The server and client debug
    >logs are shown below.
    >
    >Any insight or suggestions of how to debug would be gratefully
    >recieved!


    Looking at the logs below, it's clear your "Server" is seeing what
    your "Client" is sending, but your "Client" is NOT seeing what the
    "Server" is sending.

    Can you capture the ethernet packets between the 2 machines? Are
    both machines connected to the same switch? If not, how "far apart"
    are they??

    >PPPoE server:
    >
    >Jun 14 00:49:58 concentrator pppd[31903]: pppd 2.4.3 started by root,
    >uid 0
    >Jun 14 00:49:58 concentrator pppd[31903]: using channel 215
    >Jun 14 00:49:58 concentrator pppd[31903]: Using interface ppp0
    >Jun 14 00:49:58 concentrator pppd[31903]: Connect: ppp0 <--> /dev/pts/2
    >Jun 14 00:49:59 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:01 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:01 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:02 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:04 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:04 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:05 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:07 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:07 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:08 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:10 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:10 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:11 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:13 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:13 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:14 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:16 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:16 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:17 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:19 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:19 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:20 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:22 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:22 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:23 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:25 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:25 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:26 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >
    >PPPoE client:
    >
    >Jun 13 16:52:44 localhost pppd[5596]: Plugin rp-pppoe.so loaded.
    >Jun 13 16:52:44 localhost pppd[5597]: pppd 2.4.3 started by root, uid 0
    >Jun 13 16:52:44 localhost pppd[5597]: PADS: Service-Name: ''
    >Jun 13 16:52:44 localhost pppd[5597]: PPP session is 15
    >Jun 13 16:52:44 localhost pppd[5597]: using channel 188
    >Jun 13 16:52:44 localhost pppd[5597]: Using interface ppp0
    >Jun 13 16:52:44 localhost pppd[5597]: Connect: ppp0 <--> eth0
    >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MTU to 1500
    >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MRU to 1500
    >Jun 13 16:52:44 localhost pppd[5597]: sent [LCP ConfReq id=0x1 >1000> ]
    >Jun 13 16:53:11 localhost last message repeated 9 times
    >Jun 13 16:53:14 localhost pppd[5597]: LCP: timeout sending
    >Config-Requests
    >Jun 13 16:53:14 localhost pppd[5597]: Connection terminated.


    ========= For LAN/WAN Protocol Analysis, check out PacketView Pro! =========
    Patrick Klos Email: patrick@klos.com
    Klos Technologies, Inc. Web: http://www.klos.com/
    ==================== http://www.loving-long-island.com/ ====================

  3. Re: LCP negotiation problem

    Thanks for responding, but I just discovered this is a Debian bug:

    http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=308383

    josh.

    Patrick Klos wrote:

    > In article <1150217566.258435.185560@y43g2000cwc.googlegroups. com>,
    > josh.howlett@gmail.com wrote:
    > >I am having a problem with negotiating LCP between two Debian hosts
    > >(operating as PPPoE client and servers). The server and client debug
    > >logs are shown below.
    > >
    > >Any insight or suggestions of how to debug would be gratefully
    > >recieved!

    >
    > Looking at the logs below, it's clear your "Server" is seeing what
    > your "Client" is sending, but your "Client" is NOT seeing what the
    > "Server" is sending.
    >
    > Can you capture the ethernet packets between the 2 machines? Are
    > both machines connected to the same switch? If not, how "far apart"
    > are they??
    >
    > >PPPoE server:
    > >
    > >Jun 14 00:49:58 concentrator pppd[31903]: pppd 2.4.3 started by root,
    > >uid 0
    > >Jun 14 00:49:58 concentrator pppd[31903]: using channel 215
    > >Jun 14 00:49:58 concentrator pppd[31903]: Using interface ppp0
    > >Jun 14 00:49:58 concentrator pppd[31903]: Connect: ppp0 <--> /dev/pts/2
    > >Jun 14 00:49:59 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:01 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:01 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:02 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:04 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:04 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:05 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:07 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:07 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:08 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:10 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:10 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:11 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:13 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:13 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:14 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:16 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:16 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:17 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:19 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:19 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:20 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:22 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:22 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:23 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >Jun 14 00:50:25 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 14 00:50:25 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 > >1000> ]
    > >Jun 14 00:50:26 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    > >]
    > >
    > >PPPoE client:
    > >
    > >Jun 13 16:52:44 localhost pppd[5596]: Plugin rp-pppoe.so loaded.
    > >Jun 13 16:52:44 localhost pppd[5597]: pppd 2.4.3 started by root, uid 0
    > >Jun 13 16:52:44 localhost pppd[5597]: PADS: Service-Name: ''
    > >Jun 13 16:52:44 localhost pppd[5597]: PPP session is 15
    > >Jun 13 16:52:44 localhost pppd[5597]: using channel 188
    > >Jun 13 16:52:44 localhost pppd[5597]: Using interface ppp0
    > >Jun 13 16:52:44 localhost pppd[5597]: Connect: ppp0 <--> eth0
    > >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MTU to 1500
    > >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MRU to 1500
    > >Jun 13 16:52:44 localhost pppd[5597]: sent [LCP ConfReq id=0x1 > >1000> ]
    > >Jun 13 16:53:11 localhost last message repeated 9 times
    > >Jun 13 16:53:14 localhost pppd[5597]: LCP: timeout sending
    > >Config-Requests
    > >Jun 13 16:53:14 localhost pppd[5597]: Connection terminated.

    >
    > ========= For LAN/WAN Protocol Analysis, check out PacketView Pro! =========
    > Patrick Klos Email: patrick@klos.com
    > Klos Technologies, Inc. Web: http://www.klos.com/
    > ==================== http://www.loving-long-island.com/ ====================



  4. Re: LCP negotiation problem

    "josh.howlett@gmail.com" writes:

    >I am having a problem with negotiating LCP between two Debian hosts
    >(operating as PPPoE client and servers). The server and client debug
    >logs are shown below.


    The other side is not listening at all. So potentially some modem problem.

    >Any insight or suggestions of how to debug would be gratefully
    >recieved!


    >josh.


    >PPPoE server:


    >Jun 14 00:49:58 concentrator pppd[31903]: pppd 2.4.3 started by root,
    >uid 0
    >Jun 14 00:49:58 concentrator pppd[31903]: using channel 215
    >Jun 14 00:49:58 concentrator pppd[31903]: Using interface ppp0
    >Jun 14 00:49:58 concentrator pppd[31903]: Connect: ppp0 <--> /dev/pts/2
    >Jun 14 00:49:59 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:01 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:01 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:02 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:04 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:04 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:05 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:07 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:07 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:08 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:10 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:10 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:11 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:13 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:13 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:14 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:16 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:16 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:17 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:19 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:19 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:20 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:22 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:22 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:23 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]
    >Jun 14 00:50:25 concentrator pppd[31903]: rcvd [LCP ConfReq id=0x1 >1000> ]
    >Jun 14 00:50:25 concentrator pppd[31903]: sent [LCP ConfAck id=0x1 >1000> ]
    >Jun 14 00:50:26 concentrator pppd[31903]: sent [LCP ConfReq id=0x1
    >]


    >PPPoE client:


    >Jun 13 16:52:44 localhost pppd[5596]: Plugin rp-pppoe.so loaded.
    >Jun 13 16:52:44 localhost pppd[5597]: pppd 2.4.3 started by root, uid 0
    >Jun 13 16:52:44 localhost pppd[5597]: PADS: Service-Name: ''
    >Jun 13 16:52:44 localhost pppd[5597]: PPP session is 15
    >Jun 13 16:52:44 localhost pppd[5597]: using channel 188
    >Jun 13 16:52:44 localhost pppd[5597]: Using interface ppp0
    >Jun 13 16:52:44 localhost pppd[5597]: Connect: ppp0 <--> eth0
    >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MTU to 1500
    >Jun 13 16:52:44 localhost pppd[5597]: Couldn't increase MRU to 1500
    >Jun 13 16:52:44 localhost pppd[5597]: sent [LCP ConfReq id=0x1 >1000> ]
    >Jun 13 16:53:11 localhost last message repeated 9 times
    >Jun 13 16:53:14 localhost pppd[5597]: LCP: timeout sending
    >Config-Requests
    >Jun 13 16:53:14 localhost pppd[5597]: Connection terminated.


    As I said, it does not hear you at all. It lists none of th e packets sent
    to it.

+ Reply to Thread