Hi,

I hope someone on this lists still knows how to build this...
We have an old setup that authenticates ISDN dial-in users and puts them in a Cisco VRF depending on which user authenticates.
However this was all build about eight years ago using both home grown radius servers, etc.

At the moment I'm trying to build a new platform using FreeRadius but I get stuck it seems at some point during the authentication
and setup of the session.

A quick overview of the setup:
Cisco 180x as dial-in router
Cisco AS5350 (NAS terminating the ISDN call) running IOS c5350-jk9s-mz.124-15.T9.bin
Cisco 7200 (VHG/PE terminating the VPDN tunnel and ultimately the PPP session) running IOS c7200-jk9s-mz.123-20.bin
Freeradius v1.1.3 (default that ships with CentOS 5.5) using MySQL as an backend.

I manage to get the call to dial-in, the NAS to setup the VPDN tunnel and the VHG to send the radius request to terminate the PPP
session. I actually see that the virtual-template gets cloned to a virtual-access interface - however after a few sessions the connection
drops and if I issue a "show run" on the virtual-access interface it does not seem to have any config on it.

I've included the output of a debug of both the VHG as well as of the radius server at the end of this mail. I've also included the running
configuration of the AS5350 and 7200 incase I did something wrong there. I realize this makes for a rather large email - my apologies.

I hope someone can tell me what it is that I'm doing wrong.

Thanks a lot for taking the time to have a look.

 - Jasper

------------

