radiusd deadlock on recvfrom on port 1814
Hey, I've had FreeRADIUS Version 1.1.0 hang twice recently. The core dumps are very similar in that it appears that main is waiting on some stuff from port 1814. Honestly I don't know what 1814 is really for (proxy port?) but it seems as if fd_isset says so we should expect some data on that socket. Unless something _else_ had already received that data. I hadn't noticed this before I added radrelay and another radiusd process on the same box. Both radiusd processes are bound to different virtual interfaces and radrelay is duplicating acct packets from one to the other. It's not obvious why there would be a race condition on that socket, but my guess is something is going on there. It seems as though both radiusd processes are using the same descriptors for each of their three sockets. I've included some debug info from the core files. Is this a know bug or can it be fixed with a configuration change? Thanks, Ryan ---------------------------------------------------------------------- Process One: (gdb) print *(rad_listen_t *) mainconfig.listen $1 = {next = 0x458023e8, ipaddr = 486477016, type = RAD_LISTEN_AUTH, port = 1812, fd = 3} (gdb) print *(rad_listen_t *) mainconfig.listen->next $2 = {next = 0x4580eef8, ipaddr = 486477016, type = RAD_LISTEN_ACCT, port = 1813, fd = 4} (gdb) print *(rad_listen_t *) mainconfig.listen->next->next $3 = {next = 0x0, ipaddr = 486477016, type = RAD_LISTEN_PROXY, port = 1814, fd = 5} Process Two: gdb) print *(rad_listen_t *) mainconfig.listen $2 = {next = 0x8117fe0, ipaddr = 1459555544, type = RAD_LISTEN_AUTH, port = 1812, fd = 3} (gdb) print *(rad_listen_t *) mainconfig.listen->next $3 = {next = 0x8117ff8, ipaddr = 1459555544, type = RAD_LISTEN_ACCT, port = 1813, fd = 4} (gdb) print *(rad_listen_t *) mainconfig.listen->next->next $4 = {next = 0x0, ipaddr = 1459555544, type = RAD_LISTEN_PROXY, port = 1814, fd = 5} Process One: (gdb) info threads * 6 process 11191 0x0804d145 in main (argc=1166077688, argv=0xbfffd0c0) at radiusd.c:1323 5 process 19865 0x401c8d0b in sem_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0 4 process 19864 0x401c8d0b in sem_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0 3 process 19863 0x401c8d0b in sem_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0 2 process 19862 0x401c8d0b in sem_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0 1 process 19861 0x401c8d0b in sem_wait@GLIBC_2.0 () from /lib/tls/libpthread.so.0 (gdb) bt #0 0x401c99fe in recvfrom () from /lib/tls/libpthread.so.0 #1 0x4004e6d1 in rad_recv (fd=5) at radius.c:1044 #2 0x0804d145 in main (argc=1166077688, argv=0xbfffd0c0) at radiusd.c:1323 (gdb) print *(rad_listen_t *) listener $22 = {next = 0x0, ipaddr = 486477016, type = RAD_LISTEN_PROXY, port = 1814, fd = 5} (gdb) frame 1 #1 0x4004e6d1 in rad_recv (fd=5) at radius.c:1044 1044 radius.c: No such file or directory. in radius.c (gdb) info locals packet = (RADIUS_PACKET *) 0x4780dc38 saremote = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"} totallen = 263 salen = 16 attr = (uint8_t *) 0x0 count = -1073758352 host_ipaddr = "\000\000\000\000��������۾\005\b" seen_eap = 0 data = "stuff"... --
Ryan Melendez wrote:
I've had FreeRADIUS Version 1.1.0 hang twice recently. The core dumps are very similar in that it appears that main is waiting on some stuff from port 1814. Honestly I don't know what 1814 is really for (proxy port?) but it seems as if fd_isset says so we should expect some data on that socket. Unless something _else_ had already received that data.
1814 is for proxying, yes. And it shouldn't hang... it should do *something* at least.
I hadn't noticed this before I added radrelay and another radiusd process on the same box. Both radiusd processes are bound to different virtual interfaces and radrelay is duplicating acct packets from one to the other. It's not obvious why there would be a race condition on that socket, but my guess is something is going on there. It seems as though both radiusd processes are using the same descriptors for each of their three sockets. I've included some debug info from the core files.
The descriptors are local to the process, and don't mean anything.
Is this a know bug or can it be fixed with a configuration change?
It sounds like a kernel bug to me. recvfrom() on a UDP socket *always* returns quickly. If there's no data, it returns immediately with an error. If there is data it returns the data. If recvfrom() hangs, then it's not the fault of the application. And there's nothing the application can do to fix it. Alan DeKok.
On Thu, 2007-10-18 at 01:10 +0200, Alan DeKok wrote:
Ryan Melendez wrote:
I've had FreeRADIUS Version 1.1.0 hang twice recently. The core dumps are very similar in that it appears that main is waiting on some stuff from port 1814. Honestly I don't know what 1814 is really for (proxy port?) but it seems as if fd_isset says so we should expect some data on that socket. Unless something _else_ had already received that data.
1814 is for proxying, yes. And it shouldn't hang... it should do *something* at least.
I hadn't noticed this before I added radrelay and another radiusd process on the same box. Both radiusd processes are bound to different virtual interfaces and radrelay is duplicating acct packets from one to the other. It's not obvious why there would be a race condition on that socket, but my guess is something is going on there. It seems as though both radiusd processes are using the same descriptors for each of their three sockets. I've included some debug info from the core files.
The descriptors are local to the process, and don't mean anything.
Is this a know bug or can it be fixed with a configuration change?
It sounds like a kernel bug to me. recvfrom() on a UDP socket *always* returns quickly. If there's no data, it returns immediately with an error. If there is data it returns the data.
If recvfrom() hangs, then it's not the fault of the application. And there's nothing the application can do to fix it. recvfrom() blocks on datagram sockets just like any other type of socket unless it gets a S0_RCVTIMEO or the O_NONBLOCK is set (in which case you would receive an error).
http://www.opengroup.org/onlinepubs/000095399/functions/recvfrom.html "If no messages are available at the socket and O_NONBLOCK is not set on the socket's file descriptor, recvfrom() shall block until a message arrives. If no messages are available at the socket and O_NONBLOCK is set on the socket's file descriptor, recvfrom() shall fail and set errno to [EAGAIN] or [EWOULDBLOCK]."
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Ryan Melendez wrote:
recvfrom() blocks on datagram sockets just like any other type of socket unless it gets a S0_RCVTIMEO or the O_NONBLOCK is set (in which case you would receive an error).
Hmm... I guess I hadn't run into that before, because select() never lied about data being available. The simplest solution on your system is to set O_NONBLOCK on the sockets. But that is just a work-around for the kernel bug (i.e. race condition). If data is ready on a socket, it means that data is ready... blocking on the recvfrom() after telling the application that data is ready is not very nice. Alan DeKok.
On Wed, 2007-10-31 at 08:13 +0100, Alan DeKok wrote:
Ryan Melendez wrote:
recvfrom() blocks on datagram sockets just like any other type of socket unless it gets a S0_RCVTIMEO or the O_NONBLOCK is set (in which case you would receive an error).
Hmm... I guess I hadn't run into that before, because select() never lied about data being available.
The simplest solution on your system is to set O_NONBLOCK on the sockets. But that is just a work-around for the kernel bug (i.e. race condition). If data is ready on a socket, it means that data is ready... blocking on the recvfrom() after telling the application that data is ready is not very nice.
I'm not positive that select is lying about data being available. It could be that there is data when select is called, but _something_ out of line grabs it before recvfrom() can get to it. The only time I've ran into this in the past(not freeradius) is when some flavor of read is called on the socket outside the select loop (bad programming). I can't see anywhere this is happening in freeradius. Again, this only started happening when I began running two radiusd processes on different interfaces on a multihomed system. I also have radrelay binding to one interface and replicating acct packets to the other process. I suspect you are correct that some race condition in the kernel possibly regarding pthread. I'm going to continue investigating, I'll make the socket non-blocking as a last resort. If anyone has experienced this problem before, or has any suggestions please let me know. Thanks, Ryan
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Ryan Melendez wrote:
I'm not positive that select is lying about data being available. It could be that there is data when select is called, but _something_ out of line grabs it before recvfrom() can get to it.
Like what? There is nothing else listening on that IP address/port. The socket API makes sure of that.
The only time I've ran into this in the past(not freeradius) is when some flavor of read is called on the socket outside the select loop (bad programming). I can't see anywhere this is happening in freeradius.
There is only one place in the server where sockets are read: the main read loop.
Again, this only started happening when I began running two radiusd processes on different interfaces on a multihomed system. I also have radrelay binding to one interface and replicating acct packets to the other process.
Hmm... even 1.1.x can have one process listen on multiple interfaces. Why not try that? But 2.0 will make this much easier, as you can have different virtual servers (and thus completely different policies) for each socket. This is hard in 1.x.
I suspect you are correct that some race condition in the kernel possibly regarding pthread. I'm going to continue investigating, I'll make the socket non-blocking as a last resort.
If anyone has experienced this problem before, or has any suggestions please let me know.
I've never seen it. Alan DeKok.
On Fri, 2007-11-02 at 14:33 +0100, Alan DeKok wrote:
Ryan Melendez wrote:
I'm not positive that select is lying about data being available. It could be that there is data when select is called, but _something_ out of line grabs it before recvfrom() can get to it.
Like what? There is nothing else listening on that IP address/port. The socket API makes sure of that.
I wish I knew. One thing I specifically mention is that the two radius servers are bound to two different virtual interfaces with unique IPs. So both servers are running on the same physical interface. My only guess at this point is that something is going on with how virtual interfaces work under the hood. So something lower than the socket API... So I'm now wondering if there is something fundamentally wrong with how the kernel treats two udp sockets: 1)listening on the same port 2)bound to two different IPs, one of which is a VIF on the same physical interface 3)in two entirely different processes I'm inclined to say hell no, but stranger things have happened.
Again, this only started happening when I began running two radiusd processes on different interfaces on a multihomed system. I also have radrelay binding to one interface and replicating acct packets to the other process.
Hmm... even 1.1.x can have one process listen on multiple interfaces. Why not try that? I need to replicate acct data. I have radrelay replicating the data from the detail file of one sever to the other server bound to a virtual interface. This is the only way I found I could replicate the data while still getting the failover/unique proxy/timeout requirements. The second radius server only gets acct packets via radrelay originally sent to the first radius server.
I haven't figured out what port 1814 is actually used for. Is there anything I could do to disable the "proxy port" on one or both of the servers? What would I loose? Thanks, Ryan
Ryan Melendez wrote:
I wish I knew. One thing I specifically mention is that the two radius servers are bound to two different virtual interfaces with unique IPs.
That shouldn't matter...
So I'm now wondering if there is something fundamentally wrong with how the kernel treats two udp sockets:
1)listening on the same port 2)bound to two different IPs, one of which is a VIF on the same physical interface 3)in two entirely different processes
I'm inclined to say hell no, but stranger things have happened.
It's certainly possible that it's not a well tested portion of the kernel. In any case, set O_NONBLOCK on the sockets, and the problem should be fixed.
Hmm... even 1.1.x can have one process listen on multiple interfaces. Why not try that? I need to replicate acct data. I have radrelay replicating the data from the detail file of one sever to the other server bound to a virtual interface. This is the only way I found I could replicate the data while still getting the failover/unique proxy/timeout requirements. The second radius server only gets acct packets via radrelay originally sent to the first radius server.
Hmm.... 2.0 may handle that a lot better.
I haven't figured out what port 1814 is actually used for. Is there anything I could do to disable the "proxy port" on one or both of the servers? What would I loose?
The ability to send packets to other servers. 1814 is used when FreeRADIUS is acting as a RADIUS client (i.e. proxy). Alan DeKok.
I haven't figured out what port 1814 is actually used for. Is there anything I could do to disable the "proxy port" on one or both of the servers? What would I loose?
The ability to send packets to other servers. 1814 is used when FreeRADIUS is acting as a RADIUS client (i.e. proxy).
Am I right to assume the only time data should be read on port 1814 is when there is a reply to a proxied request? Specifically freeradius proxied a auth/acct packet on port 1814 and the "home" server replied on port 1814. The only data that should show up on 1814 is that reply from the home server? Thanks, Ryan
Ryan Melendez wrote:
Am I right to assume the only time data should be read on port 1814 is when there is a reply to a proxied request?
Yes.
Specifically freeradius proxied a auth/acct packet on port 1814 and the "home" server replied on port 1814. The only data that should show up on 1814 is that reply from the home server?
Yes. Or, attackers on the network sending you bad packets. But they won't be signed with the RADIUS shared secret, so they will be ignored. Alan DeKok.
participants (2)
-
Alan DeKok -
Ryan Melendez