Freeradius Postgres and Pap problem

Jack Allan jack.j.allan at gmail.com
Sun Jan 21 16:36:27 CET 2007


Alan DeKok wrote:
> Jack Allan wrote:
>   
>>> If in postgressql.conf, I set num_sql_socks to a number x, then when I
>>>       
>> run NTRadPing (or any other Radius client), I am only able to
>> successfully authenticate a user x times. After this, rlm_sql gives up
>> the ghost (at least I think???) and I need to restart the freeradius
>> server for anything to work. When I run in debug mode, it seems as if
>> the sockets are being closed once used (at least thats what it says on
>> the output).
>>     
>
>   Could you please post the exact messages?
>
>   I've never heard of this happening before, and it's not supposed to
> happen.
>
>   Alan DeKok.
> --
>   http://deployingradius.com       - The web site of the book
>   http://deployingradius.com/blog/ - The blog
> - 
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
>   
Hi Alan

The exact messages are in this mail. It is the dump when running radiusd 
-X. Before I show these, let me tell you my setup:
(1) Using freeradius 1.1.4 now (was using 1.1.3 when I first posted on 
the forumn)
(2) Using Postgres 8.2

I should also mention that since my last email, we have totally 
reinstalled the whole system. Another interesting thing to note: When I 
gave bogus SQL requests to my group authorisations (which I do not use 
for my setup), the problem seemed to go away. Upon further 
investigation, we found out that what was happening was that these bogus 
requests were forcing radius to reestablish a connection to postgres 
again from new, and hence a subsequent request was successfull.

I have two SQL instances: Auth (for authentication/authorisation) and 
Acct for accounting. I am not using the authenticate_query as it never 
gets loaded or used.

The test dump I will show you now has set num_sql_sockets to 1. What 
seems to happen is that user-password is not passed as an attribute 
after X authorisation attempts have been made, x being the number of sql 
sockets I specify.

We also watched radius connections to postgres using ps, and we can see 
that these threads are not round robinned, i.e., they are not cycled. 
This is what seems to be the main problem!

And here is the radiusd -X output (after this, I will also include a 
dump of ps):

Starting - reading configuration files ...
reread_config:  reading radiusd.conf
Config:   including file: /usr/local/etc/raddb/clients.conf
Config:   including file: /usr/local/etc/raddb/postgresql.conf
 main: prefix = "/usr/local"
 main: localstatedir = "/home/barry"
 main: logdir = "/home/barry/log/radius"
 main: libdir = "/usr/local/lib"
 main: radacctdir = "/home/barry/log/radius/radacct"
 main: hostname_lookups = no
 main: snmp = no
 main: max_request_time = 30
 main: cleanup_delay = 5
 main: max_requests = 1024
 main: delete_blocked_requests = 0
 main: port = 0
 main: allow_core_dumps = no
 main: log_stripped_names = no
 main: log_file = "/home/barry/log/radius/radius.log"
 main: log_auth = yes
 main: log_auth_badpass = yes
 main: log_auth_goodpass = no
 main: pidfile = "/home/barry/run/radiusd/radiusd.pid"
 main: user = "(null)"
 main: group = "(null)"
 main: usercollide = no
 main: lower_user = "no"
 main: lower_pass = "no"
 main: nospace_user = "no"
 main: nospace_pass = "no"
 main: checkrad = "/usr/local/sbin/checkrad"
 main: proxy_requests = no
 security: max_attributes = 30
 security: reject_delay = 2
 security: status_server = no
 main: debug_level = 0
read_config_files:  reading dictionary
read_config_files:  reading naslist
read_config_files:  reading clients
read_config_files:  reading realms
radiusd:  entering modules setup
Module: Library search path is /usr/local/lib
Module: Loaded exec
 exec: wait = yes
 exec: program = "(null)"
 exec: input_pairs = "request"
 exec: output_pairs = "(null)"
 exec: packet_type = "(null)"
rlm_exec: Wait=yes but no output defined. Did you mean output=none?
Module: Instantiated exec (exec)
Module: Loaded expr
Module: Instantiated expr (expr)
Module: Loaded PAP
 pap: encryption_scheme = "clear"
 pap: auto_header = no
