PPP Authentication using AAA

Topoplogy used in this scenario:

R4 (S0/0/1) ---------------------(S0/0/1) R5

Requirement for scenario:
Use AAA to auth PPP using radius and if radius is not available use local Authorization. R4 Should do the Authorization

R4 Config:
aaa new-model
!
!
aaa authentication ppp TEST group radius local

username R5 password 0 cisco

interface Serial0/0/1
 ip address 192.168.1.4 255.255.255.0
 encapsulation ppp
 ppp authentication chap TEST


radius-server host 2.2.2.2 auth-port 1645 acct-port 1646
radius-server key test


R5:
username R4 password 0 cisco

interface Serial0/0/1
 ip address 192.168.1.5 255.255.255.0
 encapsulation ppp
 clock rate 2000000
 ppp chap password 0 cisco

Testing to see if it works, using debugs to make sure radius is tried first, then local used.

debug ppp negotiation
debug radius authentication
debug aaa authentication

R4(config-if)#no shut
R4(config-if)#
*Apr 27 16:12:06.291: Se0/0/1 PPP: Outbound cdp packet dropped
*Apr 27 16:12:08.287: %LINK-3-UPDOWN: Interface Serial0/0/1, changed state to up
*Apr 27 16:12:08.291: Se0/0/1 LCP: I CONFREQ [Closed] id 24 len 10
*Apr 27 16:12:08.291: Se0/0/1 LCP:    MagicNumber 0x2A99F38C (0x05062A99F38C)
*Apr 27 16:12:08.291: Se0/0/1 LCP LCP: Missed a Link-Up transition, starting PPP
*Apr 27 16:12:08.291: AAA/BIND(0000879B): Bind i/f Serial0/0/1
*Apr 27 16:12:08.291: Se0/0/1 PPP: Using default call direction
*Apr 27 16:12:08.291: Se0/0/1 PPP: Treating connection as a dedicated line
*Apr 27 16:12:08.291: Se0/0/1 PPP: Session handle[9A0006E2] Session id[682]
*Apr 27 16:12:08.291: Se0/0/1 PPP: Phase is ESTABLISHING, Active Open
*Apr 27 16:12:08.291: Se0/0/1 PPP: Authorization NOT required
*Apr 27 16:12:08.291: Se0/0/1 LCP: O CONFREQ [Closed] id 222 len 15
*Apr 27 16:12:08.291: Se0/0/1 LCP:    AuthProto CHAP (0x0305C22305)
*Apr 27 16:12:08.291: Se0/0/1 LCP:    MagicNumber 0x2A40E8CA (0x05062A40E8CA)
*Apr 27 16:12:08.291: Se0/0/1 LCP: O CONFACK [REQsent] id 24 len 10
*Apr 27 16:12:08.295: Se0/0/1 LCP:    MagicNumber 0x2A99F38C (0x05062A99F38C)
*Apr 27 16:12:08.295: Se0/0/1 LCP: I CONFACK [ACKsent] id 222 len 15
*Apr 27 16:12:08.295: Se0/0/1 LCP:    AuthProto CHAP (0x0305C22305)
*Apr 27 16:12:08.295: Se0/0/1 LCP:    MagicNumber 0x2A40E8CA (0x05062A40E8CA)
*Apr 27 16:12:08.295: Se0/0/1 LCP: State is Open
*Apr 27 16:12:08.295: Se0/0/1 PPP: Phase is AUTHENTICATING, by this end
*Apr 27 16:12:08.295: Se0/0/1 CHAP: O CHALLENGE id 132 len 23 from "R4"
*Apr 27 16:12:08.295: Se0/0/1 PPP: Outbound cdp packet dropped
*Apr 27 16:12:08.299: Se0/0/1 CHAP: I RESPONSE id 132 len 23 from "R5"
*Apr 27 16:12:08.299: Se0/0/1 PPP: Phase is FORWARDING, Attempting Forward
*Apr 27 16:12:08.299: Se0/0/1 PPP: Phase is AUTHENTICATING, Unauthenticated User
*Apr 27 16:12:08.299: AAA/AUTHEN/PPP (0000879B): Pick method list 'TEST'
*Apr 27 16:12:08.299: Se0/0/1 PPP: Sent CHAP LOGIN Request
*Apr 27 16:12:08.299: RADIUS/ENCODE(0000879B):Orig. component type = PPP
*Apr 27 16:12:08.299: RADIUS:  AAA Unsupported Attr: interface         [175] 11 
*Apr 27 16:12:08.299: RADIUS:   53 65 72 69 61 6C 30 2F 30                       [Serial0/0]
*Apr 27 16:12:08.303: RADIUS(0000879B): Config NAS IP: 0.0.0.0
*Apr 27 16:12:08.303: RADIUS/ENCODE(0000879B): acct_session_id: 1430
*Apr 27 16:12:08.303: RADIUS(0000879B): sending
*Apr 27 16:12:08.303: RADIUS/ENCODE: Best Local IP-Address 172.16.24.4 for Radius-Server 2.2.2.2
*Apr 27 16:12:08.303: RADIUS(0000879B): Send Access-Request to 2.2.2.2:1645 id 1645/31, len 86
*Apr 27 16:12:08.303: RADIUS:  authenticator 47 FB E2 F2 D4 D7 92 4D - 87 17 CE 4D 5B 54 CE 81
*Apr 27 16:12:08.303: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
*Apr 27 16:12:08.303: RADIUS:  User-Name           [1]   4   "R5"
*Apr 27 16:12:08.303: RADIUS:  CHAP-Password       [3]   19  *
*Apr 27 16:12:08.303: RADIUS:  NAS-Port            [5]   6   10001                    
*Apr 27 16:12:08.303: RADIUS:  NAS-Port-Id         [87]  13  "Serial0/0/1"
*Apr 27 16:12:08.303: RADIUS:  NAS-Port-Type       [61]  6   Sync                      [1]
*Apr 27 16:12:08.303: RADIUS:  Service-Type        [6]   6   Framed                    [2]
*Apr 27 16:12:08.303: RADIUS:  NAS-IP-Address      [4]   6   172.16.24.4              
*Apr 27 16:12:12.943: RADIUS: Retransmit to (2.2.2.2:1645,1646) for id 1645/31
*Apr 27 16:12:17.263: %RADIUS-4-RADIUS_DEAD: RADIUS server 2.2.2.2:1645,1646 is not responding.
*Apr 27 16:12:17.263: %RADIUS-4-RADIUS_ALIVE: RADIUS server 2.2.2.2:1645,1646 is being marked alive.
*Apr 27 16:12:17.263: RADIUS: Retransmit to (2.2.2.2:1645,1646) for id 1645/31
*Apr 27 16:12:18.287: Se0/0/1 CHAP: I RESPONSE id 132 len 23 from "R5"
*Apr 27 16:12:18.287: Se0/0/1 CHAP: Ignoring Additional Response
*Apr 27 16:12:18.303: Se0/0/1 AUTH: Timeout 1
*Apr 27 16:12:22.003: RADIUS: Retransmit to (2.2.2.2:1645,1646) for id 1645/31
*Apr 27 16:12:26.867: RADIUS: No response from (2.2.2.2:1645,1646) for id 1645/31
*Apr 27 16:12:26.867: RADIUS/DECODE: No response from radius-server; parse response; FAIL
*Apr 27 16:12:26.867: RADIUS/DECODE: Case error(no response/ bad packet/ op decode);parse response; FAIL
*Apr 27 16:12:26.867: Se0/0/1 PPP: Received LOGIN Response PASS
*Apr 27 16:12:26.867: Se0/0/1 PPP: Phase is FORWARDING, Attempting Forward
*Apr 27 16:12:26.867: Se0/0/1 PPP: Phase is AUTHENTICATING, Authenticated User
*Apr 27 16:12:26.867: Se0/0/1 CHAP: O SUCCESS id 132 len 4
*Apr 27 16:12:26.871: Se0/0/1 PPP: Phase is UP
*Apr 27 16:12:26.871: Se0/0/1 IPCP: O CONFREQ [Closed] id 1 len 10
*Apr 27 16:12:26.871: Se0/0/1 IPCP:    Address 192.168.1.4 (0x0306C0A80104)
*Apr 27 16:12:26.871: Se0/0/1 CDPCP: O CONFREQ [Closed] id 1 len 4
*Apr 27 16:12:26.871: Se0/0/1 PPP: Process pending ncp packets
*Apr 27 16:12:26.871: Se0/0/1 IPCP: I CONFREQ [REQsent] id 1 len 10
*Apr 27 16:12:26.871: Se0/0/1 IPCP:    Address 192.168.1.5 (0x0306C0A80105)
*Apr 27 16:12:26.871: Se0/0/1 IPCP: O CONFACK [REQsent] id 1 len 10
*Apr 27 16:12:26.871: Se0/0/1 IPCP:    Address 192.168.1.5 (0x0306C0A80105)
*Apr 27 16:12:26.875: Se0/0/1 IPCP: I CONFACK [ACKsent] id 1 len 10
*Apr 27 16:12:26.875: Se0/0/1 IPCP:    Address 192.168.1.4 (0x0306C0A80104)
*Apr 27 16:12:26.875: Se0/0/1 IPCP: State is Open
*Apr 27 16:12:26.875: Se0/0/1 CDPCP: I CONFREQ [REQsent] id 1 len 4
*Apr 27 16:12:26.875: Se0/0/1 CDPCP: O CONFACK [REQsent] id 1 len 4
*Apr 27 16:12:26.875: Se0/0/1 CDPCP: I CONFACK [ACKsent] id 1 len 4
*Apr 27 16:12:26.875: Se0/0/1 CDPCP: State is Open
*Apr 27 16:12:26.879: Se0/0/1 IPCP: Install route to 192.168.1.5
*Apr 27 16:12:27.871: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to up



