________________________________________ 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.