Access-Reject (code 3) on an otherwise valid Accept packet / delayed reject when SQL module fails in post-auth
Hello, I'm have a FreeRADIUS 2.1.10 server on CentOS... with a backend MySQL database (logging) which is, as Alan would say, Broken - at peak usage times it's horribly overloaded. Up until yesterday, our post-auth section had a "sql" call not wrapped in a "redundant { sql / ok }". It seems that when the MySQL server gets overloaded, and the sql module fails/times out (can't find a configuration value for timeout, or a note on what the timeout actually is), the post-auth section stops and returns a Reject packet. Since it stops before attr_filter, it's returning a non-RFC-compliant REJECT... i.e. an otherwise valid and correct Access-Accept packet, but with a Code of 3 (Access-Reject) since the sql module failed. For the short-term, I wrapped the sql calls in post-auth and post-auth-type reject in redundant, followed by "ok", so that users will not get rejected because of failed logging (administrative/managerial decision, not mine) and gave up SQL post-auth logging in favor of not locking out users when the DB is struggling. Using the test described below, this appears to solve the problem of the improperly formed REJECT packets, but it still ends up with lots of "There are no DB handles to use! skipped 0, tried to connect 0" and then lots of "Info: WARNING Child is hung for request XXXX in component post-auth module sql." lines... I can only assume that these are a non-critical issue (i.e. the child is hung but will recover), but 1) I would like to set a much lower database timeout, i.e. have the sql module fail sooner and move on, and 2) as the "Login (OK|incorrect)" messages don't have the request number, it's difficult to associate these with a given client. An acceptable way to reproduce this is to start radiusd, and then issue a LOCK TABLES radpostauth WRITE; followed by bombarding the radius server with access-requests. In my case, after the DB handles fill up, I will start getting these invalid Reject packets out (a valid accept with a code of 3), along with the above log messages - and "Login OK" messages even for the clients who are rejected due to the sql failure. So a few questions: 1) The logging for this is flat-out wrong. When the SQL module fails in this way in post-auth (because of timeout), I'm still seeing "Auth: Login OK" in radius.log. I guess this could be "a matter of opinion", but the fact that I'm seeing a log message for OK but getting a reject out on the wire, seems like a bug. IMHO, the logging of ok/incorrect should either a) be delayed until JUST before the packet goes out, beyond where an Accept could turn into a Reject, or b) if/when an Accept packet is turned into a Reject and sent out on the wire, there should be an explicit log message stating such (as opposed to just the current "Sending delayed reject" which appears only in debug logs). 2) Is it the expected behavior that if a module in post-auth fails, the packet will be changed to a reject without passing through Post-Auth-Type REJECT, therefore without passing through attr_filter, therefore sending out a non-RFC-compliant Access-Reject packet? 3) As far as I can tell, this entire issue does *not* happen when running "radiusd -fXx"... in that case, radiusd will simply hang indefinitely until the DB recovers (or the table is unlocked, in testing). Does this sound right? Does anyone know if rlm_sql_mysql will behave differently in this way in debug mode as opposed to normal daemon mode? And does it seem correct that in debug mode, there doesn't seem to be a timeout for mysql? I was, however, able to replicate the issue when running "radiusd -fxx", i.e. no single threaded mode. 4) As an example of log output, see the lines below. I know that the 15:19:30 "Login OK" for client mc4k-121 port 8195 actually left as an Access-Reject packet (code 3), which still had User-Name, Callback-Id, Session-Timeout, Termination-Action, and two VSAs set, as the proper Accept for that user should. In certain instances with this problem, the SQL logging was queued somewhere (presumably on the MySQL side, waiting for the unlock) and actually made it to the DB, listed as an Accept packet and all, after radiusd sent out the incompliant Reject. However, of concern in the logs below is the fact that 3 of those Login OK lines (outer tunnel) were actually the invalid Access-Reject packets on the wire, but there's no indication of that here. While there is a vague "There are no DB handles to use" message, that doesn't specify which request it relates to (hence no way to tell which Login OK was actually rejected), nor does it explicitly say that the request will be rejected. ### BEGIN LOG SNIP Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-125 port 8255 cli 00:22:FB:8B:58:04 via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-125 port 8255 cli 00:22:FB:8B:58:04) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-125 port 10287 cli 58:B0:35:41:46:A1 via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-125 port 10287 cli 58:B0:35:41:46:A1) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8203 cli 1C:65:9D:16:2D:EB via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8203 cli 1C:65:9D:16:2D:EB) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8289 cli 70:F1:A1:8B:F2:F8 via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8289 cli 70:F1:A1:8B:F2:F8) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-126 port 6243 cli 88:53:2E:0D:F2:D7 via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-126 port 6243 cli 88:53:2E:0D:F2:D7) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8288 cli 88:9F:FA:77:F7:EE via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8288 cli 88:9F:FA:77:F7:EE) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8209 cli 8C:58:77:4C:78:CE via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8209 cli 8C:58:77:4C:78:CE) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8202 cli F0:B4:79:45:14:DD via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8202 cli F0:B4:79:45:14:DD) Thu Oct 27 15:19:29 2011 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-126 port 6278 cli 18:E7:F4:F6:C8:E6 via TLS tunnel) Thu Oct 27 15:19:29 2011 : Auth: Login OK: [usernameRedacted] (from client mc5k-126 port 6278 cli 18:E7:F4:F6:C8:E6) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8273 cli 00:26:C6:83:50:82 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8273 cli 00:26:C6:83:50:82) Thu Oct 27 15:19:30 2011 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8295 cli CC:08:E0:EA:1A:23 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8295 cli CC:08:E0:EA:1A:23) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8195 cli 00:1E:C2:AB:03:07 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8195 cli 00:1E:C2:AB:03:07) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8219 cli 00:21:E9:DE:F2:3A via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8219 cli 00:21:E9:DE:F2:3A) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8272 cli 00:25:56:51:82:C8 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8272 cli 00:25:56:51:82:C8) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8280 cli E4:CE:8F:41:DD:82 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8280 cli E4:CE:8F:41:DD:82) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8300 cli 58:1F:AA:69:48:49 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8300 cli 58:1F:AA:69:48:49) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 10241 cli 04:0C:CE:D7:B3:28 via TLS tunnel) Thu Oct 27 15:19:30 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 10241 cli 04:0C:CE:D7:B3:28) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8301 cli 8C:58:77:66:0C:AE via TLS tunnel) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8301 cli 8C:58:77:66:0C:AE) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8202 cli F0:B4:79:45:14:DD via TLS tunnel) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8202 cli F0:B4:79:45:14:DD) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8284 cli 34:51:C9:2E:05:DD via TLS tunnel) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8284 cli 34:51:C9:2E:05:DD) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8271 cli 00:22:69:68:87:B4 via TLS tunnel) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8271 cli 00:22:69:68:87:B4) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8303 cli 00:21:5C:0C:9C:61 via TLS tunnel) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8303 cli 00:21:5C:0C:9C:61) Thu Oct 27 15:19:31 2011 : Auth: Login OK: [usernameRedacted] (from client mc4k-121 port 8213 cli 00:25:00:4D:5D:EA via TLS tunnel) ### END LOG SNIP So to summarize what I'm asking for/about: 1) In instances of a "delayed reject" caused by a failure in post-auth, would it be possible to have this clearly logged to radius.log, either instead of "Login OK", or something along the lines of "WARNING - delayed reject of previous request (request id, username, Calling Station Id, client, port)"? 2) Is there any way to maintain attr_filter.access_reject even with a delayed reject because of module failure in post-auth, so that these packets are still RFC-compliant? 3) Is there any way to configure the rlm_sql_mysql timeout, or whatever is causing this module to fail when the table is locked? 4) Can I get some clarification on the "There are no DB handles to use! skipped 0, tried to connect 0" and "Info: WARNING Child is hung for request XXXX in component post-auth module sql" radius.log messages, and the severity of these (i.e. does either of them definitively mean that a request was rejected?) Thank you for any advice/insight/comments/suggestions, Jason Antman Rutgers University, NJ, USA
Jason Antman wrote: Ah... a long, detailed message with useful information. Very nice.
I'm have a FreeRADIUS 2.1.10 server on CentOS... with a backend MySQL database (logging) which is, as Alan would say, Broken - at peak usage times it's horribly overloaded. Up until yesterday, our post-auth section had a "sql" call not wrapped in a "redundant { sql / ok }". It seems that when the MySQL server gets overloaded, and the sql module fails/times out (can't find a configuration value for timeout, or a note on what the timeout actually is), the post-auth section stops and returns a Reject packet. Since it stops before attr_filter, it's returning a non-RFC-compliant REJECT..
Hmm... you mean an Access-Reject with a bunch of attributes?
For the short-term, I wrapped the sql calls in post-auth and post-auth-type reject in redundant, followed by "ok", so that users will not get rejected because of failed logging (administrative/managerial decision, not mine) and gave up SQL post-auth logging in favor of not locking out users when the DB is struggling.
Yeah... it might be better to use something like rsyslog, which will put syslog messages into a DB. If the DB is busy, it just buffers the messages to disk.
Using the test described below, this appears to solve the problem of the improperly formed REJECT packets, but it still ends up with lots of "There are no DB handles to use! skipped 0, tried to connect 0" and then lots of "Info: WARNING Child is hung for request XXXX in component post-auth module sql." lines... I can only assume that these are a non-critical issue (i.e. the child is hung but will recover), but 1) I would like to set a much lower database timeout, i.e. have the sql module fail sooner and move on, and 2) as the "Login (OK|incorrect)" messages don't have the request number, it's difficult to associate these with a given client.
OK. There is no "database timeout" config. Or if there is one... it's buried in the MySQL documentation where I can't find it.
So a few questions: 1) The logging for this is flat-out wrong. When the SQL module fails in this way in post-auth (because of timeout), I'm still seeing "Auth: Login OK" in radius.log. I guess this could be "a matter of opinion", but the fact that I'm seeing a log message for OK but getting a reject out on the wire, seems like a bug.
It's a timing bug. The server core says "Login OK" because the authenticate section succeeded. If something fails after that... it's a separate issue. The solution is to move the "Login OK" message to a module, and put it as the last thing in post-auth. I don't think it's hard, it's just that no one has done it.
IMHO, the logging of ok/incorrect should either a) be delayed until JUST before the packet goes out, beyond where an Accept could turn into a Reject, or b) if/when an Accept packet is turned into a Reject and sent out on the wire, there should be an explicit log message stating such (as opposed to just the current "Sending delayed reject" which appears only in debug logs).
Well... feel free to submit a patch.
2) Is it the expected behavior that if a module in post-auth fails, the packet will be changed to a reject without passing through Post-Auth-Type REJECT, therefore without passing through attr_filter, therefore sending out a non-RFC-compliant Access-Reject packet?
For now... yes. The server doesn't re-process a section based on problems.
3) As far as I can tell, this entire issue does *not* happen when running "radiusd -fXx"... in that case, radiusd will simply hang indefinitely until the DB recovers (or the table is unlocked, in testing). Does this sound right?
Yup. It's single threaded. If the DB never returns, the server never returns.
Does anyone know if rlm_sql_mysql will behave differently in this way in debug mode as opposed to normal daemon mode?
It won't.
And does it seem correct that in debug mode, there doesn't seem to be a timeout for mysql
There's no timeout for MySQL *ever*. In threaded mode, the server core notices that a thread is blocked and kills it. But that has nothing to do with MySQL. The same check is done for "exec wait" programs that never return.
4) As an example of log output, see the lines below. I know that the 15:19:30 "Login OK" for client mc4k-121 port 8195 actually left as an Access-Reject packet (code 3), which still had User-Name, Callback-Id, Session-Timeout, Termination-Action, and two VSAs set, as the proper Accept for that user should. In certain instances with this problem, the SQL logging was queued somewhere (presumably on the MySQL side, waiting for the unlock) and actually made it to the DB, listed as an Accept packet and all, after radiusd sent out the incompliant Reject.
Yup....
However, of concern in the logs below is the fact that 3 of those Login OK lines (outer tunnel) were actually the invalid Access-Reject packets on the wire, but there's no indication of that here. While there is a vague "There are no DB handles to use" message, that doesn't specify which request it relates to (hence no way to tell which Login OK was actually rejected), nor does it explicitly say that the request will be rejected.
Configure a "linelog" module to write "login OK" as the last entry of post-auth. Make it so that the server core *doesn't* do authlog.
So to summarize what I'm asking for/about: 1) In instances of a "delayed reject" caused by a failure in post-auth, would it be possible to have this clearly logged to radius.log, either instead of "Login OK", or something along the lines of "WARNING - delayed reject of previous request (request id, username, Calling Station Id, client, port)"?
Maybe. It will likely need source code changes.
2) Is there any way to maintain attr_filter.access_reject even with a delayed reject because of module failure in post-auth, so that these packets are still RFC-compliant?
Sure... source code changes. :(
3) Is there any way to configure the rlm_sql_mysql timeout, or whatever is causing this module to fail when the table is locked?
Nope. Or, look at the MySQL client API documentation. If there's a timeout, we can poke rlm_sql_mysql to use it.
4) Can I get some clarification on the "There are no DB handles to use! skipped 0, tried to connect 0" and "Info: WARNING Child is hung for request XXXX in component post-auth module sql" radius.log messages, and the severity of these (i.e. does either of them definitively mean that a request was rejected?)
Nope. They mean what they say. A slow child might suddenly come back && send an Access-Accept. A system might have fail-over configured, so that a DB problem fails over to another DB, or to another module. Alan DeKok.
participants (2)
-
Alan DeKok -
Jason Antman