Mailing List Archive

Nathan,

Have you taken on any new customers - what number of sessions are you
running?

How are your customers terminated - dot1q or q-in-q subinterfaces? Have
you checked to see whether you are hitting one of the many default PPPoE
Session Limits?

Might help to share your sanitised config.

- Damian

On 24/05/16 21:13, Nathan Downes wrote:
>
> Hi,
>
>
>
> This morning we started having a few clients unable to connect, I see
> the MAC addresses of the modems learnt on the core switch but LCP
> appears to fail. It is across two providers so I can’t blame them
> (issues may be different for each of them) Debugging PPP negotiation
> just repeats the below.
>
>
>
> *May 24 18:42:08.611: ppp470 LCP: Event[Timeout-] State[REQsent to
> Stopped]
>
> *May 24 18:42:08.611: ppp470 LCP: Event[DOWN] State[Stopped to Starting]
>
> *May 24 18:42:08.611: ppp470 PPP: Clearing AAA Unique Id = B70
>
> *May 24 18:42:08.611: ppp470 PPP: Phase is DOWN
>
> *May 24 18:42:10.307: ppp475 LCP: O CONFREQ [REQsent] id 5 len 18
>
> *May 24 18:42:10.307: ppp475 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:10.307: ppp475 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:10.307: ppp475 LCP: MagicNumber 0x1A8E4B9E
> (0x05061A8E4B9E)
>
> *May 24 18:42:10.307: ppp475 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:10.531: ppp472 LCP: O CONFREQ [REQsent] id 6 len 18
>
> *May 24 18:42:10.531: ppp472 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:10.531: ppp472 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:10.531: ppp472 LCP: MagicNumber 0x1A8E449C
> (0x05061A8E449C)
>
> *May 24 18:42:10.531: ppp472 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:10.531: ppp476 LCP: O CONFREQ [REQsent] id 3 len 18
>
> *May 24 18:42:10.531: ppp476 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:10.531: ppp476 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:10.531: ppp476 LCP: MagicNumber 0x1A8E5C44
> (0x05061A8E5C44)
>
> *May 24 18:42:10.531: ppp476 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:12.323: ppp475 LCP: O CONFREQ [REQsent] id 6 len 18
>
> *May 24 18:42:12.323: ppp475 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:12.323: ppp475 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:12.323: ppp475 LCP: MagicNumber 0x1A8E4B9E
> (0x05061A8E4B9E)
>
> *May 24 18:42:12.323: ppp475 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:12.547: ppp472 LCP: O CONFREQ [REQsent] id 7 len 18
>
> *May 24 18:42:12.547: ppp472 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:12.547: ppp472 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:12.547: ppp472 LCP: MagicNumber 0x1A8E449C
> (0x05061A8E449C)
>
> *May 24 18:42:12.547: ppp472 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:12.547: ppp476 LCP: O CONFREQ [REQsent] id 4 len 18
>
> *May 24 18:42:12.547: ppp476 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:12.547: ppp476 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:12.547: ppp476 LCP: MagicNumber 0x1A8E5C44
> (0x05061A8E5C44)
>
> *May 24 18:42:12.547: ppp476 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:14.339: ppp475 LCP: O CONFREQ [REQsent] id 7 len 18
>
> *May 24 18:42:14.339: ppp475 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:14.339: ppp475 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:14.339: ppp475 LCP: MagicNumber 0x1A8E4B9E
> (0x05061A8E4B9E)
>
> *May 24 18:42:14.339: ppp475 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:14.563: ppp472 LCP: O CONFREQ [REQsent] id 8 len 18
>
> *May 24 18:42:14.563: ppp472 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:14.563: ppp472 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:14.563: ppp472 LCP: MagicNumber 0x1A8E449C
> (0x05061A8E449C)
>
> *May 24 18:42:14.563: ppp472 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:14.563: ppp476 LCP: O CONFREQ [REQsent] id 5 len 18
>
> *May 24 18:42:14.563: ppp476 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:14.563: ppp476 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:14.563: ppp476 LCP: MagicNumber 0x1A8E5C44
> (0x05061A8E5C44)
>
> *May 24 18:42:14.563: ppp476 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:16.355: ppp475 LCP: O CONFREQ [REQsent] id 8 len 18
>
> *May 24 18:42:16.355: ppp475 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:16.355: ppp475 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:16.355: ppp475 LCP: MagicNumber 0x1A8E4B9E
> (0x05061A8E4B9E)
>
> *May 24 18:42:16.355: ppp475 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:16.579: ppp472 LCP: O CONFREQ [REQsent] id 9 len 18
>
> *May 24 18:42:16.579: ppp472 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:16.579: ppp472 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:16.579: ppp472 LCP: MagicNumber 0x1A8E449C
> (0x05061A8E449C)
>
> *May 24 18:42:16.579: ppp472 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:16.579: ppp476 LCP: O CONFREQ [REQsent] id 6 len 18
>
> *May 24 18:42:16.579: ppp476 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:16.579: ppp476 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:16.579: ppp476 LCP: MagicNumber 0x1A8E5C44
> (0x05061A8E5C44)
>
> *May 24 18:42:16.579: ppp476 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:18.371: ppp475 LCP: O CONFREQ [REQsent] id 9 len 18
>
> *May 24 18:42:18.371: ppp475 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:18.371: ppp475 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:18.371: ppp475 LCP: MagicNumber 0x1A8E4B9E
> (0x05061A8E4B9E)
>
> *May 24 18:42:18.371: ppp475 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:18.595: ppp472 LCP: O CONFREQ [REQsent] id 10 len 18
>
> *May 24 18:42:18.595: ppp472 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:18.595: ppp472 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:18.595: ppp472 LCP: MagicNumber 0x1A8E449C
> (0x05061A8E449C)
>
> *May 24 18:42:18.595: ppp472 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
> *May 24 18:42:18.595: ppp476 LCP: O CONFREQ [REQsent] id 7 len 18
>
> *May 24 18:42:18.595: ppp476 LCP: MRU 1492 (0x010405D4)
>
> *May 24 18:42:18.595: ppp476 LCP: AuthProto PAP (0x0304C023)
>
> *May 24 18:42:18.595: ppp476 LCP: MagicNumber 0x1A8E5C44
> (0x05061A8E5C44)
>
> *May 24 18:42:18.595: ppp476 LCP: Event[Timeout+] State[REQsent to
> REQsent]
>
>
>
> As we handoff to the providers from the switch this one is connected
> to I have very few ways of following the traffic to the other side, I
> can see requests go out but they either don’t make it to CPE or the
> response doesn’t make it back. Nothing has been changed networkwise
> in the last 3 months so bit lost. Have rebooted the switch just in
> case as it has been a year or so, but that just got more angry calls J
>
>
>
> CPE is just a simple modem on other side, no difference between
> working and non working ones, BRAS is a 7204vxr with a G2. “core”
> switch is just a simple 3560g
>
>
>
> _______________________________________________
> cisco-bba mailing list
> cisco-bba@puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-bba

