Unused Authorize Queries

Ammad Ali ammad.ali at rapidcompute.com
Mon Nov 30 11:22:04 CET 2020


Hi,

I have checked a user in debugging of user via raddebug, if the user is 
not being found in radcheck table, the freeradius is still executing 
groupcheck and groupreply tables. It look like its causing extra load on 
mysql database. Is there a way to minimize them ? or is there a way that 
if the user is not found in radcheck, then freeradius should not execute 
other queries.

Below is the debug result.

(257372773) Mon Nov 30 15:11:24 2020 : Debug: Received Access-Request 
packet from host 192.168.247.70 port 53214, id=108, length=26
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   User-Name = 'test'
(257372773) Mon Nov 30 15:11:24 2020 : Debug: # Executing section 
authorize from file /etc/raddb/sites-enabled/default
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   authorize {
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   filter_username 
filter_username {
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (!&User-Name)
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (!&User-Name)  -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ / /)
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ / 
/)  -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/@.*@/ )
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/@.*@/ )  -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/\\.\\./ )
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/\\.\\./ )  -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ /\\.$/)
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/\\.$/)   -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ /@\\./)
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&User-Name =~ 
/@\\./)   -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   } # filter_username 
filter_username = notfound
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [preprocess] = ok
(257372773) Mon Nov 30 EXPAND 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail
(257372773) Mon Nov 30    --> 
/var/log/radius/radacct/192.168.247.70/auth-detail
(257372773) Mon Nov 30 
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail 
expands to /var/log/radius/radacct/192.168.247.70/auth-detail
(257372773) Mon Nov 30 EXPAND %t
(257372773) Mon Nov 30    --> Mon Nov 30 15:11:24 2020
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [auth_log] = ok
(257372773) Mon Nov 3Checking for suffix after "@"
(257372773) Mon Nov 3No '@' in User-Name = "test", looking up realm NULL
(257372773) Mon Nov 3No such realm "NULL"
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [suffix] = noop
(257372773) Mon NoEXPAND %{User-Name}
(257372773) Mon No   --> test
(257372773) Mon NoSQL-User-Name set to 'test'
(257372773) Mon NoEXPAND SELECT id, username, attribute, value, op FROM 
radcheck WHERE username = BINARY '%{SQL-User-Name}' ORDER BY id
(257372773) Mon No   --> SELECT id, username, attribute, value, op FROM 
radcheck WHERE username = BINARY 'test' ORDER BY id
(257372773) Mon NoUser found in radcheck table
(257372773) Mon NoEXPAND SELECT groupname FROM radusergroup WHERE 
username = BINARY '%{SQL-User-Name}' ORDER BY priority
(257372773) Mon No   --> SELECT groupname FROM radusergroup WHERE 
username = BINARY 'test' ORDER BY priority
(257372773) Mon NoUser found in the group table
(257372773) Mon NoEXPAND SELECT id, groupname, attribute, Value, op FROM 
radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id
(257372773) Mon No   --> SELECT id, groupname, attribute, Value, op FROM 
radgroupcheck WHERE groupname = 'Alpine-9-KHI' ORDER BY id
(257372773) Mon NoGroup "Alpine-9-KHI" check items matched
(257372773) Mon NoEXPAND SELECT id, groupname, attribute, value, op FROM 
radgroupreply WHERE groupname = '%{Sql-Group}' and nas_ip_addr = 
'%{NAS-IP-Address}' ORDER BY id
(257372773) Mon No   --> SELECT id, groupname, attribute, value, op FROM 
radgroupreply WHERE groupname = 'Alpine-9-KHI' and nas_ip_addr = 
'192.168.247.70' ORDER BY id
(257372773) Mon NoGroup "Alpine-9-KHI" reply items processed
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [sql] = ok
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [expiration] = noop
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [logintime] = noop
(257372773) WARNING: Mon NoNo "known good" password found for the user.  
Not setting Auth-Type
(257372773) WARNING: Mon NoAuthentication will fail unless a "known 
good" password is available
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [pap] = noop
(257372773) Mon Nov 30 15:11:24 2020 : Debug:  } #  authorize = ok
(257372773) ERROR: Mon Nov 30 15:11:24 2020 : ERROR: No Auth-Type found: 
rejecting the user via Post-Auth-Type = Reject
(257372773) Mon Nov 30 15:11:24 2020 : Debug: Failed to authenticate the 
user
(257372773) Mon Nov 30 15:11:24 2020 : Debug: EXPAND Error: Invalid 
Username/Password...!
(257372773) Mon Nov 30 15:11:24 2020 : Debug:    --> Error: Invalid 
Username/Password...!
(257372773) Mon Nov 30 15:11:24 2020 : Debug: Using Post-Auth-Type Reject
(257372773) Mon Nov 30 15:11:24 2020 : Debug: # Executing group from 
file /etc/raddb/sites-enabled/default
(257372773) Mon Nov 30 15:11:24 2020 : Debug:  Post-Auth-Type REJECT {
(257372773) Mon NoEXPAND .query
(257372773) Mon No   --> .query
(257372773) Mon NoUsing query template 'query'
(257372773) Mon NoEXPAND %{User-Name}
(257372773) Mon No   --> test
(257372773) Mon NoSQL-User-Name set to 'test'
(257372773) Mon NoEXPAND INSERT INTO radpostauth (username, pass, reply, 
authdate, CallingStationId, NASPortId, nasipaddress) VALUES ( 
'%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', 
'%{reply:Packet-Type}', '%S', '%{Calling-Station-Id}', '%{NAS-Port-Id}', 
'%{NAS-IP-Address}')
(257372773) Mon No   --> INSERT INTO radpostauth (username, pass, reply, 
authdate, CallingStationId, NASPortId, nasipaddress) VALUES ( 'test', 
'', 'Access-Reject', '2020-11-30 15:11:24', '', '', '192.168.247.70')
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   [sql] = ok
(257372773) Mon Nov 30 15:11:24 2020 : DEXPAND %{User-Name}
(257372773) Mon Nov 30 15:11:24 2020 : D   --> test
(257372773) Mon Nov 30 15:11:24 2020 : DMatched entry DEFAULT at line 11
(257372773) Mon Nov 30 15:11:24 2020 : Debug: 
[attr_filter.access_reject] = updated
(257372773) Mon Nov 30 15:11:24 2020 : Debug: 
remove_reply_message_if_eap remove_reply_message_if_eap {
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&reply:EAP-Message 
&& &reply:Reply-Message)
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     if (&reply:EAP-Message 
&& &reply:Reply-Message) -> FALSE
(257372773) Mon Nov 30 15:11:24 2020 : Debug:    else else {
(257372773) Mon Nov 30 15:11:24 2020 : Debug:     [noop] = noop
(257372773) Mon Nov 30 15:11:24 2020 : Debug:    } # else else = noop
(257372773) Mon Nov 30 15:11:24 2020 : Debug:   } # 
remove_reply_message_if_eap remove_reply_message_if_eap = noop
(257372773) Mon Nov 30 15:11:24 2020 : Debug:  } # Post-Auth-Type REJECT 
= updated
(257372773) Mon Nov 30 15:11:24 2020 : Debug: Delaying response for 1 
seconds
(257372773) Mon Nov 30 15:11:25 2020 : Debug: Sending delayed response
(257372773) Mon Nov 30 15:11:25 2020 : Debug: Sending Access-Reject 
packet to host 192.168.247.70 port 53214, id=108, length=0
(257372773) Mon Nov 30 15:11:34 2020 : Debug: Cleaning up request packet 
ID 108 with timestamp +3880200

-- 


More information about the Freeradius-Users mailing list