<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type">
<title></title>
</head>
<body bgcolor="#ffffff" text="#000000">
Alan DeKok wrote:
<blockquote cite="mid45B1CAEB.5000608@deployingradius.com" type="cite">
<pre wrap="">Jack Allan wrote:
</pre>
<blockquote type="cite">
<blockquote type="cite">
<pre wrap="">If in postgressql.conf, I set num_sql_socks to a number x, then when I
</pre>
</blockquote>
<pre wrap="">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).
</pre>
</blockquote>
<pre wrap=""><!---->
Could you please post the exact messages?
I've never heard of this happening before, and it's not supposed to
happen.
Alan DeKok.
--
<a class="moz-txt-link-freetext" href="http://deployingradius.com">http://deployingradius.com</a> - The web site of the book
<a class="moz-txt-link-freetext" href="http://deployingradius.com/blog/">http://deployingradius.com/blog/</a> - The blog
-
List info/subscribe/unsubscribe? See <a class="moz-txt-link-freetext" href="http://www.freeradius.org/list/users.html">http://www.freeradius.org/list/users.html</a>
</pre>
</blockquote>
Hi Alan<br>
<br>
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:<br>
(1) Using freeradius 1.1.4 now (was using 1.1.3 when I first posted on
the forumn)<br>
(2) Using Postgres 8.2<br>
<br>
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.<br>
<br>
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.<br>
<br>
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.<br>
<br>
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!<br>
<br>
And here is the radiusd -X output (after this, I will also include a
dump of ps):<br>
<br>
Starting - reading configuration files ...<br>
reread_config: reading radiusd.conf<br>
Config: including file: /usr/local/etc/raddb/clients.conf<br>
Config: including file: /usr/local/etc/raddb/postgresql.conf<br>
main: prefix = "/usr/local"<br>
main: localstatedir = "/home/barry"<br>
main: logdir = "/home/barry/log/radius"<br>
main: libdir = "/usr/local/lib"<br>
main: radacctdir = "/home/barry/log/radius/radacct"<br>
main: hostname_lookups = no<br>
main: snmp = no<br>
main: max_request_time = 30<br>
main: cleanup_delay = 5<br>
main: max_requests = 1024<br>
main: delete_blocked_requests = 0<br>
main: port = 0<br>
main: allow_core_dumps = no<br>
main: log_stripped_names = no<br>
main: log_file = "/home/barry/log/radius/radius.log"<br>
main: log_auth = yes<br>
main: log_auth_badpass = yes<br>
main: log_auth_goodpass = no<br>
main: pidfile = "/home/barry/run/radiusd/radiusd.pid"<br>
main: user = "(null)"<br>
main: group = "(null)"<br>
main: usercollide = no<br>
main: lower_user = "no"<br>
main: lower_pass = "no"<br>
main: nospace_user = "no"<br>
main: nospace_pass = "no"<br>
main: checkrad = "/usr/local/sbin/checkrad"<br>
main: proxy_requests = no<br>
security: max_attributes = 30<br>
security: reject_delay = 2<br>
security: status_server = no<br>
main: debug_level = 0<br>
read_config_files: reading dictionary<br>
read_config_files: reading naslist<br>
read_config_files: reading clients<br>
read_config_files: reading realms<br>
radiusd: entering modules setup<br>
Module: Library search path is /usr/local/lib<br>
Module: Loaded exec<br>
exec: wait = yes<br>
exec: program = "(null)"<br>
exec: input_pairs = "request"<br>
exec: output_pairs = "(null)"<br>
exec: packet_type = "(null)"<br>
rlm_exec: Wait=yes but no output defined. Did you mean output=none?<br>
Module: Instantiated exec (exec)<br>
Module: Loaded expr<br>
Module: Instantiated expr (expr)<br>
Module: Loaded PAP<br>
pap: encryption_scheme = "clear"<br>
pap: auto_header = no<br>
Module: Instantiated pap (pap)<br>
Module: Loaded preprocess<br>
preprocess: huntgroups = "/usr/local/etc/raddb/huntgroups"<br>
preprocess: hints = "/usr/local/etc/raddb/hints"<br>
preprocess: with_ascend_hack = no<br>
preprocess: ascend_channels_per_line = 23<br>
preprocess: with_ntdomain_hack = no<br>
preprocess: with_specialix_jetstream_hack = no<br>
preprocess: with_cisco_vsa_hack = no<br>
preprocess: with_alvarion_vsa_hack = no<br>
Module: Instantiated preprocess (preprocess)<br>
Module: Loaded files<br>
files: usersfile = "/usr/local/etc/raddb/users"<br>
files: acctusersfile = "/usr/local/etc/raddb/acct_users"<br>
files: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"<br>
files: compat = "no"<br>
Module: Instantiated files (files)<br>
Module: Loaded SQL<br>
sql: driver = "rlm_sql_postgresql"<br>
sql: server = "localhost"<br>
sql: port = ""<br>
sql: login = "radiusd"<br>
sql: password = "dESEwwvSr4"<br>
sql: radius_db = "redbutton"<br>
sql: nas_table = "nas"<br>
sql: sqltrace = yes<br>
sql: sqltracefile = "/home/barry/log/radius/sqltrace.sql"<br>
sql: readclients = no<br>
sql: deletestalesessions = yes<br>
sql: num_sql_socks = 1<br>
sql: sql_user_name = "%{User-Name}"<br>
sql: default_user_profile = ""<br>
sql: query_on_not_found = no<br>
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;"<br>
sql: authorize_reply_query = "SELECT * FROM
radius_authorise_reply('%{SQL-User-Name}','%{NAS-Identifier}');"<br>
sql: authorize_group_check_query = ""<br>
sql: authorize_group_reply_query = ""<br>
sql: accounting_onoff_query = ""<br>
sql: accounting_update_query = ""<br>
sql: accounting_update_query_alt = ""<br>
sql: accounting_start_query = ""<br>
sql: accounting_start_query_alt = ""<br>
sql: accounting_stop_query = ""<br>
sql: accounting_stop_query_alt = ""<br>
sql: group_membership_query = ""<br>
sql: connect_failure_retry_delay = 60<br>
sql: simul_count_query = ""<br>
sql: simul_verify_query = ""<br>
sql: postauth_query = ""<br>
sql: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"<br>
rlm_sql (auth): Driver rlm_sql_postgresql (module rlm_sql_postgresql)
loaded and linked<br>
rlm_sql (auth): Attempting to connect to radiusd@localhost:/redbutton<br>
rlm_sql (auth): starting 0<br>
rlm_sql (auth): Attempting to connect rlm_sql_postgresql #0<br>
rlm_sql (auth): Connected new DB handle, #0<br>
Module: Instantiated sql (auth)<br>
Module: Loaded Acct-Unique-Session-Id<br>
acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address,
Client-IP-Address, NAS-Port"<br>
Module: Instantiated acct_unique (acct_unique)<br>
Module: Loaded detail<br>
detail: detailfile =
"/home/barry/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"<br>
detail: detailperm = 384<br>
detail: dirperm = 493<br>
detail: locking = no<br>
Module: Instantiated detail (detail)<br>
Module: Loaded System<br>
unix: cache = no<br>
unix: passwd = "(null)"<br>
unix: shadow = "(null)"<br>
unix: group = "(null)"<br>
unix: radwtmp = "/home/barry/log/radius/radwtmp"<br>
unix: usegroup = no<br>
unix: cache_reload = 600<br>
Module: Instantiated unix (unix)<br>
Module: Loaded radutmp<br>
radutmp: filename = "/home/barry/log/radius/radutmp"<br>
radutmp: username = "%{User-Name}"<br>
radutmp: case_sensitive = yes<br>
radutmp: check_with_nas = yes<br>
radutmp: perm = 384<br>
radutmp: callerid = yes<br>
Module: Instantiated radutmp (radutmp)<br>
sql: driver = "rlm_sql_postgresql"<br>
sql: server = "localhost"<br>
sql: port = ""<br>
sql: login = "radiusd"<br>
sql: password = "dESEwwvSr4"<br>
sql: radius_db = "redbutton"<br>
sql: nas_table = "nas"<br>
sql: sqltrace = no<br>
sql: sqltracefile = "/var/log/sqltrace.sql"<br>
sql: readclients = no<br>
sql: deletestalesessions = yes<br>
sql: num_sql_socks = 5<br>
sql: sql_user_name = "%{User-Name}"<br>
sql: default_user_profile = ""<br>
sql: query_on_not_found = no<br>
sql: authorize_check_query = ""<br>
sql: authorize_reply_query = ""<br>
sql: authorize_group_check_query = ""<br>
sql: authorize_group_reply_query = ""<br>
sql: accounting_onoff_query = ""<br>
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);"<br>
sql: accounting_update_query_alt = ""<br>
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}');"<br>
sql: accounting_start_query_alt = ""<br>
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)"<br>
sql: accounting_stop_query_alt = ""<br>
sql: group_membership_query = ""<br>
sql: connect_failure_retry_delay = 60<br>
sql: simul_count_query = ""<br>
sql: simul_verify_query = ""<br>
sql: postauth_query = ""<br>
sql: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"<br>
rlm_sql (acct): Driver rlm_sql_postgresql (module rlm_sql_postgresql)
loaded and linked<br>
rlm_sql (acct): Attempting to connect to radiusd@localhost:/redbutton<br>
rlm_sql (acct): starting 0<br>
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #0<br>
rlm_sql (acct): Connected new DB handle, #0<br>
rlm_sql (acct): starting 1<br>
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #1<br>
rlm_sql (acct): Connected new DB handle, #1<br>
rlm_sql (acct): starting 2<br>
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #2<br>
rlm_sql (acct): Connected new DB handle, #2<br>
rlm_sql (acct): starting 3<br>
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #3<br>
rlm_sql (acct): Connected new DB handle, #3<br>
rlm_sql (acct): starting 4<br>
rlm_sql (acct): Attempting to connect rlm_sql_postgresql #4<br>
rlm_sql (acct): Connected new DB handle, #4<br>
Module: Instantiated sql (acct)<br>
detail: detailfile =
"/home/barry/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d"<br>
detail: detailperm = 384<br>
detail: dirperm = 493<br>
detail: locking = no<br>
Module: Instantiated detail (reply_log)<br>
Listening on authentication *:1812<br>
Listening on accounting *:1813<br>
Ready to process requests.<br>
rad_recv: Access-Request packet from host 165.146.6.102:2322, id=38,
length=58<br>
User-Name = "jack"<br>
User-Password = "hello"<br>
NAS-Identifier = "skyrove_bree"<br>
Processing the authorize section of radiusd.conf<br>
modcall: entering group authorize for request 0<br>
modcall[authorize]: module "preprocess" returns ok for request 0<br>
users: Matched entry DEFAULT at line 1<br>
modcall[authorize]: module "files" returns ok for request 0<br>
radius_xlat: 'jack'<br>
rlm_sql (auth): sql_set_user escaped user --> 'jack'<br>
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;'<br>
rlm_sql (auth): Reserving sql socket id: 0<br>
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;<br>
rlm_sql_postgresql: Status: PGRES_TUPLES_OK<br>
rlm_sql_postgresql: affected rows =<br>
radius_xlat: ''<br>
radius_xlat: 'SELECT * FROM
radius_authorise_reply('jack','skyrove_bree');'<br>
rlm_sql_postgresql: query: SELECT * FROM
radius_authorise_reply('jack','skyrove_bree');<br>
rlm_sql_postgresql: Status: PGRES_TUPLES_OK<br>
rlm_sql_postgresql: affected rows =<br>
radius_xlat: ''<br>
rlm_sql (auth): Released sql socket id: 0<br>
modcall[authorize]: module "auth" returns ok for request 0<br>
modcall: leaving group authorize (returns ok) for request 0<br>
rad_check_password: Found Auth-Type Pap<br>
auth: type "PAP"<br>
Processing the authenticate section of radiusd.conf<br>
modcall: entering group PAP for request 0<br>
rlm_pap: login attempt with password hello<br>
rlm_pap: Using clear text password.<br>
rlm_pap: User authenticated succesfully<br>
modcall[authenticate]: module "pap" returns ok for request 0<br>
modcall: leaving group PAP (returns ok) for request 0<br>
Login OK: [jack] (from client redbuttonnas port 0)<br>
Processing the post-auth section of radiusd.conf<br>
modcall: entering group post-auth for request 0<br>
radius_xlat:
'/home/barry/log/radius/radacct/165.146.6.102/reply-detail-20070121'<br>
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<br>
modcall[post-auth]: module "reply_log" returns ok for request 0<br>
modcall: leaving group post-auth (returns ok) for request 0<br>
Sending Access-Accept of id 38 to 165.146.6.102 port 2322<br>
Session-Timeout := 2700<br>
Finished request 0<br>
Going to the next request<br>
--- Walking the entire request list ---<br>
Waking up in 6 seconds...<br>
rad_recv: Access-Request packet from host 165.146.6.102:2323, id=39,
length=58<br>
User-Name = "jack"<br>
User-Password = "hello"<br>
NAS-Identifier = "skyrove_bree"<br>
Processing the authorize section of radiusd.conf<br>
modcall: entering group authorize for request 1<br>
modcall[authorize]: module "preprocess" returns ok for request 1<br>
users: Matched entry DEFAULT at line 1<br>
modcall[authorize]: module "files" returns ok for request 1<br>
radius_xlat: 'jack'<br>
rlm_sql (auth): sql_set_user escaped user --> 'jack'<br>
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;'<br>
rlm_sql (auth): Reserving sql socket id: 0<br>
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;<br>
rlm_sql_postgresql: Status: PGRES_TUPLES_OK<br>
rlm_sql_postgresql: affected rows =<br>
radius_xlat: ''<br>
radius_xlat: 'SELECT * FROM
radius_authorise_reply('jack','skyrove_bree');'<br>
rlm_sql_postgresql: query: SELECT * FROM
radius_authorise_reply('jack','skyrove_bree');<br>
rlm_sql_postgresql: Status: PGRES_TUPLES_OK<br>
rlm_sql_postgresql: affected rows =<br>
radius_xlat: ''<br>
rlm_sql (auth): Released sql socket id: 0<br>
modcall[authorize]: module "auth" returns ok for request 1<br>
modcall: leaving group authorize (returns ok) for request 1<br>
rad_check_password: Found Auth-Type Pap<br>
auth: type "PAP"<br>
Processing the authenticate section of radiusd.conf<br>
modcall: entering group PAP for request 1<br>
rlm_pap: login attempt with password hello<br>
rlm_pap: No password configured for the user. Cannot do authentication<br>
modcall[authenticate]: module "pap" returns fail for request 1<br>
modcall: leaving group PAP (returns fail) for request 1<br>
auth: Failed to validate the user.<br>
Login incorrect: [jack/hello] (from client redbuttonnas port 0)<br>
Delaying request 1 for 2 seconds<br>
Finished request 1<br>
Going to the next request<br>
--- Walking the entire request list ---<br>
Waking up in 2 seconds...<br>
--- Walking the entire request list ---<br>
Waking up in 2 seconds...<br>
rad_recv: Access-Request packet from host 165.146.6.102:2323, id=39,
length=58<br>
Sending Access-Reject of id 39 to 165.146.6.102 port 2323<br>
--- Walking the entire request list ---<br>
Waking up in 1 seconds...<br>
--- Walking the entire request list ---<br>
Cleaning up request 0 ID 38 with timestamp 45b35aa4<br>
Waking up in 2 seconds...<br>
--- Walking the entire request list ---<br>
Cleaning up request 1 ID 39 with timestamp 45b35aa6<br>
Nothing to do. Sleeping until we see a request.<br>
<br>
And here is the output of clear && ps auxww | grep "postgres:
radius"<br>
<br>
pgsql 41099 0.0 1.5 39076 7516 ?? Is 3:24PM 0:00.04 postgres:
radiusd redbutton ::1(62480) idle (postgres)<br>
pgsql 41100 0.0 1.5 39116 7560 ?? Ss 3:24PM 0:00.04 postgres:
radiusd redbutton ::1(62481) idle (postgres)<br>
<br>
As you can see, both processes are using 04 <br>
<br>
Thanks in advance<br>
Jack<br>
<br>
<br>
</body>
</html>