The Accept Reject 123 Waltz 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.