Debug VHG:
Aug 12 16:15:42.916 CEST: ppp55 PPP: Phase is ESTABLISHING
Aug 12 16:15:42.916 CEST: ppp55 PPP: Send Message[Dynamic Bind Response]
Aug 12 16:15:42.916 CEST: ppp55 LCP: I FORCED rcvd CONFACK len 30
Aug 12 16:15:42.916 CEST: ppp55 LCP:    AuthProto CHAP (0x0305C22305)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    MagicNumber 0x0D06A846 (0x05060D06A846)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    MRRU 1524 (0x110405F4)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    EndpointDisc 1 asd-tc3-ap01 (0x130F016173642D7463332D61703031)
Aug 12 16:15:42.916 CEST: ppp55 LCP: I FORCED sent CONFACK len 38
Aug 12 16:15:42.916 CEST: ppp55 LCP:    AuthProto CHAP (0x0305C22305)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    MagicNumber 0x9A996122 (0x05069A996122)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    MRRU 1500 (0x110405DC)
Aug 12 16:15:42.916 CEST: ppp55 LCP:    EndpointDisc 1 test-klant@backup.nl
Aug 12 16:15:42.916 CEST: ppp55 LCP:     (0x131701746573742D6B6C616E74406261)
Aug 12 16:15:42.916 CEST: ppp55 LCP:     (0x636B75702E6E6C)
Aug 12 16:15:42.916 CEST: ppp55 PPP: Phase is FORWARDING, Attempting Forward
Aug 12 16:15:42.916 CEST: ppp55 PPP SSS: Receive SSS-Mgr Connect-Local
Aug 12 16:15:42.916 CEST: ppp55 PPP: Phase is AUTHENTICATING, Unauthenticated User
Aug 12 16:15:42.916 CEST: RADIUS/ENCODE(0000003C):Orig. component type = VPDN
Aug 12 16:15:42.916 CEST: RADIUS:  AAA Unsupported Attr: interface         [153] 14  
Aug 12 16:15:42.916 CEST: RADIUS:   55 6E 69 71 2D 53 65 73 73 2D 49 44              [Uniq-Sess-ID]
Aug 12 16:15:42.916 CEST: RADIUS(0000003C): Storing nasport 55 in rad_db
Aug 12 16:15:42.916 CEST: RADIUS(0000003C): Config NAS IP: 195.18.85.3
Aug 12 16:15:42.916 CEST: RADIUS/ENCODE(0000003C): acct_session_id: 60
Aug 12 16:15:42.916 CEST: RADIUS(0000003C): sending
Aug 12 16:15:42.916 CEST: RADIUS(0000003C): Send Access-Request to 195.18.104.132:1812 id 1645/71, len 114
Aug 12 16:15:42.916 CEST: RADIUS:  authenticator DD 7C 9E 37 25 71 75 C1 - 3A F2 17 44 A0 BA BF E4
Aug 12 16:15:42.916 CEST: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
Aug 12 16:15:42.916 CEST: RADIUS:  User-Name           [1]   22  "test-klant@backup.nl"
Aug 12 16:15:42.916 CEST: RADIUS:  CHAP-Password       [3]   19  *
Aug 12 16:15:42.916 CEST: RADIUS:  NAS-Port-Type       [61]  6   Virtual                   [5]
Aug 12 16:15:42.916 CEST: RADIUS:  NAS-Port            [5]   6   55                        
Aug 12 16:15:42.916 CEST: RADIUS:  Calling-Station-Id  [31]  12  "0365465531"
Aug 12 16:15:42.916 CEST: RADIUS:  Called-Station-Id   [30]  11  "207300300"
Aug 12 16:15:42.916 CEST: RADIUS:  Service-Type        [6]   6   Framed                    [2]
Aug 12 16:15:42.916 CEST: RADIUS:  NAS-IP-Address      [4]   6   195.18.85.3               
Aug 12 16:15:42.920 CEST: RADIUS: Received from id 1645/71 195.18.104.132:1812, Access-Accept, len 150
Aug 12 16:15:42.920 CEST: RADIUS:  authenticator 4B 16 16 8C 36 79 DB 45 - 61 5E D1 5D 34 51 1A 0E
Aug 12 16:15:42.920 CEST: RADIUS:  Service-Type        [6]   6   Framed                    [2]
Aug 12 16:15:42.920 CEST: RADIUS:  Framed-Protocol     [7]   6   PPP                       [1]
Aug 12 16:15:42.920 CEST: RADIUS:  Vendor, Cisco       [26]  57  
Aug 12 16:15:42.920 CEST: RADIUS:   Cisco AVpair       [1]   51  "lcp:interface-config=ip vrf forwarding test-klant"
Aug 12 16:15:42.920 CEST: RADIUS:  Vendor, Cisco       [26]  55  
Aug 12 16:15:42.920 CEST: RADIUS:   Cisco AVpair       [1]   49  "lcp:interface-config=ip unnumbered Loopback1132"
Aug 12 16:15:42.920 CEST: RADIUS:  Framed-IP-Address   [8]   6   192.168.2.1               
Aug 12 16:15:42.920 CEST: RADIUS(0000003C): Received from id 1645/71
Aug 12 16:15:42.920 CEST: ppp55 PPP: Phase is FORWARDING, Attempting Forward
Aug 12 16:15:42.920 CEST: ppp55 PPP: Send Message[Connect Local]
Aug 12 16:15:42.920 CEST: Vi2 PPP: Phase is DOWN, Setup
Aug 12 16:15:42.920 CEST: ppp55 PPP: Bind to [Virtual-Access2]
Aug 12 16:15:42.920 CEST: Vi2 PPP: Send Message[Static Bind Response]
Aug 12 16:15:42.924 CEST: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
Aug 12 16:15:42.924 CEST: Vi2 PPP: Phase is AUTHENTICATING, Authenticated User
Aug 12 16:15:42.924 CEST: Vi2 CHAP: O SUCCESS id 2 len 4
Aug 12 16:15:43.924 CEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to up
Aug 12 16:15:52.868 CEST: Vi2 CHAP: I CHALLENGE id 86 len 41 from "test-klant@backup.nl"
Aug 12 16:15:52.868 CEST: RADIUS/ENCODE(0000003C): sendauth, failing over
Aug 12 16:15:52.868 CEST: RADIUS/ENCODE(0000003C): send packet; BEGIN
Aug 12 16:15:52.868 CEST: Vi2 CHAP: Unable to authenticate for peer
Aug 12 16:15:52.868 CEST: Vi2 PPP: Sending Acct Event[Down] id[3C]
Aug 12 16:15:52.868 CEST: Vi2 PPP: Phase is TERMINATING
Aug 12 16:15:52.868 CEST: Vi2 LCP: O TERMREQ [Open] id 1 len 4
Aug 12 16:15:52.888 CEST: Vi2 LCP: I TERMACK [TERMsent] id 1 len 4
Aug 12 16:15:52.888 CEST: Vi2 LCP: State is Closed
Aug 12 16:15:52.888 CEST: Vi2 PPP: Phase is DOWN
Aug 12 16:15:52.888 CEST: Vi2 PPP: Send Message[Disconnect]
Aug 12 16:15:52.892 CEST: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down
Aug 12 16:15:53.868 CEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Virtual-Access2, changed state to down

