Why is the post-auth process result returned by jRadius Module over-written by freeradius?

Yizhi Lao laoyizhi at yahoo.com
Wed Apr 5 06:38:06 CEST 2006


Hi all,

   I am struggling with this issue right now.  I have
installed a JRadius module on FreeRadius 1.1.0 , and
made FreeRadius to call the Jradius module in
post-auth section. The Jradius handler is supposed to
replace the access-accept packet obtained from prior
authentication with a access-challenge packet.  My
logs show that rlm_jradius has correctly return
FreeRadius an Access-challenge module, with code 11.
However, Freeradius still returns an Access-accept to
the client (which is an radtest program).  Does anyone
know what is the possible reason?  Or maybe someone
can enlighten me as which part of the freeradius code
is actually handling this portion, so I can take a
look?

following is the debug output of freeradius: (the
dashed line and below are of the primary concern)

Thank you very much?

rad_recv: Access-Request packet from host
127.0.0.1:4820, id=197, length=64
        User-Name = "hellouser123"
        User-Password = "f0unT at 1n"
        NAS-IP-Address = 255.255.255.255
        NAS-Port = 0
Wed Apr  5 11:51:50 2006 : Debug:   Processing the
authorize section of radiusd.conf
Wed Apr  5 11:51:50 2006 : Debug: modcall: entering
group authorize for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authorize]: calling preprocess
(rlm_preprocess) for request 0
Wed Apr  5 11:51:50 2006 : Error: Invalid operator for
item Suffix: reverting to '=='
Wed Apr  5 11:51:50 2006 : Error: Invalid operator for
item Suffix: reverting to '=='
Wed Apr  5 11:51:50 2006 : Error: Invalid operator for
item Suffix: reverting to '=='
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authorize]: returned from preprocess
(rlm_preprocess) for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modcall[authorize]: module "preprocess" returns ok for
request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authorize]: calling ldap (rlm_ldap) for
request 0
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: -
authorize
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: performing
user authorization for hellouser123
Wed Apr  5 11:51:50 2006 : Debug: radius_xlat: 
'(&(cn=hellouser123)(objectclass=user))'
Wed Apr  5 11:51:50 2006 : Debug: radius_xlat: 
'cn=Users,dc=hellotechnology,dc=com'
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap:
ldap_get_conn: Checking Id: 0
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap:
ldap_get_conn: Got Id: 0
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: attempting
LDAP reconnection
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap:
(re)connect to 10.26.1.202:389, authentication 0
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: bind as
cn=krazy,cn=Users,dc=hellotechnology,dc=com/welcome123
to 10.26.1.202:389
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: waiting
for bind result ...
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: Bind was
successful
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: performing
search in cn=Users,dc=hellotechnology,dc=com, with
filter (&(cn=hellouser123)(objectclass=user))
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: checking
if remote access for hellouser123 is allowed by
msNPAllowDialin
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: looking
for check items in directory
...
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: looking
for reply items in directory...
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: user
hellouser123 authorized to use remote access
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap:
ldap_release_conn: Release Id: 0
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authorize]: returned from ldap (rlm_ldap)
for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modcall[authorize]: module "ldap" returns ok for
request 0
Wed Apr  5 11:51:50 2006 : Debug: modcall: leaving
group authorize (returns ok) for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
rad_check_password:  Found Auth-Type ldap
Wed Apr  5 11:51:50 2006 : Debug: auth: type "LDAP"
Wed Apr  5 11:51:50 2006 : Debug:   Processing the
authenticate section of radiusd.conf
Wed Apr  5 11:51:50 2006 : Debug: modcall: entering
group LDAP for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authenticate]: calling ldap (rlm_ldap) for
request 0
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: -
authenticate
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: login
attempt by "hellouser123" with password "f0unT at 1n"
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: user DN:
CN=hellouser123,CN=Users,DC=HelloTechnology,DC=com
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap:
(re)connect to 10.26.1.202:389, authentication 1
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: bind as
CN=hellouser123,CN=Users,DC=HelloTechnology,DC=com/f0unT at 1n
to 10.26.1.202:389
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: waiting
for bind result ...
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: Bind was
successful
Wed Apr  5 11:51:50 2006 : Debug: rlm_ldap: user
hellouser123 authenticated succesfully
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[authenticate]: returned from ldap (rlm_ldap)
for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modcall[authenticate]: module "ldap" returns ok for
request 0
Wed Apr  5 11:51:50 2006 : Debug: modcall: leaving
group LDAP (returns ok) for request 0
Wed Apr  5 11:51:50 2006 : Debug:   Processing the
post-auth section of radiusd.conf
Wed Apr  5 11:51:50 2006 : Debug: modcall: entering
group post-auth for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[post-auth]: calling jradius (rlm_jradius)
for request 0
Wed Apr  5 11:51:50 2006 : Error: rlm_jradius: could
not connect to 127.0.0.1:1814
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute User-Name (type: 1; len: 12)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute User-Password (type: 2; len: 8)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute NAS-IP-Address (type: 4; len: 4)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute NAS-Port (type: 5; len: 4)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute Client-IP-Address (type: 1052; len: 4)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute Ldap-UserDn (type: 1053; len: 50)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
packet with code: 1 (attr length: 154)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
packet with code: 2 (attr length: 0)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: packing
attribute Auth-Type (type: 1000; len: 4)
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: sending
201 bytes to jradius server
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: return
code 2; receiving 2 packets
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
packet: code=1 len=154
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=1; len=12
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=2; len=8
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=4; len=4
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=5; len=4
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=1052; len=4
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=1053; len=50
---------------------------------------------------------
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
packet: code=11 len=37
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=18; len=25
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
request: config_item: len=16
Wed Apr  5 11:51:50 2006 : Debug: rlm_jradius: reading
attribute: type=1000; len=4
Wed Apr  5 11:51:50 2006 : Debug:  
modsingle[post-auth]: returned from jradius
(rlm_jradius) for request 0
Wed Apr  5 11:51:50 2006 : Debug:  
modcall[post-auth]: module "jradius" returns ok for
request 0
Wed Apr  5 11:51:50 2006 : Debug: modcall: leaving
group post-auth (returns ok) for request 0
Sending Access-Accept of id 197 to 127.0.0.1 port 4820
        Reply-Message = "Please input SMS password"
Wed Apr  5 11:51:50 2006 : Debug: Finished request 0
Wed Apr  5 11:51:50 2006 : Debug: Going to the next
request
Wed Apr  5 11:51:50 2006 : Debug: --- Walking the
entire request list ---
Wed Apr  5 11:51:50 2006 : Debug: Waking up in 6
seconds...
Wed Apr  5 11:51:56 2006 : Debug: --- Walking the
entire request list ---
Wed Apr  5 11:51:56 2006 : Debug: Cleaning up request
0 ID 197 with timestamp 44333ed6
Wed Apr  5 11:51:56 2006 : Debug: Nothing to do. 
Sleeping until we see a request.


__________________________________________________
Do You Yahoo!?
Tired of spam?  Yahoo! Mail has the best spam protection around 
http://mail.yahoo.com 



More information about the Freeradius-Users mailing list