Module: Instantiated pap (pap)
Module: Loaded preprocess
 preprocess: huntgroups = "/usr/local/etc/raddb/huntgroups"
 preprocess: hints = "/usr/local/etc/raddb/hints"
 preprocess: with_ascend_hack = no
 preprocess: ascend_channels_per_line = 23
 preprocess: with_ntdomain_hack = no
 preprocess: with_specialix_jetstream_hack = no
 preprocess: with_cisco_vsa_hack = no
 preprocess: with_alvarion_vsa_hack = no
Module: Instantiated preprocess (preprocess)
Module: Loaded files
 files: usersfile = "/usr/local/etc/raddb/users"
 files: acctusersfile = "/usr/local/etc/raddb/acct_users"
 files: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"
 files: compat = "no"
Module: Instantiated files (files)
Module: Loaded SQL
 sql: driver = "rlm_sql_postgresql"
 sql: server = "localhost"
 sql: port = ""
 sql: login = "radiusd"
 sql: password = "dESEwwvSr4"
 sql: radius_db = "redbutton"
 sql: nas_table = "nas"
 sql: sqltrace = yes
 sql: sqltracefile = "/home/barry/log/radius/sqltrace.sql"
 sql: readclients = no
 sql: deletestalesessions = yes
 sql: num_sql_socks = 1
 sql: sql_user_name = "%{User-Name}"
 sql: default_user_profile = ""
 sql: query_on_not_found = no
 sql: authorize_check_query = " ?  SELECT -1 AS id, 
username,'User-Password' AS attribute, password AS value, '==' AS op 
??FROM raduser?WHERE username = '%{SQL-User-Name}'?UNION SELECT * FROM 
radius_authorise_check('%{SQL-User-Name}','%{NAS-Identifier}') ORDER BY id;"
 sql: authorize_reply_query = "SELECT * FROM 
radius_authorise_reply('%{SQL-User-Name}','%{NAS-Identifier}');"
 sql: authorize_group_check_query = ""
 sql: authorize_group_reply_query = ""
 sql: accounting_onoff_query = ""
 sql: accounting_update_query = ""
 sql: accounting_update_query_alt = ""
 sql: accounting_start_query = ""
 sql: accounting_start_query_alt = ""
 sql: accounting_stop_query = ""
 sql: accounting_stop_query_alt = ""
 sql: group_membership_query = ""
 sql: connect_failure_retry_delay = 60
 sql: simul_count_query = ""
 sql: simul_verify_query = ""
 sql: postauth_query = ""
 sql: safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
rlm_sql (auth): Driver rlm_sql_postgresql (module rlm_sql_postgresql) 
loaded and linked
rlm_sql (auth): Attempting to connect to radiusd at localhost:/redbutton
rlm_sql (auth): starting 0
rlm_sql (auth): Attempting to connect rlm_sql_postgresql #0
rlm_sql (auth): Connected new DB handle, #0
Module: Instantiated sql (auth)
Module: Loaded Acct-Unique-Session-Id
 acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, 
Client-IP-Address, NAS-Port"
Module: Instantiated acct_unique (acct_unique)
Module: Loaded detail
 detail: detailfile = 
"/home/barry/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
 detail: detailperm = 384
 detail: dirperm = 493
 detail: locking = no
Module: Instantiated detail (detail)
Module: Loaded System
 unix: cache = no
 unix: passwd = "(null)"
 unix: shadow = "(null)"
 unix: group = "(null)"
 unix: radwtmp = "/home/barry/log/radius/radwtmp"
 unix: usegroup = no
 unix: cache_reload = 600
Module: Instantiated unix (unix)
Module: Loaded radutmp
 radutmp: filename = "/home/barry/log/radius/radutmp"
 radutmp: username = "%{User-Name}"
 radutmp: case_sensitive = yes
 radutmp: check_with_nas = yes
 radutmp: perm = 384
 radutmp: callerid = yes
Module: Instantiated radutmp (radutmp)
 sql: driver = "rlm_sql_postgresql"
 sql: server = "localhost"
 sql: port = ""
 sql: login = "radiusd"
 sql: password = "dESEwwvSr4"
 sql: radius_db = "redbutton"
 sql: nas_table = "nas"
 sql: sqltrace = no
 sql: sqltracefile = "/var/log/sqltrace.sql"
 sql: readclients = no
 sql: deletestalesessions = yes
 sql: num_sql_socks = 5
 sql: sql_user_name = "%{User-Name}"
 sql: default_user_profile = ""
 sql: query_on_not_found = no
 sql: authorize_check_query = ""
 sql: authorize_reply_query = ""
 sql: authorize_group_check_query = ""
 sql: authorize_group_reply_query = ""
 sql: accounting_onoff_query = ""
 sql: accounting_update_query = "SELECT 
