Problem with ADSL and 3G backup route

mikebunton · ‎01-26-2012

Hi,

I have a problem with my ADSL and 3g backup routing.

The router has the ADSL and 3G connections available on bootup.
The router uses the ADSL as the first choice and then the 3G when the ADSL is down.
This part is working correctly.

When the ADSL line comes back the routing table doesn't get
populated with a new route using the ADSL so I'm unable to ping out to the internet.
There are no static routes set up (apart from default 0.0.0.0 routes) as the ip addresses
to the ISP are dynamic.

Does anyone have any ideas on how to get this going?

I'm using a track for the ATM line-protocol connection as using the IP SLA with icmp echo
doesn't seem to work (it takes the router around 40 seconds to bring up the ADSL connection).

The track 1 interface ATM0/0/0 line-protocol does seem to work for me.

The cards I have are:
EHWIC-VA-DSL-A
EHWIC-3G-HSPA+7

SM-ES3G-24-P

Router is a 2921 running 15.1.4(M3)

______________________________________________________________________________________________________________________

Building configuration...

Current configuration : 3617 bytes
!
! Last configuration change at 20:47:20 UTC Thu Jan 26 2012
! NVRAM config last updated at 20:48:01 UTC Thu Jan 26 2012
! NVRAM config last updated at 20:48:01 UTC Thu Jan 26 2012
version 15.1
service timestamps debug datetime msec
service timestamps log datetime msec
no service password-encryption
!
hostname Router
!
boot-start-marker
boot-end-marker
!
!
!
no aaa new-model
!
!
no ipv6 cef
ip source-route
ip cef
!
!
!
!
!
no ip domain lookup
!
multilink bundle-name authenticated
!
!
chat-script hspa "" "AT!SCACT=1,1" TIMEOUT 25 "OK"
crypto pki token default removal timeout 0
!
!
license udi pid CISCO2921/K9 sn FGL152212CA
hw-module sm 1
!
!
!
!
redundancy
!
!
!
!
controller Cellular 0/1
!
controller VDSL 0/0/0
!
!
track 1 interface ATM0/0/0 line-protocol
!
!
!
!
!
!
!
interface Embedded-Service-Engine0/0
no ip address
shutdown
!
interface GigabitEthernet0/0
no ip address
shutdown
duplex auto
speed auto
!
interface GigabitEthernet0/1
no ip address
shutdown
duplex auto
speed auto
!
interface GigabitEthernet0/2
no ip address
shutdown
duplex auto
speed auto
!
interface ATM0/0/0
description ADSL
no ip address
no ip redirects
no ip unreachables
no ip proxy-arp
ip flow ingress
ip nat outside
ip virtual-reassembly in
no atm ilmi-keepalive
pvc 0/100
encapsulation aal5mux ppp dialer
dialer pool-member 1
!
!
interface Ethernet0/0/0
no ip address
shutdown
no fair-queue
!
interface GigabitEthernet1/0
ip address 192.168.10.1 255.255.255.0
!
interface GigabitEthernet1/0.1
encapsulation dot1Q 10
ip address 192.168.4.1 255.255.255.0
ip nat inside
ip virtual-reassembly in
!
interface GigabitEthernet1/1
description Internal switch interface connected to EtherSwitch Service Module
no ip address
!
interface Cellular0/1/0
ip address negotiated
ip nat outside
ip virtual-reassembly in
encapsulation slip
dialer in-band
dialer pool-member 1
dialer-group 1
async mode interactive
!
interface Cellular0/1/1
no ip address
encapsulation slip
!
interface Vlan1
no ip address
!
interface Dialer1
description ADSL
ip address negotiated
no ip redirects
no ip unreachables
no ip proxy-arp
ip flow ingress
ip flow egress
ip nat outside
ip virtual-reassembly in
encapsulation ppp
no ip route-cache same-interface
no ip route-cache cef
dialer pool 1
dialer-group 1
ppp authentication chap pap callin
ppp chap hostname REMOVED
ppp chap password 7 09585B0C0A01160B5B5D
ppp direction callout
ppp pap sent-username REMOVED password REMOVED
ppp timeout authentication 5
no cdp enable
!
interface Dialer2
description 3G
ip address negotiated
ip nat outside
ip virtual-reassembly in
encapsulation slip
dialer pool 1
dialer string hspa
dialer-group 1
no fair-queue
!
ip forward-protocol nd
!
no ip http server
no ip http secure-server
!
ip route 0.0.0.0 0.0.0.0 Dialer1 track 1
ip route 0.0.0.0 0.0.0.0 Dialer2 200
!
access-list 1 permit any
dialer-list 1 protocol ip permit
!
!
!
!
!
!
control-plane
!
!
!
line con 0
line aux 0
line 2
no activation-character
no exec
transport preferred none
transport input all
transport output pad telnet rlogin lapb-ta mop udptn v120 ssh
stopbits 1
line 0/1/0
script dialer hspa
modem InOut
no exec
transport input all
rxspeed 21600000
txspeed 5760000
line 0/1/1
no exec
line 67
no activation-character
no exec
transport preferred none
transport input all
transport output pad telnet rlogin lapb-ta mop udptn v120 ssh
stopbits 1
flowcontrol software
line vty 0 4
login
transport input all
!
scheduler allocate 20000 1000
end