------------------------

Debug radius:
rad_recv: Access-Request packet from host 195.18.85.193:1645, id=42, length=122
        User-Name = "backup.nl"
        User-Password = "cisco"
        NAS-Port = 20326
        NAS-Port-Id = "Serial3/3:26"
        NAS-Port-Type = ISDN
        Calling-Station-Id = "0365465531"
        Called-Station-Id = "207300300"
        Connect-Info = "64000 HDLC"
        Service-Type = Dialout-Framed-User
        NAS-IP-Address = 195.18.85.193
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
radius_xlat:  '/var/log/radius/radacct/auth-detail-20100812'
rlm_detail: /var/log/radius/radacct/auth-detail-%Y%m%d expands to /var/log/radius/radacct/auth-detail-20100812
  modcall[authorize]: module "auth_log" returns ok for request 0
  modcall[authorize]: module "chap" returns noop for request 0
radius_xlat:  'backup.nl'
rlm_sql (sql): sql_set_user escaped user --> 'backup.nl'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM radcheck           WHERE Username = 'backup.nl'           ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'backup.nl' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM radreply           WHERE Username = 'backup.nl'           ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'backup.nl' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 4
  modcall[authorize]: module "sql" returns ok for request 0
modcall: leaving group authorize (returns ok) for request 0
auth: type Local
auth: user supplied User-Password matches local User-Password
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 0
radius_xlat:  '/var/log/radius/radacct/reply-detail-20100812'
rlm_detail: /var/log/radius/radacct/reply-detail-%Y%m%d expands to /var/log/radius/radacct/reply-detail-20100812
  modcall[post-auth]: module "reply_log" returns ok for request 0
modcall: leaving group post-auth (returns ok) for request 0
Sending Access-Accept of id 42 to 195.18.85.193 port 1645
        Cisco-AVPair += "vpdn:tunnel-id=AS5350-All"
        Cisco-AVPair += "vpdn:ip-addresses=195.18.85.3"
        Cisco-AVPair += "vpdn:tunnel-type=l2tp"
        Cisco-AVPair += "vpdn:l2tp-tunnel-password=cisco"
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 195.18.85.3:1645, id=73, length=114
        Framed-Protocol = PPP
        User-Name = "test-klant@backup.nl"
        CHAP-Password = 0x02011f8ce0ed5275d50c7a786cc7e47c6b
        NAS-Port-Type = Virtual
        NAS-Port = 57
        Calling-Station-Id = "0365465531"
        Called-Station-Id = "207300300"
        Service-Type = Framed-User
        NAS-IP-Address = 195.18.85.3
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
  modcall[authorize]: module "preprocess" returns ok for request 1
radius_xlat:  '/var/log/radius/radacct/auth-detail-20100812'
rlm_detail: /var/log/radius/radacct/auth-detail-%Y%m%d expands to /var/log/radius/radacct/auth-detail-20100812
  modcall[authorize]: module "auth_log" returns ok for request 1
  rlm_chap: Setting 'Auth-Type := CHAP'
  modcall[authorize]: module "chap" returns ok for request 1