accounting_update('%S'::timestamp with time zone, 
'%{Acct-Delay-Time:-0}'::interval, ((%{Acct-Input-Gigawords:-0}<< 32) + 
%{Acct-Input-Octets:-0})::bigint, ((%{Acct-Output-Gigawords:-0} << 32) + 
%{Acct-Output-Octets:-0})::bigint, '%{SQL-User-Name}'::text, 
'%{Acct-Session-Id}'::text, '%{Acct-Unique-Session-Id}'::text);"
 sql: accounting_update_query_alt = ""
 sql: accounting_start_query = "SELECT 
accounting_start('%{Acct-Session-Id}', 
'%{Acct-Unique-Session-Id}','%{SQL-User-Name}', ('%S'::timestamp - 
'%{Acct-Delay-Time:-0}'::interval), %{Acct-Delay-Time:-0}, 
'%{NAS-Identifier}');"
 sql: accounting_start_query_alt = ""
 sql: accounting_stop_query = "SELECT accounting_stop('%S'::timestamp - 
'%{Acct-Delay-Time:-0}'::interval, NULLIF(%{Acct-Session-Time}, 
0)::bigint, (%{Acct-Input-Gigawords:-0}::bigint << 32) + 
%{Acct-Input-Octets:-0}::bigint, (%{Acct-Output-Gigawords:-0}::bigint << 
32) + %{Acct-Output-Octets:-0}::bigint, %{Acct-Delay-Time:-0}::int, 
'%{Acct-Session-Id}'::text, '%{Acct-Unique-Session-Id}'::text, 
'%{SQL-User-Name}'::text)"
 sql: accounting_stop_query_alt = ""
 sql: group_membership_query = ""
 sql: connect_failure_retry_delay = 60
 sql: simul_count_query = ""
 sql: simul_verify_query = ""
 sql: postauth_query = ""
 sql: safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
rlm_sql (acct): Driver rlm_sql_postgresql (module rlm_sql_postgresql) 
loaded and linked
rlm_sql (acct): Attempting to connect to radiusd at localhost:/redbutton
rlm_sql (acct): starting 0
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #0
rlm_sql (acct): Connected new DB handle, #0
rlm_sql (acct): starting 1
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #1
rlm_sql (acct): Connected new DB handle, #1
rlm_sql (acct): starting 2
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #2
rlm_sql (acct): Connected new DB handle, #2
rlm_sql (acct): starting 3
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #3
rlm_sql (acct): Connected new DB handle, #3
rlm_sql (acct): starting 4
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #4
rlm_sql (acct): Connected new DB handle, #4
Module: Instantiated sql (acct)
 detail: detailfile = 
"/home/barry/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d"
 detail: detailperm = 384
 detail: dirperm = 493
 detail: locking = no
Module: Instantiated detail (reply_log)
Listening on authentication *:1812
Listening on accounting *:1813
Ready to process requests.
rad_recv: Access-Request packet from host 165.146.6.102:2322, id=38, 
length=58
        User-Name = "jack"
        User-Password = "hello"
        NAS-Identifier = "skyrove_bree"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
    users: Matched entry DEFAULT at line 1
  modcall[authorize]: module "files" returns ok for request 0
radius_xlat:  'jack'
rlm_sql (auth): sql_set_user escaped user --> 'jack'
radius_xlat:  ' ?  SELECT -1 AS id, username,'User-Password' AS 
attribute, password AS value, '==' AS op ??FROM raduser?WHERE username = 
'jack'?UNION SELECT * FROM radius_authorise_check('jack','skyrove_bree') 
ORDER BY id;'
rlm_sql (auth): Reserving sql socket id: 0
rlm_sql_postgresql: query:  ?  SELECT -1 AS id, username,'User-Password' 
AS attribute, password AS value, '==' AS op ??FROM raduser?WHERE 
username = 'jack'?UNION SELECT * FROM 
radius_authorise_check('jack','skyrove_bree') ORDER BY id;
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  ''
radius_xlat:  'SELECT * FROM radius_authorise_reply('jack','skyrove_bree');'
rlm_sql_postgresql: query: SELECT * FROM 
radius_authorise_reply('jack','skyrove_bree');
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  ''
rlm_sql (auth): Released sql socket id: 0
  modcall[authorize]: module "auth" returns ok for request 0
