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.nlauthentication. 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)