unavailable database makes freeradius 3.0.9 server unresponsive
Hello, We found a problem in freeradius 3.0.9 when database (mysql as well as redis) is not working for a while. Server: Ubuntu 14.04, fresh install of freeradius 3.0.9 compiled from sources using default settings. When database is going down server hangs on first processed request and stops processing any further requests. There is no connection timeout nor any other timeout to database request. In freeradius 2.x when database was not available server responded with Reject until database was on. In freeradius 3.0.9 server stops responding to any requests, even when database comes up. Below there is an example with redis module. The same problem we have when mysql server goes down. After redis is stopped: Fri Jul 24 17:44:34 2015 : Debug: (1) policy usercache.authorize { Fri Jul 24 17:44:34 2015 : Debug: (1) update request { Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): Reserved connection (3) Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): executing the query: "exists map/usercache/id/" Fri Jul 24 17:44:34 2015 : ERROR: (1) Server closed the connection Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): Reconnecting (3) Fri Jul 24 17:44:34 2015 : Error: rlm_redis (redis): Problems with redisConnect('10.113.13.245', 6379), Connection refused There are no other messages on screen when in radius -XXX mode. There is no timeout for such operation thus server stops processing any requests. When redis goes up few seconds later it does not enable processing requests. When radiusd works as a service in the log we have: Fri Jul 24 17:50:00 2015 : Info: Ready to process requests ****** First radiusclient requests Fri Jul 24 17:50:21 2015 : Info: rlm_redis (redis): 0 of 5 connections in use. Need more spares Fri Jul 24 17:50:21 2015 : Info: rlm_redis (redis): Opening additional connection (5), 1 of 27 pending slots used Fri Jul 24 17:50:21 2015 : Info: rlm_sql (sql): 0 of 5 connections in use. Need more spares Fri Jul 24 17:50:21 2015 : Info: rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used Fri Jul 24 17:50:21 2015 : Auth: (0) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [test8/test] (from client stage-client port 0) Fri Jul 24 17:50:33 2015 : Info: rlm_redis (redis): Closing connection (3): Hit idle_timeout, was idle for 34 seconds Fri Jul 24 17:50:33 2015 : Info: rlm_redis (redis): Closing connection (4): Hit idle_timeout, was idle for 33 seconds ****** REDIS STOP + 2 radiusclient requests Fri Jul 24 17:50:33 2015 : ERROR: (1) ERROR: Server closed the connection Fri Jul 24 17:50:33 2015 : Error: rlm_redis (redis): Problems with redisConnect('10.113.13.245', 6379), Connection refused Fri Jul 24 17:50:38 2015 : Error: (1) Ignoring duplicate packet from client stage-client port 57494 - ID: 197 due to unfinished request in component authorize module Fri Jul 24 17:50:43 2015 : Error: (1) Ignoring duplicate packet from client stage-client port 57494 - ID: 197 due to unfinished request in component authorize module Fri Jul 24 17:50:57 2015 : Error: (2) Ignoring duplicate packet from client stage-client port 42331 - ID: 188 due to unfinished request in component authorize module Fri Jul 24 17:51:02 2015 : Error: (2) Ignoring duplicate packet from client stage-client port 42331 - ID: 188 due to unfinished request in component authorize module Fri Jul 24 17:51:11 2015 : Error: Unresponsive child for request 1, in component authorize module Fri Jul 24 17:51:30 2015 : Error: Unresponsive child for request 2, in component authorize module ****** REDIS START + 1 radiusclient request Fri Jul 24 17:52:24 2015 : Error: (3) Ignoring duplicate packet from client stage-client port 51752 - ID: 89 due to unfinished request in component authorize module Fri Jul 24 17:52:29 2015 : Error: (3) Ignoring duplicate packet from client stage-client port 51752 - ID: 89 due to unfinished request in component authorize module Fri Jul 24 17:52:57 2015 : Error: Unresponsive child for request 3, in component authorize module How to reproduce the issue: 1. Make a request to the freeradius server using radiusclient. 2. Stop the database server. 3. Make another connection to the freeradius server using radiusclient. (the client request will time-out...) 4. Start the database server. 5. All following radiusclient requests will time out. Can anybody suggest what shall be reconfigured in order to keep freeradius responding and properly get Access-reject response when database is unavailable? Mike ________________________________________ Uwaga: Tre?? niniejszej wiadomo?ci mo?e by? poufna i obj?ta zakazem jej ujawniania. Je?li czytelnik tej wiadomo?ci nie jest jej zamierzonym adresatem, pracownikiem lub po?rednikiem upowa?nionym do jej przekazania adresatowi, informujemy ?e wszelkie rozprowadzanie, rozpowszechnianie lub powielanie niniejszej wiadomo?ci jest zabronione. Je?li otrzyma?e? t? wiadomo?? omy?kowo, prosz? bezzw?ocznie odes?a? j? nadawcy, a sam? wiadomo?? usun?? z komputera. Dzi?kujemy. ________________________________ Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited.If you have received this communication in error, please notify the sender immediately by replying to the message and deleting it from your computer. Thank you. ________________________________
On Jul 27, 2015, at 11:06 AM, Michal Tomaszewski <Michal.Tomaszewski@cca.pl> wrote:
When database is going down server hangs on first processed request and stops processing any further requests. There is no connection timeout nor any other timeout to database request.
That may happen, especially when the client library for the back-end database locks.
In freeradius 2.x when database was not available server responded with Reject until database was on. In freeradius 3.0.9 server stops responding to any requests, even when database comes up.
Hmm... that's bad.
Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): Reconnecting (3)
Fri Jul 24 17:44:34 2015 : Error: rlm_redis (redis): Problems with redisConnect('10.113.13.245', 6379), Connection refused
That's the problem code. It's something Arran changed recently... Alan DeKok.
On Jul 27, 2015, at 11:06 AM, Michal Tomaszewski <Michal.Tomaszewski@cca.pl> wrote:
When database is going down server hangs on first processed request and stops processing any further requests. There is no connection timeout nor any other timeout to database request.
That may happen, especially when the client library for the back-end database locks.
Yes, but there was a timeout and process was not locked indefinitely. Other requests were processed properly. In 3.0.9 it hangs all the processing.
In freeradius 2.x when database was not available server responded with Reject until database was on. In freeradius 3.0.9 server stops responding to any requests, even when database comes up.
Hmm... that's bad.
Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): Reconnecting (3)
Fri Jul 24 17:44:34 2015 : Error: rlm_redis (redis): Problems with redisConnect('10.113.13.245', 6379), Connection refused
That's the problem code. It's something Arran changed recently...
I've made the same test when sql server is down: Mon Jul 27 17:25:02 2015 : Debug: (2) sql: Executing select query: SELECT id, username, attribute, value, op FROM radius_radcheck WHERE username = 'test8' AND (hotspot_id is null OR hotspot_id = '0' ) ORDER BY id Mon Jul 27 17:25:02 2015 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Mon Jul 27 17:25:02 2015 : Debug: rlm_sql (sql): Reconnecting (0) Mon Jul 27 17:25:02 2015 : Debug: rlm_sql_mysql: Starting connect to MySQL server Mon Jul 27 17:25:02 2015 : Error: rlm_sql_mysql: Couldn't connect to MySQL server stage-user@127.0.0.1:stage_main Mon Jul 27 17:25:02 2015 : Error: rlm_sql_mysql: MySQL error: Can't connect to MySQL server on '127.0.0.1' (111) Mon Jul 27 17:25:02 2015 : Debug: rlm_sql_mysql: Socket destructor called, closing socket And from this point freeradius is not processing any further requests nor there are no any further information on debug screen. Radclient has a timeout: no response from server for ID XXX socket N In freeradius 2.x the processing ended with the message SQL_DOWN following by an access-reject and server did not hang. ________________________________________ Uwaga: Treść niniejszej wiadomości może być poufna i objęta zakazem jej ujawniania. Jeśli czytelnik tej wiadomości nie jest jej zamierzonym adresatem, pracownikiem lub pośrednikiem upoważnionym do jej przekazania adresatowi, informujemy że wszelkie rozprowadzanie, rozpowszechnianie lub powielanie niniejszej wiadomości jest zabronione. Jeśli otrzymałeś tę wiadomość omyłkowo, proszę bezzwłocznie odesłać ją nadawcy, a samą wiadomość usunąć z komputera. Dziękujemy. ________________________________ Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited.If you have received this communication in error, please notify the sender immediately by replying to the message and deleting it from your computer. Thank you. ________________________________
On Jul 27, 2015, at 11:40 AM, Michal Tomaszewski <Michal.Tomaszewski@cca.pl> wrote:
Yes, but there was a timeout and process was not locked indefinitely. Other requests were processed properly. In 3.0.9 it hangs all the processing.
I've pushed a fix. Please try the v3.0.x branch from git. Alan DeKok.
I've pushed a fix. Please try the v3.0.x branch from git.
Thanks a lot Alan. I'll keep you informed. ________________________________________ Uwaga: Treść niniejszej wiadomości może być poufna i objęta zakazem jej ujawniania. Jeśli czytelnik tej wiadomości nie jest jej zamierzonym adresatem, pracownikiem lub pośrednikiem upoważnionym do jej przekazania adresatowi, informujemy że wszelkie rozprowadzanie, rozpowszechnianie lub powielanie niniejszej wiadomości jest zabronione. Jeśli otrzymałeś tę wiadomość omyłkowo, proszę bezzwłocznie odesłać ją nadawcy, a samą wiadomość usunąć z komputera. Dziękujemy. ________________________________ Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited.If you have received this communication in error, please notify the sender immediately by replying to the message and deleting it from your computer. Thank you. ________________________________
I've pushed a fix. Please try the v3.0.x branch from git.
Thanks a lot Alan. I'll keep you informed.
We compiled today the code from git and everything seems to work correctly. We tested both SQL and Redis unavailability. In both cases it is not hanging the server. Thank you very much for help and changes! Mike ________________________________________ Uwaga: Treść niniejszej wiadomości może być poufna i objęta zakazem jej ujawniania. Jeśli czytelnik tej wiadomości nie jest jej zamierzonym adresatem, pracownikiem lub pośrednikiem upoważnionym do jej przekazania adresatowi, informujemy że wszelkie rozprowadzanie, rozpowszechnianie lub powielanie niniejszej wiadomości jest zabronione. Jeśli otrzymałeś tę wiadomość omyłkowo, proszę bezzwłocznie odesłać ją nadawcy, a samą wiadomość usunąć z komputera. Dziękujemy. ________________________________ Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited.If you have received this communication in error, please notify the sender immediately by replying to the message and deleting it from your computer. Thank you. ________________________________
On 27 Jul 2015, at 11:20, Alan DeKok <aland@deployingradius.com> wrote:
On Jul 27, 2015, at 11:06 AM, Michal Tomaszewski <Michal.Tomaszewski@cca.pl> wrote:
When database is going down server hangs on first processed request and stops processing any further requests. There is no connection timeout nor any other timeout to database request.
That may happen, especially when the client library for the back-end database locks.
In freeradius 2.x when database was not available server responded with Reject until database was on. In freeradius 3.0.9 server stops responding to any requests, even when database comes up.
Hmm... that's bad.
Fri Jul 24 17:44:34 2015 : Debug: rlm_redis (redis): Reconnecting (3)
Fri Jul 24 17:44:34 2015 : Error: rlm_redis (redis): Problems with redisConnect('10.113.13.245', 6379), Connection refused
That's the problem code. It's something Arran changed recently...
All my work on rlm_redis has been in v3.1.x. The only change I made in that file recently was to rename fr_connection_del to fr_connection_close https://github.com/FreeRADIUS/freeradius-server/commits/v3.0.x/src/modules/r... and something with consting in the argument tokeniser, which is unlikely to have broken this. In the connection pool the changes I made were to separate out the reconnection logic into a separate function. The additional calls to it should never have beed made, as nothing set 'needs_reconecting'. IIRC some changes were backported from v3.1.x for the MRU connection re-use pattern which could have caused this issue. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
what are your connection pool settings?
All standard from package. Just IP addresses and passwords are changed. ________________________________________ Uwaga: Treść niniejszej wiadomości może być poufna i objęta zakazem jej ujawniania. Jeśli czytelnik tej wiadomości nie jest jej zamierzonym adresatem, pracownikiem lub pośrednikiem upoważnionym do jej przekazania adresatowi, informujemy że wszelkie rozprowadzanie, rozpowszechnianie lub powielanie niniejszej wiadomości jest zabronione. Jeśli otrzymałeś tę wiadomość omyłkowo, proszę bezzwłocznie odesłać ją nadawcy, a samą wiadomość usunąć z komputera. Dziękujemy. ________________________________ Note: The information contained in this message may be privileged and confidential and protected from disclosure. If the reader of this message is not the intended recipient, or an employee or agent responsible for delivering this message to the intended recipient, you are hereby notified that any dissemination, distribution or copying of this communication is strictly prohibited.If you have received this communication in error, please notify the sender immediately by replying to the message and deleting it from your computer. Thank you. ________________________________
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Arran Cudbard-Bell -
Michal Tomaszewski