FreeRADIUS blocked trying to close SQL connection
Hi, I'm having issues when dealing with an Oracle database. When running with -Xxx (timestamps are important here) I see the following: Thu Jul 2 09:31:25 2020 : Debug: (55) if (Stripped-User-Domain == '<REDACTED>') -> TRUE Thu Jul 2 09:31:25 2020 : Debug: (55) if (Stripped-User-Domain == '<REDACTED>') { Thu Jul 2 09:31:25 2020 : Debug: (55) update control { Thu Jul 2 09:31:25 2020 : Debug: (55) &Tmp-Integer-0 := 2 Thu Jul 2 09:31:25 2020 : Debug: (55) } # update control = noop Thu Jul 2 09:31:25 2020 : Debug: (55) } # if (Stripped-User-Domain == '<REDACTED>') = noop Thu Jul 2 09:31:25 2020 : Debug: (55) ... skipping elsif: Preceding "if" was taken Thu Jul 2 09:31:25 2020 : Debug: (55) ... skipping else: Preceding "if" was taken Thu Jul 2 09:31:25 2020 : Debug: (55) update control { Thu Jul 2 09:31:25 2020 : Info: rlm_sql (sql_oracle_<REDACTED>): Closing connection (25): Hit idle_timeout, was idle for 66328 seconds Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): 0 of 0 connections in use. You may need to increase "spare" Thu Jul 2 09:47:09 2020 : Info: rlm_sql (sql_oracle_<REDACTED>): Opening additional connection (26), 1 of 16 pending slots used Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Reserved connection (26) Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Released connection (26) Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Reserved connection (26) Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Released connection (26) Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Reserved connection (26) Thu Jul 2 09:47:09 2020 : Debug: (55) Executing select query: SELECT <REDACTED> FROM DUAL Thu Jul 2 09:47:09 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Released connection (26) It follows printing (with the same timestamp) all queued requests processing (which are by then useless), and finally: Thu Jul 2 09:47:14 2020 : Debug: (55) Cleaning up request packet ID 151 with timestamp +172989 Thu Jul 2 09:47:15 2020 : Debug: (57) Cleaning up request packet ID 152 with timestamp +173933 Thu Jul 2 09:47:15 2020 : Debug: (59) Cleaning up request packet ID 153 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: (60) Cleaning up request packet ID 154 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: (62) Cleaning up request packet ID 155 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: (64) Cleaning up request packet ID 156 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: (65) Cleaning up request packet ID 157 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: Waking up in 0.3 seconds. Thu Jul 2 09:47:15 2020 : Debug: (82) Cleaning up request packet ID 96 with timestamp +173934 Thu Jul 2 09:47:15 2020 : Debug: Waking up in 4.8 seconds. Thu Jul 2 09:47:20 2020 : Debug: (67) Cleaning up request packet ID 158 with timestamp +173934 Thu Jul 2 09:47:20 2020 : Debug: Waking up in 9.6 seconds. Thu Jul 2 09:47:30 2020 : Debug: (56) Cleaning up request packet ID 75 with timestamp +173933 Thu Jul 2 09:47:30 2020 : Debug: (58) Cleaning up request packet ID 76 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (61) Cleaning up request packet ID 77 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (63) Cleaning up request packet ID 78 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (66) Cleaning up request packet ID 79 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: Waking up in 0.1 seconds. Thu Jul 2 09:47:30 2020 : Debug: (68) Cleaning up request packet ID 80 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (69) Cleaning up request packet ID 81 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (70) Cleaning up request packet ID 82 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (71) Cleaning up request packet ID 83 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (72) Cleaning up request packet ID 84 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (73) Cleaning up request packet ID 85 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (74) Cleaning up request packet ID 86 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (75) Cleaning up request packet ID 87 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (76) Cleaning up request packet ID 88 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (77) Cleaning up request packet ID 89 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (78) Cleaning up request packet ID 90 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (79) Cleaning up request packet ID 91 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (80) Cleaning up request packet ID 92 with timestamp +173934 Thu Jul 2 09:47:30 2020 : Debug: (81) Cleaning up request packet ID 93 with timestamp +173934 That ~16 minutes delay seems to be consistent during these episodes: Sun Jun 28 21:38:55 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Closing expired connection (145): Hit max_uses limit Sun Jun 28 21:54:39 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): 0 of 0 connections in use. You may need to increase "spare" Is it normal to block while closing a SQL connection? Is FreeRADIUS waiting for something all that time? Kind regards, Alberto
On Jul 2, 2020, at 7:52 AM, Alberto Martínez Setién via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I'm having issues when dealing with an Oracle database.
When running with -Xxx (timestamps are important here) I see the following:
Yes, sometimes it's necessary. ...
That ~16 minutes delay seems to be consistent during these episodes:
Sun Jun 28 21:38:55 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): Closing expired connection (145): Hit max_uses limit Sun Jun 28 21:54:39 2020 : Debug: rlm_sql (sql_oracle_<REDACTED>): 0 of 0 connections in use. You may need to increase "spare"
Is it normal to block while closing a SQL connection? Is FreeRADIUS waiting for something all that time?
FreeRADIUS calls the Oracle client libraries to do things like open / close connections. If the connection closing takes 16 minutes, then it's not the fault of FreeRADIUS. What is likely happening is that you have network issues. i.e. TCP connections are being blocked in the network. OR you have a stateful firewall between FreeRADIUS and Oracle, and the firewall is dropping TCP connections. The timeout is likely due to the OS and / or the Oracle library trying to gracefully close a connection. The connection *should* exist, and *does* exist so far as the OS is concerned. However, packets for that connection are dropped by the firewall. The solution here is to ensure that your network works properly. Don't put a firewall between the RADIUS server and the database. Or if you must have a firewall, ensure that it works properly. No amount of poking FreeRADIUS will make your local network work better. You MUST fix the network. Alan DeKok.
participants (2)
-
Alan DeKok -
Alberto Martínez Setién