Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

I have a Cisco 887 as our primary router; it is configured for dual-stack. There is a small 'catch' with our ISP's IPv6 configuration though; after the connection is established, we must perform a DHCPv6 for our prefix delegation to tell the ISP's network where to route our assign /56.

This works fine, except when the connection goes down and comes back up:

Feb  5 08:54:15.194 ACST: Vi2 LCP: I TERMREQ [Open] id 3 len 4
Feb  5 08:54:15.194 ACST: Vi2 PPP DISC: Received LCP TERMREQ from peer
Feb  5 08:54:15.194 ACST: PPP: NET STOP send to AAA.
Feb  5 08:54:15.194 ACST: Vi2 PPP: Phase is TERMINATING

This is not a problem for IPv4 (only takes ~3 seconds to come back up and isn't frequent), but for IPv6, the Cisco fails to send a fresh PD request, which means IPv6 stops routing until the Cisco decides it's time to send another PD request.

Our ISP has identified the problem, and written an EEM to handle the situation (workaround, but nevertheless). Refer to [1]. We have the EEM in our 887:

event manager applet MONITOR-IPV6-DHCP-APP 
event syslog pattern "DIALER-6-BIND"
action 1.0 cli command "enable"
action 1.1 cli command "clear ipv6 dhcp client Dialer1"
action 2.0 syslog priority debugging msg "Refreshed IPv6 DHCP PD lease (Dialer rebind)"
!

However only the first command ('enable') appears to be executed:

Feb  5 08:54:15.194 ACST: Vi2 LCP: I TERMREQ [Open] id 3 len 4
Feb  5 08:54:15.194 ACST: Vi2 PPP DISC: Received LCP TERMREQ from peer
Feb  5 08:54:15.194 ACST: PPP: NET STOP send to AAA.
Feb  5 08:54:15.194 ACST: Vi2 PPP: Phase is TERMINATING
Feb  5 08:54:15.194 ACST: Vi2 IPCP: Event[DOWN] State[Open to Starting]
Feb  5 08:54:15.194 ACST: Vi2 IPCP: Event[CLOSE] State[Starting to Initial]
Feb  5 08:54:15.198 ACST: Vi2 IPV6CP: Event[DOWN] State[Open to Starting]
Feb  5 08:54:15.198 ACST: Vi2 IPV6CP: Event[CLOSE] State[Starting to Initial]
Feb  5 08:54:15.198 ACST: Vi2 LCP: O TERMACK [Open] id 3 len 4
Feb  5 08:54:15.198 ACST: Vi2 LCP: Event[Receive TermReq] State[Open to Stopping]
Feb  5 08:54:15.198 ACST: Di1 Deleted neighbor route from AVL tree: topoid 0, address 150.101.xxx.xxx
Feb  5 08:54:15.198 ACST: Di1 IPCP: Remove route to 150.101.212.45
Feb  5 08:54:16.110 ACST: Vi2 PPP: Outbound ip packet dropped, line protocol not up
Feb  5 08:54:17.182 ACST: Vi2 PPP: No remote authentication for call-out
Feb  5 08:54:17.182 ACST: Vi2 LCP: Event[Timeout-] State[Stopping to Stopped]
Feb  5 08:54:17.182 ACST: Vi2 LCP: Event[DOWN] State[Stopped to Starting]
Feb  5 08:54:17.182 ACST: Vi2 PPP: Phase is DOWN
Feb  5 08:54:17.186 ACST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to down
Feb  5 08:54:18.182 ACST: PPP: Alloc Context [85878D10]
Feb  5 08:54:18.182 ACST: ppp13 PPP: Phase is ESTABLISHING
Feb  5 08:54:18.182 ACST: Vi2 PPP: Using dialer call direction
Feb  5 08:54:18.182 ACST: Vi2 PPP: Treating connection as a callout
Feb  5 08:54:18.182 ACST: Vi2 PPP: Session handle[B3000015] Session id[13]
Feb  5 08:54:18.182 ACST: Vi2 LCP: Event[OPEN] State[Initial to Starting]
Feb  5 08:54:18.182 ACST: Vi2 PPP: No remote authentication for call-out
Feb  5 08:54:18.182 ACST: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
Feb  5 08:54:18.182 ACST: Vi2 LCP:    MagicNumber 0x3640E9BC (0x05063640E9BC)
Feb  5 08:54:18.182 ACST: Vi2 LCP: Event[UP] State[Starting to REQsent]
Feb  5 08:54:18.234 ACST: Vi2 PPP: Outbound ip packet dropped, line protocol not up
Feb  5 08:54:18.378 ACST: Vi2 LCP: I CONFREQ [REQsent] id 83 len 15
Feb  5 08:54:18.378 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.378 ACST: Vi2 LCP:    MagicNumber 0x36FC641E (0x050636FC641E)
Feb  5 08:54:18.378 ACST: Vi2 LCP: O CONFACK [REQsent] id 83 len 15
Feb  5 08:54:18.378 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.378 ACST: Vi2 LCP:    MagicNumber 0x36FC641E (0x050636FC641E)
Feb  5 08:54:18.378 ACST: Vi2 LCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Feb  5 08:54:18.378 ACST: Vi2 LCP: I CONFACK [ACKsent] id 1 len 10
Feb  5 08:54:18.378 ACST: Vi2 LCP:    MagicNumber 0x3640E9BC (0x05063640E9BC)
Feb  5 08:54:18.378 ACST: Vi2 LCP: Event[Receive ConfAck] State[ACKsent to Open]
Feb  5 08:54:18.398 ACST: Vi2 PPP: Phase is AUTHENTICATING, by the peer
Feb  5 08:54:18.398 ACST: Vi2 LCP: State is Open
Feb  5 08:54:18.398 ACST: Vi2 CHAP: I CHALLENGE id 140 len 33 from "vwzp-windsor"
Feb  5 08:54:18.398 ACST: Vi2 CHAP: Using hostname from interface CHAP
Feb  5 08:54:18.398 ACST: Vi2 CHAP: Using password from interface CHAP
Feb  5 08:54:18.398 ACST: Vi2 CHAP: O RESPONSE id 140 len 59 from "xxxxxxxxxxxxxxxxx@ipv6.internode.on.net"
Feb  5 08:54:18.682 ACST: Vi2 LCP: I CONFREQ [Open] id 1 len 19
Feb  5 08:54:18.682 ACST: Vi2 LCP:    MRU 1492 (0x010405D4)
Feb  5 08:54:18.682 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.682 ACST: Vi2 LCP:    MagicNumber 0xA38A8FBC (0x0506A38A8FBC)
Feb  5 08:54:18.682 ACST: Vi2 PPP DISC: PPP Renegotiating
Feb  5 08:54:18.682 ACST: PPP: NET STOP send to AAA.
Feb  5 08:54:18.686 ACST: Vi2 LCP: Event[LCP Reneg] State[Open to Open]
Feb  5 08:54:18.686 ACST: Vi2 LCP: Event[DOWN] State[Open to Starting]
Feb  5 08:54:18.686 ACST: Vi2 PPP: Phase is DOWN
Feb  5 08:54:18.686 ACST: PPP: Alloc Context [85878B48]
Feb  5 08:54:18.686 ACST: ppp13 PPP: Phase is ESTABLISHING
Feb  5 08:54:18.686 ACST: Vi2 PPP: Using dialer call direction
Feb  5 08:54:18.690 ACST: Vi2 PPP: Treating connection as a callout
Feb  5 08:54:18.690 ACST: Vi2 PPP: Session handle[59000016] Session id[13]
Feb  5 08:54:18.690 ACST: Vi2 LCP: Event[OPEN] State[Initial to Starting]
Feb  5 08:54:18.690 ACST: Vi2 PPP: No remote authentication for call-out
Feb  5 08:54:18.690 ACST: Vi2 LCP: O CONFREQ [Starting] id 1 len 10
Feb  5 08:54:18.690 ACST: Vi2 LCP:    MagicNumber 0x3640EBB9 (0x05063640EBB9)
Feb  5 08:54:18.690 ACST: Vi2 LCP: Event[UP] State[Starting to REQsent]
Feb  5 08:54:18.690 ACST: Vi2 LCP: I CONFREQ [REQsent] id 1 len 19
Feb  5 08:54:18.690 ACST: Vi2 LCP:    MRU 1492 (0x010405D4)
Feb  5 08:54:18.690 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.690 ACST: Vi2 LCP:    MagicNumber 0xA38A8FBC (0x0506A38A8FBC)
Feb  5 08:54:18.690 ACST: Vi2 LCP: O CONFNAK [REQsent] id 1 len 8
Feb  5 08:54:18.690 ACST: Vi2 LCP:    MRU 1500 (0x010405DC)
Feb  5 08:54:18.690 ACST: Vi2 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]
Feb  5 08:54:18.710 ACST: Vi2 LCP: I CONFACK [REQsent] id 1 len 10
Feb  5 08:54:18.710 ACST: Vi2 LCP:    MagicNumber 0x3640EBB9 (0x05063640EBB9)
Feb  5 08:54:18.710 ACST: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
Feb  5 08:54:18.710 ACST: Vi2 LCP: I CONFREQ [ACKrcvd] id 2 len 19
Feb  5 08:54:18.710 ACST: Vi2 LCP:    MRU 1500 (0x010405DC)
Feb  5 08:54:18.710 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.710 ACST: Vi2 LCP:    MagicNumber 0xA38A8FBC (0x0506A38A8FBC)
Feb  5 08:54:18.710 ACST: Vi2 LCP: O CONFACK [ACKrcvd] id 2 len 19
Feb  5 08:54:18.710 ACST: Vi2 LCP:    MRU 1500 (0x010405DC)
Feb  5 08:54:18.710 ACST: Vi2 LCP:    AuthProto CHAP (0x0305C22305)
Feb  5 08:54:18.710 ACST: Vi2 LCP:    MagicNumber 0xA38A8FBC (0x0506A38A8FBC)
Feb  5 08:54:18.710 ACST: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
Feb  5 08:54:18.718 ACST: Vi2 PPP: Phase is AUTHENTICATING, by the peer
Feb  5 08:54:18.718 ACST: Vi2 LCP: State is Open
Feb  5 08:54:18.758 ACST: Vi2 CHAP: I CHALLENGE id 141 len 31 from "lns20.mel4"
Feb  5 08:54:18.758 ACST: Vi2 CHAP: Using hostname from interface CHAP
Feb  5 08:54:18.758 ACST: Vi2 CHAP: Using password from interface CHAP
Feb  5 08:54:18.758 ACST: Vi2 CHAP: O RESPONSE id 141 len 59 from "xxxxxxxxxxxxxxx@ipv6.internode.on.net"
Feb  5 08:54:18.926 ACST: Vi2 CHAP: I SUCCESS id 141 len 4
Feb  5 08:54:18.926 ACST: Vi2 PPP: Phase is FORWARDING, Attempting Forward
Feb  5 08:54:18.926 ACST: Vi2 PPP: Queue IPCP code[1] id[1]
Feb  5 08:54:18.930 ACST: Vi2 PPP: Phase is ESTABLISHING, Finish LCP
Feb  5 08:54:18.930 ACST: Vi2 PPP: Phase is UP
Feb  5 08:54:18.930 ACST: Vi2 IPCP: Protocol configured, start CP. state[Initial]
Feb  5 08:54:18.930 ACST: Vi2 IPCP: Event[OPEN] State[Initial to Starting]
Feb  5 08:54:18.930 ACST: Vi2 IPCP: O CONFREQ [Starting] id 1 len 10
Feb  5 08:54:18.930 ACST: Vi2 IPCP:    Address 0.0.0.0 (0x030600000000)
Feb  5 08:54:18.930 ACST: Vi2 IPCP: Event[UP] State[Starting to REQsent]
Feb  5 08:54:18.930 ACST: Vi2 IPV6CP: Protocol configured, start CP. state[Initial]
Feb  5 08:54:18.930 ACST: Vi2 IPV6CP: Event[OPEN] State[Initial to Starting]
Feb  5 08:54:18.930 ACST: Vi2 IPV6CP: O CONFREQ [Starting] id 1 len 14
Feb  5 08:54:18.930 ACST: Vi2 IPV6CP:    Interface-Id CEEF:48FF:xxxx:xxxx (0x010ACEEF48FFxxxxxxxx)
Feb  5 08:54:18.930 ACST: Vi2 IPV6CP: Event[UP] State[Starting to REQsent]
Feb  5 08:54:18.930 ACST: Vi2 PPP: Process pending ncp packets
Feb  5 08:54:18.930 ACST: Vi2 IPCP: Redirect packet to Vi2
Feb  5 08:54:18.930 ACST: Vi2 IPCP: I CONFREQ [REQsent] id 1 len 10
Feb  5 08:54:18.930 ACST: Vi2 IPCP:    Address 150.101.xxx.xxx (0x03069665D42C)
Feb  5 08:54:18.930 ACST: Vi2 IPCP: O CONFACK [REQsent] id 1 len 10
Feb  5 08:54:18.930 ACST: Vi2 IPCP:    Address 150.101.xxx.xxx (0x03069665D42C)
Feb  5 08:54:18.930 ACST: Vi2 IPCP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Feb  5 08:54:18.934 ACST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
Feb  5 08:54:18.950 ACST: Vi2 IPCP: I CONFNAK [ACKsent] id 1 len 10
Feb  5 08:54:18.950 ACST: Vi2 IPCP:    Address 59.167.xxx.xxx (0x03063BA7B47D)
Feb  5 08:54:18.950 ACST: Vi2 IPCP: O CONFREQ [ACKsent] id 2 len 10
Feb  5 08:54:18.950 ACST: Vi2 IPCP:    Address 59.167.xxx.xxx (0x03063BA7B47D)
Feb  5 08:54:18.950 ACST: Vi2 IPCP: Event[Receive ConfNak/Rej] State[ACKsent to ACKsent]
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP: I CONFREQ [REQsent] id 1 len 14
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP:    Interface-Id 0224:14FF:FE9A:9A00 (0x010A022414FFFE9A9A00)
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP: O CONFACK [REQsent] id 1 len 14
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP:    Interface-Id 0224:14FF:FE9A:9A00 (0x010A022414FFFE9A9A00)
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP: Event[Receive ConfReq+] State[REQsent to ACKsent]
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP: I CONFACK [ACKsent] id 1 len 14
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP:    Interface-Id CEEF:48FF:xxxx:xxxx (0x010ACEEF48FFxxxxxxxx)
Feb  5 08:54:18.950 ACST: Vi2 IPV6CP: Event[Receive ConfAck] State[ACKsent to Open]
Feb  5 08:54:18.970 ACST: Vi2 IPCP: I CONFACK [ACKsent] id 2 len 10
Feb  5 08:54:18.970 ACST: Vi2 IPCP:    Address 59.167.xxx.xxx (0x03063BA7B47D)
Feb  5 08:54:18.970 ACST: Vi2 IPCP: Event[Receive ConfAck] State[ACKsent to Open]
Feb  5 08:54:18.974 ACST: Vi2 IPV6CP: State is Open
Feb  5 08:54:18.974 ACST: Vi2 IPCP: State is Open
Feb  5 08:54:18.974 ACST: Vi2 DDR: dialer protocol up
Feb  5 08:54:18.974 ACST: Di1 IPCP: Install negotiated IP interface address 59.167.xxx.xxx
Feb  5 08:54:18.974 ACST: Di1 Added to neighbor route AVL tree: topoid 0, address 150.101.xxx.xxx
Feb  5 08:54:18.978 ACST: Di1 IPCP: Install route to 150.101.xxx.xxx
Feb  5 08:54:18.978 ACST: Vi2 DDR: dialer protocol up
Feb  5 08:59:18.342 ACST: %PARSER-5-CFGLOG_LOGGEDCMD: User:admin  logged command:!exec: enable