______________________________________________________________________________

POWERED ROUTER ON - ADSL TO TAKE PREFERENCE (THIS WORKS CORRECTLY)

Router#sho track
Track 1
Interface ATM0/0/0 line-protocol
Line protocol is Up
2 changes, last change 00:00:17
Tracked by:
STATIC-IP-ROUTING 0

Router#sho ip route
Codes: L - local, C - connected, S - static, R - RIP, M - mobile, B - BGP
       D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2
       ia - IS-IS inter area, * - candidate default, U - per-user static route
       o - ODR, P - periodic downloaded static route, H - NHRP, l - LISP
       + - replicated route, % - next hop override

Gateway of last resort is 0.0.0.0 to network 0.0.0.0

S*    0.0.0.0/0 is directly connected, Dialer1
      122.0.0.0/32 is subnetted, 2 subnets
C        122.59.232.1 is directly connected, Dialer1
C        122.59.238.242 is directly connected, Dialer1
      192.168.4.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.4.0/24 is directly connected, GigabitEthernet1/0.1
L        192.168.4.1/32 is directly connected, GigabitEthernet1/0.1
      192.168.10.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.10.0/24 is directly connected, GigabitEthernet1/0
L        192.168.10.1/32 is directly connected, GigabitEthernet1/0
Router#

_________________________________________________________________________________

PULLED OUT ADSL CONNECTION TO SIMULATE ADSL GOING DOWN - 3G TO TAKE OVER (THIS WORKS CORRECTLY)

Router#sho track
Track 1
Interface ATM0/0/0 line-protocol
Line protocol is Down (hw down)
3 changes, last change 00:00:21
Tracked by:
STATIC-IP-ROUTING 0

Router#sho ip route
Codes: L - local, C - connected, S - static, R - RIP, M - mobile, B - BGP
       D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2
       ia - IS-IS inter area, * - candidate default, U - per-user static route
       o - ODR, P - periodic downloaded static route, H - NHRP, l - LISP
       + - replicated route, % - next hop override

Gateway of last resort is 0.0.0.0 to network 0.0.0.0

S*    0.0.0.0/0 is directly connected, Dialer2
      192.168.4.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.4.0/24 is directly connected, GigabitEthernet1/0.1
L        192.168.4.1/32 is directly connected, GigabitEthernet1/0.1
      192.168.10.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.10.0/24 is directly connected, GigabitEthernet1/0
L        192.168.10.1/32 is directly connected, GigabitEthernet1/0
Router#ping 4.2.2.2
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 4.2.2.2, timeout is 2 seconds:
..
Jan 26 21:11:05.363: %LINK-3-UPDOWN: Interface Cellular0/1/0, changed state to up.
Jan 26 21:11:05.363: %DIALER-6-BIND: Interface Ce0/1/0 bound to profile Di2
Jan 26 21:11:06.363: %LINEPROTO-5-UPDOWN: Line protocol on Interface Cellular0/1/0, changed state to up!!
Success rate is 40 percent (2/5), round-trip min/avg/max = 240/270/300 ms
Router#ping 4.2.2.2
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 4.2.2.2, timeout is 2 seconds:
!!!!!
Success rate is 100 percent (5/5), round-trip min/avg/max = 240/266/360 ms