Hi Damian



Only about 500, and there was 2 new ones in last few days, but that is then
causing problems with about 10-15. I don't think it is a config issue, I
shutdown one of the providers interfaces late last night and it stopped, so
it is limited to them. A few even connected back when I brought it back up.
Even so some aren't connecting with the other provider it is appearing to be
different issue. One of those lovely coincidentally at the same time ones
that just cloud the real problem :)



No dot1q or q-in-q for this part, I guess it's dot1q but 7204 is on a
switchport and not using VLANs internally.



I'll contact both providers and put faults in for each non working service
and go from there. Having that issue limited to one provider makes it easier
to suggest where the fault lies, I assumed it was both when we had clients
on both having problems.





From: cisco-bba [mailto:cisco-bba-bounces@puck.nether.net] On Behalf Of
Damian Kissick
Sent: Wednesday, 25 May 2016 6:21 AM
To: cisco-bba@puck.nether.net
Subject: Re: [cisco-bba] LCP failing - any ideas?



Nathan,

Have you taken on any new customers - what number of sessions are you
running?

How are your customers terminated - dot1q or q-in-q subinterfaces? Have you
checked to see whether you are hitting one of the many default PPPoE Session
Limits?

Might help to share your sanitised config.

- Damian

On 24/05/16 21:13, Nathan Downes wrote:

Hi,



This morning we started having a few clients unable to connect, I see the
MAC addresses of the modems learnt on the core switch but LCP appears to
fail. It is across two providers so I can't blame them (issues may be
different for each of them) Debugging PPP negotiation just repeats the
below.