The (important) part of clearing the dhcp client on Dialer1, and the syslog command never happen. I have spoken to the ISP and they "do not support" Cisco, even though we purchased the router from them, and they performed the initial configuration of it.

[1] http://www.internode.on.net/support/guides/internet_access/ipv6/cisco_routers/

share|improve this question
1  
you should provide us more logs. The last 5 lines does not show if "DIALER-6-BIND" appeared or not. Do show log | i DIALER-6-BIND. The EEM script waits for that string (event syslog pattern "DIALER-6-BIND"). –  petrus Feb 4 '13 at 23:02
    
There's a fair bit since I have debug logging on, but I'll add it to the OP now. –  fukawi2 Feb 5 '13 at 5:29
    
My eyes screwed up my lines reading the timestamps this morning; the 'enable' is me logging it, not the EEM. So since that string isn't present, I guess that explains it. The question now is, what is a good string to use instead? –  fukawi2 Feb 5 '13 at 5:37
add comment

1 Answer

up vote 0 down vote accepted

From the logs, it does not look like the EEM script has been executed at all.

It waits for a string, DIALER-6-BIND, which does not seem to appear. You could however modify the EEM script to match this log line:

%LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up

The EEM script would look like this:

event manager applet MONITOR-IPV6-DHCP-APP 
event syslog pattern "Virtual-Access2, changed state to up"
action 1.0 cli command "enable"
action 1.1 cli command "clear ipv6 dhcp client Dialer1"
action 2.0 syslog priority debugging msg "Refreshed IPv6 DHCP PD lease (Dialer rebind)"
share|improve this answer
    
Awesome, thanks. I've modded the configuration. I'll wait for the next failure to confirm it works. –  fukawi2 Feb 5 '13 at 22:50
    
This appears to have worked so I've accepted the answer; thanks again! Feb 7 21:33:25.895 ACST: %HA_EM-7-LOG: MONITOR-IPV6-DHCP-APP: Refreshed IPv6 DHCP PD lease (Dialer rebind) –  fukawi2 Feb 11 '13 at 1:52
    
@fukawi2: That's unfortunate that your line goes down, but good news that the applet works :) –  petrus Feb 12 '13 at 22:34
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.