Router#sho ip route
Codes: L - local, C - connected, S - static, R - RIP, M - mobile, B - BGP
       D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2
       ia - IS-IS inter area, * - candidate default, U - per-user static route
       o - ODR, P - periodic downloaded static route, H - NHRP, l - LISP
       + - replicated route, % - next hop override

Gateway of last resort is 0.0.0.0 to network 0.0.0.0

S*    0.0.0.0/0 is directly connected, Dialer2
      122.0.0.0/32 is subnetted, 1 subnets
C        122.63.155.132 is directly connected, Dialer2
      192.168.4.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.4.0/24 is directly connected, GigabitEthernet1/0.1
L        192.168.4.1/32 is directly connected, GigabitEthernet1/0.1
      192.168.10.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.10.0/24 is directly connected, GigabitEthernet1/0
L        192.168.10.1/32 is directly connected, GigabitEthernet1/0
Router#

________________________________________________________________________________

PLUGGED IN ADSL TO SIMULATE CONNECTION COMING BACK UP - ASDL TO TAKE OVER FROM 3G (THIS DOESN'T WORK)

Router#sho track
Track 1
Interface ATM0/0/0 line-protocol
Line protocol is Up
4 changes, last change 00:00:14
Tracked by:
STATIC-IP-ROUTING 0
Router#

Router#sho ip route
Codes: L - local, C - connected, S - static, R - RIP, M - mobile, B - BGP
       D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2
       ia - IS-IS inter area, * - candidate default, U - per-user static route
       o - ODR, P - periodic downloaded static route, H - NHRP, l - LISP
       + - replicated route, % - next hop override

Gateway of last resort is 0.0.0.0 to network 0.0.0.0

S*    0.0.0.0/0 is directly connected, Dialer1
      122.0.0.0/32 is subnetted, 1 subnets
C        122.63.155.132 is directly connected, Dialer2
      192.168.4.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.4.0/24 is directly connected, GigabitEthernet1/0.1
L        192.168.4.1/32 is directly connected, GigabitEthernet1/0.1
      192.168.10.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.10.0/24 is directly connected, GigabitEthernet1/0
L        192.168.10.1/32 is directly connected, GigabitEthernet1/0
Router#ping 4.2.2.2
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 4.2.2.2, timeout is 2 seconds:
.....
Success rate is 0 percent (0/5)
Router#

After a short time the Cellular interface goes down and the route to dialer 2 is removed from the routing table.

Router#sho ip ro
Jan 26 21:15:47.467: %LINK-3-UPDOWN: Interface Cellular0/1/0, changed state to downute
Codes: L - local, C - connected, S - static, R - RIP, M - mobile, B - BGP
       D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2
       ia - IS-IS inter area, * - candidate default, U - per-user static route
       o - ODR, P - periodic downloaded static route, H - NHRP, l - LISP
       + - replicated route, % - next hop override

Gateway of last resort is 0.0.0.0 to network 0.0.0.0

S*    0.0.0.0/0 is directly connected, Dialer1
      192.168.4.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.4.0/24 is directly connected, GigabitEthernet1/0.1
L        192.168.4.1/32 is directly connected, GigabitEthernet1/0.1
      192.168.10.0/24 is variably subnetted, 2 subnets, 2 masks
C        192.168.10.0/24 is directly connected, GigabitEthernet1/0
L        192.168.10.1/32 is directly connected, GigabitEthernet1/0
Router#ping 4.2.2.2
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 4.2.2.2, timeout is 2 seconds:
.....
Success rate is 0 percent (0/5)

Many thanks for your help.

Mike

mavespig · ‎01-27-2012

Hi Mike,

I don't think that SLA is at fault here. When the DSL link comes back up, you can see that 'show track' reports is up, and that the default route correctly points to dia1.

It seems that the dialer interface is not getting an IP address, after the link comes back up. Originally it has a dynamic IP 122.59.238.242, but where it comes back up there is no entry in the routing table.

When the line is back up, do you see an IP assigned in 'show int dia 1'?

Can you enable deb ppp negotiation, and see if IPCP is correctly negotiated?

Hope this helps

Marco

mikebunton · ‎01-29-2012

Hi Marco,

Thanks for your reply.

I've turned on the PPP neg and see that the IPCP isn't negotiating correctly which would mean there is no IP address assigned to the dialer 1 interface.

I've put the traces in below and also the 'working' PPP neg trace from when the router boots up with the ADSL connected.

Would you know why the IPCP doesn't negotiate correctly?

I've just tried booting the router with the ADSL disconnected and the 3G works fine.

Plug in the ADSL and the ADSL takes first preference - works fine.

Disconnect ADSL and 3G takes over - works fine.

Plug in ADSL and it doesn't work!!

____________________________________________________________________________________________________________________

PPP protocol negotiation debugging is on
Router#
Router#
Router#
Jan 29 19:31:15.207: %CONTROLLER-5-UPDOWN: Controller VDSL 0/0/0, changed state to up
Jan 29 19:31:23.955: %TRACKING-5-STATE: 1 interface AT0/0/0 line-protocol Down->Up
Jan 29 19:31:25.083: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to up
Jan 29 19:31:26.083: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0/0/0, changed state to up
Jan 29 19:31:32.899: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
Jan 29 19:31:32.899: Vi2 PPP: Sending cstate UP notification
Jan 29 19:31:32.899: Vi2 PPP: Processing CstateUp message
Jan 29 19:31:32.899: PPP: Alloc Context [30994234]
Jan 29 19:31:32.899: ppp2 PPP: Phase is ESTABLISHING
Jan 29 19:31:32.899: Vi2 PPP: Using configured call direction
Jan 29 19:31:32.899: Vi2 PPP: Treating connection as a callout
Jan 29 19:31:32.899: Vi2 PPP: Session handle[DE000002] Session id[2]
Jan 29 19:31:32.899: Vi2 LCP: Event[OPEN] State[Initial to Starting]
Jan 29 19:31:32.899: Vi2 PPP: No remote authentication for call-out
Jan 29 19:31:32.899: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
Jan 29 19:31:32.899: Vi2 LCP:    MagicNumber 0x0782C29D (0x05060782C29D)
Jan 29 19:31:32.899: Vi2 LCP: Event[UP] State[Starting to REQsent]
Jan 29 19:31:32.959: Vi2 LCP: I CONFREQ [REQsent] id 198 len 18
Jan 29 19:31:32.959: Vi2 LCP:    MRU 1500 (0x010405DC)
Jan 29 19:31:32.959: Vi2 LCP:    AuthProto PAP (0x0304C023)
Jan 29 19:31:32.959: Vi2 LCP:    MagicNumber 0x1445EBED (0x05061445EBED)
Jan 29 19:31:32.959: Vi2 LCP: O CONFACK [REQsent] id 198 len 18
Jan 29 19:31:32.959: Vi2 LCP:    MRU 1500 (0x010405DC)
Jan 29 19:31:32.959: Vi2 LCP:    AuthProto PAP (0x0304C023)
Jan 29 19:31:32.959: Vi2 LCP:    MagicNumber 0x1445EBED (0x05061445EBED)
Jan 29 19:31:32.959: Vi2 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Jan 29 19:31:32.959: Vi2 LCP: I CONFACK [ACKsent] id 1 len 10
Jan 29 19:31:32.959: Vi2 LCP:    MagicNumber 0x0782C29D (0x05060782C29D)
Jan 29 19:31:32.959: Vi2 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Jan 29 19:31:32.979: Vi2 PPP: Phase is AUTHENTICATING, by the peer
Jan 29 19:31:32.979: Vi2 PAP: Using hostname from interface PAP
Jan 29 19:31:32.979: Vi2 PAP: Using password from interface PAP
Jan 29 19:31:32.979: Vi2 PAP: O AUTH-REQ id 1 len 39 from "REMOVED CUSTOMER USERNAME"
Jan 29 19:31:32.979: Vi2 LCP: State is Open
Jan 29 19:31:32.987: Vi2 PAP: I AUTH-ACK id 1 len 13 msg is "Login ok"
Jan 29 19:31:32.987: Vi2 PPP: Phase is FORWARDING, Attempting Forward
Jan 29 19:31:32.991: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
Jan 29 19:31:32.991: Vi2 PPP: Phase is UP
Jan 29 19:31:32.991: Vi2 IPCP: I CONFREQ [UNKNOWN] id 88 len 10
Jan 29 19:31:32.991: Vi2 IPCP:    Address 122.59.232.1 (0x03067A3BE801)
Jan 29 19:31:32.991: Vi2 LCP: O PROTREJ [Open] id 2 len 16 protocol IPCP (0x0158000C03067A3BE801)
Jan 29 19:31:32.995: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
Router#

_________________________________________________________________________________________________________

Router#sho int dial 1
Dialer1 is up, line protocol is up (spoofing)
Hardware is Unknown
Description: ADSL Dialer 1
Internet address will be negotiated using IPCP
MTU 1500 bytes, BW 56 Kbit/sec, DLY 20000 usec,
     reliability 255/255, txload 1/255, rxload 1/255
Encapsulation PPP, LCP Closed, loopback not set
Keepalive set (10 sec)
DTR is pulsed for 1 seconds on reset
Last input never, output never, output hang never
Last clearing of "show interface" counters 00:07:21
Input queue: 0/75/0/0 (size/max/drops/flushes); Total output drops: 0
Queueing strategy: weighted fair
Output queue: 0/1000/64/0 (size/max total/threshold/drops)
     Conversations 0/0/16 (active/max active/max total)
     Reserved Conversations 0/0 (allocated/max allocated)
     Available Bandwidth 42 kilobits/sec
5 minute input rate 0 bits/sec, 0 packets/sec
5 minute output rate 0 bits/sec, 0 packets/sec
     5 packets input, 510 bytes
     10 packets output, 580 bytes
Router#

_______________________________________________________________________________________________________

Normal 'working' PPP Neg

Router#debug ppp neg
PPP protocol negotiation debugging is on
Router#
Jan 29 19:41:33.835: %CONTROLLER-5-UPDOWN: Controller VDSL 0/0/0, changed state to up
Jan 29 19:41:39.747: %TRACKING-5-STATE: 1 interface AT0/0/0 line-protocol Down->Up
Jan 29 19:41:41.071: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to up
Jan 29 19:41:42.071: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0/0/0, changed state to up
Jan 29 19:41:49.919: %DIALER-6-BIND: Interface Vi2 bound to profile Di1
Jan 29 19:41:49.923: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
Jan 29 19:41:49.923: Vi2 PPP: Sending cstate UP notification
Jan 29 19:41:49.923: Vi2 PPP: Processing CstateUp message
Jan 29 19:41:49.931: PPP: Alloc Context [2AC662B4]
Jan 29 19:41:49.931: ppp1 PPP: Phase is ESTABLISHING
Jan 29 19:41:49.931: Vi2 PPP: Using configured call direction
Jan 29 19:41:49.931: Vi2 PPP: Treating connection as a callout
Jan 29 19:41:49.931: Vi2 PPP: Session handle[6E000001] Session id[1]
Jan 29 19:41:49.931: Vi2 LCP: Event[OPEN] State[Initial to Starting]
Jan 29 19:41:49.931: Vi2 PPP: No remote authentication for call-out
Jan 29 19:41:49.931: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
Jan 29 19:41:49.931: Vi2 LCP:    MagicNumber 0x077F6AAB (0x0506077F6AAB)
Jan 29 19:41:49.931: Vi2 LCP: Event[UP] State[Starting to REQsent]
Jan 29 19:41:49.991: Vi2 LCP: I CONFACK [REQsent] id 1 len 10
Jan 29 19:41:49.991: Vi2 LCP:    MagicNumber 0x077F6AAB (0x0506077F6AAB)
Jan 29 19:41:49.991: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
Jan 29 19:41:51.943: Vi2 LCP: O CONFREQ [ACKrcvd] id 2 len 10
Jan 29 19:41:51.943: Vi2 LCP:    MagicNumber 0x077F6AAB (0x0506077F6AAB)
Jan 29 19:41:51.943: Vi2 LCP: Event[Timeout+] State[ACKrcvd to REQsent]
Jan 29 19:41:51.951: Vi2 LCP: I CONFACK [REQsent] id 2 len 10
Jan 29 19:41:51.951: Vi2 LCP:    MagicNumber 0x077F6AAB (0x0506077F6AAB)
Jan 29 19:41:51.951: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
Jan 29 19:41:52.699: Vi2 LCP: I CONFREQ [ACKrcvd] id 85 len 18
Jan 29 19:41:52.699: Vi2 LCP:    MRU 1500 (0x010405DC)
Jan 29 19:41:52.699: Vi2 LCP:    AuthProto PAP (0x0304C023)
Jan 29 19:41:52.699: Vi2 LCP:    MagicNumber 0x527282D9 (0x0506527282D9)
Jan 29 19:41:52.699: Vi2 LCP: O CONFACK [ACKrcvd] id 85 len 18
Jan 29 19:41:52.699: Vi2 LCP:    MRU 1500 (0x010405DC)
Jan 29 19:41:52.699: Vi2 LCP:    AuthProto PAP (0x0304C023)
Jan 29 19:41:52.699: Vi2 LCP:    MagicNumber 0x527282D9 (0x0506527282D9)
Jan 29 19:41:52.699: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
Jan 29 19:41:52.711: Vi2 PPP: Phase is AUTHENTICATING, by the peer
Jan 29 19:41:52.711: Vi2 PAP: Using hostname from interface PAP
Jan 29 19:41:52.711: Vi2 PAP: Using password from interface PAP
Jan 29 19:41:52.711: Vi2 PAP: O AUTH-REQ id 1 len 39 from "REMOVED CUSTOMER USERNAME"
Jan 29 19:41:52.711: Vi2 LCP: State is Open
Jan 29 19:41:52.723: Vi2 PAP: I AUTH-ACK id 1 len 13 msg is "Login ok"
Jan 29 19:41:52.723: Vi2 PPP: Phase is FORWARDING, Attempting Forward
Jan 29 19:41:52.723: Vi2 PPP: Queue IPCP code[1] id[91]
Jan 29 19:41:52.723: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
Jan 29 19:41:52.723: Vi2 PPP: Phase is UP
Jan 29 19:41:52.723: Vi2 IPCP: Protocol configured, start CP. state[Initial]
Jan 29 19:41:52.723: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
Jan 29 19:41:52.723: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
Jan 29 19:41:52.723: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
Jan 29 19:41:52.723: Vi2 IPCP: Event[UP] State[Starting to REQsent]
Jan 29 19:41:52.723: Vi2 PPP: Process pending ncp packets
Jan 29 19:41:52.723: Vi2 IPCP: Redirect packet to Vi2
Jan 29 19:41:52.723: Vi2 IPCP: I CONFREQ [REQsent] id 91 len 10
Jan 29 19:41:52.723: Vi2 IPCP:    Address 122.59.232.1 (0x03067A3BE801)
Jan 29 19:41:52.723: Vi2 IPCP: O CONFACK [REQsent] id 91 len 10
Jan 29 19:41:52.723: Vi2 IPCP:    Address 122.59.232.1 (0x03067A3BE801)
Jan 29 19:41:52.723: Vi2 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Jan 29 19:41:52.727: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
Jan 29 19:41:52.799: Vi2 IPCP: I CONFNAK [ACKsent] id 1 len 10
Jan 29 19:41:52.799: Vi2 IPCP:    Address 122.59.238.242 (0x03067A3BEEF2)
Jan 29 19:41:52.799: Vi2 IPCP: O CONFREQ [ACKsent] id 2 len 10
Jan 29 19:41:52.799: Vi2 IPCP:    Address 122.59.238.242 (0x03067A3BEEF2)
Jan 29 19:41:52.799: Vi2 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Jan 29 19:41:52.811: Vi2 IPCP: I CONFACK [ACKsent] id 2 len 10
Jan 29 19:41:52.811: Vi2 IPCP:    Address 122.59.238.242 (0x03067A3BEEF2)
Jan 29 19:41:52.811: Vi2 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
Jan 29 19:41:52.839: Vi2 IPCP: State is Open
Jan 29 19:41:52.839: Di1 IPCP: Install negotiated IP interface address 122.59.238.242
Jan 29 19:41:52.839: Di1 Added to neighbor route AVL tree: topoid 0, address 122.59.232.1
Jan 29 19:41:52.839: Di1 IPCP: Install route to 122.59.232.1
Router#

Any further comments or discussion is much appreciated.

Regards,

Mike

mavespig · ‎01-31-2012

Hi Mike,

That's a good test, now we know that SLA works fine, but since the dialer can't get an IP, the router can't forward traffic.

It's interesting that ISP starts the IPCP negotiation, but the router rejects it:

Jan 29 19:31:32.991: Vi2 IPCP: I CONFREQ [UNKNOWN] id 88 len 10

Jan 29 19:31:32.991: Vi2 IPCP: Address 122.59.232.1 (0x03067A3BE801)

Jan 29 19:31:32.991: Vi2 LCP: O PROTREJ [Open] id 2 len 16 protocol IPCP (0x0158000C03067A3BE801)

A few questions:

- Instead of disconnecting the cable, try to shut/no shut the interface. Can the dialer get an IP now?

- If you remove completely SLA configuration, and disconnect/reconnect the cable, does the dialer get the IP?

- which IOS are you using?

Thanks

Marco

mikebunton · ‎01-31-2012

Hi Marco,

I've removed the track, shut down cell interface, shut down dialer 2, removed the route that uses dialer 2 and I've cleared the routing and cef tables

So we are now only using the ASDL connection.

When I shut/no shut the vdsl controller I still get the same IPCP problem.

I was running 15.1.4(M3) so upgraded to 15.2.2T to see if that made any difference but still the same issue.

Here is my lastest trace:

Router(config)#controller vdSL 0/0/0

Router(config-controller)#shut

Router(config-controller)#

Jan 31 22:26:13.931: %CONTROLLER-5-UPDOWN: Controller VDSL 0/0/0, changed state to administratively down

Jan 31 22:26:16.455: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to down

Jan 31 22:26:17.455: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0/0/0, changed state to down

Jan 31 22:26:17.651: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down

Jan 31 22:26:17.651: Vi2 PPP DISC: Authentication configuration changed

Jan 31 22:26:17.651: PPP: NET STOP send to AAA.

Jan 31 22:26:17.651: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di1

Jan 31 22:26:17.651: Vi2 PPP: Sending cstate DOWN notification

Jan 31 22:26:17.651: Di1 Deleted neighbor route from AVL tree: topoid 0, address 122.59.232.1

Jan 31 22:26:17.651: Di1 IPCP: Remove route to 122.59.232.1

Jan 31 22:26:17.651: Vi2 IPCP: Event[DOWN] State[Open to Starting]

Jan 31 22:26:17.651: Vi2 IPCP: Event[CLOSE] State[Starting to Initial]

Jan 31 22:26:17.651: Vi2 LCP: Event[DOWN] State[Open to Starting]

Jan 31 22:26:17.651: Vi2 PPP: Phase is DOWN

Jan 31 22:26:17.651: Vi2 PPP: Processing CstateDown message

Jan 31 22:26:17.655: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to down

Router(config-controller)#

Router(config-controller)#no shut

Router(config-controller)#

Jan 31 22:27:37.635: %CONTROLLER-5-UPDOWN: Controller VDSL 0/0/0, changed state to up

Jan 31 22:27:46.467: %LINK-3-UPDOWN: Interface ATM0/0/0, changed state to up

Jan 31 22:27:47.467: %LINEPROTO-5-UPDOWN: Line protocol on Interface ATM0/0/0, changed state to up

Jan 31 22:27:50.375: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up

Jan 31 22:27:50.375: Vi2 PPP: Sending cstate UP notification

Jan 31 22:27:50.375: Vi2 PPP: Processing CstateUp message

Jan 31 22:27:50.375: PPP: Alloc Context [30B35B24]

Jan 31 22:27:50.375: ppp2 PPP: Phase is ESTABLISHING

Jan 31 22:27:50.375: Vi2 PPP: Using configured call direction

Jan 31 22:27:50.375: Vi2 PPP: Treating connection as a callout

Jan 31 22:27:50.375: Vi2 PPP: Session handle[A9000002] Session id[2]

Jan 31 22:27:50.375: Vi2 LCP: Event[OPEN] State[Initial to Starting]

Jan 31 22:27:50.375: Vi2 PPP: No remote authentication for call-out

Jan 31 22:27:50.375: Vi2 LCP: O CONFREQ [Starting] id 1 len 10

Jan 31 22:27:50.375: Vi2 LCP: MagicNumber 0x078F1585 (0x0506078F1585)

Jan 31 22:27:50.375: Vi2 LCP: Event[UP] State[Starting to REQsent]

Jan 31 22:27:50.387: Vi2 LCP: I TERMREQ [REQsent] id 120 len 4

Jan 31 22:27:50.387: Vi2 LCP: O TERMACK [REQsent] id 120 len 4

Jan 31 22:27:50.387: Vi2 LCP: Event[Receive TermReq] State[REQsent to REQsent]

Jan 31 22:27:52.379: Vi2 LCP: O CONFREQ [REQsent] id 2 len 10

Jan 31 22:27:52.379: Vi2 LCP: MagicNumber 0x078F1585 (0x0506078F1585)

Jan 31 22:27:52.379: Vi2 LCP: Event[Timeout+] State[REQsent to REQsent]

Jan 31 22:27:52.439: Vi2 LCP: I CONFREQ [REQsent] id 242 len 18

Jan 31 22:27:52.439: Vi2 LCP: MRU 1500 (0x010405DC)

Jan 31 22:27:52.439: Vi2 LCP: AuthProto PAP (0x0304C023)

Jan 31 22:27:52.439: Vi2 LCP: MagicNumber 0x136B8077 (0x0506136B8077)

Jan 31 22:27:52.439: Vi2 LCP: O CONFACK [REQsent] id 242 len 18

Jan 31 22:27:52.439: Vi2 LCP: MRU 1500 (0x010405DC)

Jan 31 22:27:52.439: Vi2 LCP: AuthProto PAP (0x0304C023)

Jan 31 22:27:52.439: Vi2 LCP: MagicNumber 0x136B8077 (0x0506136B8077)

Jan 31 22:27:52.439: Vi2 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]