*May 24 18:42:08.611: ppp470 LCP: Event[Timeout-] State[REQsent to Stopped]

*May 24 18:42:08.611: ppp470 LCP: Event[DOWN] State[Stopped to Starting]

*May 24 18:42:08.611: ppp470 PPP: Clearing AAA Unique Id = B70

*May 24 18:42:08.611: ppp470 PPP: Phase is DOWN

*May 24 18:42:10.307: ppp475 LCP: O CONFREQ [REQsent] id 5 len 18

*May 24 18:42:10.307: ppp475 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:10.307: ppp475 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:10.307: ppp475 LCP: MagicNumber 0x1A8E4B9E (0x05061A8E4B9E)

*May 24 18:42:10.307: ppp475 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:10.531: ppp472 LCP: O CONFREQ [REQsent] id 6 len 18

*May 24 18:42:10.531: ppp472 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:10.531: ppp472 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:10.531: ppp472 LCP: MagicNumber 0x1A8E449C (0x05061A8E449C)

*May 24 18:42:10.531: ppp472 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:10.531: ppp476 LCP: O CONFREQ [REQsent] id 3 len 18

*May 24 18:42:10.531: ppp476 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:10.531: ppp476 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:10.531: ppp476 LCP: MagicNumber 0x1A8E5C44 (0x05061A8E5C44)

*May 24 18:42:10.531: ppp476 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:12.323: ppp475 LCP: O CONFREQ [REQsent] id 6 len 18

*May 24 18:42:12.323: ppp475 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:12.323: ppp475 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:12.323: ppp475 LCP: MagicNumber 0x1A8E4B9E (0x05061A8E4B9E)

*May 24 18:42:12.323: ppp475 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:12.547: ppp472 LCP: O CONFREQ [REQsent] id 7 len 18

*May 24 18:42:12.547: ppp472 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:12.547: ppp472 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:12.547: ppp472 LCP: MagicNumber 0x1A8E449C (0x05061A8E449C)

*May 24 18:42:12.547: ppp472 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:12.547: ppp476 LCP: O CONFREQ [REQsent] id 4 len 18

*May 24 18:42:12.547: ppp476 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:12.547: ppp476 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:12.547: ppp476 LCP: MagicNumber 0x1A8E5C44 (0x05061A8E5C44)

*May 24 18:42:12.547: ppp476 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:14.339: ppp475 LCP: O CONFREQ [REQsent] id 7 len 18

*May 24 18:42:14.339: ppp475 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:14.339: ppp475 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:14.339: ppp475 LCP: MagicNumber 0x1A8E4B9E (0x05061A8E4B9E)

*May 24 18:42:14.339: ppp475 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:14.563: ppp472 LCP: O CONFREQ [REQsent] id 8 len 18

*May 24 18:42:14.563: ppp472 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:14.563: ppp472 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:14.563: ppp472 LCP: MagicNumber 0x1A8E449C (0x05061A8E449C)

*May 24 18:42:14.563: ppp472 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:14.563: ppp476 LCP: O CONFREQ [REQsent] id 5 len 18

*May 24 18:42:14.563: ppp476 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:14.563: ppp476 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:14.563: ppp476 LCP: MagicNumber 0x1A8E5C44 (0x05061A8E5C44)

*May 24 18:42:14.563: ppp476 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:16.355: ppp475 LCP: O CONFREQ [REQsent] id 8 len 18

*May 24 18:42:16.355: ppp475 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:16.355: ppp475 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:16.355: ppp475 LCP: MagicNumber 0x1A8E4B9E (0x05061A8E4B9E)

*May 24 18:42:16.355: ppp475 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:16.579: ppp472 LCP: O CONFREQ [REQsent] id 9 len 18

*May 24 18:42:16.579: ppp472 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:16.579: ppp472 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:16.579: ppp472 LCP: MagicNumber 0x1A8E449C (0x05061A8E449C)

*May 24 18:42:16.579: ppp472 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:16.579: ppp476 LCP: O CONFREQ [REQsent] id 6 len 18

*May 24 18:42:16.579: ppp476 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:16.579: ppp476 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:16.579: ppp476 LCP: MagicNumber 0x1A8E5C44 (0x05061A8E5C44)

