FreeRADIUS blocked trying to close SQL connection

[Alberto Martínez Setién]

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