Hi,
First of all - I've posted this to both the NAS en NSP list since it touches
on both I guess.
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 and L2F as the tunnel protocol. I've been
asked to migrate this setup to a new location which needs to be running
before we can dismantle the old setup. I've trying to do
away with all of the homegrown bits and make it a standard solution using
L2TP as the tunnel protocol.
A quick overview of the setup which I'm using to test with:
Cisco 180x as dial-in router
Cisco AS5350 (NAS/LAC terminating the ISDN call) running
IOS c5350-jk9s-mz.124-15.T9.bin
Cisco 7200 (VHG/PE/LNS terminating the VPDN tunnel and ultimately the PPP
session into an MPLS VPN) running IOS c7200-jk9s-mz.123-20.bin
Freeradius using MySQL as an backend.
I manage to get the call to dial-in, the NAS/LAC to setup the VPDN tunnel
and the VHG/LNS 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 while the session is up.
I've included the output of a debug of both the VHG/LNS 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 guess the interesting bit so far from the debug is this section:
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
I hope someone can tell me what it is that I'm doing wrong. If extra debug
of information is needed please let me know - I'll be happy to supply this.
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)
First of all - I've posted this to both the NAS en NSP list since it touches
on both I guess.
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 and L2F as the tunnel protocol. I've been
asked to migrate this setup to a new location which needs to be running
before we can dismantle the old setup. I've trying to do
away with all of the homegrown bits and make it a standard solution using
L2TP as the tunnel protocol.
A quick overview of the setup which I'm using to test with:
Cisco 180x as dial-in router
Cisco AS5350 (NAS/LAC terminating the ISDN call) running
IOS c5350-jk9s-mz.124-15.T9.bin
Cisco 7200 (VHG/PE/LNS terminating the VPDN tunnel and ultimately the PPP
session into an MPLS VPN) running IOS c7200-jk9s-mz.123-20.bin
Freeradius using MySQL as an backend.
I manage to get the call to dial-in, the NAS/LAC to setup the VPDN tunnel
and the VHG/LNS 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 while the session is up.
I've included the output of a debug of both the VHG/LNS 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 guess the interesting bit so far from the debug is this section:
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
I hope someone can tell me what it is that I'm doing wrong. If extra debug
of information is needed please let me know - I'll be happy to supply this.
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)
Attached Files:
-
nas_config.txt (6.83 KB)
-
vhg_config.txt (7.08 KB)
-
dial_1800.txt (3.04 KB)