03-30-2016 03:29 AM - edited 03-05-2019 03:40 AM
Hi
A remote backup router I look after went offline all of a sudden. I've took a look and its no PPP is not coming up correctly, although I can see from the debugs the provider is handing out the correct IP for the device
Where you see XXXXXXXXXXX in the debug that's the correct IP
It seems to fail with this output at the bottom of the debug
Mar 30 09:35:32.933: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.601: %DIALER-6-BIND: Interface Vi3 bound to profile Di1
Mar 30 09:35:32.605: %LINK-3-UPDOWN: Interface Virtual-Access3, changed state to up
Mar 30 09:35:32.605: Vi3 PPP: Sending cstate UP notification
Mar 30 09:35:32.605: Vi3 PPP: Processing CstateUp message
Mar 30 09:35:32.605: PPP: Alloc Context [870EFA04]
Mar 30 09:35:32.609: ppp514 PPP: Phase is ESTABLISHING
Mar 30 09:35:32.609: Vi3 PPP: Using dialer call direction
Mar 30 09:35:32.609: Vi3 PPP: Treating connection as a callout
Mar 30 09:35:32.609: Vi3 PPP: Session handle[1800003D] Session id[514]
Mar 30 09:35:32.609: Vi3 LCP: Event[OPEN] State[Initial to Starting]
Mar 30 09:35:32.609: Vi3 PPP: No remote authentication for call-out
Mar 30 09:35:32.609: Vi3 LCP: O CONFREQ [Starting] id 1 len 10
Mar 30 09:35:32.609: Vi3 LCP: MagicNumber 0x77C4711B (0x050677C4711B)
Mar 30 09:35:32.609: Vi3 LCP: Event[UP] State[Starting to REQsent]
Mar 30 09:35:32.629: Vi3 LCP: I CONFREQ [REQsent] id 1 len 18
Mar 30 09:35:32.629: Vi3 LCP: MRU 1500 (0x010405DC)
Mar 30 09:35:32.629: Vi3 LCP: AuthProto PAP (0x0304C023)
Mar 30 09:35:32.629: Vi3 LCP: MagicNumber 0x07449CAF (0x050607449CAF)
Mar 30 09:35:32.629: Vi3 LCP: O CONFACK [REQsent] id 1 len 18
Mar 30 09:35:32.629: Vi3 LCP: MRU 1500 (0x010405DC)
Mar 30 09:35:32.629: Vi3 LCP: AuthProto PAP (0x0304C023)
Mar 30 09:35:32.629: Vi3 LCP: MagicNumber 0x07449CAF (0x050607449CAF)
Mar 30 09:35:32.629: Vi3 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Mar 30 09:35:32.629: Vi3 LCP: I CONFACK [ACKsent] id 1 len 10
Mar 30 09:35:32.629: Vi3 LCP: MagicNumber 0x77C4711B (0x050677C4711B)
Mar 30 09:35:32.633: Vi3 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Mar 30 09:35:32.637: Vi3 PPP: Phase is AUTHENTICATING, by the peer
Mar 30 09:35:32.637: Vi3 PAP: Using hostname from interface PAP
Mar 30 09:35:32.637: Vi3 PAP: Using password from interface PAP
Mar 30 09:35:32.637: Vi3 PAP: O AUTH-REQ id 1 len 29 from XXXXXXXXXXXXXXXXXXXXX
Mar 30 09:35:32.637: Vi3 LCP: State is Open
Mar 30 09:35:32.841: Vi3 PAP: I AUTH-ACK id 1 len 5
Mar 30 09:35:32.841: Vi3 PPP: Phase is FORWARDING, Attempting Forward
Mar 30 09:35:32.841: Vi3 PPP: Phase is ESTABLISHING, Finish LCP
Mar 30 09:35:32.841: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access3, changed state to up
Mar 30 09:35:32.841: Vi3 PPP: No AAA accounting method list
Mar 30 09:35:32.841: Vi3 PPP: Phase is UP
Mar 30 09:35:32.841: Vi3 IPCP: Protocol configured, start CP. state[Initial]
Mar 30 09:35:32.841: Vi3 IPCP: Event[OPEN] State[Initial to Starting]
Mar 30 09:35:32.841: Vi3 IPCP: O CONFREQ [Starting] id 1 len 10
Mar 30 09:35:32.841: Vi3 IPCP: Address 0.0.0.0 (0x030600000000)
Mar 30 09:35:32.841: Vi3 IPCP: Event[UP] State[Starting to REQsent]
Mar 30 09:35:32.845: Vi3 CDPCP: Protocol configured, start CP. state[Initial]
Mar 30 09:35:32.845: Vi3 CDPCP: Event[OPEN] State[Initial to Starting]
Mar 30 09:35:32.845: Vi3 CDPCP: O CONFREQ [Starting] id 1 len 4
Mar 30 09:35:32.845: Vi3 CDPCP: Event[UP] State[Starting to REQsent]
Mar 30 09:35:32.845: Vi3 IPCP: I CONFREQ [REQsent] id 1 len 10
Mar 30 09:35:32.845: Vi3 IPCP: Address XXXXXXXXXXXX (0x0306506B6CF1)
Mar 30 09:35:32.845: Vi3 IPCP: O CONFACK [REQsent] id 1 len 10
Mar 30 09:35:32.845: Vi3 IPCP: Address XXXXXXXXXXXXXX (0x0306506B6CF1)
Mar 30 09:35:32.845: Vi3 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Mar 30 09:35:32.865: Vi3 IPCP: I CONFNAK [ACKsent] id 1 len 10
Mar 30 09:35:32.865: Vi3 IPCP: Address XXXXXXXXXXXXXXX (0x03065E46F41C)
Mar 30 09:35:32.865: Vi3 IPCP: O CONFREQ [ACKsent] id 2 len 10
Mar 30 09:35:32.865: Vi3 IPCP: Address XXXXXXXXXXXXX (0x03065E46F41C)
Mar 30 09:35:32.865: Vi3 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Mar 30 09:35:32.889: Vi3 IPCP: I CONFACK [ACKsent] id 2 len 10
Mar 30 09:35:32.889: Vi3 IPCP: Address XXXXXXXXXXXXXXXXX (0x03065E46F41C)
Mar 30 09:35:32.889: Vi3 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
Mar 30 09:35:32.893: Vi3 IPCP: State is Open
Mar 30 09:35:32.893: Di1 IPCP: Install negotiated IP interface address XXXXXXXXXXXXXXXXX
Mar 30 09:35:32.893: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to up
Mar 30 09:35:32.901: Di1 IPCP: Install default route thru 80.107.108.241
Mar 30 09:35:32.901: Di1 Added to neighbor route AVL tree: topoid 0, address 80.107.108.241
Mar 30 09:35:32.901: Di1 IPCP: Install route to 80.107.108.241
Mar 30 09:35:32.905: Vi3 IPCP: I CONFREQ [Open] id 2 len 10
Mar 30 09:35:32.905: Vi3 IPCP: Address 80.107.108.241 (0x0306506B6CF1)
Mar 30 09:35:32.905: Vi3 IPCP: O CONFREQ [Open] id 3 len 10
Mar 30 09:35:32.905: Vi3 IPCP: Address 0.0.0.0 (0x030600000000)
Mar 30 09:35:32.905: Vi3 IPCP: O CONFACK [Open] id 2 len 10
Mar 30 09:35:32.905: Vi3 IPCP: Address 80.107.108.241 (0x0306506B6CF1)
Mar 30 09:35:32.905: Vi3 IPCP: Event[Receive ConfReq+] State[Open to ACKsent]
Mar 30 09:35:32.917: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.921: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.929: Vi3 IPCP: I CONFNAK [ACKsent] id 3 len 10
Mar 30 09:35:32.929: Vi3 IPCP: Address 94.70.244.28 (0x03065E46F41C)
Mar 30 09:35:32.929: Vi3 IPCP: O CONFREQ [ACKsent] id 4 len 10
Mar 30 09:35:32.929: Vi3 IPCP: Address 94.70.244.28 (0x03065E46F41C)
Mar 30 09:35:32.929: Vi3 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Mar 30 09:35:32.933: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.933: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.937: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel1, changed state to down
Mar 30 09:35:32.937: Di1 Deleted neighbor route from AVL tree: topoid 0, address 80.107.108.241
Mar 30 09:35:32.937: Di1 IPCP: Remove route to 80.107.108.241
Mar 30 09:35:32.937: Di1 IPCP: Remove default route thru 80.107.108.241
Relevant config
interface Vlan
no ip address
pppoe enable group global
pppoe-client dial-pool-number 1
end
interface Dialer1
ip address negotiated
ip access-group OUTSIDE-IN in
no ip redirects
no ip unreachables
no ip proxy-arp
ip nat outside
ip inspect fw out
ip virtual-reassembly in
encapsulation ppp
dialer pool 1
dialer idle-timeout 0
dialer persistent
dialer-group 1
ppp authentication chap pap callin
ppp chap hostname XXXXXXXXXX
ppp chap password 7 031C4E46090E7045
ppp pap sent-username XXXXXXXXX
ppp ipcp route default
end
Thanks
03-30-2016 06:03 AM
Hi
The NCP is the layer 3 negotiation , try without the callin in case ISP changed something there side and then re-apply it as its usually required with ipcp
what version software are you on looks to be a known bug with that output too but if it was working before it m,ay not be that , as well I would try add under vlan int ip tcp adjust-mss 1452 and ip mtu 1492 under dialer as its pppoe
https://bst.cloudapps.cisco.com/bugsearch/bug/CSCee19119/?referring_site=bugquickviewredir
I would remove ip inspect as well from the interface in case itrs having an adverse effect on L3 negotiation , put it back on after its fixed
03-30-2016 06:42 AM
Mark
Thanks for the response
I did modify the MTU earlier and bounced the interface, but same result
Now tried it with MTU and MSS and but not coming up
With IP Inspect removed and callin present and not present still getting the same output on the debug
The router is running c880data-universalk9-mz.152-4.M3.bin, it wouldn't be too much hassle to try a different IOS though
Thanks
03-30-2016 07:12 AM
That ios is an ED but still if it was working before im hesitant to think its ios issue but you never know if something got triggered in software , if you do try switch just to see go to an MD release better chance of the bug not being there if its is one , safe harbour version is bets choice star beside the image
Have you checked with the ISP providing the service just in case they have changed something ? or are having issues on their end , the negotiation could be failing at the end from their peer , the reason I say this is this line is last then it fails ----
Mar 30 09:35:32.929: Vi3 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Its like you get the address but the get another one
Mar 30 09:35:32.905: Vi3 IPCP: Address 80.107.108.241 (0x0306506B6CF1)
Mar 30 09:35:32.905: Vi3 IPCP: Event[Receive ConfReq+] State[Open to ACKsent]
Mar 30 09:35:32.917: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.921: Vi3 PPP: Outbound ip packet dropped, NCP not negotiated
Mar 30 09:35:32.929: Vi3 IPCP: I CONFNAK [ACKsent] id 3 len 10
Mar 30 09:35:32.929: Vi3 IPCP: Address 94.70.244.28 (0x03065E46F41C)
ConfNak
If the received configuration option is recognizable and acceptable, but some value is not acceptable, the router transmits a CONFNAK message. The router appends the option and value that it can accept in the CONFNAK message so that the peer can include that option in the next CONFREQ message.
03-30-2016 08:08 AM
thanks I will look into it further
Regarding the 2 address's coming in, I thought that was the router/ISP sorting out which will be the interface IP, and which will be gateway to be used due to the ipcp route default command?
thanks
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide