proxy server goes deaf after "Client has closed connection" (RadSec to home server)
It appears there was another layer to my latest issue. Sometimes a server using RadSec to proxy to a home server ends up just waiting around unable to see any more incoming requests, and not having completed the current request. In this case the server is 3.0, and is sandwiched between our internal instance and our federation server (doing radsecproxy-ish stuff.) This may only happen in a corner case when the federation server is taking a while to reply, perhaps in this case where it exceeds our internal instance's response_window. I'm testing now whether using an immense response_window on the internal instance works as a workaround (assuming the federation server doesn't have any prolonged issues, of course) which would help support that theory. Info: (32) Proxying request to home server XXX.XXX.XXX.XXX port 2083 Tue Mar 6 13:59:08 2012 : Debug: Proxy is writing 122 bytes to SSL Tue Mar 6 13:59:08 2012 : Debug: Thread 3 waiting to be assigned a request Tue Mar 6 13:59:08 2012 : Debug: Proxy SSL socket has data to read Tue Mar 6 13:59:08 2012 : Debug: Client has closed connection (though, the client is UDP which has no transport layer connection, so... maybe that's talking about the home server, not a client? Not sure if that's coming from listen.c or tls_listen.c) (at this point the server does not see any additional requests sent to it, so we kill it to see if it is hanging out anywhere interesting... really should do this several times more to verify... maybe try a kill -9 next time...) Program received signal SIGINT, Interrupt. 0x0000003c7520dff4 in __lll_lock_wait () from /lib64/libpthread.so.0 #0 0x0000003c7520dff4 in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x0000003c75209328 in _L_lock_854 () from /lib64/libpthread.so.0 #2 0x0000003c752091f7 in pthread_mutex_lock () from /lib64/libpthread.so.0 #3 0x000000000042bb54 in remove_from_proxy_hash (request=0x805170) at process.c:1579 #4 0x000000000042d4f5 in request_done (request=<value optimized out>, action=<value optimized out>) at process.c:532 #5 0x000000000042f42d in remove_all_proxied_requests ( ctx=<value optimized out>, data=<value optimized out>) at process.c:1540 #6 0x00007ffff7de7822 in WalkNodeInOrder (X=<value optimized out>, callback=0x42f400 <remove_all_proxied_requests>, context=0x7fffec003710) at rbtree.c:551 #7 0x0000000000431354 in event_new_fd (this=0x7fffec003710) at process.c:3553 #8 0x000000000043c648 in proxy_tls_recv (listener=0x7fffec003710) at tls_listen.c:499 #9 0x0000000000430a8a in event_socket_handler (xel=<value optimized out>, fd=<value optimized out>, ctx=0x7fffec003710) at process.c:3309 #10 0x00007ffff7deddfb in fr_event_loop (el=0x7d0b10) at event.c:415 #11 0x0000000000422534 in main (argc=<value optimized out>, argv=<value optimized out>) at radiusd.c:413 Just one of those occasions where the grass looks greener on the SEGV side of the fence :-)
Brian Julin wrote:
(at this point the server does not see any additional requests sent to it, so we kill it to see if it is hanging out anywhere interesting... really should do this several times more to verify... maybe try a kill -9 next time...)
It's hanging because it's trying to lock the proxy mutex twice. That's a no-no. I'll push a fix later today. Alan DeKok.
________________________________________ Alan DeKok [aland@deployingradius.com] wrote
Sent: Wednesday, March 07, 2012 3:52 AM To: FreeRadius users mailing list Subject: Re: proxy server goes deaf after "Client has closed connection" (RadSec to home server)
Brian Julin wrote:
(at this point the server does not see any additional requests sent to it, so we kill it to see if it is hanging out anywhere interesting... really should do this several times more to verify... maybe try a kill -9 next time...)
It's hanging because it's trying to lock the proxy mutex twice. That's a no-no.
I'll push a fix later today.
This keeps the server listening, but there are some lingering issues: 10:40:31 : Info: (18) Proxying request to home server XXX.XXX.XXX.XXX port 2083 10:40:31 : Debug: Proxy is writing 123 bytes to SSL 10:40:31 : Debug: Thread 1 waiting to be assigned a request 10:40:31 : Debug: Proxy SSL socket has data to read 10:40:31 : Debug: Client has closed connection 10:40:31 : Info: ... closing socket proxy (YYY.YYY.YYY.YYY, 39314) -> home_server (XXX.XXX.XXX.XXX, 2083) 10:40:31 : Debug: Waking up in 0.3 seconds. 10:40:31 : Debug: Waking up in 0.4 seconds. 10:40:31 : Debug: Waking up in 29.1 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 51126, id=247, length=147 10:40:34 : Debug: Opening new proxy (YYY.YYY.YYY.YYY, 0) -> home_server (XXX.XXX.XXX.XXX, 2083) 10:40:34 : Debug: Trying SSL to port 2083 10:40:34 : Debug: Requiring Server certificate 10:40:34 : Debug: Listening on proxy (YYY.YYY.YYY.YYY, 41712) -> home_server (XXX.XXX.XXX.XXX, 2083) 10:40:34 : Debug: No Post-Proxy-Type Fail: ignoring 10:40:34 : Debug: Waking up in 26.8 seconds. (... resends from the client don't work... This may or may not be time-window related...) rad_recv: Access-Request packet from host 127.0.0.1 port 51126, id=247, length=147 10:40:40 : Proxy: (18) Failed to insert entry into proxy list. 10:40:40 : Proxy: (18) Failed to insert initial packet into the proxy list. 10:40:40 : Debug: No Post-Proxy-Type Fail: ignoring 10:40:40 : Debug: Waking up in 20.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 51126, id=247, length=147 10:40:52 : Proxy: (18) Failed to insert entry into proxy list. 10:40:52 : Proxy: (18) Failed to insert initial packet into the proxy list. 10:40:52 : Debug: No Post-Proxy-Type Fail: ignoring 10:40:52 : Debug: Waking up in 8.9 seconds. 10:41:01 : Debug: Waking up in 4.9 seconds. 10:41:06 : Info: (18) Cleaning up request packet ID 247 with timestamp +4879 10:41:06 : Info: Ready to process requests. (...this next set of requests succeeds...) rad_recv: Access-Request packet from host 127.0.0.1 port 51126, id=251, length=147 10:48:06 : Debug: Waking up in 0.3 seconds. 10:48:06 : Debug: Thread 4 got semaphore 10:48:06 : Debug: Thread 4 handling request 19, (10 handled so far) (...) 10:48:06 : Info: (27) Finished request 27. 10:48:06 : Debug: Thread 2 waiting to be assigned a request 10:48:06 : Debug: Waking up in 0.1 seconds. 10:48:07 : Debug: Waking up in 4.1 seconds. 10:48:11 : Info: (19) Cleaning up request packet ID 251 with timestamp +5334 10:48:11 : Info: (20) Cleaning up request packet ID 177 with timestamp +5334 10:48:11 : Info: (21) Cleaning up request packet ID 59 with timestamp +5334 10:48:11 : Info: (22) Cleaning up request packet ID 56 with timestamp +5334 10:48:11 : Debug: Waking up in 0.1 seconds. 10:48:11 : Info: (24) Cleaning up request packet ID 183 with timestamp +5334 10:48:11 : Info: (25) Cleaning up request packet ID 243 with timestamp +5334 10:48:11 : Info: (26) Cleaning up request packet ID 134 with timestamp +5334 10:48:11 : Info: (27) Cleaning up request packet ID 128 with timestamp +5334 10:48:11 : Info: Ready to process requests. (...however, this can now happen on subsequent requests, or sometimes out of the blue. It doesn't always...) 10:56:37 : Debug: Proxy SSL socket has data to read 10:56:37 : Debug: Client has closed connection 10:56:37 : Info: ... closing socket proxy (YYY.YYY.YYY.YYY, 41712) -> home_server (XXX.XXX.XXX.XXX, 2083) 10:56:37 : Error: Fatal error removing socket: (unknown error) [Thread 0x7ffff4f94700 (LWP 24568) exited] [Thread 0x7ffff5995700 (LWP 24567) exited] [Thread 0x7ffff6d97700 (LWP 24565) exited] [Thread 0x7ffff6396700 (LWP 24566) exited] (...That one above was "from out of the blue". This one I put a breakpoint in and it happened while processing a request..) Breakpoint 1, event_new_fd (this=0x805790) at process.c:3715 3715 radlog(L_ERR, "Fatal error removing socket: %s", (gdb) bt #0 event_new_fd (this=0x805790) at process.c:3715 #1 0x000000000043c718 in proxy_tls_recv (listener=0x805790) at tls_listen.c:499 #2 0x0000000000430a9a in event_socket_handler (xel=<value optimized out>, fd=<value optimized out>, ctx=0x805790) at process.c:3327 #3 0x00007ffff7deddfb in fr_event_loop (el=0x7d0c20) at event.c:415 #4 0x00000000004224e4 in main (argc=<value optimized out>, argv=<value optimized out>) at radiusd.c:413 (gdb) list 3710 */ 3711 if (this->type == RAD_LISTEN_PROXY) { 3712 PTHREAD_MUTEX_LOCK(&proxy_mutex); 3713 if (!fr_packet_list_socket_remove(proxy_list, 3714 this->fd, NULL)) { (...) (gdb) print proxy_list $1 = (fr_packet_list_t *) 0x7de490 (gdb) print this->fd $3 = 9 ...likely just not in the list. P.S./OT: the new TLS PWD stuff could use some autoconfigure love for RHELs that don't have EC support in OpenSSL.
Brian Julin wrote:
This keeps the server listening, but there are some lingering issues:
Well, fixes are welcome. I don't have time to look into this for a few weeks at least. Alan DeKok.
Alan DeKok [aland@deployingradius.com] wrote:
Sent: Friday, March 09, 2012 3:25 AM Brian Julin wrote:
This keeps the server listening, but there are some lingering issues:
Well, fixes are welcome.
I don't have time to look into this for a few weeks at least.
request_proxy_anew was assuming its argument would be installed in the proxy_list, which wasn't the case, so it was removing it twice causing .num_outgoing counters to roll over. Then, request_proxy was not expecting the case where the argument was already in the proxy_list (put there by request_proxy_anew) and was failing when attempting to add it a second time. The latter makes me wonder why or if request_proxy_anew works at all. The attached patch seems to do the trick. Some caveats: This bypasses (for certain situations) the attempts to make sure that a duplicate packet does not reuse the proxy_list ID of its predecessor. Not knowing the reasoning behind that, I don't know if that's important or not. request_proxy has a "retransmit" flag as a parameter, which might be the better test to avoid inserting the entry twice, or might not be. Off topic, JOOC, while reading through the source I was left wondering what prevents proxy_wait_for_reply from entering master-only functions from a non-master thread when it falls through the DUP case into the TIMER case.
Brian Julin wrote:
request_proxy_anew was assuming its argument would be installed in the proxy_list, which wasn't the case, so it was removing it twice causing .num_outgoing counters to roll over. Then, request_proxy was not expecting the case where the argument was already in the proxy_list (put there by request_proxy_anew) and was failing when attempting to add it a second time. The latter makes me wonder why or if request_proxy_anew works at all.
It was tested at one point. But the code has changed since then. It's nice to know that code was understandable. The state machine in process.c is complicated enough that I try not to touch it too much.
The attached patch seems to do the trick. Some caveats:
This bypasses (for certain situations) the attempts to make sure that a duplicate packet does not reuse the proxy_list ID of its predecessor. Not knowing the reasoning behind that, I don't know if that's important or not.
It's not important.
request_proxy has a "retransmit" flag as a parameter, which might be the better test to avoid inserting the entry twice, or might not be.
I think that flag is independent of the issue you found.
Off topic, JOOC, while reading through the source I was left wondering what prevents proxy_wait_for_reply from entering master-only functions from a non-master thread when it falls through the DUP case into the TIMER case.
Whoops. You're right. I'll go commit a fix for that. Alan DeKok.
Alan DeKok Wrote
Brian Julin wrote:
The latter makes me wonder why or if request_proxy_anew works at all.
It was tested at one point. But the code has changed since then.
Given the complexity of RADIUS state management, automating a comprehensive test suite for it would be a very interesting endeavor. It might even be worthy of a GSoC project proposal, to get an aspiring coder to flesh out src/tests, firing up test servers and VMs/fragrouters to really work the corner cases and cover previous issues from the ML/git-log against regressions. Not sure how far they would get, but they'd sure learn a lot about application internetworking by trying, and the resulting framework would probably be applicable to other heavily-interfaced server suites.
It's nice to know that code was understandable.
That... took a while. I even had to draw pictures. :-) If I ever do that again, maybe I'll finish them enough to submit them as devel docs. Thanks again for holding it all together, Alan. -- Brian
participants (2)
-
Alan DeKok -
Brian Julin