Freeradius 3.0.12 problems - redis and mysql pool connections
Michal Tomaszewski
Michal.Tomaszewski at cca.pl
Thu Dec 22 16:30:16 CET 2016
Hello Alan,
I found 2 problems in freeradius 3.0.12
To be short:
Our several freeradius servers are using MySQL cluster (percona) and redis master/slave mapped to local port using HA Proxy on each freeradius server.
So in fact each Freeradius sees 1 local port for MySQL and 1 local port for redis.
We are not using server pool and load balancing definition in Freeradius in order to have strict control on which database server is used for all writes from several Freeradius servers.
To be sure Freeradius is starting when redis or sql is not started yet (or not available for a while) in both redis and sql pool definition we have to use:
pool {
start = 0
but we also want to have min number of connections defined higher than 0 (e.g. in a standard way):
min = ${thread[pool].min_spare_servers}
So min > start.
When server (sql or redis) becomes available Freeradius opens some connections.
After restart of sql or redis Freeradius should open new connections to those servers as old connections are not longer available.
And we have 2 errors
#1
When redis becomes unavailable for a while (restart of redis-server or simple restart of HA_Proxy) Freeradius does not check that connection is no longer available and keeps those invalid connections till lifetime time. In fact in such situation old connection should be discarded and new connection shall be opened.
Standard lifetime in mods-available/redis is set to 86400 so redis module is not able to read/write anything from redis-server for 24 hours.
In /var/log/freeradius/radius.log there are only ERRORs when there is redis write command, there is no error information when there is (unsuccessful) read command. To see that debug mode shall be started.
So in fact redis module is not verifying redis valid/invalid connection state.
Changing lifetime to e.g. 60 helps to force redis module start working (in 60 second from redis-server restart) but that is just a workaround not a solution.
#2
In var/log/freeradius/radius.log we have lots of errors:
ERROR: SQL query failed: no connection
It seems that error shows up when connection is closed by e.g. idle-timeout...
Example:
Thu Dec 22 15:48:35 2016 : Debug: attribute --> User-Name
Thu Dec 22 15:48:35 2016 : Debug: (81) EXPAND %{User-Name}
Thu Dec 22 15:48:35 2016 : Debug: (81) --> h274_xxxxxxxxxxxxxx
Thu Dec 22 15:48:35 2016 : Debug: (81) SQL-User-Name set to 'h274_xxxxxxxxxxxxxx'
Thu Dec 22 15:48:35 2016 : Debug: rlm_sql (sql): Reserved connection (4)
Thu Dec 22 15:48:35 2016 : Debug: (81) Executing select query: INSERT INTO radius_radacct_closed ( acctsessionid, acctuniqueid, username, hotspot_id, device_id, felogin_id, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress ) VALUES ('585be1cc00000004', 'e2a5c5294e55743ffc9169de47d5de4a', 'h274_xxxxxxxxxxxxxx', '274', '3625', '3799789', '', '192.168.176.1', '00000004', 'Wireless-802.11', FROM_UNIXTIME(1482418115 - 1460), FROM_UNIXTIME(1482418115), FROM_UNIXTIME(1482418115), 1460, '', '', '', '0' << 32 | '129433', '0' << 32 | '1435982', 'h274-xxxxxxxxxxxxxx', 'EC-9B-F3-19-4A-F2', 'Lost-Carrier', '', '', '192.168.176.5')
Thu Dec 22 15:48:35 2016 : ERROR: (81) SQL query failed: no connection
Thu Dec 22 15:48:35 2016 : Debug: rlm_sql (sql): Released connection (4)
Thu Dec 22 15:48:35 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:48:35 2016 : Debug: (81) EXPAND %{sql: INSERT INTO radius_radacct_closed ( acctsessionid, acctuniqueid, username, hotspot_id, device_id, felogin_id, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress ) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{User-Name}', '%{LOCATION-HotspotID}', '%{LOCATION-DeviceID}', '%{LOCATION-FELogin-Id}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%l - %{%{Acct-Session-Time}:-0}), FROM_UNIXTIME(%l), FROM_UNIXTIME(%l), %{%{Acct-Session-Time}:-NULL}, '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') }
Thu Dec 22 15:48:35 2016 : Debug: (81) -->
freeradius log looks like:
radius1:~$ tail /var/log/freeradius/radius.log
Thu Dec 22 15:59:45 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:47 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:47 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:48 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:48 2016 : ERROR: (164) ERROR: SQL query failed: no connection
Thu Dec 22 15:59:48 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:51 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:54 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:54 2016 : Info: Need 0 more connections to reach min connections (5)
Thu Dec 22 15:59:54 2016 : ERROR: (172) ERROR: SQL query failed: no connection
We tested to set freeradius use mysql directly, without haproxy and using default values in mods-availables/sql (including pool { start value) but it did not change this strange behavior.
Any help would be appreciated...
Regards,
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. ________________________________
More information about the Freeradius-Users
mailing list