R5 debugs showing its only sending the challenge response:

*Apr 27 16:00:58.935: Se0/0/1 PPP: Using default call direction
*Apr 27 16:00:58.935: Se0/0/1 PPP: Treating connection as a dedicated line
*Apr 27 16:00:58.935: Se0/0/1 PPP: Session handle[73000966] Session id[682]
*Apr 27 16:00:58.935: Se0/0/1 PPP: Authorization required
*Apr 27 16:00:58.939: Se0/0/1 PPP: No authorization without authentication
*Apr 27 16:00:59.939: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to up
*Apr 27 16:02:38.899: Se0/0/1 PPP: Authorization required
*Apr 27 16:02:38.907: Se0/0/1 PPP: No authorization without authentication
*Apr 27 16:02:38.907: Se0/0/1 CHAP: I CHALLENGE id 130 len 23 from "R4"
*Apr 27 16:02:38.907: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:02:38.907: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:02:38.907: Se0/0/1 CHAP: O RESPONSE id 130 len 23 from "R5"
*Apr 27 16:02:48.883: Se0/0/1 AUTH: Timeout 1
*Apr 27 16:02:48.883: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:02:48.883: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:02:48.883: Se0/0/1 CHAP: O RESPONSE id 130 len 23 from "R5"
*Apr 27 16:02:57.131: Se0/0/1 CHAP: I SUCCESS id 130 len 4
*Apr 27 16:03:38.515: %LINK-3-UPDOWN: Interface Serial0/0/1, changed state to down
*Apr 27 16:03:39.515: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to down
*Apr 27 16:03:43.823: %LINK-3-UPDOWN: Interface Serial0/0/1, changed state to up
*Apr 27 16:03:43.823: Se0/0/1 PPP: Using default call direction
*Apr 27 16:03:43.823: Se0/0/1 PPP: Treating connection as a dedicated line
*Apr 27 16:03:43.823: Se0/0/1 PPP: Session handle[69000967] Session id[684]
*Apr 27 16:03:43.823: Se0/0/1 PPP: Authorization required
*Apr 27 16:03:43.827: Se0/0/1 PPP: No authorization without authentication
*Apr 27 16:03:43.831: Se0/0/1 CHAP: I CHALLENGE id 131 len 23 from "R4"
*Apr 27 16:03:43.831: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:03:43.831: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:03:43.831: Se0/0/1 CHAP: O RESPONSE id 131 len 23 from "R5"
*Apr 27 16:03:53.843: Se0/0/1 AUTH: Timeout 1
*Apr 27 16:03:53.843: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:03:53.843: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:03:53.843: Se0/0/1 CHAP: O RESPONSE id 131 len 23 from "R5"
*Apr 27 16:04:02.463: Se0/0/1 CHAP: I SUCCESS id 131 len 4
*Apr 27 16:04:03.467: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to up
*Apr 27 16:05:15.587: %LINK-3-UPDOWN: Interface Serial0/0/1, changed state to down
*Apr 27 16:05:16.587: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to down
*Apr 27 16:05:21.475: %LINK-3-UPDOWN: Interface Serial0/0/1, changed state to up
*Apr 27 16:05:21.475: Se0/0/1 PPP: Using default call direction
*Apr 27 16:05:21.475: Se0/0/1 PPP: Treating connection as a dedicated line
*Apr 27 16:05:21.475: Se0/0/1 PPP: Session handle[A3000968] Session id[685]
*Apr 27 16:05:21.475: Se0/0/1 PPP: Authorization required
*Apr 27 16:05:21.483: Se0/0/1 PPP: No authorization without authentication
*Apr 27 16:05:21.483: Se0/0/1 CHAP: I CHALLENGE id 132 len 23 from "R4"
*Apr 27 16:05:21.483: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:05:21.483: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:05:21.487: Se0/0/1 CHAP: O RESPONSE id 132 len 23 from "R5"
*Apr 27 16:05:31.475: Se0/0/1 AUTH: Timeout 1
*Apr 27 16:05:31.475: Se0/0/1 CHAP: Using hostname from unknown source
*Apr 27 16:05:31.475: Se0/0/1 CHAP: Using password from AAA
*Apr 27 16:05:31.475: Se0/0/1 CHAP: O RESPONSE id 132 len 23 from "R5"
*Apr 27 16:05:40.059: Se0/0/1 CHAP: I SUCCESS id 132 len 4
*Apr 27 16:05:41.059: %LINEPROTO-5-UPDOWN: Line protocol on Interface Serial0/0/1, changed state to up


**********************************************************************************
CHAP I = Chap input
CHAP: 0 = Chap output