Cisco, DNIS and ISDN Problems
Wilhelm Lehmann
wilhelm at namibnet.com
Thu Aug 4 20:32:48 CEST 2005
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 at nitros9.org [mailto:aland at nitros9.org] On Behalf Of Alan DeKok
Sent: 04 August 2005 04:37 PM
To: wilhelm at namibnet.com; FreeRadius users mailing list
Subject: Re: Cisco, DNIS and ISDN Problems
"Wilhelm Lehmann" <wilhelm at 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.
More information about the Freeradius-Users
mailing list