Catching DB errors in sqlippool
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.
On Apr 9, 2018, at 10:02 AM, Бенджамин Томпсон <b.thompson@latera.ru> wrote:
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.
That's good.
The first problem I noticed is that when requsts are sent to multiple DB nodes at the same time,
That's a MySQL issue. FreeRADIUS issues one query to the DB. It's up to MySQL to distribute in the cluster.
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
Hmm... that's unfriendly.
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:
Try upgrade to 3.0.16. Hmm... I can't fix the database problem. But I will push a fix for 3.0.17 which makes the module return "fail" in this situation. But the best fix is to use a database that works. Having a clustered database fail on simple transactions is... not smart. Alan DeKok.
2018-04-10 21:14 GMT+03:00 Бенджамин Томпсон <b.thompson@latera.ru>:
Hmm... I can't fix the database problem. But I will push a fix for
3.0.17 which makes the module return "fail" in this situation.
Tested, works, many thanks
The module now returns fail which is great. However I noticed that when I call the sqlipool for a second time it skips the allocate_clear request and goes straight to allocate_find: (66) sqlippool: EXPAND %{User-Name} (66) sqlippool: --> testusername34 (66) sqlippool: SQL-User-Name set to 'testusername34' (66) sqlippool: EXPAND START TRANSACTION (66) sqlippool: --> START TRANSACTION (66) sqlippool: Executing query: START TRANSACTION (66) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = '%{User-Name}' (66) sqlippool: --> UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = 'testusername34' (66) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = 'testusername34' (66) sqlippool: ERROR: rlm_sql_mysql: ERROR 1213 (WSREP detected deadlock/conflict and aborted the transaction. Try restarting the transaction): 40001 rlm_sql (sql): Released connection (4) (66) [sqlippool] = fail (66) if (!ok) { (66) if (!ok) -> TRUE (66) if (!ok) { (66) update reply { (66) &Framed-IP-Address !* ANY (66) } # update reply = noop rlm_sql (sql): Reserved connection (0) (66) sqlippool: EXPAND %{User-Name} (66) sqlippool: --> testusername34 (66) sqlippool: SQL-User-Name set to 'testusername34' (66) sqlippool: EXPAND START TRANSACTION (66) sqlippool: --> START TRANSACTION (66) sqlippool: Executing query: START TRANSACTION (66) 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 I also tried to call do_not_respond but the problem is that it does not seem to work in the post_auth section.
Hmm... I can't fix the database problem. But I will push a fix for
3.0.17 which makes the module return "fail" in this situation.
Tested, works, many thanks
The module now returns fail which is great. However I noticed that when I call the sqlipool for a second time it skips the allocate_clear request and goes straight to allocate_find:
(66) sqlippool: EXPAND %{User-Name} (66) sqlippool: --> testusername34 (66) sqlippool: SQL-User-Name set to 'testusername34' (66) sqlippool: EXPAND START TRANSACTION (66) sqlippool: --> START TRANSACTION (66) sqlippool: Executing query: START TRANSACTION (66) sqlippool: EXPAND UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = '%{User-Name}' (66) sqlippool: --> UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = 'testusername34' (66) sqlippool: Executing query: UPDATE radippool SET nasipaddress = '', callingstationid = '', expiry_time = NOW() - INTERVAL 1 SECOND WHERE pool_key = 'testusername34' (66) sqlippool: ERROR: rlm_sql_mysql: ERROR 1213 (WSREP detected deadlock/conflict and aborted the transaction. Try restarting the transaction): 40001 rlm_sql (sql): Released connection (4) (66) [sqlippool] = fail (66) if (!ok) { (66) if (!ok) -> TRUE (66) if (!ok) { (66) update reply { (66) &Framed-IP-Address !* ANY (66) } # update reply = noop rlm_sql (sql): Reserved connection (0) (66) sqlippool: EXPAND %{User-Name} (66) sqlippool: --> testusername34 (66) sqlippool: SQL-User-Name set to 'testusername34' (66) sqlippool: EXPAND START TRANSACTION (66) sqlippool: --> START TRANSACTION (66) sqlippool: Executing query: START TRANSACTION (66) 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
I also tried to call do_not_respond but the problem is that it does not seem to work in the post_auth section.
I solved the issued with do_not_respond by calling sqlippool.post-auth from the authorize section.
participants (2)
-
Alan DeKok -
Бенджамин Томпсон