Radiusd hangs on redis cluster failover (sometimes)
Hello, I have an issue with FreeRADIUS 4.0.x and Redis cluster. When I shut down one of the nodes (all have freeradius and use redis cluster), redis recovers and cluster state is OK but it seems freeradius doesn't refresh cluster topology, and when I send a packet to one of the working nodes it is trying to send command to node that is down and then just hangs and doesn't return response. I cannot stop radiusd after that (i.e. ctrl+c doesn't work) and it must be killed. The last line in log is this, and nothing is printed after that: Debug : (7) rediswho - [16] >>> Sending command(s) to 192.168.1.8:7004 (fr_redis_cluster_state_init) Btw. I changed the message in cluster.c just to confirm which function is called (there are two same Sending command(s) msg in that file), it is this line https://github.com/FreeRADIUS/freeradius-server/blob/master/src/lib/redis/cl... . So 192.168.1.8 is the node that I shut down to test high availability, and I send packet after redis is recovered. This doesn't happen when I shut down the other node, I can see in log how radius refreshes cluster topology and everything just continues to work. Before every test, I always make sure cluster state is ok and master/slaves are in balance on all nodes. Attached is a log file I get with `radiusd -X` on the node that fails and hangs after it tries to contact node that is down. Thanks, Milan
On Aug 7, 2019, at 1:37 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
I have an issue with FreeRADIUS 4.0.x and Redis cluster. When I shut down one of the nodes (all have freeradius and use redis cluster), redis recovers and cluster state is OK but it seems freeradius doesn't refresh cluster topology, and when I send a packet to one of the working nodes it is trying to send command to node that is down and then just hangs and doesn't return response. I cannot stop radiusd after that (i.e. ctrl+c doesn't work) and it must be killed.
That isn't good.
The last line in log is this, and nothing is printed after that:
Debug : (7) rediswho - [16] >>> Sending command(s) to 192.168.1.8:7004 (fr_redis_cluster_state_init)
Btw. I changed the message in cluster.c just to confirm which function is called (there are two same Sending command(s) msg in that file), it is this line https://github.com/FreeRADIUS/freeradius-server/blob/master/src/lib/redis/cl... . So 192.168.1.8 is the node that I shut down to test high availability, and I send packet after redis is recovered.
This doesn't happen when I shut down the other node,
What "other" node? I know there's a cluster, but what is different between the two nodes?
I can see in log how radius refreshes cluster topology and everything just continues to work. Before every test, I always make sure cluster state is ok and master/slaves are in balance on all nodes.
Attached is a log file I get with `radiusd -X` on the node that fails and hangs after it tries to contact node that is down.
Please don't attach log files as zips. The mailing list deletes them. Attach log files in-line. If they're too large, put them on a pastebin web site somewhere. Alan DeKok.
What "other" node? I know there's a cluster, but what is different between the two nodes?
Nothing is different, they use the same build of FreeRADIUS, the same config, everything should be the same, install is done from my custom RPM repository. Every node connects to Redis via 127.0.0.1, ports 7001-7008. Please don't attach log files as zips. The mailing list deletes them.
Attach log files in-line. If they're too large, put them on a pastebin web site somewhere.
Sorry about that, the log file is now here https://pastebin.com/raw/5TPP9vEh . After the last line, when it tries to contact the node that is down, it hangs and must be killed. What I noticed so far, I use virtual machines for testing, if I power off, i.e. unplug power then radius on active node hangs, but if I do a proper shut down it gets the new cluster topology and continues to work. That doesn't make much sense to me, i.e. how is that related to the problem, but that is what I see. Thanks, Milan On Thu, Aug 8, 2019 at 4:37 PM Alan DeKok <aland@deployingradius.com> wrote:
On Aug 7, 2019, at 1:37 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
I have an issue with FreeRADIUS 4.0.x and Redis cluster. When I shut down one of the nodes (all have freeradius and use redis cluster), redis recovers and cluster state is OK but it seems freeradius doesn't refresh cluster topology, and when I send a packet to one of the working nodes it is trying to send command to node that is down and then just hangs and doesn't return response. I cannot stop radiusd after that (i.e. ctrl+c doesn't work) and it must be killed.
That isn't good.
The last line in log is this, and nothing is printed after that:
Debug : (7) rediswho - [16] >>> Sending command(s) to 192.168.1.8:7004 (fr_redis_cluster_state_init)
Btw. I changed the message in cluster.c just to confirm which function is called (there are two same Sending command(s) msg in that file), it is this line https://github.com/FreeRADIUS/freeradius-server/blob/master/src/lib/redis/cl... . So 192.168.1.8 is the node that I shut down to test high availability, and I send packet after redis is recovered.
This doesn't happen when I shut down the other node,
What "other" node? I know there's a cluster, but what is different between the two nodes?
I can see in log how radius refreshes cluster topology and everything just continues to work. Before every test, I always make sure cluster state is ok and master/slaves are in balance on all nodes.
Attached is a log file I get with `radiusd -X` on the node that fails and hangs after it tries to contact node that is down.
Please don't attach log files as zips. The mailing list deletes them. Attach log files in-line. If they're too large, put them on a pastebin web site somewhere.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Aug 8, 2019, at 12:05 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
Nothing is different, they use the same build of FreeRADIUS, the same config, everything should be the same, install is done from my custom RPM repository. Every node connects to Redis via 127.0.0.1, ports 7001-7008.
Hmm... OK.
Sorry about that, the log file is now here https://pastebin.com/raw/5TPP9vEh
Which still has "Debug:" added to the start of every line. So you've done something *other* than just "radiusd -X".
After the last line, when it tries to contact the node that is down, it hangs and must be killed.
The short answer is that the rlm_redis code is blocking in v4. It has a timeout, so it should come back at some point. But the rlm_redis module needs to be converted to use the async Redis API. Which is a matter of ongoing work.
What I noticed so far, I use virtual machines for testing, if I power off, i.e. unplug power then radius on active node hangs, but if I do a proper shut down it gets the new cluster topology and continues to work. That doesn't make much sense to me, i.e. how is that related to the problem, but that is what I see.
If you power off the Redis node correctly, then the kernel closes all active TCP connections. Which means that FreeRADIUS gets a notice that the connection is gone, and can handle it. If you just power off the Redis node, then the kernel thinks that the TCP connections are still active. And then tries to connect until a timeout is reached. The recommendations are: a) don't hard-power critical systems b) if v4 works, great. If it doesn't, submit patches, or use v3. The short answer is "only use v4 if you know what you're doing." Alan DeKok.
Which still has "Debug:" added to the start of every line. So you've done something *other* than just "radiusd -X".
I did this: [root@node2 idbox]# cat etc/raddb/radiusd.conf | grep debug_level debug_level = 0 [root@node2 idbox]# radiusd -f -X -d etc/raddb/ > /tmp/radius.log ^C[root@node2 idbox]# cat /tmp/radius.log | grep "^Debug" | wc -l 1369 Snapshot is from two weeks ago, I also noticed radclient now print Debug lines, and detail logs for accounting messages now contain this line https://github.com/FreeRADIUS/freeradius-server/blob/master/src/modules/prot... , i.e."No accounting section found..." , probably related to some recent changes. If you power off the Redis node correctly, then the kernel closes all
active TCP connections. Which means that FreeRADIUS gets a notice that the connection is gone, and can handle it. If you just power off the Redis node, then the kernel thinks that the TCP connections are still active. And then tries to connect until a timeout is reached.
This hint about kernel can help, will check state of TCP connections and see if I can alter behavior with some Redis options, like tcp-keepalive. Thanks, Milan On Thu, Aug 8, 2019 at 8:13 PM Alan DeKok <aland@deployingradius.com> wrote:
On Aug 8, 2019, at 12:05 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
Nothing is different, they use the same build of FreeRADIUS, the same config, everything should be the same, install is done from my custom RPM repository. Every node connects to Redis via 127.0.0.1, ports 7001-7008.
Hmm... OK.
Sorry about that, the log file is now here https://pastebin.com/raw/5TPP9vEh
Which still has "Debug:" added to the start of every line. So you've done something *other* than just "radiusd -X".
After the last line, when it tries to contact the node that is down, it hangs and must be killed.
The short answer is that the rlm_redis code is blocking in v4. It has a timeout, so it should come back at some point.
But the rlm_redis module needs to be converted to use the async Redis API. Which is a matter of ongoing work.
What I noticed so far, I use virtual machines for testing, if I power off, i.e. unplug power then radius on active node hangs, but if I do a proper shut down it gets the new cluster topology and continues to work. That doesn't make much sense to me, i.e. how is that related to the problem, but that is what I see.
If you power off the Redis node correctly, then the kernel closes all active TCP connections. Which means that FreeRADIUS gets a notice that the connection is gone, and can handle it.
If you just power off the Redis node, then the kernel thinks that the TCP connections are still active. And then tries to connect until a timeout is reached.
The recommendations are:
a) don't hard-power critical systems
b) if v4 works, great. If it doesn't, submit patches, or use v3.
The short answer is "only use v4 if you know what you're doing."
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Aug 9, 2019, at 7:25 AM, Milan Nikolic <gen2brain@gmail.com> wrote:
I did this:
[root@node2 idbox]# cat etc/raddb/radiusd.conf | grep debug_level debug_level = 0 [root@node2 idbox]# radiusd -f -X -d etc/raddb/ > /tmp/radius.log
Which adds the "Debug :" headers. That's why we say "radiusd -X", and not anything else. If you want to dump it to a file, do: $ script debug.txt $ radiusd -X ... $ exit and then send "debug.txt". Note no "-f" is needed. No "-d /etc/raddb" is needed.
Snapshot is from two weeks ago, I also noticed radclient now print Debug lines, and detail logs for accounting messages now contain this line https://github.com/FreeRADIUS/freeradius-server/blob/master/src/modules/prot... , i.e."No accounting section found..." , probably related to some recent changes.
If only there was some kind of debug log you could post which shows the actual error. Oh well. I guess it's a mystery. Alan DeKok.
Which adds the "Debug :" headers. That's why we say "radiusd -X", and not anything else. If you want to dump it to a file, do: $ script debug.txt $ radiusd -X ... $ exit and then send "debug.txt".
So I now did exactly that and still have Debug lines in the log, see here (you can see what command is started after script in the log) https://pastebin.com/2nWMBKRM , that is not normal or now there are less Debug lines as you prefer? If the path to directory or redirection of output can affect logging than I must say is not usual behavior and can be one of the reasons why every thread has a couple of posts where just this is discussed and not the actual issue. Is there anything that can be enabled in the config file to get similar output (for me, not to post to lists)? For such powerful software debugging looks like the weakest thing. I tried debug_level 1, 2, 3, I was happy that I can change level "on fly" with radmin tool but all useful information I can only get with `-X` or `-Xx`. In my case, that means I must stop service, change config (I use some configs from ENV and it is not enough to export those because service forks as a user), manually start, find the issue then change back and start service. Not practical at all in production. If only there was some kind of debug log you could post which shows the
actual error. Oh well. I guess it's a mystery.
Debug log is above, sorry, I had to recompile, I commented out that line, because I don't want it in detail log, here is what I get: Fri Aug 9 15:34:48 2019 Module-Failure-Message = "No 'accounting Start' section found: Ignoring it." Acct-Status-Type = Start User-Name = "127.0.0.1" Framed-IP-Address = 127.0.0.1 Calling-Station-Id = "06411112222" 3GPP-IMSI = "1111111" 3GPP-IMEISV = "2222222" Acct-Unique-Session-Id = "䷋E\343Ũk\013:,\250\351o\344X" Timestamp = 1565364888 Should I add empty accounting Start {} section, is that a must now (didn't try that, just cross my mind)? What about others, i.e. Stop/Alive, etc. My "default" site config is very simple and basic, I only use Accounting-Request/Response and listen. Thank you, Milan On Fri, Aug 9, 2019 at 3:58 PM Alan DeKok <aland@deployingradius.com> wrote:
On Aug 9, 2019, at 7:25 AM, Milan Nikolic <gen2brain@gmail.com> wrote:
I did this:
[root@node2 idbox]# cat etc/raddb/radiusd.conf | grep debug_level debug_level = 0 [root@node2 idbox]# radiusd -f -X -d etc/raddb/ > /tmp/radius.log
Which adds the "Debug :" headers. That's why we say "radiusd -X", and not anything else.
If you want to dump it to a file, do:
$ script debug.txt $ radiusd -X ... $ exit
and then send "debug.txt".
Note no "-f" is needed. No "-d /etc/raddb" is needed.
Snapshot is from two weeks ago, I also noticed radclient now print Debug lines, and detail logs for accounting messages now contain this line
https://github.com/FreeRADIUS/freeradius-server/blob/master/src/modules/prot...
, i.e."No accounting section found..." , probably related to some recent changes.
If only there was some kind of debug log you could post which shows the actual error. Oh well. I guess it's a mystery.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Aug 9, 2019, at 1:27 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
So I now did exactly that and still have Debug lines in the log, see here (you can see what command is started after script in the log) https://pastebin.com/2nWMBKRM , that is not normal or now there are less Debug lines as you prefer?
The default configuration doesn't do that. I'm running the server from git HEAD, with the default configuration. I've never seen to add the "Debug :" output to every line.
If the path to directory or redirection of output can affect logging than I must say is not usual behavior and can be one of the reasons why every thread has a couple of posts where just this is discussed and not the actual issue.
That is simply not true. The majority of times that happens, it's for v3, AND they include the full timestamp in the debug output. Which means that they have *deliberately* used "radiusd -Xx".
Is there anything that can be enabled in the config file to get similar output (for me, not to post to lists)? For such powerful software debugging looks like the weakest thing. I tried debug_level 1, 2, 3, I was happy that I can change level "on fly" with radmin tool but all useful information I can only get with `-X` or `-Xx`. In my case, that means I must stop service, change config (I use some configs from ENV and it is not enough to export those because service forks as a user), manually start, find the issue then change back and start service. Not practical at all in production.
This is where test systems come in handy.
Debug log is above, sorry, I had to recompile, I commented out that line, because I don't want it in detail log, here is what I get:
Fri Aug 9 15:34:48 2019 Module-Failure-Message = "No 'accounting Start' section found: Ignoring it."
Then you're not running the default configuration. Which has an empty "accounting start" section.
Should I add empty accounting Start {} section, is that a must now (didn't try that, just cross my mind)? What about others, i.e. Stop/Alive, etc. My "default" site config is very simple and basic, I only use Accounting-Request/Response and listen.
Ah. So you deleted almost everything in the default configuration. And then got surprised that the server produced a warning message. That is not a productive thing to do. If you're running v4, "good luck". If it works, great. If it doesn't, submit a patch to fix it. v4 is in active development, and you should NOT be running it unless you know what you're doing. Alan DeKok.
Alan, Thank you for your time and patience. I understand that v4 is in active development and many things are missing or misbehave but I still need to use it. Milan On Fri, Aug 9, 2019 at 8:45 PM Alan DeKok <aland@deployingradius.com> wrote:
On Aug 9, 2019, at 1:27 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
So I now did exactly that and still have Debug lines in the log, see here (you can see what command is started after script in the log) https://pastebin.com/2nWMBKRM , that is not normal or now there are less Debug lines as you prefer?
The default configuration doesn't do that. I'm running the server from git HEAD, with the default configuration. I've never seen to add the "Debug :" output to every line.
If the path to directory or redirection of output can affect logging than I must say is not usual behavior and can be one of the reasons why every thread has a couple of posts where just this is discussed and not the actual issue.
That is simply not true. The majority of times that happens, it's for v3, AND they include the full timestamp in the debug output. Which means that they have *deliberately* used "radiusd -Xx".
Is there anything that can be enabled in the config file to get similar output (for me, not to post to lists)? For such powerful software debugging looks like the weakest thing. I tried debug_level 1, 2, 3, I was happy that I can change level "on fly" with radmin tool but all useful information I can only get with `-X` or `-Xx`. In my case, that means I must stop service, change config (I use some configs from ENV and it is not enough to export those because service forks as a user), manually start, find the issue then change back and start service. Not practical at all in production.
This is where test systems come in handy.
Debug log is above, sorry, I had to recompile, I commented out that line, because I don't want it in detail log, here is what I get:
Fri Aug 9 15:34:48 2019 Module-Failure-Message = "No 'accounting Start' section found: Ignoring it."
Then you're not running the default configuration. Which has an empty "accounting start" section.
Should I add empty accounting Start {} section, is that a must now (didn't try that, just cross my mind)? What about others, i.e. Stop/Alive, etc. My "default" site config is very simple and basic, I only use Accounting-Request/Response and listen.
Ah. So you deleted almost everything in the default configuration. And then got surprised that the server produced a warning message.
That is not a productive thing to do.
If you're running v4, "good luck". If it works, great. If it doesn't, submit a patch to fix it.
v4 is in active development, and you should NOT be running it unless you know what you're doing.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi, I just wanted to send an update, maybe it will be useful for someone else or for developers. What I found out is that when radiusd goes to some mode where ctrl+c/restart doesn't work and it must be killed, if I wait for at least 15min it will recover and it works normally after that. I first tried to change tcp_keepalive_intvl and tcp_keepalive_probes in the kernel, and Redis keepalive but without success. Instead, what fixed it for me was to change rediswho module pool settings, start=0, min=0, lifetime=60, cleanup_interval=30 and idle_timeout=0. Now everything works as expected and the Redis cluster and FreeRADIUS can both survive force power off. Regards, Milan On Fri, Aug 9, 2019 at 9:02 PM Milan Nikolic <gen2brain@gmail.com> wrote:
Alan,
Thank you for your time and patience. I understand that v4 is in active development and many things are missing or misbehave but I still need to use it.
Milan
On Fri, Aug 9, 2019 at 8:45 PM Alan DeKok <aland@deployingradius.com> wrote:
On Aug 9, 2019, at 1:27 PM, Milan Nikolic <gen2brain@gmail.com> wrote:
So I now did exactly that and still have Debug lines in the log, see here (you can see what command is started after script in the log) https://pastebin.com/2nWMBKRM , that is not normal or now there are less Debug lines as you prefer?
The default configuration doesn't do that. I'm running the server from git HEAD, with the default configuration. I've never seen to add the "Debug :" output to every line.
If the path to directory or redirection of output can affect logging than I must say is not usual behavior and can be one of the reasons why every thread has a couple of posts where just this is discussed and not the actual issue.
That is simply not true. The majority of times that happens, it's for v3, AND they include the full timestamp in the debug output. Which means that they have *deliberately* used "radiusd -Xx".
Is there anything that can be enabled in the config file to get similar output (for me, not to post to lists)? For such powerful software debugging looks like the weakest thing. I tried debug_level 1, 2, 3, I was happy that I can change level "on fly" with radmin tool but all useful information I can only get with `-X` or `-Xx`. In my case, that means I must stop service, change config (I use some configs from ENV and it is not enough to export those because service forks as a user), manually start, find the issue then change back and start service. Not practical at all in production.
This is where test systems come in handy.
Debug log is above, sorry, I had to recompile, I commented out that line, because I don't want it in detail log, here is what I get:
Fri Aug 9 15:34:48 2019 Module-Failure-Message = "No 'accounting Start' section found: Ignoring it."
Then you're not running the default configuration. Which has an empty "accounting start" section.
Should I add empty accounting Start {} section, is that a must now (didn't try that, just cross my mind)? What about others, i.e. Stop/Alive, etc. My "default" site config is very simple and basic, I only use Accounting-Request/Response and listen.
Ah. So you deleted almost everything in the default configuration. And then got surprised that the server produced a warning message.
That is not a productive thing to do.
If you're running v4, "good luck". If it works, great. If it doesn't, submit a patch to fix it.
v4 is in active development, and you should NOT be running it unless you know what you're doing.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (2)
-
Alan DeKok -
Milan Nikolic