radius_xlat:  'test-klant@backup.nl'
rlm_sql (sql): sql_set_user escaped user --> 'test-klant@backup.nl'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM radcheck           WHERE Username = 'test-klant@backup.nl'           ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test-klant@backup.nl' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM radreply           WHERE Username = 'test-klant@backup.nl'           ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'test-klant@backup.nl' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
  modcall[authorize]: module "sql" returns ok for request 1
modcall: leaving group authorize (returns ok) for request 1
  rad_check_password:  Found Auth-Type CHAP
auth: type "CHAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group CHAP for request 1
  rlm_chap: login attempt by "test-klant@backup.nl" with CHAP password
  rlm_chap: Using clear text password test for user test-klant@backup.nl authentication.
  rlm_chap: chap user test-klant@backup.nl authenticated succesfully
  modcall[authenticate]: module "chap" returns ok for request 1
modcall: leaving group CHAP (returns ok) for request 1
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 1
radius_xlat:  '/var/log/radius/radacct/reply-detail-20100812'
rlm_detail: /var/log/radius/radacct/reply-detail-%Y%m%d expands to /var/log/radius/radacct/reply-detail-20100812
  modcall[post-auth]: module "reply_log" returns ok for request 1
modcall: leaving group post-auth (returns ok) for request 1
Sending Access-Accept of id 73 to 195.18.85.3 port 1645
        Service-Type := Framed-User
        Framed-Protocol := PPP
        Cisco-AVPair += "lcp:interface-config#1=ip vrf forwarding test-klant"
        Cisco-AVPair += "lcp:interface-config#2=ip vrf forwarding test-klant"
Finished request 1
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 42 with timestamp 4c64044c
Cleaning up request 1 ID 73 with timestamp 4c64044c
Nothing to do.  Sleeping until we see a request.
rad_recv: Accounting-Request packet from host 195.18.85.193:1646, id=43, length=263
        Acct-Session-Id = "00000114"
        Framed-Protocol = PPP
        Tunnel-Medium-Type:0 = IP
        Tunnel-Client-Endpoint:0 = "195.18.85.193"
        Tunnel-Server-Endpoint:0 = "195.18.85.3"
        Tunnel-Type:0 = L2TP
        Acct-Tunnel-Connection = "1057600042"
        Tunnel-Client-Auth-Id:0 = "AS5350-All"
        Tunnel-Server-Auth-Id:0 = "asd-cap-dr03"
        User-Name = "test-klant@backup.nl"
        Acct-Authentic = RADIUS
        Acct-Session-Time = 10
        Acct-Input-Octets = 53
        Acct-Output-Octets = 16
        Acct-Input-Packets = 2
        Acct-Output-Packets = 2
        Acct-Terminate-Cause = Host-Request
        Acct-Status-Type = Stop
        NAS-Port = 20326
        NAS-Port-Id = "Serial3/3:26"
        NAS-Port-Type = ISDN
        Calling-Station-Id = "0365465531"
        Called-Station-Id = "207300300"
        Connect-Info = "64000 HDLC"
        Service-Type = Framed-User
        NAS-IP-Address = 195.18.85.193
        Acct-Delay-Time = 0
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 2
  modcall[preacct]: module "preprocess" returns noop for request 2
rlm_acct_unique: Hashing 'NAS-Port = 20326,Client-IP-Address = 195.18.85.193,NAS-IP-Address = 195.18.85.193,Acct-Session-Id = "00000114",User-Name = "test-klant@backup.nl"'
rlm_acct_unique: Acct-Unique-Session-ID = "76ea71aaa12d8845".
  modcall[preacct]: module "acct_unique" returns ok for request 2
modcall: leaving group preacct (returns ok) for request 2
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 2
radius_xlat:  '/var/log/radius/radacct/detail-20100812'
rlm_detail: /var/log/radius/radacct/detail-%Y%m%d expands to /var/log/radius/radacct/detail-20100812
  modcall[accounting]: module "detail" returns ok for request 2
  modcall[accounting]: module "unix" returns ok for request 2
radius_xlat:  '/var/log/radius/radutmp'
radius_xlat:  'test-klant@backup.nl'
rlm_radutmp: Logout for NAS asd-tc3-ap01 port 20326, but no Login record
  modcall[accounting]: module "radutmp" returns ok for request 2
