Server logs say users authenticate, but they don't (Now with more details!)

Ernie Dunbar maillist at lightspeed.ca
Thu Nov 9 21:34:24 CET 2006 

Here's the output from `freeradius -X` for one attempted user login:

rad_recv: Access-Request packet from host AS5300:1645, id=32, length=88
        NAS-IP-Address = AS5300
        NAS-Port = 47
        NAS-Port-Type = Async
        User-Name = "Pheilmann"
        Called-Station-Id = "6811527"
        User-Password = "XXXXXXX"
        Service-Type = Framed-User
        Framed-Protocol = PPP
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
radius_xlat:  'Pheilmann'
rlm_sql (sql): sql_set_user escaped user --> 'Pheilmann'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE
Username = 'Pheilmann' ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_mysql: query:  SELECT id,UserName,Attribute,Value,op FROM radcheck
WHERE Username = 'Pheilmann' ORDER BY id
radius_xlat:  'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
 FROM radgroupcheck,usergroup WHERE usergroup.Username = 'Pheilmann' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
rlm_sql_mysql: query:  SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
 FROM radgroupcheck,usergroup WHERE usergroup.Username = 'Pheilmann' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE
Username = 'Pheilmann' ORDER BY id'
rlm_sql_mysql: query:  SELECT id,UserName,Attribute,Value,op FROM radreply
WHERE Username = 'Pheilmann' ORDER BY id
radius_xlat:  'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
 FROM radgroupreply,usergroup WHERE usergroup.Username = 'Pheilmann' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql_mysql: query:  SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
 FROM radgroupreply,usergroup WHERE usergroup.Username = 'Pheilmann' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id
rlm_sql (sql): Released sql socket id: 4
  modcall[authorize]: module "sql" returns ok for request 0
modcall: group authorize returns ok for request 0
auth: type Local
auth: user supplied User-Password matches local User-Password
Login OK: [Pheilmann/XXXXXXX] (from client dialup port 47)
Sending Access-Accept of id 32 to AS5300:1645
Finished request 0
Going to the next request

It looks to me that it's only sending Access-Accept back to the AS5300. I
would expect that's what it's supposed to do.

> G'day Ernie,
>
> What value are you sending for Service-Type?  Best way to check is
> radiusd -X, and watch for the Access-Accept that freeradius sends, in
> case your authorization config isn't quite right.
>
> Cheers,
> James.
>
> Ernie Dunbar wrote:
>> Okay, after doing these tests, we can see that the Cisco is now
>> accepting
>> the packets.
>>
>> However, the AS5300 is now telling us "no appropriate authorization type
>> for user". Here's the logs from the AS5300 (XX.XX.XX.X is the new
>> server,
>> XX.XX.XX.Y is the backup that was offline for the duration of the test):
>>
>> *Jan  3 16:30:43: RADIUS: Trying next server (XX.XX.XX.X) for id 20
>> *Jan  3 16:30:43: RADIUS: Retransmit id 20
>> *Jan  3 16:30:43: RADIUS: Received from id 20 XX.XX.XX.X:1812,
>> Access-Accept, len 20
>> *Jan  3 16:30:43: RADIUS: saved authorization data for user 616D09DC at
>> 614184A4
>> *Jan  3 16:30:43: RADIUS: no appropriate authorization type for user.
>> *Jan  3 16:30:43: RADIUS: ustruct sharecount=1
>> *Jan  3 16:30:43: RADIUS: Initial Transmit Async56 id 21
>> XX.XX.XX.Y:1645,
>> Access-Request, len 88
>> *Jan  3 16:30:43:         Attribute 4 6 CCF4E9FE
>> *Jan  3 16:30:43:         Attribute 5 6 00000038
>> *Jan  3 16:30:43:         Attribute 61 6 00000000
>> *Jan  3 16:30:43:         Attribute 1 11 72737461
>> *Jan  3 16:30:43:         Attribute 30 9 36383131
>> *Jan  3 16:30:43:         Attribute 2 18 A3B5B2A0
>> *Jan  3 16:30:43:         Attribute 6 6 00000002
>> *Jan  3 16:30:43:         Attribute 7 6 00000001
>> *Jan  3 16:30:44: %ISDN-6-DISCONNECT: Interface Serial2:5  disconnected
>> from unknown , call lasted 53 seconds
>> *Jan  3 16:30:44:  isdn_Call_disconnect()
>>
>>
>>> Hi Ernie,
>>>
>>> * Run radiusd -X and check that Access-Accept is being sent, and how
>>> long after the Access-Request this is.
>>>
>>> * Verify with tcpdump that the packet is actually getting onto the
>>> wire.
>>>
>>> * Check for iptables rules/access-lists that might be
>>> dropping/rejecting
>>> the packets.
>>>
>>> * Make sure your AS5300 and freeradius are configured to use the same
>>> port numbers.  freeradius shouldn't be seeing the Access-Request if
>>> not,
>>> but it might be worth a look.
>>>
>>> Ernie Dunbar wrote:
>>>>> G'day Ernie,
>>>>>
>>>>> Can you sniff on the AS5300 and ensure the Access-Accept packets are
>>>>> arriving before the 3 second (default) timeout?
>>>> Yes, we tried that. The access-accept packets aren't arriving at all!
>>>>
>>>>> Does it work if you temporarily disable the Simultaneous-Use check?
>>>> No, that doesn't work either.
>>>>
>>>> -
>>>> List info/subscribe/unsubscribe? See
>>>> http://www.freeradius.org/list/users.html
>>>
>>> --
>>> James Wakefield,
>>> Unix Administrator, Information Technology Services Division
>>> Deakin University, Geelong, Victoria 3217 Australia.
>>>
>>> Phone: 03 5227 8690 International: +61 3 5227 8690
>>> Fax:   03 5227 8866 International: +61 3 5227 8866
>>> E-mail:   james.wakefield at deakin.edu.au
>>> Website:  http://www.deakin.edu.au
>>> -
>>> List info/subscribe/unsubscribe? See
>>> http://www.freeradius.org/list/users.html
>>>
>>
>>
>> -
>> List info/subscribe/unsubscribe? See
>> http://www.freeradius.org/list/users.html
>
>
> --
> James Wakefield,
> Unix Administrator, Information Technology Services Division
> Deakin University, Geelong, Victoria 3217 Australia.
>
> Phone: 03 5227 8690 International: +61 3 5227 8690
> Fax:   03 5227 8866 International: +61 3 5227 8866
> E-mail:   james.wakefield at deakin.edu.au
> Website:  http://www.deakin.edu.au
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>

More information about the Freeradius-Users mailing list