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@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@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