modcall: leaving group authorize (returns ok) for request 0
  rad_check_password:  Found Auth-Type Pap
auth: type "PAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group PAP for request 0
rlm_pap: login attempt with password hello
rlm_pap: Using clear text password.
rlm_pap: User authenticated succesfully
  modcall[authenticate]: module "pap" returns ok for request 0
modcall: leaving group PAP (returns ok) for request 0
Login OK: [jack] (from client redbuttonnas port 0)
  Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 0
radius_xlat:  
'/home/barry/log/radius/radacct/165.146.6.102/reply-detail-20070121'
rlm_detail: 
/home/barry/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d 
expands to 
/home/barry/log/radius/radacct/165.146.6.102/reply-detail-20070121
  modcall[post-auth]: module "reply_log" returns ok for request 0
modcall: leaving group post-auth (returns ok) for request 0
Sending Access-Accept of id 38 to 165.146.6.102 port 2322
        Session-Timeout := 2700
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 165.146.6.102:2323, id=39, 
length=58
        User-Name = "jack"
        User-Password = "hello"
        NAS-Identifier = "skyrove_bree"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
  modcall[authorize]: module "preprocess" returns ok for request 1
    users: Matched entry DEFAULT at line 1
  modcall[authorize]: module "files" returns ok for request 1
radius_xlat:  'jack'
rlm_sql (auth): sql_set_user escaped user --> 'jack'
radius_xlat:  ' ?  SELECT -1 AS id, username,'User-Password' AS 
attribute, password AS value, '==' AS op ??FROM raduser?WHERE username = 
'jack'?UNION SELECT * FROM radius_authorise_check('jack','skyrove_bree') 
ORDER BY id;'
rlm_sql (auth): Reserving sql socket id: 0
rlm_sql_postgresql: query:  ?  SELECT -1 AS id, username,'User-Password' 
AS attribute, password AS value, '==' AS op ??FROM raduser?WHERE 
username = 'jack'?UNION SELECT * FROM 
radius_authorise_check('jack','skyrove_bree') ORDER BY id;
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  ''
radius_xlat:  'SELECT * FROM radius_authorise_reply('jack','skyrove_bree');'
rlm_sql_postgresql: query: SELECT * FROM 
radius_authorise_reply('jack','skyrove_bree');
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat:  ''
rlm_sql (auth): Released sql socket id: 0
  modcall[authorize]: module "auth" returns ok for request 1
modcall: leaving group authorize (returns ok) for request 1
  rad_check_password:  Found Auth-Type Pap
auth: type "PAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group PAP for request 1
rlm_pap: login attempt with password hello
rlm_pap: No password configured for the user.  Cannot do authentication
  modcall[authenticate]: module "pap" returns fail for request 1
modcall: leaving group PAP (returns fail) for request 1
auth: Failed to validate the user.
Login incorrect: [jack/hello] (from client redbuttonnas port 0)
Delaying request 1 for 2 seconds
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 2 seconds...
--- Walking the entire request list ---
Waking up in 2 seconds...
rad_recv: Access-Request packet from host 165.146.6.102:2323, id=39, 
length=58
Sending Access-Reject of id 39 to 165.146.6.102 port 2323
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 38 with timestamp 45b35aa4
Waking up in 2 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 39 with timestamp 45b35aa6
Nothing to do.  Sleeping until we see a request.

And here is the output of clear && ps auxww | grep "postgres: radius"

pgsql 41099  0.0  1.5 39076  7516  ??  Is    3:24PM   0:00.04 postgres: 
radiusd redbutton ::1(62480) idle (postgres)
pgsql 41100  0.0  1.5 39116  7560  ??  Ss    3:24PM   0:00.04 postgres: 
radiusd redbutton ::1(62481) idle (postgres)

As you can see, both processes are using 04

Thanks in advance
Jack


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20070121/14071911/attachment.html>


More information about the Freeradius-Users mailing list