Closed haegar closed 1 month ago
alandekok
commented
6 months ago Please try this patch, and run with -sf -l stdout -xxx. It won't fix the problem, but it adds more debug output which may help to track it down.
Please post the debug output here.
I may not have time to look at this in more detail for a week or so.
haegar
commented
6 months ago Moin,
Thankks for the quick response.
Testing with your debug patch applied and executing
$ /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -sf -l stdout -xxx
Skipped the startup messages, they are similar to the bug report itself.
Messages from freeradius when client requests come in:
Thu Mar 14 22:01:05 2024 : Debug: (0) Received Access-Request Id 115 from 127.0.0.1:59607 to 127.0.0.1:3812 length 78 Thu Mar 14 22:01:05 2024 : Debug: (0) User-Name = "test@shs" Thu Mar 14 22:01:05 2024 : Debug: (0) User-Password = "test" Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1 Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-Port = 23 Thu Mar 14 22:01:05 2024 : Debug: (0) Message-Authenticator = 0x134d0021047f9de7740da15a1c0666e3 Thu Mar 14 22:01:05 2024 : Debug: (0) session-state: No State attribute Thu Mar 14 22:01:05 2024 : Debug: (0) # Executing section authorize from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward Thu Mar 14 22:01:05 2024 : Debug: (0) authorize { Thu Mar 14 22:01:05 2024 : Debug: (0) update control { Thu Mar 14 22:01:05 2024 : Debug: (0) Proxy-To-Realm = 'shs' Thu Mar 14 22:01:05 2024 : Debug: (0) } # update control = noop Thu Mar 14 22:01:05 2024 : Debug: (0) update request { Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Type} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Access-Request Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := Access-Request Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address} Thu Mar 14 22:01:05 2024 : Debug: (0) --> 127.0.0.1 Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1 Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := Thu Mar 14 22:01:05 2024 : Debug: (0) } # update request = noop Thu Mar 14 22:01:05 2024 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap) Thu Mar 14 22:01:05 2024 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap) Thu Mar 14 22:01:05 2024 : Debug: (0) [pap] = noop Thu Mar 14 22:01:05 2024 : Debug: (0) } # authorize = noop Thu Mar 14 22:01:05 2024 : Debug: Using home pool auth for realm shs Thu Mar 14 22:01:05 2024 : Debug: (0) Starting proxy to home server 172.16.9.102 port 2083 Thu Mar 14 22:01:05 2024 : Debug: (0) server caradius { Thu Mar 14 22:01:05 2024 : Debug: (0) # Executing section pre-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward Thu Mar 14 22:01:05 2024 : Debug: (0) pre-proxy { Thu Mar 14 22:01:05 2024 : Debug: (0) update proxy-request { Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Type} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Access-Request Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := Access-Request Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "Access-Request" with "Access-Request" Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address} Thu Mar 14 22:01:05 2024 : Debug: (0) --> 127.0.0.1 Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1 Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "127.0.0.1" with "127.0.0.1" Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "" with "" Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp} Thu Mar 14 22:01:05 2024 : Debug: (0) --> Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "" with "" Thu Mar 14 22:01:05 2024 : Debug: (0) } # update proxy-request = noop Thu Mar 14 22:01:05 2024 : Debug: (0) } # pre-proxy = noop Thu Mar 14 22:01:05 2024 : Debug: (0) } Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Thu Mar 14 22:01:05 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.102, 2083) Thu Mar 14 22:01:05 2024 : Debug: Requiring Server certificate Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello Thu Mar 14 22:01:05 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello Thu Mar 14 22:01:05 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 40477) -> home_server (172.16.9.102, 2083)' Thu Mar 14 22:01:05 2024 : Debug: Listening on proxy (10.113.0.10, 40477) -> home_server (172.16.9.102, 2083) Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: request is now in proxy hash Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: allocating destination 172.16.9.102 port 2083 - Id 115 Thu Mar 14 22:01:05 2024 : Debug: (0) Proxying request to home server 172.16.9.102 port 2083 (TLS) timeout 10.000000 Thu Mar 14 22:01:05 2024 : Debug: (0) Sent Access-Request Id 115 from 10.113.0.10:40477 to 172.16.9.102:2083 length 122 Thu Mar 14 22:01:05 2024 : Debug: (0) User-Name = "test@shs" Thu Mar 14 22:01:05 2024 : Debug: (0) User-Password = "test" Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1 Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-Port = 23 Thu Mar 14 22:01:05 2024 : Debug: (0) Message-Authenticator = 0x134d0021047f9de7740da15a1c0666e3 Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request" Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1" Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := "" Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := "" Thu Mar 14 22:01:05 2024 : Debug: (0) Proxy-State = 0x313135 Thu Mar 14 22:01:05 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello Thu Mar 14 22:01:05 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) Saving 122 bytes of RADIUS traffic for later (total 122) Thu Mar 14 22:01:05 2024 : Debug: Waking up in 0.3 seconds. Thu Mar 14 22:01:05 2024 : Debug: (0) Expecting proxy response no later than 9.666745 seconds from now Thu Mar 14 22:01:05 2024 : Debug: Waking up in 0.5 seconds. Thu Mar 14 22:01:06 2024 : Debug: Waking up in 9.1 seconds. Thu Mar 14 22:01:10 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 172.16.9.102 port 2083 proto TCP - ID: 115 Thu Mar 14 22:01:10 2024 : Debug: Waking up in 4.9 seconds. Thu Mar 14 22:01:15 2024 : Debug: (0) No proxy response, giving up on request and marking it done Thu Mar 14 22:01:15 2024 : ERROR: (0) Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.102 port 2083 Thu Mar 14 22:01:15 2024 : Debug: (0) Clearing existing &reply: attributes Thu Mar 14 22:01:15 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication Thu Mar 14 22:01:15 2024 : Debug: (0) server caradius { Thu Mar 14 22:01:15 2024 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring. Thu Mar 14 22:01:15 2024 : Debug: (0) # Executing group from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward Thu Mar 14 22:01:15 2024 : Debug: (0) } Thu Mar 14 22:01:15 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [test@shs] (from client caradius-world4 port 23) Thu Mar 14 22:01:15 2024 : Debug: (0) There was no response configured: rejecting request Thu Mar 14 22:01:15 2024 : Debug: (0) Using Post-Auth-Type Reject Thu Mar 14 22:01:15 2024 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring. Thu Mar 14 22:01:15 2024 : Auth: (0) Login incorrect (Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.102 port 2083): [test@shs] (from client caradius-world4 port 23) Thu Mar 14 22:01:15 2024 : Debug: (0) Sent Access-Reject Id 115 from 127.0.0.1:3812 to 127.0.0.1:59607 length 20 Thu Mar 14 22:01:15 2024 : Debug: (0) Finished request Thu Mar 14 22:01:15 2024 : Debug: Waking up in 4.9 seconds. Thu Mar 14 22:01:20 2024 : Debug: (0) Cleaning up request packet ID 115 with timestamp +31 due to cleanup_delay was reached
The messages from your debug patch only appear way after the TLS client hello errors were already reported.
(And strangely freeradius reported "Sent Access-Request Id 115 ...", when clearly due to the TLS establishing error the request has not been sent to the server yet).
Greetings, Haegar
alandekok
commented
2 months ago After some debugging, it looks like an OpenSSL issue.
The call to SSL_connect() is supposed to be blocking if the underlying socket is blocking. However, SSL_connect() always returns WANT_WRITE, which it's not supposed to do when the socket is blocking.
In addition, when SSL_connect() returns WANT_WRITE, there is no data to write. Repeated calls to SSL_connect() always result in WANT_WRITE. When looking at the underlying BIO, there's no data for OpenSSL to write.
And this behavior of SSL_connect() happens for both blocking, and non-blocking sockets.
So it looks like something in OpenSSL changed. There's likely two bugs: (1) SSL_connect() returning WANT_WRITE when there's no data to send, and (2) SSL_connect() returning WANT_WRITE for non-blocking sockets.
haegar
commented
1 month ago Moin,
(Working with freeradius 3.2 git release_3_2_5-38-gc4fbd09742, debian unstable, and using openssl 3.2.2-1)
I did some further debugging, and with the following totally ugly and non-production usable patch I made all the connections to work:
--- a/src/main/tls_listen.c
+++ b/src/main/tls_listen.c
@@ -1057,6 +1059,8 @@ static int try_connect(listen_socket_t *
int ret;
time_t now;
+ DEBUG3("try_connect()");
+
now = time(NULL);
if ((sock->opened + sock->connect_timeout) < now) {
tls_error_io_log(NULL, sock->ssn, 0, "Timeout in SSL_connect");
@@ -1065,17 +1069,34 @@ static int try_connect(listen_socket_t *
ret = SSL_connect(sock->ssn->ssl);
if (ret <= 0) {
- switch (SSL_get_error(sock->ssn->ssl, ret)) {
+ int error, retry;
+ error = SSL_get_error(sock->ssn->ssl, ret);
+ retry = 0;
+
+ while (error == SSL_ERROR_WANT_READ || error == SSL_ERROR_WANT_WRITE) {
+ retry++;
+ DEBUG3("try_connect failed with %d - retry %d", error, retry);
+ usleep(10);
+ ret = SSL_connect(sock->ssn->ssl);
+ if (ret > 0) {
+ sock->ssn->connected = true;
+ return 1;
+ } else {
+ error = SSL_get_error(sock->ssn->ssl, ret);
+ }
+ }
+
+ switch (error) {
default:
tls_error_io_log(NULL, sock->ssn, ret, "Failed in " STRINGIFY(__FUNCTION__) " (SSL_connect)");
return -1;
case SSL_ERROR_WANT_READ:
- DEBUG3("(TLS) SSL_connect() returned WANT_READ");
+ DEBUG3("try_connect (TLS) SSL_connect() returned WANT_READ");
return 2;
case SSL_ERROR_WANT_WRITE:
- DEBUG3("(TLS) SSL_connect() returned WANT_WRITE");
+ DEBUG3("try_connect (TLS) SSL_connect() returned WANT_WRITE");
return 2;
}
}
@@ -1113,7 +1134,10 @@ static ssize_t proxy_tls_read(rad_listen
rcode = try_connect(sock);
if (rcode <= 0) return rcode;
- if (rcode == 2) return 0; /* more negotiation needed */
+ if (rcode == 2) {
+ DEBUG3("proxy_tls_read: try_connect() returned 2, more negotiation needed");
+ return 0; /* more negotiation needed */
+ }
#ifdef WITH_RADIUSV11
if (!sock->alpn_checked && (fr_radiusv11_client_get_alpn(listener) < 0)) {
@@ -1156,11 +1180,11 @@ static ssize_t proxy_tls_read(rad_listen
switch (err) {
case SSL_ERROR_WANT_READ:
- DEBUG3("(TLS) OpenSSL returned WANT_READ");
+ DEBUG3("proxy_tls_read SSL_read 1 (TLS) OpenSSL returned WANT_READ");
return 0;
case SSL_ERROR_WANT_WRITE:
- DEBUG3("(TLS) OpenSSL returned WANT_WRITE");
+ DEBUG3("proxy_tls_read SSL_read 1 (TLS) OpenSSL returned WANT_WRITE");
return 0;
case SSL_ERROR_ZERO_RETURN:
@@ -1218,11 +1242,11 @@ static ssize_t proxy_tls_read(rad_listen
switch (err) {
case SSL_ERROR_WANT_READ:
- DEBUG3("(TLS) OpenSSL returned WANT_READ");
+ DEBUG3("proxy_tls_read SSL_read 2 (TLS) OpenSSL returned WANT_READ");
return 0;
case SSL_ERROR_WANT_WRITE:
- DEBUG3("(TLS) OpenSSL returned WANT_WRITE");
+ DEBUG3("proxy_tls_read SSL_read 2 (TLS) OpenSSL returned WANT_WRITE");
return 0;
case SSL_ERROR_ZERO_RETURN:
@@ -1426,6 +1450,8 @@ int proxy_tls_send(rad_listen_t *listene
* connection.
*/
if (rcode == 2) {
+ DEBUG3("proxy_tls_send: try_connect() returned 2, more negotiation needed");
+
PTHREAD_MUTEX_LOCK(&sock->mutex);
if ((sock->ssn->clean_out.used + request->proxy->data_len) > MAX_RECORD_SIZE) {
PTHREAD_MUTEX_UNLOCK(&sock->mutex);
@@ -1506,11 +1532,11 @@ int proxy_tls_send(rad_listen_t *listene
break;
case SSL_ERROR_WANT_READ:
- DEBUG3("(TLS) OpenSSL returned WANT_READ");
+ DEBUG3("proxy_tls_send (TLS) OpenSSL returned WANT_READ");
break;
case SSL_ERROR_WANT_WRITE:
- DEBUG3("(TLS) OpenSSL returned WANT_WRITE");
+ DEBUG3("proxy_tls_send (TLS) OpenSSL returned WANT_WRITE");
break;
default:
@@ -1579,7 +1605,7 @@ int proxy_tls_send_reply(rad_listen_t *l
case SSL_ERROR_NONE:
case SSL_ERROR_WANT_READ:
case SSL_ERROR_WANT_WRITE:
- DEBUG3("(TLS) SSL_write() returned %s", ERR_reason_error_string(err));
+ DEBUG3("proxy_tls_send_reply (TLS) SSL_write() returned %s", ERR_reason_error_string(err));
break; /* let someone else retry */
default:
Log output from my patched binary creating a successful connection:
Fri Jul 26 18:07:15 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Fri Jul 26 18:07:15 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Fri Jul 26 18:07:15 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.156, 2083)
Fri Jul 26 18:07:15 2024 : Debug: Requiring Server certificate
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE
Fri Jul 26 18:07:15 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 59773) -> home_server (172.16.9.156, 2083)'
Fri Jul 26 18:07:15 2024 : Debug: Listening on proxy (10.113.0.10, 59773) -> home_server (172.16.9.156, 2083)
Fri Jul 26 18:07:15 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Fri Jul 26 18:07:15 2024 : Debug: (0) proxy: request is now in proxy hash
Fri Jul 26 18:07:15 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 171
Fri Jul 26 18:07:15 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000
Fri Jul 26 18:07:15 2024 : Debug: (0) Sent Access-Request Id 171 from 10.113.0.10:59773 to 172.16.9.156:2083 length 122
Fri Jul 26 18:07:15 2024 : Debug: (0) Message-Authenticator = 0x7b5cdcf5142f71e757dc45a8f4203c9f
Fri Jul 26 18:07:15 2024 : Debug: (0) User-Name = "test@shs"
Fri Jul 26 18:07:15 2024 : Debug: (0) User-Password = "test"
Fri Jul 26 18:07:15 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Fri Jul 26 18:07:15 2024 : Debug: (0) NAS-Port = 23
Fri Jul 26 18:07:15 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request"
Fri Jul 26 18:07:15 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1"
Fri Jul 26 18:07:15 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := ""
Fri Jul 26 18:07:15 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := ""
Fri Jul 26 18:07:15 2024 : Debug: (0) Proxy-State = 0x313139
Fri Jul 26 18:07:15 2024 : Debug: try_connect()
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 3 - retry 1
...
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 2 - retry 358
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 2 - retry 359
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (13)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHello
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Certificate
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain
Fri Jul 26 18:07:15 2024 : Debug: (0) TLS-Cert-Serial := "42d93b4ae3681c41c88cd52984fc01c44a67ee37"
Fri Jul 26 18:07:15 2024 : Debug: (0) TLS-Cert-Expiration := "21210626141305Z"
Fri Jul 26 18:07:15 2024 : Debug: (0) TLS-Cert-Valid-Since := "210720141305Z"
...
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) verify return : 1
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 1 certificate in chain
Fri Jul 26 18:07:15 2024 : Debug: (0) TLS-Client-Cert-Serial := "ac1bf9b8e545622180b4190759026e29"
...
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) verify return : 1
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerKeyExchange
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (7)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, CertificateRequest
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (8)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHelloDone
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSD] - Client SSLv3/TLS read server done (9)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Certificate
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCC] - Client SSLv3/TLS write client certificate (14)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientKeyExchange
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (16)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, CertificateVerify
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (17)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 ChangeCipherSpec
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (18)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Finished
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (20)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 2 - retry 360
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 2 - retry 361
...
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Fri Jul 26 18:07:15 2024 : Debug: try_connect failed with 2 - retry 684
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (20)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (11)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Finished
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRFIN] - Client SSLv3/TLS read finished (12)
Fri Jul 26 18:07:15 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [SSLOK] - SSL negotiation finished successfully (1)
Fri Jul 26 18:07:15 2024 : Debug: Proxy is writing 122 bytes to SSL
Fri Jul 26 18:07:15 2024 : Debug: Waking up in 0.1 seconds.
Fri Jul 26 18:07:15 2024 : Debug: Proxy SSL socket has data to read
Fri Jul 26 18:07:15 2024 : Debug: Proxy received header saying we have a packet of 90 bytes
Fri Jul 26 18:07:15 2024 : Proxy: (0) Marking home server 172.16.9.156 port 2083 alive
Fri Jul 26 18:07:15 2024 : Debug: (0) Clearing existing &reply: attributes
Fri Jul 26 18:07:15 2024 : Debug: (0) Received Access-Reject Id 171 from 172.16.9.156:2083 to 10.113.0.10:59773 length 90
Fri Jul 26 18:07:15 2024 : Debug: (0) Message-Authenticator = 0x3505e2c1ea481e9b6d9eb11a8763c260
Fri Jul 26 18:07:15 2024 : Debug: (0) Reply-Message = "RADIUS_DOESNT_EXIST:Access code doesn't exist"
Fri Jul 26 18:07:15 2024 : Debug: (0) Proxy-State = 0x313139
Fri Jul 26 18:07:15 2024 : Debug: (0) server caradius {
Fri Jul 26 18:07:15 2024 : Debug: (0) # Executing section post-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Fri Jul 26 18:07:15 2024 : Debug: (0) post-proxy {
...
Fri Jul 26 18:07:15 2024 : Auth: (0) Login incorrect (Home Server says so): [test@shs] (from client caradius-world4 port 23)
Fri Jul 26 18:07:15 2024 : Debug: (0) Using Post-Auth-Type Reject
Fri Jul 26 18:07:15 2024 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring.
Fri Jul 26 18:07:15 2024 : Auth: (0) Login incorrect: [test@shs] (from client caradius-world4 port 23)
Fri Jul 26 18:07:15 2024 : Debug: (0) Sent Access-Reject Id 119 from 127.0.0.1:3812 to 127.0.0.1:33443 length 126
Fri Jul 26 18:07:15 2024 : Debug: (0) Message-Authenticator = 0x3505e2c1ea481e9b6d9eb11a8763c260
Fri Jul 26 18:07:15 2024 : Debug: (0) Reply-Message = "RADIUS_DOESNT_EXIST:Access code doesn't exist"
Fri Jul 26 18:07:15 2024 : Debug: (0) Finished request
Fri Jul 26 18:07:15 2024 : Debug: Waking up in 0.1 seconds.
Fri Jul 26 18:07:15 2024 : Debug: Waking up in 4.8 seconds.
So it needs to retry quite a lot in my hack, but then it works. Naturally it can't be done this kind of blocking way normally.
Without my retry loop in try_connect() I see that the function gets executed once after the initial SSL_connect returned WANT_READ/WANT_WRITE, when trying to send the packet, but never again until timeout - so it looks like a bug somewhere in the state machine, not retrying / continuing the TLS handshake when the socket becomes available to read/write something again.
(In my hacky loop both WANT_READ and WANT_WRITE happen on retries, and without the usleep() the retry count even goes up till 25000-30000)
Greetings, Sven
alandekok
commented
1 month ago @haegar have you tried the v3.2.x HEAD? We've pushed a number of patches which should help.
Unfortunately, we can't really busy-loop in a hot path in the server. So other approaches may be better for production.
haegar
commented
1 month ago Yes, my debugging today was done with c4fbd097429fee9d9ab6be0f8b3a60523199b46c, the mentioned "git describe --tags" release_3_2_5-38-gc4fbd09742.
It has similar problems to my earier tests, just slightly different log messages, the end result being identical, not establishing the home server connection because of TLS WANT_READ/WANT_WRITE.
And sure, I know freeradius can't busy loop - this is why I described my patch as "unusable in production".
I just tried this easy and dirty way to see if the comment from the SSL_connect manpage "SSL_connect() will yield SSL_ERROR_WANT_READ or SSL_ERROR_WANT_WRITE. The calling process then must repeat the call after taking appropriate action to satisfy the needs of SSL_connect()." makes any sense.
I was not able to really understand the freeradius event loop and how to retry the try_connect() and do the sending of the buffered data created in proxy_tls_send() - "When using a nonblocking socket, nothing is to be done, but select() can be used to check for the required condition."
proxy_tls_send() has some return codes, is assigned as "this->proxy_send = proxy_tls_send;", but non of the callers seem to even look at the function return value - so that does not seem to be a path for a retry when the socket becomes available for reading/writing.
moracca
commented
1 month ago I was encountering a similar "Error in SSLv3/TLS write client hello" error when I was running 3.2.4, but after building from the latest commits on v3.2.x I'm not seeing that anymore. At least, my TLS handshake appears to complete succesfully.
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server certificate
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Client TLSv1.3 read server certificate verify
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read finished
(0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write change cipher spec
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client certificate
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write certificate verify
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Handshake state - SSL negotiation finished successfully
(0) Proxying request <...>
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
Thread 1 waiting to be assigned a request
(0) (TLS) RADIUS/TLS - send TLS 1.3 Alert, warning close_notify
(TLS) Closing connection
Closing TLS socket to home server
Waking up in 0.1 seconds.
(0) Waiting for client retransmission in order to do a proxy retransmit
Waking up in 29.3 seconds.I'm still facing other issues I'm trying to work through, but wanted to at least add that in my case the latest code fixed the SSLv3 issue for me
alandekok
commented
1 month ago @haegar it's not clear to me why the system still blocks. Is this configured with nonblock = yes, or nonblock = no
on top of that, yes. nothing checks the return code of proxy_send(). If the socket is blocked, the client will retry, and then the server will retry the proxied packet.
If the socket fails, then the caller should check the return code of proxy_send(), and try to transmit the packet on another socket.
But the most important issue to fix first is to find out why it's blocking on the connection. Any other changes aren't necessary to fix that issue, and won't help with it.
From what I can find out, SSL_connect() returns WANT_WRITE, but it doesn't actually have any data to send. I'll see if I can track that down.
alandekok
commented
1 month ago @haegar please try this patch. It works around the issue that the underlying connect() called by SSL_connect() is perhaps returning EINPROGRESS. When the socket is writable,
haegar
commented
1 month ago First: My current test setting uses "nonblock = yes" in the home_server section.
And you patch definitely improves things, the SSL connection now gets established perfectly, just something afterwards seems missing.
Log output from /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -sf -l stdout -xxx 2>&1 | tee /tmp/1.out
(Yes, I know my test setup does not include the new blastradius config settings yet, but that does not matter here)
Mon Jul 29 20:22:59 2024 : Info: Ready to process requests
Mon Jul 29 20:23:04 2024 : Error: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Mon Jul 29 20:23:04 2024 : Error: BlastRADIUS check: Received packet with Message-Authenticator.
Mon Jul 29 20:23:04 2024 : Error: Setting "require_message_authenticator = true" for client caradius-world4
Mon Jul 29 20:23:04 2024 : Error: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Mon Jul 29 20:23:04 2024 : Error: It looks like the client has been updated to protect from the BlastRADIUS attack.
Mon Jul 29 20:23:04 2024 : Error: Please set "require_message_authenticator = true" for client caradius-world4
Mon Jul 29 20:23:04 2024 : Error: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Mon Jul 29 20:23:04 2024 : Debug: (0) Received Access-Request Id 72 from 127.0.0.1:55916 to 127.0.0.1:3812 length 78
Mon Jul 29 20:23:04 2024 : Debug: (0) Message-Authenticator = 0x6dac74a678dbb4f2636478620f573936
Mon Jul 29 20:23:04 2024 : Debug: (0) User-Name = "test@shs"
Mon Jul 29 20:23:04 2024 : Debug: (0) User-Password = "test"
Mon Jul 29 20:23:04 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Mon Jul 29 20:23:04 2024 : Debug: (0) NAS-Port = 23
Mon Jul 29 20:23:04 2024 : Debug: (0) session-state: No State attribute
Mon Jul 29 20:23:04 2024 : Debug: (0) # Executing section authorize from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Mon Jul 29 20:23:04 2024 : Debug: (0) authorize {
Mon Jul 29 20:23:04 2024 : Debug: (0) update control {
Mon Jul 29 20:23:04 2024 : Debug: (0) &Proxy-To-Realm = 'shs'
Mon Jul 29 20:23:04 2024 : Debug: (0) } # update control = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) update request {
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> Access-Request
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Type := Access-Request
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> 127.0.0.1
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) -->
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IPv6-Address :=
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp}
Mon Jul 29 20:23:04 2024 : Debug: (0) -->
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Event-Timestamp :=
Mon Jul 29 20:23:04 2024 : Debug: (0) } # update request = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap)
Mon Jul 29 20:23:04 2024 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap)
Mon Jul 29 20:23:04 2024 : Debug: (0) [pap] = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) } # authorize = noop
Mon Jul 29 20:23:04 2024 : Debug: Using home pool auth for realm shs
Mon Jul 29 20:23:04 2024 : Debug: (0) Starting proxy to home server 172.16.9.156 port 2083
Mon Jul 29 20:23:04 2024 : Debug: (0) server caradius {
Mon Jul 29 20:23:04 2024 : Debug: (0) # Executing section pre-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Mon Jul 29 20:23:04 2024 : Debug: (0) pre-proxy {
Mon Jul 29 20:23:04 2024 : Debug: (0) update proxy-request {
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> Access-Request
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Type := Access-Request
Mon Jul 29 20:23:04 2024 : Debug: (0) Overwriting value "Access-Request" with "Access-Request"
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> 127.0.0.1
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Mon Jul 29 20:23:04 2024 : Debug: (0) Overwriting value "127.0.0.1" with "127.0.0.1"
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) -->
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IPv6-Address :=
Mon Jul 29 20:23:04 2024 : Debug: (0) Overwriting value "" with ""
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp}
Mon Jul 29 20:23:04 2024 : Debug: (0) -->
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Event-Timestamp :=
Mon Jul 29 20:23:04 2024 : Debug: (0) Overwriting value "" with ""
Mon Jul 29 20:23:04 2024 : Debug: (0) } # update proxy-request = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) } # pre-proxy = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) }
Mon Jul 29 20:23:04 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Mon Jul 29 20:23:04 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Mon Jul 29 20:23:04 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.156, 2083)
Mon Jul 29 20:23:04 2024 : Debug: Requiring Server certificate
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE
Mon Jul 29 20:23:04 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 34655) -> home_server (172.16.9.156, 2083)'
Mon Jul 29 20:23:04 2024 : Debug: Listening on proxy (10.113.0.10, 34655) -> home_server (172.16.9.156, 2083)
Mon Jul 29 20:23:04 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Mon Jul 29 20:23:04 2024 : Debug: (0) proxy: request is now in proxy hash
Mon Jul 29 20:23:04 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 95
Mon Jul 29 20:23:04 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000
Mon Jul 29 20:23:04 2024 : Debug: (0) Sent Access-Request Id 95 from 10.113.0.10:34655 to 172.16.9.156:2083 length 121
Mon Jul 29 20:23:04 2024 : Debug: (0) Message-Authenticator = 0x6dac74a678dbb4f2636478620f573936
Mon Jul 29 20:23:04 2024 : Debug: (0) User-Name = "test@shs"
Mon Jul 29 20:23:04 2024 : Debug: (0) User-Password = "test"
Mon Jul 29 20:23:04 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Mon Jul 29 20:23:04 2024 : Debug: (0) NAS-Port = 23
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request"
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1"
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := ""
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := ""
Mon Jul 29 20:23:04 2024 : Debug: (0) Proxy-State = 0x3732
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) has 0 bytes in the buffer
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) Saving 121 bytes of RADIUS traffic for later (total 121)
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (13)
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
... about 7200 lines repeating the WANT_READ and "Waking up in 0.3 seconds" - all from the same second.
Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds. Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (13) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHello Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Certificate Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Cert-Serial := "42d93b4ae3681c41c88cd52984fc01c44a67ee37" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Cert-Expiration := "21210626141305Z" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Cert-Valid-Since := "210720141305Z" Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) chain-depth : 1 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) error : 0 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) verify return : 1 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 1 certificate in chain Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-Serial := "ac1bf9b8e545622180b4190759026e29" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-Expiration := "21210626152950Z" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-Valid-Since := "210720152950Z" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-X509v3-Subject-Key-Identifier += "B6:E9:54:63:9E:53:A8:3D:3B:40:1E:E9:65:7B:38:8A:F6:B7:4D:FB" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Server Authentication" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-X509v3-Key-Usage += "Digital Signature, Key Encipherment" Mon Jul 29 20:23:04 2024 : Debug: (0) TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1" Mon Jul 29 20:23:04 2024 : Warning: Certificate chain - 1 intermediate CA cert(s) untrusted Mon Jul 29 20:23:04 2024 : Warning: To forbid these certificates see 'reject_unknown_intermediate_ca' Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) chain-depth : 0 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) error : 0 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) verify return : 1 Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerKeyExchange Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (7) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, CertificateRequest Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (8) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHelloDone Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSD] - Client SSLv3/TLS read server done (9) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Certificate Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCC] - Client SSLv3/TLS write client certificate (14) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientKeyExchange Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (16) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, CertificateVerify Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (17) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 ChangeCipherSpec Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (18) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Finished Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (20) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Proxy SSL socket has data to read Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds.
...5000 more lines of WANT_READ+Waking up in 0.3 seconds logged, again all still in the same second
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds. Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.3 seconds. Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished Mon Jul 29 20:23:04 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.2 seconds. Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (20) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (11) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Finished Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRFIN] - Client SSLv3/TLS read finished (12) Mon Jul 29 20:23:04 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [SSLOK] - SSL negotiation finished successfully (1) Mon Jul 29 20:23:04 2024 : Debug: Proxy SSL socket has data to read Mon Jul 29 20:23:04 2024 : Debug: (TLS) proxy writing 121 to socket Mon Jul 29 20:23:04 2024 : Debug: (TLS) OpenSSL returned WANT_READ Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.2 seconds. Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.2 seconds.
Now the "Waking up in 0.2 seconds" line repeated around 900 times
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.2 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.2 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Proxy SSL socket has data to read
Mon Jul 29 20:23:04 2024 : Debug: Proxy received header saying we have a packet of 89 bytes
Mon Jul 29 20:23:04 2024 : Proxy: (0) Marking home server 172.16.9.156 port 2083 alive
Mon Jul 29 20:23:04 2024 : Debug: (0) Clearing existing &reply: attributes
Mon Jul 29 20:23:04 2024 : Debug: (0) Received Access-Reject Id 95 from 172.16.9.156:2083 to 10.113.0.10:34655 length 89
Mon Jul 29 20:23:04 2024 : Debug: (0) Message-Authenticator = 0x3b323026252af29528a7aef1400259cb
Mon Jul 29 20:23:04 2024 : Debug: (0) Reply-Message = "RADIUS_DOESNT_EXIST:Access code doesn't exist"
Mon Jul 29 20:23:04 2024 : Debug: (0) Proxy-State = 0x3732
Mon Jul 29 20:23:04 2024 : Debug: (0) server caradius {
Mon Jul 29 20:23:04 2024 : Debug: (0) # Executing section post-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Mon Jul 29 20:23:04 2024 : Debug: (0) post-proxy {
Mon Jul 29 20:23:04 2024 : Debug: (0) update proxy-reply {
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{proxy-reply:Packet-Type}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> Access-Reject
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Type := Access-Reject
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{proxy-reply:Packet-Src-IP-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) --> 172.16.9.156
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IP-Address := 172.16.9.156
Mon Jul 29 20:23:04 2024 : Debug: (0) EXPAND %{proxy-reply:Packet-Src-IPv6-Address}
Mon Jul 29 20:23:04 2024 : Debug: (0) -->
Mon Jul 29 20:23:04 2024 : Debug: (0) &SCES-Tmp-Packet-Src-IPv6-Address :=
Mon Jul 29 20:23:04 2024 : Debug: (0) } # update proxy-reply = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) } # post-proxy = noop
Mon Jul 29 20:23:04 2024 : Debug: (0) }
Mon Jul 29 20:23:04 2024 : Auth: (0) Login incorrect (Home Server says so): [test@shs] (from client caradius-world4 port 23)
Mon Jul 29 20:23:04 2024 : Debug: (0) Using Post-Auth-Type Reject
Mon Jul 29 20:23:04 2024 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring.
Mon Jul 29 20:23:04 2024 : Auth: (0) Login incorrect: [test@shs] (from client caradius-world4 port 23)
Mon Jul 29 20:23:04 2024 : Debug: (0) Sent Access-Reject Id 72 from 127.0.0.1:3812 to 127.0.0.1:55916 length 126
Mon Jul 29 20:23:04 2024 : Debug: (0) Sent Access-Reject Id 72 from 127.0.0.1:3812 to 127.0.0.1:55916 length 126
Mon Jul 29 20:23:04 2024 : Debug: (0) Message-Authenticator = 0x3b323026252af29528a7aef1400259cb
Mon Jul 29 20:23:04 2024 : Debug: (0) Reply-Message = "RADIUS_DOESNT_EXIST:Access code doesn't exist"
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Reject"
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "172.16.9.156"
Mon Jul 29 20:23:04 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := ""
Mon Jul 29 20:23:04 2024 : Debug: (0) Finished request
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.4 seconds.
At this point the radtest client has received the response.
But the server keeps looping the "Waking up in 0.4 seconds" line, counting down to 0.3 seconds, 0.2, 0.1 seconds - around 38000 times.
Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.1 seconds. Mon Jul 29 20:23:04 2024 : Debug: Waking up in 0.1 seconds. Mon Jul 29 20:23:04 2024 : Debug: Waking up in 4.5 seconds. Mon Jul 29 20:23:04 2024 : Debug: Waking up in 4.5 seconds.
And then about 40000 (!) more, until the 4.5 seconds have expired
Mon Jul 29 20:23:09 2024 : Debug: Waking up in 0.1 seconds. Mon Jul 29 20:23:09 2024 : Debug: Waking up in 0.1 seconds. Mon Jul 29 20:23:09 2024 : Debug: (0) Cleaning up request packet ID 72 with timestamp +5 due to cleanup_delay was reached Mon Jul 29 20:23:09 2024 : Debug: Waking up in 174.9 seconds. Mon Jul 29 20:23:09 2024 : Debug: Waking up in 174.9 seconds. Mon Jul 29 20:23:09 2024 : Debug: Waking up in 174.9 seconds.
And basically repeating the waking up lines as fast as it can loop until I Ctrl-C the freeradius.
alandekok
commented
1 month ago @haegar Ok, that's good news. I think I can fix the Waking up error without too much work. I'll push a fix.
alandekok
commented
1 month ago I've pushed that patch to v3.2.x, along with another patch to src/lib/event.c which prevents the infinite loop
haegar
commented
1 month ago Thanks Alan! We are getting there, but not on the finish line yet!
Some different things:
Excessive loop calling tls_write_available(), until the SSL_connect() is successful - as the socket is writeable even when SSL_connect returns WANT_READ, the tls_write_available(), gets called again and again, even when we don't have anything to write currently, we are just waiting to read more from the remote side for the ssl connect to be able to continue.
I as able to work around this using the following patch:
aka calling proxy_listener_thaw(listener) when the SSL_connect returned WANT_READ, instead of WANT_WRITE.. So basically freezing the listened when we need to wait for writing, thawing when we wait to read.
2. Additionally in my patch I surrounded the try_connect() all by taking the socket mutex - not sure if that is really needed. But in the other two places that call try_connect() the proxy_tls_send() function wraps the try_connect() call in mutex lock/unlock, and the proxy_tls_read() function has the explicit comment that it is already called with the mutex held.
3. And at the end the main thing: It works perfectly fine in single thread (-s) execution, but totally does not in normal threaded mode!
(With or withour my experiment2.diff, with plain current 3.2 git HEAD)
Multi threaded logs from /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -f -l stdout -xxx 2>&1 | tee /tmp/1.out
Mon Jul 29 23:57:53 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Mon Jul 29 23:57:53 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Mon Jul 29 23:57:53 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.156, 2083)
Mon Jul 29 23:57:53 2024 : Debug: Requiring Server certificate
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE
Mon Jul 29 23:57:53 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 49399) -> home_server (172.16.9.156, 2083)'
Mon Jul 29 23:57:53 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Mon Jul 29 23:57:53 2024 : Debug: (0) proxy: request is now in proxy hash
Mon Jul 29 23:57:53 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 88
Mon Jul 29 23:57:53 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000
Mon Jul 29 23:57:53 2024 : Debug: (0) Sent Access-Request Id 88 from 10.113.0.10:49399 to 172.16.9.156:2083 length 121
Mon Jul 29 23:57:53 2024 : Debug: (0) Message-Authenticator = 0xf1f91e2ce3146afc4f7f69d4189852dd
Mon Jul 29 23:57:53 2024 : Debug: (0) User-Name = "test@shs"
Mon Jul 29 23:57:53 2024 : Debug: (0) User-Password = "test"
Mon Jul 29 23:57:53 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Mon Jul 29 23:57:53 2024 : Debug: (0) NAS-Port = 23
Mon Jul 29 23:57:53 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request"
Mon Jul 29 23:57:53 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1"
Mon Jul 29 23:57:53 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := ""
Mon Jul 29 23:57:53 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := ""
Mon Jul 29 23:57:53 2024 : Debug: (0) Proxy-State = 0x3731
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
Mon Jul 29 23:57:53 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) has 0 bytes in the buffer
Mon Jul 29 23:57:53 2024 : Debug: (0) (TLS) Saving 121 bytes of RADIUS traffic for later (total 121)
Mon Jul 29 23:57:53 2024 : Debug: Thread 4 waiting to be assigned a request
Mon Jul 29 23:57:53 2024 : Debug: Listening on proxy (10.113.0.10, 49399) -> home_server (172.16.9.156, 2083)
Mon Jul 29 23:57:53 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 23:57:53 2024 : Debug: (0) Expecting proxy response no later than 9.666602 seconds from now
Mon Jul 29 23:57:53 2024 : Debug: Waking up in 9.5 seconds.
Mon Jul 29 23:57:58 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 172.16.9.156 port 2083 proto TCP - ID: 88
Mon Jul 29 23:57:58 2024 : Debug: Waking up in 4.9 seconds.
Mon Jul 29 23:58:03 2024 : Debug: (0) No proxy response, giving up on request and marking it done
Mon Jul 29 23:58:03 2024 : ERROR: (0) Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.156 port 2083
Mon Jul 29 23:58:03 2024 : Debug: Waking up in 0.3 seconds.
Mon Jul 29 23:58:03 2024 : Debug: Thread 5 got semaphore
Mon Jul 29 23:58:03 2024 : Debug: Thread 5 handling request 0, (1 handled so far)
Mon Jul 29 23:58:03 2024 : Debug: (0) Clearing existing &reply: attributes
Mon Jul 29 23:58:03 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Mon Jul 29 23:58:03 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Mon Jul 29 23:58:03 2024 : Debug: (0) server caradius {
Mon Jul 29 23:58:03 2024 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring.
Mon Jul 29 23:58:03 2024 : Debug: (0) # Executing group from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Mon Jul 29 23:58:03 2024 : Debug: (0) }
Mon Jul 29 23:58:03 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [test@shs] (from client caradius-world4 port 23)
Mon Jul 29 23:58:03 2024 : Debug: (0) There was no response configured: rejecting request
Mon Jul 29 23:58:03 2024 : Debug: (0) Using Post-Auth-Type Reject
Mon Jul 29 23:58:03 2024 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring.
Mon Jul 29 23:58:03 2024 : Auth: (0) Login incorrect (Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.156 port 2083): [test@shs] (from client caradius-world4 port 23)
Mon Jul 29 23:58:03 2024 : Debug: (0) Sent Access-Reject Id 71 from 127.0.0.1:3812 to 127.0.0.1:33088 length 38
Mon Jul 29 23:58:03 2024 : Debug: (0) Finished request
Mon Jul 29 23:58:03 2024 : Debug: Thread 5 waiting to be assigned a request
Mon Jul 29 23:58:03 2024 : Debug: Waking up in 4.6 seconds.
Mon Jul 29 23:58:08 2024 : Debug: (0) Cleaning up request packet ID 71 with timestamp +3 due to cleanup_delay was reached
Mon Jul 29 23:58:08 2024 : Debug: Waking up in 164.9 seconds.
Multi-threaded it seems like the proxy_listener_freeze() does not do what it does in single-thread mode.
And even the client retransmit of the query does not trigger another try_connect(), as the retransmit gets filtered out before by "Debug: Suppressing duplicate proxied request (tcp) to home server 172.16.9.156 port 2083 proto TCP - ID: 88", and thus never triggering another send call.
alandekok
commented
1 month ago @haegar I've pushed a fix for OpenSSL WANT_READ as you suggested.
I've also attached a patch which may help with the proxy retransmission
haegar
commented
1 month ago @alandekok Forgot to push? Last commit in 3.2 branch I see is 7ad89db393 "Tidy up" from Nick Porter, nothing from you today.
moracca
commented
1 month ago I've been tracking this issue and have rebuilt on the latest commits 9c646ef5711669922c8e528d51464058a5d23d5c
I'm not sure if my issue matches exactly, but its similar enough that I figured I'd add some additional data.
If i don't allow TLS 1.3 my log looks like this:
(TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (52.202.34.209, 2083)
Requiring Server certificate
(0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Client before SSL initialization
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
tls: (TLS) System call (I/O) error (-1)
(TLS) Failed opening connection on proxy socket 'proxy (0.0.0.0, 0) -> home_server (52.202.34.209, 2083)'
(0) Failed to insert request into the proxy listWhen I enable TLS 1.3, it seems to get through the handshake ok, but once I send the actual auth request, the connection closes and I never get a response
(TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (44.215.254.228, 2083)
Requiring Server certificate
(0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Client before SSL initialization
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server hello
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, EncryptedExtensions
(0) (TLS) RADIUS/TLS - Handshake state - Client TLSv1.3 read encrypted extensions
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateRequest
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server certificate request
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain
(0) TLS-Cert-Serial := "1000"
(0) TLS-Cert-Expiration := "301121142902Z"
(0) TLS-Cert-Valid-Since := "221214142902Z"
(0) TLS-Cert-Subject := "/C=US/ST=California/L=San Mateo/O=WBA/OU=WBA Issuing ICA/CN=openroaming.org/dnQualifier=WBA WRIX ECC Intermediate CA-4"
(0) TLS-Cert-Issuer := "/C=SG/ST=Singapore/L=Singapore/O=Wireless Broadband Alliance/OU=WBA/CN=openroaming.org/emailAddress=enb-devops@cisco.com/dnQualifier=WBA WRIX ECC Policy Intermediate CA-01"
(0) TLS-Cert-Common-Name := "openroaming.org"
(0) (TLS) RADIUS/TLS - Creating attributes from 1 certificate in chain
(0) TLS-Client-Cert-Serial := "5a0a9b61cba2c3459f6e3f41a2893805"
(0) TLS-Client-Cert-Expiration := "270314184021Z"
(0) TLS-Client-Cert-Valid-Since := "240314174021Z"
(0) TLS-Client-Cert-Subject := "/C=US/O=Single Digits, Inc./OU=WBA:WRIX End-Entity/CN=3af521.net/UID=3af521.SINGLEDIGITS:US"
(0) TLS-Client-Cert-Issuer := "/C=US/ST=California/L=San Mateo/O=WBA/OU=WBA Issuing ICA/CN=openroaming.org/dnQualifier=WBA WRIX ECC Intermediate CA-4"
(0) TLS-Client-Cert-Common-Name := "3af521.net"
(0) TLS-Client-Cert-Subject-Alt-Name-Dns := "3af521.net"
(0) TLS-Client-Cert-Subject-Alt-Name-Dns := "*.3af521.net"
(0) TLS-Client-Cert-Subject-Alt-Name-Dns := "3af521.com"
(0) TLS-Client-Cert-Subject-Alt-Name-Dns := "*.3af521.com"
(0) TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0) TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:C7:81:F5:34:EA:E7:9D:0D:C1:EF:3E:D5:5C:4E:DF:F8:B0:D1:1E:32\n"
(0) TLS-Client-Cert-X509v3-Subject-Key-Identifier += "55:18:55:6A:81:9D:C6:53:02:F1:38:EA:62:AC:5E:8C:D1:E8:6E:6F"
(0) TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Server Authentication"
(0) TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.14122.1.1.6\n"
(0) TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Certificate chain - 1 intermediate CA cert(s) untrusted
To forbid these certificates see 'reject_unknown_intermediate_ca'
(TLS) untrusted certificate with depth [3] subject name /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN=openroaming.org/emailAddress=enb-devops@cisco.com
(TLS) untrusted certificate with depth [2] subject name /C=SG/ST=Singapore/L=Singapore/O=Wireless Broadband Alliance/OU=WBA/CN=openroaming.org/emailAddress=enb-devops@cisco.com/dnQualifier=WBA WRIX ECC Policy Intermediate CA-01
(TLS) untrusted certificate with depth [1] subject name /C=US/ST=California/L=San Mateo/O=WBA/OU=WBA Issuing ICA/CN=openroaming.org/dnQualifier=WBA WRIX ECC Intermediate CA-4
(TLS) untrusted certificate with depth [0] subject name /C=US/O=Single Digits, Inc./OU=WBA:WRIX End-Entity/CN=3af521.net/UID=3af521.SINGLEDIGITS:US
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server certificate
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Client TLSv1.3 read server certificate verify
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read finished
(0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write change cipher spec
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client certificate
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write certificate verify
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Handshake state - SSL negotiation finished successfully
(0) Proxying request to home server 44.215.254.228 port 2083 (TLS) timeout 30.000000
(0) Sent Access-Request Id 105 from 172.30.88.133:45037 to 44.215.254.228:2083 length 433
<request attributes>
Listening on proxy (172.30.88.133, 45037) -> home_server (44.215.254.228, 2083)
Waking up in 0.4 seconds.
(0) Proxy-State = 0x3935
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
Thread 1 waiting to be assigned a request
(0) (TLS) RADIUS/TLS - send TLS 1.3 Alert, warning close_notify
(TLS) Closing connection
(TLS) Closing connection to home server
Waking up in 0.7 seconds.
(0) Waiting for client retransmission in order to do a proxy retransmit
Waking up in 28.7 seconds.this system is running freebsd 13.2 with OpenSSL 1.1.1t-freebsd but I have tried on a system running freebsd 14.2 w/ OpenSSL 3.0.13 and had similar results.
alandekok
commented
1 month ago @moracca We'll have to spin up a FreeBSD box and see what happens.
For the case of TLS 1.2, the "I/O error" is coming from OpenSSL. It's trying to do a system call, and the system call is failing. We would need to know what system call it's doing, and why it's failing.
For the case of TLS 1.3, the issue is that OpenSSL is sending a "close_notify" by itself. i.e. we don't ask it to send any data, but OpenSSL decides to send data.
This looks like some odd behavior in FreeBSD with respect to interaction between sockets and OpenSSL, and how we set it all up. It works for us on OSX and Linux variants, which makes it harder to debug.
Have you configured the listeners with nonblock = yes? Or is it no ? That would help us narrow down which code path is being used.
moracca
commented
1 month ago originally I didn't have nonblock specified, so I believe it defaults to nonblock = no.
When I set nonblock = yes on the home server, I get this result:
(TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (52.202.34.209, 2083)
Requiring Server certificate
(0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
(0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
(TLS) Ignoring cbtls_msg call with pseudo content type 256, version 00000000
(TLS) Received 177 bytes of TLS data
(TLS) 01 00 00 ad 03 03 34 59 14 bc 06 3c 38 b6 fe cc
(TLS) 96 bc 1b 6a 30 92 fd 85 c9 ac c7 53 03 1a ad 4a
(TLS) 3e 29 ab 5e 9f 51 00 00 38 c0 2c c0 30 00 9f cc
(TLS) a9 cc a8 cc aa c0 2b c0 2f 00 9e c0 24 c0 28 00
(TLS) 6b c0 23 c0 27 00 67 c0 0a c0 14 00 39 c0 09 c0
(TLS) 13 00 33 00 9d 00 9c 00 3d 00 3c 00 35 00 2f 00
(TLS) ff 01 00 00 4c 00 0b 00 04 03 00 01 02 00 0a 00
(TLS) 04 00 02 00 17 00 16 00 00 00 17 00 00 00 0d 00
(TLS) 30 00 2e 04 03 05 03 06 03 08 07 08 08 08 09 08
(TLS) 0a 08 0b 08 04 08 05 08 06 04 01 05 01 06 01 03
(TLS) 03 02 03 03 01 02 01 03 02 02 02 04 02 05 02 06
(TLS) 02
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE
Opened new proxy socket 'proxy (172.30.88.133, 58449) -> home_server (52.202.34.209, 2083)'
Listening on proxy (172.30.88.133, 58449) -> home_server (52.202.34.209, 2083)
(0) proxy: Trying to allocate ID (1/2)
(0) proxy: request is now in proxy hash
(0) proxy: allocating destination 52.202.34.209 port 2083 - Id 185
(0) Proxying request to home server 52.202.34.209 port 2083 (TLS) timeout 30.000000
(0) Sent Access-Request Id 185 from 172.30.88.133:58449 to 52.202.34.209:2083 length 433
(0) <requests attributes>
(0) Proxy-State = 0x3537
(0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello
(TLS) SSL_connect() returned WANT_WRITE
(0) (TLS) has 0 bytes in the buffer
(0) (TLS) Saving 433 bytes of RADIUS traffic for later (total 433)
(0) Expecting proxy response no later than 29.999829 seconds from now
Waking up in 29.9 seconds.
(0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
(TLS) SSL_connect() returned WANT_READ
Waking up in 29.9 seconds.
(TLS) Proxy socket has data to read
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
tls: (TLS) System call (I/O) error (-1)
(TLS) Closing connection
(TLS) Closing connection to home server
Waking up in 0.9 seconds.
(0) Waiting for client retransmission in order to do a proxy retransmit
Waking up in 28.6 seconds.Any hints on how I could track down what system call is failing? I tried to truss the radiusd process, I'm not sure if it gives you any additional information. The process seems to crash at the end.
moracca
commented
1 month ago additional info:
When I change my home server definintion to proxy to a server I control, I am able to see this in that server's logs:
Listening on auth+acct from client (172.30.88.133, 43146) -> (*, 2083, virtual-server=default)
Waking up in 0.4 seconds.
(0) (TLS) RADIUS/TLS -Initiating new session
(0) (TLS) Reading from socket 5
(0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
(0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Server before SSL initialization (0)
(TLS) Ignoring cbtls_msg call with pseudo content type 256, version 00000301
(0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Server before SSL initialization (0)
(TLS) Received 177 bytes of TLS data
(TLS) 01 00 00 ad 03 03 51 2a 8a b5 2c 3e 8d 52 4f 44
(TLS) 10 4a 27 e8 8a 48 81 30 c0 81 57 7b 51 10 ad 3f
(TLS) 9d a2 5a 46 ce e2 00 00 38 c0 2c c0 30 00 9f cc
(TLS) a9 cc a8 cc aa c0 2b c0 2f 00 9e c0 24 c0 28 00
(TLS) 6b c0 23 c0 27 00 67 c0 0a c0 14 00 39 c0 09 c0
(TLS) 13 00 33 00 9d 00 9c 00 3d 00 3c 00 35 00 2f 00
(TLS) ff 01 00 00 4c 00 0b 00 04 03 00 01 02 00 0a 00
(TLS) 04 00 02 00 17 00 16 00 00 00 17 00 00 00 0d 00
(TLS) 30 00 2e 04 03 05 03 06 03 08 07 08 08 08 09 08
(TLS) 0a 08 0b 08 04 08 05 08 06 04 01 05 01 06 01 03
(TLS) 03 02 03 03 01 02 01 03 02 02 02 04 02 05 02 06
(TLS) 02
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello
(TLS) Ignoring cbtls_msg call with pseudo content type 256, version 00000303
(TLS) Received 2 bytes of TLS data
(TLS) 02 28
(0) (TLS) RADIUS/TLS - send TLS 1.2 Alert, fatal handshake_failure
ERROR: (0) (TLS) RADIUS/TLS - Alert write:fatal:handshake failure
ERROR: (0) (TLS) RADIUS/TLS - Server : Error in error
ERROR: (0) (TLS) Failed reading from OpenSSL: /usr/src/crypto/openssl/ssl/statem/statem_srvr.c[2221]:error:0A0000C1:SSL routines::no shared cipher
ERROR: (0) (TLS) System call (I/O) error (-1)
(0) (TLS) Failed in TLS handshake receive
(TLS) Closing socket from client port 43146
(TLS) Closing connection
... shutting down socket auth+acct from client (172.30.88.133, 43146) -> (*, 2083, virtual-server=default)
... cleaning up socket auth+acct from client (172.30.88.133, 43146) -> (*, 2083, virtual-server=default)
Ready to process requests@moracca
SSL routines::no shared cipher
This is a TLS layer issue. The client and server are misconfigured. They don't have any common ciphers which they can use.
This problem is almost always caused by (a) forcing one side to use an old / insecure TLS version which is not supported by the other side, or (b) forcing one or both systems to have custom cipher_list settings.
Either way, the systems are not configured to be compatible on the TLS layer. Use the default configuration, it will work.
i.e. when the systems are configured to not talk TLS, it becomes impossible to debug TLS layer issues.
moracca
commented
1 month ago I think I had the secret misconfigured. once I had that fixed, I also set cipher_list = "DEFAULT" in the home server config, (not sure if that was needed since I didn't have it set elsewhere on either the proxy or the radsec server).
I edited only the ipaddr value in my existing home_server config for the domain to point to a local freeradius server that has radsec enabled. The same cert is on both sides. It looks very similar to the failing case when I point to the idp's radsec server, except that my local server actually responds to the request with an Access-Accept, whereas the idp's server just never responds. This is with nonblock = yes btw
Below is a log of a complete working connection to this local server. And below that, the non-working log when I proxy to the IDP server. There must be some misconfiguration or mismatch between my server and theirs, but I'm not quite sure what without access to the logs of their server. But, I think this at least proves that radsec can function, at least in the right conditions.
WORKING working radsec.log
NOT WORKING not working radsec.log
alandekok
commented
1 month ago @moracca The "no shared ciphers" error is pretty definitive that it's a TLS negotiation / configuration issue. and not anything to do with FreeRADIUS socket handling.
alandekok
commented
1 month ago @moracca We've tested it with FreeBSD and it works fine. The issue you see seems to be the TLS misconfiguration.
moracca
commented
1 month ago thank you -- yes I have it working between my two hosts, and have a troubleshooting session scheduled to see if we can determine in the logs of the non-responding radius server what is not aligning.
haegar
commented
1 month ago Sorry, was not able to test your patch yesterday.
First testing git 3.2 branch 9c646ef5711669922c8e528d51464058a5d23d5c, without the additional patch.
In single thread mode called as /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -sf -l stdout -xxx it works perfectly! TLS Connection establishes quickly, no cpu-looping spike, direct radius answer received - the whole request takes way less than a second.
But multithreaded mode does not work: /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -f -l stdout -xxx
... Thu Aug 1 16:48:45 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Thu Aug 1 16:48:45 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Thu Aug 1 16:48:45 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Thu Aug 1 16:48:45 2024 : Debug: (0) (TLS) Saving 121 bytes of RADIUS traffic for later (total 121) Thu Aug 1 16:48:45 2024 : Debug: Thread 5 waiting to be assigned a request Thu Aug 1 16:48:45 2024 : Debug: Listening on proxy (10.113.0.10, 50023) -> home_server (172.16.9.156, 2083) Thu Aug 1 16:48:45 2024 : Debug: Waking up in 0.3 seconds. Thu Aug 1 16:48:45 2024 : Debug: (0) Expecting proxy response no later than 9.666611 seconds from now Thu Aug 1 16:48:45 2024 : Debug: Waking up in 0.2 seconds.
In single-thread mode the function tls_write_available() gets called at this point, but in multi-thread mode it does not happen.
Could it be that the event select() running in another thread does not get triggered/restarted after using proxy_listener_freeze(), thus the main loop still waiting for something to read from the tls tcp proxy connection, not expecting that it now should "report" when the socket becomes writeable?
Now second step, trying with your proxy-resend patch from comment https://github.com/FreeRADIUS/freeradius-server/issues/5310#issuecomment-2258150029 on top:
Single thread performance got worse - now the client has to always at least timeout and retransmit once, which otherwise in single thread mode was not needed:
... Thu Aug 1 16:58:29 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Thu Aug 1 16:58:29 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Thu Aug 1 16:58:29 2024 : Debug: (0) (TLS) Saving 122 bytes of RADIUS traffic for later (total 122) Thu Aug 1 16:58:29 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (13) Thu Aug 1 16:58:29 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Thu Aug 1 16:58:29 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Thu Aug 1 16:58:29 2024 : Debug: (TLS) Proxy socket has data to read ... Thu Aug 1 16:58:30 2024 : Debug: (TLS) proxy writing 122 to socket ... writing the outstanding buffered request ... Thu Aug 1 16:58:30 2024 : Debug: (TLS) OpenSSL returned WANT_READ Thu Aug 1 16:58:30 2024 : Debug: (TLS) Proxy socket read no data from the network Thu Aug 1 16:58:30 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 16:58:30 2024 : Debug: (TLS) Proxy socket has data to read Thu Aug 1 16:58:30 2024 : Debug: Proxy received header saying we have a packet of 90 bytes Thu Aug 1 16:58:30 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 172.16.9.156 port 2083 - ID 28 ... answer received from remote server - but dropped, as the request (which was still buffered and in the try_connect() second execution sent) has been removed from the hash by the patch ... Thu Aug 1 16:58:30 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 16:58:30 2024 : Debug: (0) Waiting for client retransmission in order to do a proxy retransmit Thu Aug 1 16:58:30 2024 : Debug: Waking up in 29.6 seconds. ... now client does retransmit ... Thu Aug 1 16:58:34 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Thu Aug 1 16:58:34 2024 : Debug: (0) proxy: request is now in proxy hash Thu Aug 1 16:58:34 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 114 Thu Aug 1 16:58:34 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000 Thu Aug 1 16:58:34 2024 : Debug: (0) Sent Access-Request Id 114 from 10.113.0.10:42891 to 172.16.9.156:2083 length 122 ... Thu Aug 1 16:58:34 2024 : Debug: Proxy is writing 122 bytes to SSL Thu Aug 1 16:58:34 2024 : Debug: Waking up in 24.9 seconds. Thu Aug 1 16:58:34 2024 : Debug: (TLS) Proxy socket has data to read Thu Aug 1 16:58:34 2024 : Debug: Proxy received header saying we have a packet of 90 bytes Thu Aug 1 16:58:34 2024 : Proxy: (0) Marking home server 172.16.9.156 port 2083 alive Thu Aug 1 16:58:34 2024 : Debug: (0) Clearing existing &reply: attributes ...
and retried packet sent, answer received, and relayed back to the client. So instead of <<1s before,it now takes >>5s (with 5s retry timeout) when the tls connection has not been established before yet. (which in our main tls-proxy-usecase is basically all the time, as this radius2radsec forwarding is used for maintenance logins to on-site equipment)
And last testing with the patch, but in multi-thread mode:
Thu Aug 1 17:12:37 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Thu Aug 1 17:12:37 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Thu Aug 1 17:12:37 2024 : Debug: (0) (TLS) Saving 122 bytes of RADIUS traffic for later (total 122) Thu Aug 1 17:12:37 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 17:12:37 2024 : Debug: Thread 5 waiting to be assigned a request Thu Aug 1 17:12:37 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (13) Thu Aug 1 17:12:37 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Thu Aug 1 17:12:37 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Thu Aug 1 17:12:37 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 17:12:37 2024 : Debug: (TLS) Proxy socket has data to read ... Thu Aug 1 17:12:37 2024 : Debug: (TLS) proxy writing 122 to socket Thu Aug 1 17:12:37 2024 : Debug: (TLS) OpenSSL returned WANT_READ Thu Aug 1 17:12:37 2024 : Debug: (TLS) Proxy socket read no data from the network Thu Aug 1 17:12:37 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 17:12:37 2024 : Debug: (TLS) Proxy socket has data to read Thu Aug 1 17:12:37 2024 : Debug: Proxy received header saying we have a packet of 90 bytes Thu Aug 1 17:12:37 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 172.16.9.156 port 2083 - ID 133 Thu Aug 1 17:12:37 2024 : Debug: Waking up in 0.1 seconds. Thu Aug 1 17:12:38 2024 : Debug: (0) Waiting for client retransmission in order to do a proxy retransmit ... Thu Aug 1 17:12:38 2024 : Debug: (0) Waiting for client retransmission in order to do a proxy retransmit Thu Aug 1 17:12:38 2024 : Debug: Waking up in 29.6 seconds. Thu Aug 1 17:12:42 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Thu Aug 1 17:12:42 2024 : Debug: (0) proxy: request is now in proxy hash Thu Aug 1 17:12:42 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 147 Thu Aug 1 17:12:42 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000 Thu Aug 1 17:12:42 2024 : Debug: (0) Sent Access-Request Id 147 from 10.113.0.10:33853 to 172.16.9.156:2083 length 122 Thu Aug 1 17:12:42 2024 : Debug: (0) Message-Authenticator = 0xe8db31dc0dd80408c4f7dff7859ae22c ... Thu Aug 1 17:12:42 2024 : Debug: Proxy is writing 122 bytes to SSL Thu Aug 1 17:12:42 2024 : Debug: Waking up in 24.9 seconds. Thu Aug 1 17:12:42 2024 : Debug: (TLS) Proxy socket has data to read Thu Aug 1 17:12:42 2024 : Debug: Proxy received header saying we have a packet of 90 bytes Thu Aug 1 17:12:42 2024 : Proxy: (0) Marking home server 172.16.9.156 port 2083 alive Thu Aug 1 17:12:42 2024 : Debug: Waking up in 0.3 seconds. Thu Aug 1 17:12:42 2024 : Debug: Thread 2 got semaphore Thu Aug 1 17:12:42 2024 : Debug: Thread 2 handling request 0, (1 handled so far) Thu Aug 1 17:12:42 2024 : Debug: (0) Clearing existing &reply: attributes Thu Aug 1 17:12:42 2024 : Debug: (0) Received Access-Reject Id 147 from 172.16.9.156:2083 to 10.113.0.10:33853 length 90 ...
So now in the multi-threaded case it also works (as the client retry is now a second way to reach the try_connect() function), but still needs at least one (I saw 2 in some tests) client retransmit cycles to get a response.
Overall better than no response at all, but still not really good.
Main overall lleftover problem I see is really that the tls_proxy_freeze() does not really "interrupt" the already running event select() call in another thread and "tell" it that we are now interesting in the writeability state of the proxy socket.
alandekok
commented
1 month ago @haegar
Could it be that the event select() running in another thread does not get triggered/restarted after using proxy_listener_freeze(), thus the main loop still waiting for something to read from the tls tcp proxy connection, not expecting that it now should "report" when the socket becomes writeable?
Yes. I've pushed what should be a fix.
haegar
commented
1 month ago Thanks @alandekok
Now on git 3.2 branch 9d2e3ea1cdfc444fb74310231ef49fba38150701
It now works "sometimes"! Meaning restart freeradius, send test packets, sometimes the tls establishes and transmits send+reply perfectly, another freeradius restart and test packet and it does nothing, like documented above a bunch of times for the multi-thread case. Still trying to debug in more detail.
But while doing this and reading the source code for once I left the test freeradius from a successful cycle running, instead of aborting it shortly after.
And it crashed when the home_server idle_timeout expired!
Never saw that before with any freeradius version, so it very well could be a side-effect of some very recent change.
Reduced the idle_timeout setting from the previous 600 to 30 for easier testing now.
Single thread mode again everything is fine:
Thu Aug 1 19:01:28 2024 : Debug: (0) Finished request Thu Aug 1 19:01:28 2024 : Debug: Waking up in 0.2 seconds. Thu Aug 1 19:01:28 2024 : Debug: Waking up in 4.7 seconds. Thu Aug 1 19:01:33 2024 : Debug: (0) Cleaning up request packet ID 25 with timestamp +5 due to cleanup_delay was reached Thu Aug 1 19:01:33 2024 : Debug: Waking up in 27.7 seconds. Thu Aug 1 19:02:01 2024 : Debug: Reached idle timeout on socket proxy (10.113.0.10, 57123) -> home_server (172.16.9.156, 2083) Thu Aug 1 19:02:01 2024 : Info: ... shutting down socket proxy (10.113.0.10, 57123) -> home_server (172.16.9.156, 2083) (1 of 8) Thu Aug 1 19:02:01 2024 : Info: Ready to process requests
But the same in multi thread mode:
Thu Aug 1 19:05:38 2024 : Debug: (1) Sent Access-Reject Id 138 from 127.0.0.1:3812 to 127.0.0.1:59105 length 38 Thu Aug 1 19:05:38 2024 : Debug: (1) Finished request Thu Aug 1 19:05:38 2024 : Debug: Thread 4 waiting to be assigned a request Thu Aug 1 19:05:39 2024 : Debug: Waking up in 1.3 seconds. Thu Aug 1 19:05:40 2024 : Debug: (2) Cleaning up request packet ID 107 with timestamp +79 due to cleanup_delay was reached Thu Aug 1 19:05:40 2024 : Debug: Waking up in 3.3 seconds. Thu Aug 1 19:05:43 2024 : Debug: (1) Cleaning up request packet ID 138 with timestamp +72 due to cleanup_delay was reached Thu Aug 1 19:05:43 2024 : Debug: Waking up in 17.6 seconds. Thu Aug 1 19:06:01 2024 : Debug: Reached idle timeout on socket proxy (10.113.0.10, 40811) -> home_server (172.16.9.156, 2083) Thu Aug 1 19:06:01 2024 : Info: ... shutting down socket proxy (10.113.0.10, 40811) -> home_server (172.16.9.156, 2083) (2 of 8) Thu Aug 1 19:06:01 2024 : Debug: ... cleaning up socket proxy (10.113.0.10, 40811) -> home_server (172.16.9.156, 2083) Thu Aug 1 19:06:01 2024 : Debug: Waking up in 6.9 seconds. Thu Aug 1 19:06:01 2024 : Error: Exiting due to internal error: Failed in select: Bad file descriptor Thu Aug 1 19:06:01 2024 : Debug: Thread 3 got semaphore Thu Aug 1 19:06:01 2024 : Debug: Thread 3 exiting... Thu Aug 1 19:06:01 2024 : Debug: Thread 5 got semaphore Thu Aug 1 19:06:01 2024 : Debug: Thread 1 got semaphore Thu Aug 1 19:06:01 2024 : Debug: Thread 5 exiting... Thu Aug 1 19:06:01 2024 : Debug: Thread 4 got semaphore Thu Aug 1 19:06:01 2024 : Debug: Thread 2 got semaphore Thu Aug 1 19:06:01 2024 : Debug: Thread 1 exiting... Thu Aug 1 19:06:01 2024 : Debug: Thread 4 exiting... Thu Aug 1 19:06:01 2024 : Debug: Thread 2 exiting... Thu Aug 1 19:06:01 2024 : Debug: Deleting thread 1 Thu Aug 1 19:06:01 2024 : Debug: Deleting thread 2 Thu Aug 1 19:06:01 2024 : Debug: Deleting thread 3 Thu Aug 1 19:06:01 2024 : Debug: Deleting thread 4 Thu Aug 1 19:06:01 2024 : Debug: Deleting thread 5
alandekok
commented
1 month ago We've pushed a bunch of changes, and it should now fix all of the above issues.
moracca
commented
1 month ago UPDATE:
after debugging with the owner of the remote radsec server we realized that the issue in my case was a intermediate certificate trust problem. My server was sending its own client certificate, and the remote server had only the root server trusted, so it was unable to verify the intermediates. Once I appended the intermediate and root ca to my certificate_file, the connection succeeded when using TLS 1.3. There is not much indication on my side when things go wrong, it looks pretty much the same as when things go right, except I get don't a response.
If I attempt to use TLS 1.2, I still get Error: tls: (TLS) System call (I/O) error (-1) and the process crashes from a segmentation fault I believe. Not sure what is the best way to gather more infor on that, but that likely deserves its own issue anyway.
Thanks
alandekok
commented
1 month ago @moracca
If I attempt to use TLS 1.2, I still get Error: tls: (TLS) System call (I/O) error (-1) and the process crashes from a segmentation fault I believe.
Are you using the latest code from git?
Do you have a gdb back trace? The github issue template && the FreeRADIUS docs describe how to get a back trace.
moracca
commented
1 month ago Not the very latest. I can rebuild with that and see if I can get the backtrace for you.
I think the crash coincides with a "no shared ciphers" error seen on the remote radsec server logs
assuming you want me to open a new issue for that, yes?
moracca
commented
1 month ago BTW the link in the defect issue template takes me to a 404 error https://github.com/FreeRADIUS/freeradius-server/blob/master/doc/source/bugs.md
alandekok
commented
1 month ago @moracca Please use the latest version. It's not useful to report crashes when my previous message said that we've fixed them all.
The "no shared ciphers" isn't a bug. It's a misconfiguration issue.
moracca
commented
1 month ago I agree that no shared ciphers is a misconfiguration, but I was only adding that because it seemed to align with when the process crashed. I have rebuilt on the latest code and with developer enabled, still crashing. I don't think I have everything set right for the full debugging output since I'm seeing the warning about symbols not being available and I see ??? in the output.
Starting program: /usr/local/sbin/radiusd -Xxxxx
warning: Could not load shared library symbols for [vdso].
Do you need "set solib-search-path" or "set sysroot"?
[Detaching after fork from child process 20372]
[Detaching after fork from child process 20385]
[Detaching after fork from child process 20386]
[Detaching after fork from child process 20387]
[Detaching after fork from child process 20392]
[Detaching after fork from child process 20393]
[Detaching after fork from child process 20394]
[Detaching after fork from child process 20395]
[Detaching after fork from child process 20396]
[Detaching after fork from child process 20397]
[Detaching after fork from child process 20398]
[Detaching after fork from child process 20399]
Program received signal SIGSEGV, Segmentation fault.
Address not mapped to object.
0x0000000000262b6a in home_server_ldb ()
Id Target Id Frame
* 1 LWP 100890 of process 20369 0x0000000000262b6a in home_server_ldb ()
Thread 1 (LWP 100890 of process 20369):
#0 0x0000000000262b6a in home_server_ldb ()
#1 0x000000000025ccf6 in ??? ()
#2 0x00000000002574b5 in request_receive ()
#3 0x000000000023fd9d in ??? ()
#4 0x0000000800330acf in fr_event_loop () at /usr/local/lib/freeradius-3.2.6/libfreeradius-radius.so
#5 0x000000000024ce49 in main ()But I will open a separate issue for my problems since its probably off-topic from this thread.
thanks for the help
haegar
commented
1 month ago Moin,
Now on 3.2 git 27a1a47787e87b9e8e4d2bfea1890ab9ab81eba0
The select+crash problem is totally fixed! Thanks for that.
The blocking "sometimes" (race condition) in the multithreaded tls connection case I think I found the source, but not a final solution yet.
Debug patch used - mainly just debug messages to understand what is happening experiment4.diff.gz
First a problem found in the proxy_listener_freeze() and proxy_listener_thaw() functions is that the called function fr_event_fd_write_handler() returns only 0 on errors, and 1 on success. Thus the check of
if (fr_event_fd_write_handler(el, 0, listener->fd, write_handler, listener) < 0) {
in proxy_listener_freeze/thaw will continue without error indication on failed calls to fr_event_fd_write_handler() - but when it fails it continues without setting up the write handler, and thus not waiting on the write events for the socket.
After changing these lines to
if (fr_event_fd_write_handler(el, 0, listener->fd, write_handler, listener) <= 0) {
ERROR("Fatal error freezing socket: %s", fr_strerror());
fr_exit(1);
}
we hit the second, more difficult problem:
I see that this failure really happens - not every call, for me like 25% of the freeradius start, wait a bit + client request test cycles.
The source of these failures seems to be a race condition.
fr_event_fd_write_handler() depends on that the listener has already been added to the main list of readers .
But in the multithreaded case that happens async from the thread doing the try_connect() / SSL_connect() calls, by radius_update_listener() adding the new listener only to the new_listeners list, and notifying the master thread using RADIUS_SIGNAL_SELF_NEW_FD.
At the time of proxy_listener_freeze() if the real event_new_fd(this) in the master thread has already happend everything is good, the fd becomes part of the write_fds list, and the signal RADIUS_SIGNAL_SELF_EVENT_UPDATE makes the select restart, and once it becomes writeable it gets handled correctly, resulting in the TLS connection getting established.
But if the RADIUS_SIGNAL_SELF_NEW_FD has not been processed yet, the fr_event_fd_write_handler() called by proxy_listener_freeze() will do nothing (or fail with my change above), as the function will not find the proxy socket doing the loop of
for (i = 0; i < el->max_readers; i++) {
if (el->readers[i].fd != fd) continue;
...
}
And with my debug outputs I see that this is exactly what happens:
Mon Aug 5 18:11:54 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Mon Aug 5 18:11:54 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 59277) -> home_server (172.16.9.156, 2083)' Mon Aug 5 18:11:54 2024 : Debug: radius_update_listener(fd 14) ... (now the new listener has been added to the new_listeners list, and the NEW_FD signal sent - but not received/processed yet) ... Mon Aug 5 18:11:54 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Mon Aug 5 18:11:54 2024 : Debug: (0) proxy: request is now in proxy hash Mon Aug 5 18:11:54 2024 : Debug: (0) proxy: allocating destination 172.16.9.156 port 2083 - Id 114 Mon Aug 5 18:11:54 2024 : Debug: (0) Proxying request to home server 172.16.9.156 port 2083 (TLS) timeout 10.000000 Mon Aug 5 18:11:54 2024 : Debug: (0) Sent Access-Request Id 114 from 10.113.0.10:59277 to 172.16.9.156:2083 length 122 post select: 1 Mon Aug 5 18:11:54 2024 : Debug: (0) Message-Authenticator = 0xb57c52bb5bb22212b9760bb545919e9a Mon Aug 5 18:11:54 2024 : Debug: (0) User-Name = "test@shs" select reported fd 5 readable Mon Aug 5 18:11:54 2024 : Debug: (0) User-Password = "test" Mon Aug 5 18:11:54 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1 Mon Aug 5 18:11:54 2024 : Debug: (0) NAS-Port = 23 Mon Aug 5 18:11:54 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request" Mon Aug 5 18:11:54 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1" Mon Aug 5 18:11:54 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := "" Mon Aug 5 18:11:54 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := "" Mon Aug 5 18:11:54 2024 : Debug: (0) Proxy-State = 0x323335 Mon Aug 5 18:11:54 2024 : Debug: try_connect(fd 14) Mon Aug 5 18:11:54 2024 : Debug: handle_signal_self() received RADIUS_SIGNAL_SELF_NEW_FD ... here the master thread receives the NEW_FD signal, and races with the child thrad handling the SSL_connect() ... Mon Aug 5 18:11:54 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Mon Aug 5 18:11:54 2024 : Debug: proxy_listener_freeze fd 14 Mon Aug 5 18:11:54 2024 : Error: Fatal error freezing socket: Failed finding socket, caller must allocate a new one ... here we see the proxy_listener_freeze() being called and failing before the event_new_fd(), which outputs the "Debug: Listening on" message below ... Mon Aug 5 18:11:54 2024 : Debug: Listening on proxy (10.113.0.10, 59277) -> home_server (172.16.9.156, 2083) Mon Aug 5 18:11:54 2024 : Debug: Waking up in 0.3 seconds.
Hope this gives you enough meat to find a solution for this race.
alandekok
commented
1 month ago @haegar Perhaps try this patch. If delays the addition of the write_handler until the socket is known.
haegar
commented
1 month ago Yeah!
Thanks @alandekok - with the patch applied I don't see any problems anymore!
Connects all the time without delays/stopping, single threaded, multi threaded, tls 1.2, tls 1.3, all packet forwarding without retransmits needed, correct idle disconnect, no crashes!
alandekok
commented
1 month ago @haegar Thanks. I've pushed the patches.
haegar
commented
1 month ago And still works perfectly with git 3.2 5c2cabfec4bc028d6989182acd47d66131a75369.
I think this bug can finally be closed!
Thanks for your time @alandekok !
moracca
commented
1 month ago great news!
Is there any expected timeline for a 3.2.6 release?
Thanks!
olivierbeytrison
commented
2 weeks ago Thanks!
I had the same issue. And it also fixed #5308
Cheers!
What type of defect/bug is this?
Unexpected behaviour (obvious or verified by project member)
How can the issue be reproduced?
Setup is freeradius 3.2 git 66e6389789c19d0b2 listening on udp port, and trying to forward all requests received there via radsec/tcp+tls to homeserver. The setup in a slightly more complex config than in this reproduction is used for forward authentication from devices which can't do tls radius (aka switches) via such radius proxies encrypted over the internet to our datacenter.
Establishing connection to tls homeserver fails with "ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello". Same setup works with freeradius 3.2.1, and works "sometimes" with 3.2.3 release, where it sometimes breaks with slightly different ssl error messages, and sometimes seems to work - was unable to figure out a scheme, so I tried with the latest git snapshot I am reporting about here.
Both radsec server (tested with freeradius 3.2.1 and with radiator) and this freeradius client use a custom private CA, which generated the server and client certificates.
Accessing the radsec server via openssl s_client also works just fine and establishes the ssl connection.
This problem may be similar to #5308, but I don't listen for TLS connections, and don't get assertion failed or crashes - just the outbound TLS connection fails to get established.
Tried both tls_min_version = "1.2" tls_max_version = "1.2" (where freeradius tries to use tls 1.2) and tls_min_version = "1.2" tls_max_version = "1.3" where it tries to use tls 1.3 fail in absolutely the same way.
Log output from the FreeRADIUS daemon
Relevant log output from client utilities
The client output it relatively useless, just showing that it tries to send the auth requests three times, and then receives the reject sent by freeradius because of "Auth: (0) Login incorrect (Failing proxied request for user "test", due to lack of any response from home server 172.16.9.102 port 2083): [test] (from client caradius-world4 port 23)"
$ radtest -d /home/haegar/freeradius-testing/ -t pap test test 127.0.0.1:3812 23 test123
Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74 User-Name = "test" User-Password = "test" NAS-IP-Address = 127.0.1.1 NAS-Port = 23 Message-Authenticator = 0x00 Cleartext-Password = "test" Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74 User-Name = "test" User-Password = "test" NAS-IP-Address = 127.0.1.1 NAS-Port = 23 Message-Authenticator = 0x00 Cleartext-Password = "test" Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74 User-Name = "test" User-Password = "test" NAS-IP-Address = 127.0.1.1 NAS-Port = 23 Message-Authenticator = 0x00 Cleartext-Password = "test" Received Access-Reject Id 82 from 127.0.0.1:ee4 to 127.0.0.1:38876 length 20 (0) -: Expected Access-Accept got Access-Reject radclient: Received reply to request we did not send. (id=82 socket 3)
Backtrace from LLDB or GDB