radius_xlat:  'test-klant@backup.nl'
rlm_sql (sql): sql_set_user escaped user --> 'test-klant@backup.nl'
radius_xlat:  'UPDATE radacct SET AcctStopTime = '2010-08-12 16:25:26', AcctSessionTime = '10', AcctInputOctets = '53', AcctOutputOctets = '16', AcctTerminateCause = 'Host-Request', AcctStopDelay = '0', ConnectInfo_stop = '64000 HDLC' WHERE AcctSessionId = '00000114' AND UserName = 'test-klant@backup.nl' AND NASIPAddress = '195.18.85.193''
rlm_sql (sql): Reserving sql socket id: 2
radius_xlat:  'INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('00000114', '76ea71aaa12d8845', 'test-klant@backup.nl', '', '195.18.85.193', '20326', 'ISDN', DATE_SUB('2010-08-12 16:25:26', INTERVAL (10 + 0) SECOND), '2010-08-12 16:25:26', '10', 'RADIUS', '', '64000 HDLC', '53', '16', '207300300', '0365465531', 'Host-Request', 'Framed-User', 'PPP', '', '0', '0')'
rlm_sql (sql): Released sql socket id: 2
  modcall[accounting]: module "sql" returns ok for request 2
modcall: leaving group accounting (returns ok) for request 2
Sending Accounting-Response of id 43 to 195.18.85.193 port 1646
Finished request 2
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 2 ID 43 with timestamp 4c640456
Nothing to do.  Sleeping until we see a request.

-------------------

Database entries MySQL:
mysql> select * from radcheck where UserName = 'backup.nl';
+------+-----------+-----------+----+-------+
| id   | UserName  | Attribute | op | Value |
+------+-----------+-----------+----+-------+
| 1445 | backup.nl | Password  | == | cisco | 
+------+-----------+-----------+----+-------+
1 row in set (0.00 sec)

mysql> select * from radreply where UserName = 'backup.nl';
+------+-----------+--------------+----+---------------------------------+
| id   | UserName  | Attribute    | op | Value                           |
+------+-----------+--------------+----+---------------------------------+
| 2246 | backup.nl | Cisco-AVPair | += | vpdn:tunnel-id=AS5350-All       | 
| 2247 | backup.nl | Cisco-AVPair | += | vpdn:ip-addresses=195.18.85.3   | 
| 2248 | backup.nl | Cisco-AVPair | += | vpdn:tunnel-type=l2tp           | 
| 2249 | backup.nl | Cisco-AVPair | += | vpdn:l2tp-tunnel-password=cisco | 
+------+-----------+--------------+----+---------------------------------+
4 rows in set (0.00 sec)

mysql> select * from radcheck where UserName = 'test-klant@backup.nl';
+------+----------------------+-----------+----+-------+
| id   | UserName             | Attribute | op | Value |
+------+----------------------+-----------+----+-------+
| 1444 | test-klant@backup.nl | Password  | == | test  | 
+------+----------------------+-----------+----+-------+
1 row in set (0.00 sec)

mysql> select * from radreply where UserName = 'test-klant@backup.nl';
+------+----------------------+-------------------+----+-----------------------------------------------------+
| id   | UserName             | Attribute         | op | Value                                               |
+------+----------------------+-------------------+----+-----------------------------------------------------+
| 2231 | test-klant@backup.nl | Service-Type      | := | Framed-User                                         | 
| 2250 | test-klant@backup.nl | Framed-Protocol   | := | PPP                                                 | 
| 2263 | test-klant@backup.nl | Cisco-AVPair      | += | lcp:interface-config#1=ip vrf forwarding test-klant | 
| 2264 | test-klant@backup.nl | Cisco-AVPair      | += | lcp:interface-config#2=ip vrf forwarding test-klant | 
+------+----------------------+-------------------+----+-----------------------------------------------------+
4 rows in set (0.00 sec)