Catching DB errors in sqlippool
Бенджамин Томпсон
b.thompson at latera.ru
Mon Apr 9 16:02:05 CEST 2018
Hi
I have a test setup consisting of three servers and on each of them is
installed FreeRADIUS (3.0.12) and one node of a Percona MySQL cluster.
FreeRADIUS is configured to allocate IP addreses from the database using
sqlipool. Authentication data is stored elsewhere.
The idea was to build a fully redundant system which could cope with
loosing one or more nodes of the backend DB.
It was very easy to set up and I generated some load with radperf and did
some testing and everything generally worked apart from a couple of
problems.
The first problem I noticed is that when requsts are sent to multiple DB
nodes at the same time, the DB sometimes throws a cluster conflict error.
This error is picked up by the sqlippool module and this is how it looks in
the logs:
ERROR: (220) sqlippool: rlm_sql_mysql: ERROR 1213 (WSREP detected
deadlock/conflict and aborted the transaction. Try restarting the
transaction): 40001
As there was a problem with the transaction I wanted to configure
FreeRADIUS either to retry the request to the DB or to silently drop the
packet. The problem is that the module returns the code ok:
Debug: (220) modsingle[post-auth]: calling sqlippool (rlm_sqlippool)
Debug: rlm_sql (sql): Reserved connection (9)
Debug: %{User-Name}
Debug: Parsed xlat tree:
Debug: attribute --> User-Name
Debug: (220) sqlippool: EXPAND %{User-Name}
Debug: (220) sqlippool: --> testusername111
Debug: (220) sqlippool: SQL-User-Name set to 'testusername111'
Debug: START TRANSACTION
Debug: Parsed xlat tree:
Debug: literal --> START TRANSACTION
Debug: (220) sqlippool: EXPAND START TRANSACTION
Debug: (220) sqlippool: --> START TRANSACTION
Debug: (220) sqlippool: Executing query: START TRANSACTION
Debug: SELECT framedipaddress FROM radippool WHERE pool_name =
'%{control:Pool-Name}' AND (pool_key = '%{User-Name}' or expiry_time <
NOW()) ORDER BY (pool_key <> '%{User-Name}'), expiry_time LIMIT 1 FOR UPDATE
Debug: Parsed xlat tree:
Debug: literal --> SELECT framedipaddress FROM radippool WHERE
pool_name = '
Debug: attribute --> Pool-Name
Debug: literal --> ' AND (pool_key = '
Debug: attribute --> User-Name
Debug: literal --> ' or expiry_time < NOW()) ORDER BY (pool_key <> '
Debug: attribute --> User-Name
Debug: literal --> '), expiry_time LIMIT 1 FOR UPDATE
Debug: (220) sqlippool: EXPAND SELECT framedipaddress FROM radippool
WHERE pool_name = '%{control:Pool-Name}' AND (pool_key =
'%{User-Name}' or expiry_time < NOW()) ORDER BY (pool_key <>
'%{User-Name}'), expiry_time LIMIT 1 FOR UPDATE
Debug: (220) sqlippool: --> SELECT framedipaddress FROM radippool
WHERE pool_name = 'POOL1' AND (pool_key = 'testusername111' or
expiry_time < NOW()) ORDER BY (pool_key <> 'testusername111'), expiry_time
LIMIT 1 FOR UPDATE
Debug: (220) sqlippool: Executing select query: SELECT framedipaddress
FROM radippool WHERE pool_name = 'POOL1' AND (pool_key =
'testusername111' or expiry_time < NOW()) ORDER BY (pool_key <>
'testusername111'), expiry_time LIMIT 1 FOR UPDATE
Debug: (220) sqlippool: Allocated IP 10.192.0.110
Debug: UPDATE radippool SET nasipaddress = '%{NAS-IP-Address}',
pool_key = '%{User-Name}', callingstationid =
'%{Calling-Station-Id}', username = '%{User-Name}',
expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress =
'10.192.0.110'
Debug: Parsed xlat tree:
Debug: literal --> UPDATE radippool SET nasipaddress = '
Debug: attribute --> NAS-IP-Address
Debug: literal --> ', pool_key = '
Debug: attribute --> User-Name
Debug: literal --> ', callingstationid = '
Debug: attribute --> Calling-Station-Id
Debug: literal --> ', username = '
Debug: attribute --> User-Name
Debug: literal --> ', expiry_time = NOW() + INTERVAL 3600 SECOND
WHERE framedipaddress = '10.192.0.110'
Debug: (220) sqlippool: EXPAND UPDATE radippool SET nasipaddress =
'%{NAS-IP-Address}', pool_key = '%{User-Name}', callingstationid =
'%{Calling-Station-Id}', username = '%{User-Name}',
expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress =
'10.192.0.110'
Debug: (220) sqlippool: --> UPDATE radippool SET nasipaddress =
'127.0.0.1', pool_key = 'testusername111', callingstationid =
'testusername111', username = 'testusername111', expiry_time =
NOW() + INTERVAL 3600 SECOND WHERE framedipaddress = '10.192.0.110'
Debug: (220) sqlippool: Executing query: UPDATE radippool SET
nasipaddress = '127.0.0.1', pool_key = 'testusername111',
callingstationid = 'testusername111', username = 'testusername111',
expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress =
'10.192.0.110'
Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
Debug: COMMIT
Debug: Parsed xlat tree:
Debug: literal --> COMMIT
Debug: (220) sqlippool: EXPAND COMMIT
Debug: (220) sqlippool: --> COMMIT
Debug: (220) sqlippool: Executing query: COMMIT
Debug: rlm_sql_mysql: No additional diagnostic info on server
ERROR: (220) sqlippool: rlm_sql_mysql: ERROR 1213 (WSREP detected
deadlock/conflict and aborted the transaction. Try restarting the
transaction): 40001
Debug: rlm_sql (sql): Released connection (9)
Debug: Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name}
(did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user
%{User-Name})
Debug: Parsed xlat tree:
Debug: literal --> Allocated IP:
Debug: attribute --> Framed-IP-Address
Debug: literal --> from
Debug: attribute --> Pool-Name
Debug: literal --> (did
Debug: attribute --> Called-Station-Id
Debug: literal --> cli
Debug: attribute --> Calling-Station-Id
Debug: literal --> port
Debug: attribute --> NAS-Port
Debug: literal --> user
Debug: attribute --> User-Name
Debug: literal --> )
Debug: (220) sqlippool: EXPAND Allocated IP: %{reply:Framed-IP-Address}
from %{control:Pool-Name} (did %{Called-Station-Id} cli
%{Calling-Station-Id} port %{NAS-Port} user %{User-Name})
Debug: (220) sqlippool: --> Allocated IP: 10.192.0.110 from POOL1 (did
cli testusername111 port user testusername111)
Debug: (220) modsingle[post-auth]: returned from sqlippool
(rlm_sqlippool)
Debug: (220) [sqlippool] = ok
As the module returns ok I could not see any way to deal with the error.
Sometimes I noticed that the SELECT request failed to return an IP address.
In this case the module returned notfound and as I understand it I could
use some unlang to send the request again (I'm not sure how many times it's
wise to to this). However, I also tried to drop the request by calling
do_not_respond when Framed-IP-Address is empty, but I found that this did
not prevent the request from being sent:
Debug: (222) if (!&reply:Framed-IP-Address) {
Debug: (222) if (!&reply:Framed-IP-Address) -> TRUE
Debug: (222) if (!&reply:Framed-IP-Address) {
Debug: (222) policy do_not_respond {
Debug: (222) update control {
Debug: (222) &Response-Packet-Type := Do-Not-Respond
Debug: (222) } # update control = noop
Debug: (222) modsingle[post-auth]: calling handled (rlm_always)
Debug: (222) modsingle[post-auth]: returned from handled
(rlm_always)
Debug: (222) [handled] = handled
Debug: (222) } # policy do_not_respond = handled
Debug: (222) } # if (!&reply:Framed-IP-Address) = handled
Debug: (222) } # post-auth = handled
Debug: | %{reply:Framed-IP-Address}
Debug: Parsed xlat tree:
Debug: literal --> |
Debug: attribute --> Framed-IP-Address
Debug: (222) EXPAND | %{reply:Framed-IP-Address}
Debug: (222) --> |
Auth: (222) Login OK: [testusername112/testpassword112] (from client
localhost port 0 cli testusername112) |
Debug: (222) Sent Access-Accept Id 28 from 127.0.0.1:1812 to
127.0.0.1:54122 length 0
I would be grateful for any help or advice on these issues.
More information about the Freeradius-Users
mailing list