*May 24 18:42:16.579: ppp476 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:18.371: ppp475 LCP: O CONFREQ [REQsent] id 9 len 18

*May 24 18:42:18.371: ppp475 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:18.371: ppp475 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:18.371: ppp475 LCP: MagicNumber 0x1A8E4B9E (0x05061A8E4B9E)

*May 24 18:42:18.371: ppp475 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:18.595: ppp472 LCP: O CONFREQ [REQsent] id 10 len 18

*May 24 18:42:18.595: ppp472 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:18.595: ppp472 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:18.595: ppp472 LCP: MagicNumber 0x1A8E449C (0x05061A8E449C)

*May 24 18:42:18.595: ppp472 LCP: Event[Timeout+] State[REQsent to REQsent]

*May 24 18:42:18.595: ppp476 LCP: O CONFREQ [REQsent] id 7 len 18

*May 24 18:42:18.595: ppp476 LCP: MRU 1492 (0x010405D4)

*May 24 18:42:18.595: ppp476 LCP: AuthProto PAP (0x0304C023)

*May 24 18:42:18.595: ppp476 LCP: MagicNumber 0x1A8E5C44 (0x05061A8E5C44)

*May 24 18:42:18.595: ppp476 LCP: Event[Timeout+] State[REQsent to REQsent]



As we handoff to the providers from the switch this one is connected to I
have very few ways of following the traffic to the other side, I can see
requests go out but they either don't make it to CPE or the response doesn't
make it back. Nothing has been changed networkwise in the last 3 months so
bit lost. Have rebooted the switch just in case as it has been a year or so,
but that just got more angry calls :)



CPE is just a simple modem on other side, no difference between working and
non working ones, BRAS is a 7204vxr with a G2. "core" switch is just a
simple 3560g






_______________________________________________
cisco-bba mailing list
cisco-bba@puck.nether.net <mailto:cisco-bba@puck.nether.net>
https://puck.nether.net/mailman/listinfo/cisco-bba

Can you get out to to a CEP to run debugs their too, that would be
really helpful to compare against the central debugs from your 7200.

So the logs you have given so far it sem's the LNS is not receiving
the response from the CPE, but maybe the CPE isn't receiving the
outbound packets in the first place. This would help narrow down the
problem domain.

Also if you do get to debug the CPE end, get more than just
negotiation "debug ppp nego; debug ppp authen; debug ppp packets;
debug ppp error; debug ppp subscr".

Cheers,
James.
_______________________________________________
cisco-bba mailing list
cisco-bba@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-bba

Hi James,

Debug PPP packets I tried yesterday, the 7200 then died a fast death and
required a reboot :) may have been because I had telnet in.

Turns out one of the providers could see mac addresses looping to them, and
we figured out the other provider has some issue in the network where
everything that goes out to them was coming back. As they are both in same
vlan I set switchport protected on both cross connects so they can't talk to
each other, issues on first provider disappeared. So now it's in the hands
of the other provider.

Still have customers out but at least it's not an unknown problem. I'll
see what reason they come up with.

-----Original Message-----
From: cisco-bba [mailto:cisco-bba-bounces@puck.nether.net] On Behalf Of
James Bensley
Sent: Wednesday, 25 May 2016 7:09 PM
To: cisco-bba@puck.nether.net
Subject: Re: [cisco-bba] LCP failing - any ideas?

Can you get out to to a CEP to run debugs their too, that would be really
helpful to compare against the central debugs from your 7200.

So the logs you have given so far it sem's the LNS is not receiving the
response from the CPE, but maybe the CPE isn't receiving the outbound
packets in the first place. This would help narrow down the problem domain.

Also if you do get to debug the CPE end, get more than just negotiation
"debug ppp nego; debug ppp authen; debug ppp packets; debug ppp error; debug
ppp subscr".

Cheers,
James.
_______________________________________________
cisco-bba mailing list
cisco-bba@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-bba
_______________________________________________
cisco-bba mailing list
cisco-bba@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-bba

Yeah debug ppp packet is for the CPE end only :)

Glad you got it sorted!

Cheers,
James.
_______________________________________________
cisco-bba mailing list
cisco-bba@puck.nether.net
https://puck.nether.net/mailman/listinfo/cisco-bba