FreeRADIUS blocked trying to close SQL connection

classic Classic list List threaded Threaded
2 messages Options
| Threaded
Open this post in threaded view
|

FreeRADIUS blocked trying to close SQL connection

Users mailing list
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
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
| Threaded
Open this post in threaded view
|

Re: FreeRADIUS blocked trying to close SQL connection

Alan DeKok-2
On Jul 2, 2020, at 7:52 AM, Alberto Martínez Setién via Freeradius-Users <[hidden email]> 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.


-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html