Jan 31 22:27:52.439: Vi2 LCP: I CONFACK [ACKsent] id 2 len 10

Jan 31 22:27:52.443: Vi2 LCP: MagicNumber 0x078F1585 (0x0506078F1585)

Jan 31 22:27:52.443: Vi2 LCP: Event[Receive ConfAck] State[ACKsent to Open]

Jan 31 22:27:52.443: Vi2 PPP: Phase is AUTHENTICATING, by the peer

Jan 31 22:27:52.443: Vi2 PAP: Using hostname from interface PAP

Jan 31 22:27:52.443: Vi2 PAP: Using password from interface PAP

Jan 31 22:27:52.443: Vi2 PAP: O AUTH-REQ id 1 len 39 from "REMOVED FROM TRACE"

Jan 31 22:27:52.443: Vi2 LCP: State is Open

Jan 31 22:27:52.455: Vi2 PAP: I AUTH-ACK id 1 len 13 msg is "Login ok"

Jan 31 22:27:52.455: Vi2 PPP: Phase is FORWARDING, Attempting Forward

Jan 31 22:27:52.455: Vi2 PPP: Queue IPCP code[1] id[82]

Jan 31 22:27:52.455: Vi2 PPP: Phase is ESTABLISHING, Finish LCP

Jan 31 22:27:52.455: Vi2 PPP: Phase is UP

Jan 31 22:27:52.455: Vi2 PPP: Process pending ncp packets

Jan 31 22:27:52.455: Vi2 IPCP: Redirect packet to Vi2

Jan 31 22:27:52.455: Vi2 IPCP: I CONFREQ [UNKNOWN] id 82 len 10

Jan 31 22:27:52.455: Vi2 IPCP: Address 122.59.232.1 (0x03067A3BE801)

Jan 31 22:27:52.455: Vi2 LCP: O PROTREJ [Open] id 3 len 16 protocol IPCP (0x0152000C03067A3BE801)

Jan 31 22:27:52.459: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up

Do you think the 122.59.232.1 address is still somewhere in the router so that why the router rejects the IPCP/LCP protocol?

Many thaks for you time Marco.

Regards,

Mike

mavespig · ‎02-01-2012

Hi Mike,

IOS is not behaving correctly, I suspect that the virtual-access interface is not released when the cable is disconnected, and when the link comes back up it still believes that the interface is up and doesn't need an IP, hence it rejects IPCP.

I'm pretty sure I've seen a similar bug already but I can't find the id at the moment.

Did you try already a different IOS image, e.g.15.2 train?

Marco