proxy server goes deaf after "Client has closed connection" (RadSec to home server)

[Brian Julin]

________________________________________
Alan DeKok [aland at 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.