The Accept Reject 123 Waltz

[Stelio Gouveia]

Hi,

Please help with this bizarre problem!

EVERY third radtest packet I sent gets rejected! 123! 123! 123! Every
now and then there's a bit of randomness, e.g. two rejects in a row,
but I can sit in front of the computer all day with the up arrow and
dance to the rythm!

I've included both the Accept and Reject outputs from radius running
in Debug mode below.

The pertinent messages I see are the following:

.
.
rlm_sql: Failed to create the pair: Unknown value  for attribute
ChilliSpot-Max-Output-Octets
rlm_sql (sql): Error getting data from database
.
.
.
auth: No password configured for the user
auth: Failed to validate the user.
.
.
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=253, length=68
Sending Access-Reject of id 253 to 127.0.0.1 port 32776

----

I'm using sql for both sessions and accounting in radiusd.conf
(radutmp is commented out everywhere)

I've tried this in freeRADIUS 1.0.2, 1.0.4 and 1.1.2

Why's it only every third time?

Please help!

Stelio





THE ACCEPT

Waking up in 4 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=15, length=68
      User-Name = "testuser"
      User-Password = "password"
      NAS-IP-Address = 255.255.255.255
      NAS-Port = 1812
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 7
modcall[authorize]: module "preprocess" returns ok for request 7
modcall[authorize]: module "chap" returns noop for request 7
modcall[authorize]: module "mschap" returns noop for request 7
modcall[authorize]: module "suffix" returns noop for request 7
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 7
  users: Matched entry DEFAULT at line 152
modcall[authorize]: module "files" returns ok for request 7
radius_xlat:  'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat:  ' ??SELECT id, UserName, Attribute, Value, Op ??FROM
radcheck ??WHERE Username = 'testuser' ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_postgresql: query:  ??SELECT id, UserName, Attribute, Value,
Op ??FROM radcheck ??WHERE Username = 'testuser' ??ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  'SELECT radgroupcheck.id, radgroupcheck.GroupName,
??radgroupcheck.Attribute, radgroupcheck.Value,radgroupcheck.Op ??FROM
radgroupcheck, usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupcheck.GroupName
??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: query: SELECT radgroupcheck.id,
radgroupcheck.GroupName, ??radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op ??FROM radgroupcheck, usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY
radgroupcheck.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  REMOVED FROM DUMP TO CUTDOWN SIZE...
rlm_sql_postgresql: query:  REMOVED FROM DUMP TO CUTDOWN SIZE...
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql: Failed to create the pair: Unknown value  for attribute
ChilliSpot-Max-Output-Octets
rlm_sql (sql): Error getting data from database
radius_xlat:  'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op
??FROM radgroupreply,usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupreply.GroupName
??ORDER BY radgroupreply.id'
rlm_sql_postgresql: query: SELECT radgroupreply.id,
radgroupreply.GroupName, radgroupreply.Attribute,
??radgroupreply.Value, radgroupreply.Op ??FROM radgroupreply,usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupreply.GroupName ??ORDER BY
radgroupreply.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 4
modcall[authorize]: module "sql" returns ok for request 7
modcall: leaving group authorize (returns ok) for request 7
rad_check_password:  Found Auth-Type Local
auth: type Local
auth: user supplied User-Password matches local User-Password
Processing the session section of radiusd.conf
modcall: entering group session for request 7
radius_xlat:  'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat:  'SELECT COUNT(*) FROM radacct WHERE
UserName='testuser' AND AcctStopTime IS NULL'
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_postgresql: query: SELECT COUNT(*) FROM radacct WHERE
UserName='testuser' AND AcctStopTime IS NULL
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 3
modcall[session]: module "sql" returns ok for request 7
modcall: leaving group session (returns ok) for request 7
Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 7
radius_xlat:
'/usr/local/var/log/radius/radacct/127.0.0.1/reply-detail-20060613'
rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d
expands to /usr/local/var/log/radius/radacct/127.0.0.1/reply-detail-20060613
modcall[post-auth]: module "reply_log" returns ok for request 7
rlm_sql (sql): Processing sql_postauth
radius_xlat:  'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat:  'INSERT into radpostauth (username, pass, reply,
authdate) ??values ('testuser', 'password', 'Access-Accept',
NOW())'
radius_xlat:  '/usr/local/var/log/radius/sqltrace.sql'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth
(username, pass, reply, authdate) ??values ('testuser',
'password', 'Access-Accept', NOW())
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql_postgresql: query: INSERT into radpostauth (username, pass,
reply, authdate) ??values ('testuser', 'password',
'Access-Accept', NOW())
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: affected rows = 1
rlm_sql (sql): Released sql socket id: 2
modcall[post-auth]: module "sql" returns ok for request 7
modcall: leaving group post-auth (returns ok) for request 7
Sending Access-Accept of id 15 to 127.0.0.1 port 32776
Finished request 7
Going to the next request
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 6 ID 11 with timestamp 448eb25e
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 7 ID 15 with timestamp 448eb261
Nothing to do.  Sleeping until we see a request.

THE REJECT

--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=253, length=68
      User-Name = "testuser"
      User-Password = "password"
      NAS-IP-Address = 255.255.255.255
      NAS-Port = 1812
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 5
modcall[authorize]: module "preprocess" returns ok for request 5
modcall[authorize]: module "chap" returns noop for request 5
modcall[authorize]: module "mschap" returns noop for request 5
modcall[authorize]: module "suffix" returns noop for request 5
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 5
  users: Matched entry DEFAULT at line 152
modcall[authorize]: module "files" returns ok for request 5
radius_xlat:  'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat:  ' ??SELECT id, UserName, Attribute, Value, Op ??FROM
radcheck ??WHERE Username = 'testuser' ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_postgresql: query:  ??SELECT id, UserName, Attribute, Value,
Op ??FROM radcheck ??WHERE Username = 'testuser' ??ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  'SELECT radgroupcheck.id, radgroupcheck.GroupName,
??radgroupcheck.Attribute, radgroupcheck.Value,radgroupcheck.Op ??FROM
radgroupcheck, usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupcheck.GroupName
??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: query: SELECT radgroupcheck.id,
radgroupcheck.GroupName, ??radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op ??FROM radgroupcheck, usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY
radgroupcheck.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  REMOVED FROM DUMP TO CUTDOWN SIZE...
rlm_sql_postgresql: query: REMOVED FROM DUMP TO CUTDOWN SIZE...
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql: Failed to create the pair: Unknown value  for attribute
ChilliSpot-Max-Output-Octets
rlm_sql (sql): Error getting data from database
radius_xlat:  'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op
??FROM radgroupreply,usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupreply.GroupName
??ORDER BY radgroupreply.id'
rlm_sql_postgresql: query: SELECT radgroupreply.id,
radgroupreply.GroupName, radgroupreply.Attribute,
??radgroupreply.Value, radgroupreply.Op ??FROM radgroupreply,usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupreply.GroupName ??ORDER BY
radgroupreply.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 1
modcall[authorize]: module "sql" returns ok for request 5
modcall: leaving group authorize (returns ok) for request 5
rad_check_password:  Found Auth-Type Local
auth: type Local
auth: No password configured for the user
auth: Failed to validate the user.
Delaying request 5 for 1 seconds
Finished request 5
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=253, length=68
Sending Access-Reject of id 253 to 127.0.0.1 port 32776
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 4 ID 249 with timestamp 448eb1c7
Cleaning up request 5 ID 253 with timestamp 448eb1c7
Nothing to do.  Sleeping until we see a request.