At this time, I did a radiusd -X and saw the debug information scroll across the screen, sitting at "ready to process requests"...

However, no requests are coming in. I am attempting this by connecting from

You say it yourself: no request reaches the Radius server. I propose to check if the internal linux firewall isn't blocking incomming packets. First try to disable the firewall: /etc/init.d/iptables stop Then test again the authentication. If it works, reconfigure your firewall: it must accept incoming requests to UDP ports 1812 and 1813. HTH, Thibault

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

Phil Mayers wrote:

That is very odd.

I note you are running custom SQL queries against a union of a password table and a stored procedure - it is possible something occurs inside the stored proc that causes a backend to lock up or start behaving abnormally.

What happens if you execute:

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;

...repeatedly inside "psql" (with a connection using the same parameters at the FreeRadius driver)?

Note that you are incorrect about the connections being "dropped", and that you should not expect round-robin behaviour. The server will open a certain number of sockets. When a request comes in, the server grabs an unused socket from the list, uses it, and returns it. Which socket you get cannot be easily predicted.

...

rlm_sql (auth): Reserving sql socket id: 0 rlm_sql (auth): Released sql socket id: 0

...

Sending Access-Accept of id 38 to 165.146.6.102 port 2322

...

rlm_sql (auth): Reserving sql socket id: 0 rlm_sql (auth): Released sql socket id: 0

...

Sending Access-Reject of id 39 to 165.146.6.102 port 2323

That is, both request went to the same socket (and thus postmaster backend).

I would suggest bumping the logging on postgres and seeing if you can determine why a query against the same backend, on the same connection, fails on subsequent calls. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Hi Phil Thanks to your advice, I have solved the problem. Although it had nothing to do with the user functions that I had created. The culprit was the UNION statement. I don't know why this is the case, but after removing the UNION statement, everything works perfectly. I plan to investigate this and post to you guys so that the community will have a knowledge base. But you can do a simple test. Just union together two SQL statements. Make these statements static (for the test) so that you do not access a table. You will get the same problem that I have. Have you any idea why? Thanks so much for the help. Have a good day. Jack