Cisco, DNIS and ISDN Problems
Hi Everyone, I have been using Livingston Radius for a very long time, and decided it was time to upgrade to FreeRadius. We have various pop's authenticating to our radius server, and to make sure everything worked ok I first set only the lucent based pop's to authenticate on FreeRadius. This worked 100% and we decided to let the cisco boxes also authenticate on the new radius server. Suddenly we found the ISDN users can't authenticate. "tail -f radius.log Thu Aug 4 11:24:28 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:30 2005 : Auth: Login incorrect: [sonjapretorius/xxx] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:31 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:33 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:52 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:24:58 2005 : Auth: Login OK: [lords/<CHAP-Password>] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:25:05 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:10 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:51 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 72 cli 061xxx) Thu Aug 4 11:25:56 2005 : Auth: Login OK: [kaysererongo/<CHAP-Password>] (from client Windhoek-as1 port 72 cli 061xxx) " The two Login OK's are Async users. I noticed the port numbers are very high on the ISDN users, 20000+ while the Async ports are < 200 Just something else, for example the same user "japhet" can connect fine as he should on the Lucent NAS on ISDN or Async. The moment he connects to the Cisco I get the Login incorrect. No changes done at all. (Async works fine on the Cisco) On the DNIS:1040 even on my Livingston radius I used to get the dnis:1040 user every time a user connects to the cisco nas's but this is just a minor irritation it didn't affect the users operation. How can I get rid of this ? The National Teleco (running the Cisco's) say there is nothing they can do, as they share the E1's and modems with all ISP's in our country, but determining who's customer it is by the number dialed, and this is where the dnis:1040 comes from and told me just to ignore it. Running radiusd -xx gives no info as to why it was rejected. Hope someone can assist. Thank you Wilhelm Lehmann
You probably have done this already, but if you have not, make sure you statically specify the authentication port and accouting port numbers in your cisco AAA configuration, if you are using the newer port numbers. If you just enable radius authentication on Cisco routers ( at least the ones I have worked on ), they deafult to the old port numbers. So if your radius is using the new port numbers, for whatever reason, The Cisco routers ( the ones I have used ), dont complain about the port mismatch, rather reject valid users. So if your radius Authentication is 1812 and accouting port is 1813, make sure on your cisco box you state this specifically with radius-server host a.b.c.d authentication-port 1812 accounting-port 1813 Good Luck, Herbert.
Hi Everyone,
I have been using Livingston Radius for a very long time, and decided it was time to upgrade to FreeRadius.
We have various pop's authenticating to our radius server, and to make sure everything worked ok I first set only the lucent based pop's to authenticate on FreeRadius. This worked 100% and we decided to let the cisco boxes also authenticate on the new radius server.
Suddenly we found the ISDN users can't authenticate.
"tail -f radius.log Thu Aug 4 11:24:28 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:30 2005 : Auth: Login incorrect: [sonjapretorius/xxx] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:31 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:33 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:52 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:24:58 2005 : Auth: Login OK: [lords/<CHAP-Password>] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:25:05 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:10 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:51 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 72 cli 061xxx) Thu Aug 4 11:25:56 2005 : Auth: Login OK: [kaysererongo/<CHAP-Password>] (from client Windhoek-as1 port 72 cli 061xxx) "
The two Login OK's are Async users. I noticed the port numbers are very high on the ISDN users, 20000+ while the Async ports are < 200
Just something else, for example the same user "japhet" can connect fine as he should on the Lucent NAS on ISDN or Async. The moment he connects to the Cisco I get the Login incorrect. No changes done at all. (Async works fine on the Cisco)
On the DNIS:1040 even on my Livingston radius I used to get the dnis:1040 user every time a user connects to the cisco nas's but this is just a minor irritation it didn't affect the users operation. How can I get rid of this ? The National Teleco (running the Cisco's) say there is nothing they can do, as they share the E1's and modems with all ISP's in our country, but determining who's customer it is by the number dialed, and this is where the dnis:1040 comes from and told me just to ignore it.
Running radiusd -xx gives no info as to why it was rejected.
Hope someone can assist.
Thank you
Wilhelm Lehmann
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Thank you for the reply, but this is done. Still does not explain why the user works on Async but not on ISDN connecting to the same cisco box. The same user works 100% on Async and ISDN on the lucent NAS. Just a note, switching the IP on the Cisco for authentication and accounting back to the Livingston radius (port 1812 and 1813) all works fine again (ISDN and Async) It is just on freeradius my ISDN calls are rejected and only on the cisco NAS. The Lucent (Livingston) pass NAS-Port = 0 for all ISDN users. But the High ports the Cisco pass of ISDN works fine on my old radius box. Thanks Wilhelm -----Original Message----- From: h_maosa@blueyonder.co.uk [mailto:h_maosa@blueyonder.co.uk] Sent: 04 August 2005 01:00 PM To: wilhelm@namibnet.com; FreeRadius users mailing list Subject: Re: Cisco, DNIS and ISDN Problems You probably have done this already, but if you have not, make sure you statically specify the authentication port and accouting port numbers in your cisco AAA configuration, if you are using the newer port numbers. If you just enable radius authentication on Cisco routers ( at least the ones I have worked on ), they deafult to the old port numbers. So if your radius is using the new port numbers, for whatever reason, The Cisco routers ( the ones I have used ), dont complain about the port mismatch, rather reject valid users. So if your radius Authentication is 1812 and accouting port is 1813, make sure on your cisco box you state this specifically with radius-server host a.b.c.d authentication-port 1812 accounting-port 1813 Good Luck, Herbert.
Hi Everyone,
I have been using Livingston Radius for a very long time, and decided it was time to upgrade to FreeRadius.
We have various pop's authenticating to our radius server, and to make sure everything worked ok I first set only the lucent based pop's to authenticate on FreeRadius. This worked 100% and we decided to let the cisco boxes also authenticate on the new radius server.
Suddenly we found the ISDN users can't authenticate.
"tail -f radius.log Thu Aug 4 11:24:28 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:30 2005 : Auth: Login incorrect: [sonjapretorius/xxx] (from client Windhoek-as2 port 20012 cli 061xxx) Thu Aug 4 11:24:31 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:33 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as2 port 20330 cli 061xxx) Thu Aug 4 11:24:52 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:24:58 2005 : Auth: Login OK: [lords/<CHAP-Password>] (from client Industria-as1 port 77 cli 061xxx) Thu Aug 4 11:25:05 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:10 2005 : Auth: Login incorrect: [japhet/xxx] (from client Windhoek-as1 port 20424 cli 061xxx) Thu Aug 4 11:25:51 2005 : Auth: Login incorrect: [dnis:1040/cisco] (from client Windhoek-as1 port 72 cli 061xxx) Thu Aug 4 11:25:56 2005 : Auth: Login OK: [kaysererongo/<CHAP-Password>] (from client Windhoek-as1 port 72 cli 061xxx) "
The two Login OK's are Async users. I noticed the port numbers are very high on the ISDN users, 20000+ while the Async ports are < 200
Just something else, for example the same user "japhet" can connect fine as he should on the Lucent NAS on ISDN or Async. The moment he connects to the Cisco I get the Login incorrect. No changes done at all. (Async works fine on the Cisco)
On the DNIS:1040 even on my Livingston radius I used to get the dnis:1040 user every time a user connects to the cisco nas's but this is just a minor irritation it didn't affect the users operation. How can I get rid of this ? The National Teleco (running the Cisco's) say there is nothing they can do, as they share the E1's and modems with all ISP's in our country, but determining who's customer it is by the number dialed, and this is where the dnis:1040 comes from and told me just to ignore it.
Running radiusd -xx gives no info as to why it was rejected.
Hope someone can assist.
Thank you
Wilhelm Lehmann
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
"Wilhelm Lehmann" <wilhelm@namibnet.com> wrote:
I have been using Livingston Radius for a very long time, and decided it was time to upgrade to FreeRadius.
Good choice. :)
We have various pop's authenticating to our radius server, and to make sure everything worked ok I first set only the lucent based pop's to authenticate on FreeRadius. This worked 100% and we decided to let the cisco boxes also authenticate on the new radius server.
So... you didn't test ISDN?
Suddenly we found the ISDN users can't authenticate. ... Running radiusd -xx gives no info as to why it was rejected.
Are you sure? If you're not familiar with FreeRADIUS, you may be missing something. 99.99% of the time, the server prints out messages saying why a request is reject. The information is there. Please post the debug log to the list, and let someone else interpret it. Alan DeKok.
Hi, As Requested I done a radiusd -xxx While the server was running I did the following : Logged on using async, worked on both the Cisco and the Lucent, no point posting the debug for this, since it is working. I then logged on using ISDN, Same username, same password as for the Async, and got the following. (Lucent again works 100% on ISDN as well, but on the Cisco the user connects, but does not allow any data flow. And no IP address is assigned by the Cisco) Sometimes the User connects and the immediately disconnects, telling the user Authentication Failure. The log for this is *** connect disconnect *** The Logs are labeled *** Lucent **** and *** Cisco *** (Looks the same to me) Without changing any other parameters on the Cisco, I changed the ip of the radius server from the IP of the FreeRadius box to the IP of Livingston Radius Box, and suddenly ISDN works fine on the cisco again. *** Lucent *** Thu Aug 4 18:59:19 2005 : Debug: Thread 1 handling request 31, (7 handled so far) User-Name = "bennie" CHAP-Password = 0x0156c562ae1dc20b0e432b22ff2212c805 NAS-IP-Address = 196.45.xx.xx NAS-Port = 0 NAS-Port-Type = ISDN Service-Type = Framed-User Framed-Protocol = PPP Calling-Station-Id = "061xxxxx" Thu Aug 4 18:59:19 2005 : Debug: Processing the authorize section of radiusd.conf Thu Aug 4 18:59:19 2005 : Debug: modcall: entering group authorize for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "preprocess" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 31 Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.45.1.10/auth-detail-20050804' Thu Aug 4 18:59:19 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to / usr/local/var/log/radius/radacct/196.45.1.10/auth-detail-20050804 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "auth_log" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: rlm_chap: Setting 'Auth-Type := CHAP' Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "chap" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "mschap" returns noop for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 31 Thu Aug 4 18:59:19 2005 : Debug: rlm_realm: No '@' in User-Name = "bennie", looking up realm NULL Thu Aug 4 18:59:19 2005 : Debug: rlm_realm: No such realm "NULL" Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "suffix" returns noop for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: rlm_eap: No EAP-Message, not doing EAP Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "eap" returns noop for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling files (rlm_files) for request 31 Thu Aug 4 18:59:19 2005 : Debug: users: Matched entry DEFAULT at line 149 Thu Aug 4 18:59:19 2005 : Debug: users: Matched entry DEFAULT at line 168 Thu Aug 4 18:59:19 2005 : Debug: users: Matched entry DEFAULT at line 181 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "files" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 31 Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: 'bennie' Thu Aug 4 18:59:19 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'bennie' Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'bennie' ORDER BY id' Thu Aug 4 18:59:19 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Thu Aug 4 18:59:19 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'benni e' ORDER BY id Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgroupcheck. GroupName ORDER BY radgroupcheck.id' Thu Aug 4 18:59:19 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgro upcheck.GroupName ORDER BY radgroupcheck.id Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'bennie' ORDER BY id' Thu Aug 4 18:59:19 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'benni e' ORDER BY id Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgroupreply. GroupName ORDER BY radgroupreply.id' Thu Aug 4 18:59:19 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgro upreply.GroupName ORDER BY radgroupreply.id Thu Aug 4 18:59:19 2005 : Debug: rlm_sql (sql): Released sql socket id: 3 Thu Aug 4 18:59:19 2005 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[authorize]: module "sql" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall: group authorize returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: rad_check_password: Found Auth-Type Local Thu Aug 4 18:59:19 2005 : Debug: auth: type Local Thu Aug 4 18:59:19 2005 : Debug: auth: user supplied CHAP-Password matches local User-Password Thu Aug 4 18:59:19 2005 : Auth: Login OK: [bennie/<CHAP-Password>] (from client e1-whk-1-gw port 0 cli 061245690) Thu Aug 4 18:59:19 2005 : Debug: Processing the post-auth section of radiusd.conf Thu Aug 4 18:59:19 2005 : Debug: modcall: entering group post-auth for request 31 Thu Aug 4 18:59:19 2005 : Debug: modsingle[post-auth]: calling reply_log (rlm_detail) for request 31 Thu Aug 4 18:59:19 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.45.1.10/reply-detail-20050804' Thu Aug 4 18:59:19 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.45.1.10/reply-detail-20050804 Thu Aug 4 18:59:19 2005 : Debug: modsingle[post-auth]: returned from reply_log (rlm_detail) for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall[post-auth]: module "reply_log" returns ok for request 31 Thu Aug 4 18:59:19 2005 : Debug: modcall: group post-auth returns ok for request 31 Sending Access-Accept of id 198 to 196.45.1.10:1031 Framed-IP-Address = 255.255.255.254 Framed-MTU = 1500 Service-Type := Framed-User Framed-Protocol = PPP Framed-Compression = Van-Jacobson-TCP-IP Idle-Timeout = 600 Port-Limit = 2 Thu Aug 4 18:59:19 2005 : Debug: Finished request 31 *** Cisco *** Thu Aug 4 18:58:44 2005 : Debug: Thread 5 handling request 14, (3 handled so far) NAS-IP-Address = 196.44.128.3 NAS-Port = 20016 NAS-Port-Type = ISDN User-Name = "bennie" Called-Station-Id = "1040" Calling-Station-Id = "061xxx" User-Password = "xxx" Service-Type = Framed-User Framed-Protocol = PPP Thu Aug 4 18:58:44 2005 : Debug: Processing the authorize section of radiusd.conf Thu Aug 4 18:58:44 2005 : Debug: modcall: entering group authorize for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "preprocess" returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 14 Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.3/auth-detail-20050804' Thu Aug 4 18:58:44 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to / usr/local/var/log/radius/radacct/196.44.128.3/auth-detail-20050804 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "auth_log" returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "chap" returns noop for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "mschap" returns noop for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 14 Thu Aug 4 18:58:44 2005 : Debug: rlm_realm: No '@' in User-Name = "bennie", looking up realm NULL Thu Aug 4 18:58:44 2005 : Debug: rlm_realm: No such realm "NULL" Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "suffix" returns noop for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: rlm_eap: No EAP-Message, not doing EAP Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "eap" returns noop for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling files (rlm_files) for request 14 Thu Aug 4 18:58:44 2005 : Debug: users: Matched entry DEFAULT at line 149 Thu Aug 4 18:58:44 2005 : Debug: users: Matched entry DEFAULT at line 168 Thu Aug 4 18:58:44 2005 : Debug: users: Matched entry DEFAULT at line 181 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "files" returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 14 Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: 'bennie' Thu Aug 4 18:58:44 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'bennie' Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'bennie' ORDER BY id' Thu Aug 4 18:58:44 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 0 Thu Aug 4 18:58:44 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'benni e' ORDER BY id Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgroupcheck. GroupName ORDER BY radgroupcheck.id' Thu Aug 4 18:58:44 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgro upcheck.GroupName ORDER BY radgroupcheck.id Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'bennie' ORDER BY id' Thu Aug 4 18:58:44 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'benni e' ORDER BY id Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgroupreply. GroupName ORDER BY radgroupreply.id' Thu Aug 4 18:58:44 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'bennie' AND usergroup.GroupName = radgro upreply.GroupName ORDER BY radgroupreply.id Thu Aug 4 18:58:44 2005 : Debug: rlm_sql (sql): Released sql socket id: 0 Thu Aug 4 18:58:44 2005 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[authorize]: module "sql" returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall: group authorize returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: rad_check_password: Found Auth-Type Local Thu Aug 4 18:58:44 2005 : Debug: auth: type Local Thu Aug 4 18:58:44 2005 : Debug: auth: user supplied User-Password matches local User-Password Thu Aug 4 18:58:44 2005 : Auth: Login OK: [bennie/bianca] (from client Windhoek-as1 port 20016 cli 061245690) Thu Aug 4 18:58:44 2005 : Debug: Processing the post-auth section of radiusd.conf Thu Aug 4 18:58:44 2005 : Debug: modcall: entering group post-auth for request 14 Thu Aug 4 18:58:44 2005 : Debug: modsingle[post-auth]: calling reply_log (rlm_detail) for request 14 Thu Aug 4 18:58:44 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.3/reply-detail-20050804' Thu Aug 4 18:58:44 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.44.128.3/reply-detail-20050804 Thu Aug 4 18:58:44 2005 : Debug: modsingle[post-auth]: returned from reply_log (rlm_detail) for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall[post-auth]: module "reply_log" returns ok for request 14 Thu Aug 4 18:58:44 2005 : Debug: modcall: group post-auth returns ok for request 14 Sending Access-Accept of id 38 to 196.44.128.3:1645 Framed-IP-Address = 255.255.255.254 Framed-MTU = 1500 Service-Type := Framed-User Framed-Protocol = PPP Framed-Compression = Van-Jacobson-TCP-IP Idle-Timeout = 600 Port-Limit = 2 Thu Aug 4 18:58:44 2005 : Debug: Finished request 14 *** connect disconnect *** Thu Aug 4 19:25:39 2005 : Debug: Thread 2 handling request 260, (52 handled so far) NAS-IP-Address = 196.44.128.19 NAS-Port = 20016 NAS-Port-Type = ISDN User-Name = "pfister" Called-Station-Id = "1040" Calling-Station-Id = "061xxx" User-Password = "xxx" Service-Type = Framed-User Framed-Protocol = PPP Thu Aug 4 19:25:39 2005 : Debug: Processing the authorize section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group authorize for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "preprocess" returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 260 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.19/auth-detail-20050804' Thu Aug 4 19:25:39 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.44.128.19/auth-detail-20050804 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "auth_log" returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "chap" returns noop for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "mschap" returns noop for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 260 Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No '@' in User-Name = "pfister", looking up realm NULL Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No such realm "NULL" Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "suffix" returns noop for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: rlm_eap: No EAP-Message, not doing EAP Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "eap" returns noop for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling files (rlm_files) for request 260 Thu Aug 4 19:25:39 2005 : Debug: users: Matched entry DEFAULT at line 149 Thu Aug 4 19:25:39 2005 : Debug: users: Matched entry DEFAULT at line 168 Thu Aug 4 19:25:39 2005 : Debug: users: Matched entry DEFAULT at line 181 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "files" returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 260 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'pfister' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'pfister' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pfister' ORDER BY id' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'pfister' ORDER BY id Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pfister' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'pfister' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pfister' ORDER BY id' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'pfister' ORDER BY id Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'pfister' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'pfister' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Released sql socket id: 3 Thu Aug 4 19:25:39 2005 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[authorize]: module "sql" returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall: group authorize returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: rad_check_password: Found Auth-Type Local Thu Aug 4 19:25:39 2005 : Debug: auth: type Local Thu Aug 4 19:25:39 2005 : Debug: auth: user supplied User-Password matches local User-Password Thu Aug 4 19:25:39 2005 : Auth: Login OK: [pfister/p816f] (from client Windhoek-as2 port 20016 cli 061236664) Thu Aug 4 19:25:39 2005 : Debug: Processing the post-auth section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group post-auth for request 260 Thu Aug 4 19:25:39 2005 : Debug: modsingle[post-auth]: calling reply_log (rlm_detail) for request 260 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.19/reply-detail-20050804' Thu Aug 4 19:25:39 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.44.128.19/reply-detail-20050804 Thu Aug 4 19:25:39 2005 : Debug: modsingle[post-auth]: returned from reply_log (rlm_detail) for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall[post-auth]: module "reply_log" returns ok for request 260 Thu Aug 4 19:25:39 2005 : Debug: modcall: group post-auth returns ok for request 260 Sending Access-Accept of id 162 to 196.44.128.19:1645 Framed-IP-Address = 255.255.255.254 Framed-MTU := 1500 Service-Type := Framed-User Framed-Protocol := PPP Framed-Compression := Van-Jacobson-TCP-IP Thu Aug 4 19:25:39 2005 : Debug: Finished request 260 Thu Aug 4 19:25:39 2005 : Debug: Going to the next request Thu Aug 4 19:25:39 2005 : Debug: Thread 2 waiting to be assigned a request rad_recv: Accounting-Request packet from host 196.44.128.19:1646, id=163, length=104 Thu Aug 4 19:25:39 2005 : Debug: Waking up in 4 seconds... Thu Aug 4 19:25:39 2005 : Debug: Thread 5 got semaphore Thu Aug 4 19:25:39 2005 : Debug: Thread 5 handling request 261, (52 handled so far) NAS-IP-Address = 196.44.128.19 NAS-Port = 20016 NAS-Port-Type = ISDN User-Name = "pfister" Called-Station-Id = "1040" Calling-Station-Id = "061xxx" Acct-Status-Type = Start Acct-Authentic = RADIUS Service-Type = Framed-User Acct-Session-Id = "000079DD" Framed-Protocol = PPP Acct-Delay-Time = 0 Thu Aug 4 19:25:39 2005 : Debug: Processing the preacct section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group preacct for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling preprocess (rlm_preprocess) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "preprocess" returns noop for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 261 Thu Aug 4 19:25:39 2005 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 20016,Client-IP-Address = 196.44.128.19,NAS-IP-Address = 196.44.128.19,Acct-Session-Id = "000079DD",User-Name = "pfister"' Thu Aug 4 19:25:39 2005 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "b6402d49349c157f". Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "acct_unique" returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling suffix (rlm_realm) for request 261 Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No '@' in User-Name = "pfister", looking up realm NULL Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No such realm "NULL" Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from suffix (rlm_realm) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "suffix" returns noop for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling files (rlm_files) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from files (rlm_files) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "files" returns noop for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall: group preacct returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: Processing the accounting section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group accounting for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling detail (rlm_detail) for request 261 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.19/detail-20050804' Thu Aug 4 19:25:39 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.44.128.19/detail-20050804 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from detail (rlm_detail) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "detail" returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling unix (rlm_unix) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from unix (rlm_unix) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "unix" returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling radutmp (rlm_radutmp) for request 261 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radutmp' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'pfister' Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "radutmp" returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling sql (rlm_sql) for request 261 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'pfister' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'pfister' Thu Aug 4 19:25:39 2005 : Debug: 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('000079DD', 'b6402d49349c157f', 'pfister', '', '196.44.128.19', '20016', 'ISDN', '2005-08-04 19:25:39', '0', '0', 'RADIUS', '', '', '0', '0', '1040', '061236664', '', 'Framed-User', 'PPP', '', '0', '0')' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/sqltrace.sql' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: 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('000079DD', 'b6402d49349c157f', 'pfister', '', '196.44.128.19', '20016', 'ISDN', '2005-08-04 19:25:39', '0', '0', 'RADIUS', '', '', '0', '0', '1040', '061236664', '', 'Framed-User', 'PPP', '', '0', '0') Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Released sql socket id: 2 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from sql (rlm_sql) for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "sql" returns ok for request 261 Thu Aug 4 19:25:39 2005 : Debug: modcall: group accounting returns ok for request 261 Sending Accounting-Response of id 163 to 196.44.128.19:1646 Thu Aug 4 19:25:39 2005 : Debug: Finished request 261 Thu Aug 4 19:25:39 2005 : Debug: Going to the next request Thu Aug 4 19:25:39 2005 : Debug: Thread 5 waiting to be assigned a request rad_recv: Accounting-Request packet from host 196.44.128.19:1646, id=164, length=140 Thu Aug 4 19:25:39 2005 : Debug: Waking up in 4 seconds... Thu Aug 4 19:25:39 2005 : Debug: Thread 4 got semaphore Thu Aug 4 19:25:39 2005 : Debug: Thread 4 handling request 262, (53 handled so far) NAS-IP-Address = 196.44.128.19 NAS-Port = 20016 NAS-Port-Type = ISDN User-Name = "pfister" Called-Station-Id = "1040" Calling-Station-Id = "061xxxx" Acct-Status-Type = Stop Acct-Authentic = RADIUS Service-Type = Framed-User Acct-Session-Id = "000079DD" Framed-Protocol = PPP Acct-Terminate-Cause = User-Request Acct-Input-Octets = 138 Acct-Output-Octets = 96 Acct-Input-Packets = 6 Acct-Output-Packets = 6 Acct-Session-Time = 0 Acct-Delay-Time = 0 Thu Aug 4 19:25:39 2005 : Debug: Processing the preacct section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group preacct for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling preprocess (rlm_preprocess) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "preprocess" returns noop for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 262 Thu Aug 4 19:25:39 2005 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 20016,Client-IP-Address = 196.44.128.19,NAS-IP-Address = 196.44.128.19,Acct-Session-Id = "000079DD",User-Name = "pfister"' Thu Aug 4 19:25:39 2005 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "b6402d49349c157f". Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "acct_unique" returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling suffix (rlm_realm) for request 262 Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No '@' in User-Name = "pfister", looking up realm NULL Thu Aug 4 19:25:39 2005 : Debug: rlm_realm: No such realm "NULL" Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from suffix (rlm_realm) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "suffix" returns noop for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: calling files (rlm_files) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[preacct]: returned from files (rlm_files) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[preacct]: module "files" returns noop for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall: group preacct returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: Processing the accounting section of radiusd.conf Thu Aug 4 19:25:39 2005 : Debug: modcall: entering group accounting for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling detail (rlm_detail) for request 262 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/196.44.128.19/detail-20050804' Thu Aug 4 19:25:39 2005 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/196.44.128.19/detail-20050804 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from detail (rlm_detail) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "detail" returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling unix (rlm_unix) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from unix (rlm_unix) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "unix" returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling radutmp (rlm_radutmp) for request 262 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/radutmp' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'pfister' Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "radutmp" returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: calling sql (rlm_sql) for request 262 Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'pfister' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'pfister' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: 'UPDATE radacct SET AcctStopTime = '2005-08-04 19:25:39', AcctSessionTime = '0', AcctInputOctets = '138', AcctOutputOctets = '96', AcctTerminateCause = 'User-Request', AcctStopDelay = '0', ConnectInfo_stop = '' WHERE AcctSessionId = '000079DD' AND UserName = 'pfister' AND NASIPAddress = '196.44.128.19'' Thu Aug 4 19:25:39 2005 : Debug: radius_xlat: '/usr/local/var/log/radius/sqltrace.sql' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 1 Thu Aug 4 19:25:39 2005 : Debug: rlm_sql_mysql: query: UPDATE radacct SET AcctStopTime = '2005-08-04 19:25:39', AcctSessionTime = '0', AcctInputOctets = '138', AcctOutputOctets = '96', AcctTerminateCause = 'User-Request', AcctStopDelay = '0', ConnectInfo_stop = '' WHERE AcctSessionId = '000079DD' AND UserName = 'pfister' AND NASIPAddress = '196.44.128.19' Thu Aug 4 19:25:39 2005 : Debug: rlm_sql (sql): Released sql socket id: 1 Thu Aug 4 19:25:39 2005 : Debug: modsingle[accounting]: returned from sql (rlm_sql) for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall[accounting]: module "sql" returns ok for request 262 Thu Aug 4 19:25:39 2005 : Debug: modcall: group accounting returns ok for request 262 Sending Accounting-Response of id 164 to 196.44.128.19:1646 Thu Aug 4 19:25:39 2005 : Debug: Finished request 262 *** END of Paste *** Thank you, Wilhelm -----Original Message----- From: aland@nitros9.org [mailto:aland@nitros9.org] On Behalf Of Alan DeKok Sent: 04 August 2005 04:37 PM To: wilhelm@namibnet.com; FreeRadius users mailing list Subject: Re: Cisco, DNIS and ISDN Problems "Wilhelm Lehmann" <wilhelm@namibnet.com> wrote:
I have been using Livingston Radius for a very long time, and decided it was time to upgrade to FreeRadius.
Good choice. :)
We have various pop's authenticating to our radius server, and to make sure everything worked ok I first set only the lucent based pop's to authenticate on FreeRadius. This worked 100% and we decided to let the cisco boxes also authenticate on the new radius server.
So... you didn't test ISDN?
Suddenly we found the ISDN users can't authenticate. ... Running radiusd -xx gives no info as to why it was rejected.
Are you sure? If you're not familiar with FreeRADIUS, you may be missing something. 99.99% of the time, the server prints out messages saying why a request is reject. The information is there. Please post the debug log to the list, and let someone else interpret it. Alan DeKok.
"Wilhelm Lehmann" <wilhelm@namibnet.com> wrote:
I then logged on using ISDN, Same username, same password as for the Async, and got the following. (Lucent again works 100% on ISDN as well, but on the Cisco the user connects, but does not allow any data flow. And no IP address is assigned by the Cisco) Sometimes the User connects and the immediately disconnects, telling the user Authentication Failure. The log for this is *** connect disconnect ***
The only problem is that the debug output you posted shows the server sending Access-Accept. So it does NOT match the logs you posted earlier, which showed authentication failure. And the Access-Accepts that it sends back are the *same* for both Lucent & Cisco. So if one works and the other doesn't, it's a NAS problem. i.e. one of the NASes expects something additional that you're not sending it. There is *nothing* magic about RADIUS, Livingston, or FreeRADIUS. If you can make FreeRADIUS send back to the Cisco NAS *exactly* the same packet that Livingston sends, then it will work. I'll bet large amounts of money that you've configured FreeRADIUS to send *different* packets back to the NASes than what was sent back by Livingston. Fix that, and the problem will go away. Alan DeKok.
participants (3)
-
Alan DeKok -
h_maosaï¼ blueyonder.co.uk -
Wilhelm Lehmann