Issue with home server proxy after upgrading from 3.2.3 to 3.2.5
After upgrading from 3.2.3 to 3.2.5, when proxying to third party home servers, the request stalls and after 30 seconds gives up. Two examples are below, both different servers depending on the realm. One is Google's radsec server and one is WBA's OpenRoaming radsec server. I've tried multiple clients, Android, iOS and Windows with the same result Example 1: Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 18:33:21 2024 : Debug: (0) Starting proxy to home server 146.148.44.172 port 2083 Sun Jul 14 18:33:21 2024 : Debug: (0) server default { Sun Jul 14 18:33:21 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 18:33:21 2024 : Debug: (0) pre-proxy { Sun Jul 14 18:33:21 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 18:33:21 2024 : Debug: (0) } Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 18:33:21 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Requiring Server certificate Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083)' Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 18:33:21 2024 : Debug: Listening on proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: allocating destination 146.148.44.172 port 2083 - Id 160 Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying request to home server 146.148.44.172 port 2083 (TLS) timeout 30.000000 Sun Jul 14 18:33:21 2024 : Debug: (0) Sent Access-Request Id 160 from 10.210.0.17:49473 to 146.148.44.172:2083 length 457 Sun Jul 14 18:33:21 2024 : Debug: (0) User-Name = " anonymous@openroaming.goog" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 18:33:21 2024 : Debug: (0) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 18:33:21 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port = 2 Sun Jul 14 18:33:21 2024 : Debug: (0) Calling-Station-Id := "7A-74-DB-94-B9-B9" Sun Jul 14 18:33:21 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Session-Id = "436F6F1202EEE66A" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Multi-Session-Id = "80C9B13F6851715F" Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 18:33:21 2024 : Debug: (0) EAP-Message = 0x0263001f01616e6f6e796d6f7573406f70656e726f616d696e672e676f6f67 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 18:33:21 2024 : Debug: (0) Message-Authenticator = 0x291dcaa493772a756028e8807f7966f6 Sun Jul 14 18:33:21 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 18:33:21 UTC" Sun Jul 14 18:33:21 2024 : Debug: (0) Proxy-State = 0x323134 Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 18:33:21 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 18:33:21 2024 : Debug: (0) Expecting proxy response no later than 29.671359 seconds from now Sun Jul 14 18:33:21 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 18:33:22 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:22 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 18:33:23 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:23 2024 : Debug: Waking up in 28.0 seconds. Example 2: Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying due to Home-Server-Name Sun Jul 14 21:19:02 2024 : Debug: (3) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:19:02 2024 : Debug: (3) server default { Sun Jul 14 21:19:02 2024 : Debug: (3) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:02 2024 : Debug: (3) pre-proxy { Sun Jul 14 21:19:02 2024 : Debug: (3) } # pre-proxy = noop Sun Jul 14 21:19:02 2024 : Debug: (3) } Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to open a new listener to the home server Sun Jul 14 21:19:02 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Requiring Server certificate Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:19:02 2024 : Debug: Listening on proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: request is now in proxy hash Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: allocating destination 34.71.27.162 port 2083 - Id 129 Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:19:02 2024 : Debug: (3) Sent Access-Request Id 129 from 10.210.0.17:58915 to 34.71.27.162:2083 length 459 Sun Jul 14 21:19:02 2024 : Debug: (3) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:19:02 2024 : Debug: (3) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:19:02 2024 : Debug: (3) Service-Type = Framed-User Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:19:02 2024 : Debug: (3) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Session-Id = "D603341511C2BCD5" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Multi-Session-Id = "8E65FAC05F4D0058" Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Framed-MTU = 1400 Sun Jul 14 21:19:02 2024 : Debug: (3) EAP-Message = 0x02fa002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-AP-Version = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:19:02 2024 : Debug: (3) Message-Authenticator = 0xaca57ed0829ccbef818ef945142ee620 Sun Jul 14 21:19:02 2024 : Debug: (3) Event-Timestamp = "Jul 14 2024 21:19:02 UTC" Sun Jul 14 21:19:02 2024 : Debug: (3) Proxy-State = 0x313238 Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) has 0 bytes in the buffer Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) Saving 459 bytes of RADIUS traffic for later (total 459) Sun Jul 14 21:19:02 2024 : Debug: Thread 2 waiting to be assigned a request Sun Jul 14 21:19:02 2024 : Debug: (3) Expecting proxy response no later than 29.673344 seconds from now Sun Jul 14 21:19:02 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:19:03 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:03 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 21:19:04 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:04 2024 : Debug: Waking up in 28.0 seconds. Sun Jul 14 21:19:32 2024 : Debug: (3) No proxy response, giving up on request and marking it done Sun Jul 14 21:19:32 2024 : Proxy: Marking home server 34.71.27.162 port 2083 as zombie (it has not responded in 30.000000 seconds). Sun Jul 14 21:19:32 2024 : ERROR: (3) Failing proxied request for user " anonymous@test.orportal.org", due to lack of any response from home server 34.71.27.162 port 2083 Sun Jul 14 21:19:32 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:32 2024 : Debug: Thread 1 got semaphore Sun Jul 14 21:19:32 2024 : Debug: Thread 1 handling request 3, (1 handled so far) Sun Jul 14 21:19:32 2024 : Debug: (3) Clearing existing &reply: attributes Sun Jul 14 21:19:32 2024 : Debug: (3) Found Post-Proxy-Type Fail-Authentication Sun Jul 14 21:19:32 2024 : Debug: (3) server default { Sun Jul 14 21:19:32 2024 : Debug: (3) Post-Proxy-Type sub-section not found. Ignoring. Sun Jul 14 21:19:32 2024 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:32 2024 : Debug: (3) } Sun Jul 14 21:19:32 2024 : Auth: (3) Login incorrect (Home Server failed to respond): [anonymous@test.orportal.org/<via Auth-Type = eap>] (from client 158.115.148.241 port 1 cli 92-D4-9F-CE-0B-03) However, sometimes, after a long delay, when the AP sends another request/retry, it will work: Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 21:12:33 2024 : Debug: (0) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:33 2024 : Debug: (0) server default { Sun Jul 14 21:12:33 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:33 2024 : Debug: (0) pre-proxy { Sun Jul 14 21:12:33 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 21:12:33 2024 : Debug: (0) } Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 21:12:33 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: Requiring Server certificate Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: allocating destination 34.71.27.162 port 2083 - Id 125 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:33 2024 : Debug: (0) Sent Access-Request Id 125 from 10.210.0.17:52075 to 34.71.27.162:2083 length 457 Sun Jul 14 21:12:33 2024 : Debug: (0) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:33 2024 : Debug: (0) Called-Station-Id := "EA-CB-BC-8A-1A-6E" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:33 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:33 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11n / RSSI: 66 / Channel: 11" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Session-Id = "C761770D256A61C9" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Multi-Session-Id = "6004A9491042AF0E" Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Network-Name = "WiFi SDK" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 21:12:33 2024 : Debug: (0) EAP-Message = 0x024c002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: Listening on proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:33 2024 : Debug: (0) Message-Authenticator = 0x682d40e95aad80a327255abd7a299545 Sun Jul 14 21:12:33 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 21:12:33 UTC" Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: (0) Login-IP-Host := 158.115.148.241 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxy-State = 0x3931 Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 21:12:33 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 21:12:33 2024 : Debug: (0) Expecting proxy response no later than 29.670882 seconds from now Sun Jul 14 21:12:33 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:12:34 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:34 2024 : Debug: Waking up in 29.1 seconds. Sun Jul 14 21:12:35 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:35 2024 : Debug: Waking up in 28.1 seconds. [delay of approx 11 seconds] Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying due to Home-Server-Name Sun Jul 14 21:12:46 2024 : Debug: (1) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:46 2024 : Debug: (1) server default { Sun Jul 14 21:12:46 2024 : Debug: (1) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:46 2024 : Debug: (1) pre-proxy { Sun Jul 14 21:12:46 2024 : Debug: (1) } # pre-proxy = noop Sun Jul 14 21:12:46 2024 : Debug: (1) } Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: request is now in proxy hash Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: allocating destination 34.71.27.162 port 2083 - Id 218 Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:46 2024 : Debug: (1) Sent Access-Request Id 218 from 10.210.0.17:52075 to 34.71.27.162:2083 length 459 Sun Jul 14 21:12:46 2024 : Debug: (1) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:46 2024 : Debug: (1) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:46 2024 : Debug: (1) Service-Type = Framed-User Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:46 2024 : Debug: (1) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 59 / Channel: 40" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Session-Id = "61F9B0FCE7763CE0" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Multi-Session-Id = "8549D73EAF2A1D02" Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Framed-MTU = 1400 Sun Jul 14 21:12:46 2024 : Debug: (1) EAP-Message = 0x0244002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-AP-Version = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:46 2024 : Debug: (1) Message-Authenticator = 0xc65d316989bbd3bf645feb05d9cd5633 Sun Jul 14 21:12:46 2024 : Debug: (1) Event-Timestamp = "Jul 14 2024 21:12:46 UTC" Sun Jul 14 21:12:46 2024 : Debug: (1) Proxy-State = 0x313133 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) has 457 bytes in the buffer Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) Saving 459 bytes of RADIUS traffic for later (total 916) Sun Jul 14 21:12:46 2024 : Debug: Thread 4 waiting to be assigned a request Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ServerHello Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, EncryptedExtensions Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TREE] - Client TLSv1.3 read encrypted extensions (38) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateRequest Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server certificate request Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.2 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 4 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 3 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 3 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 2 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /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 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain and the rest works.... auth is successful. When I restore back to 3.2.3 with the exact same config, it works the first time, every time. I have tested against 4 different proxy home servers and they all have similar behaviour so it must be some local issue. Any thoughts? Thanks, James
On Jul 14, 2024, at 5:23 PM, James Wood via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
After upgrading from 3.2.3 to 3.2.5, when proxying to third party home servers, the request stalls and after 30 seconds gives up.
Hm... we'll take a look. Unfortunately, these things are difficult to resolve. For now, perhaps use 3.2.3, and set "require_message_authenticator". We'll take a look and fix it before 3.2.6 is released. Alan DeKok.
One more question... is the 3.2.3 and 3.2.5 on the same system? Or are they on different systems? Other tests we've done indicate that the issue is related to a newer version of OpenSSL. i.e. OpenSSL 3.? fails, and OpenSSL <3.? works. So which OpenSSL version(s) are being used? You can do this on both systems: radiusd -vvx | grep -iw ssl And then see what it prints. On my system, I get Sun Jul 14 19:27:20 2024 : Debug: ssl : 3.3.0a dev Alan DeKok.
One more question... is the 3.2.3 and 3.2.5 on the same system? Or are they on different systems?
Other tests we've done indicate that the issue is related to a newer version of OpenSSL. i.e. OpenSSL 3.? fails, and OpenSSL <3.? works.
So which OpenSSL version(s) are being used? You can do this on both systems:
radiusd -vvx | grep -iw ssl
And then see what it prints. On my system, I get
Yes, exact same system, just configure/make/make install between the different versions whilst re-using the same config. I also tested with the message_authenticator and limit_proxy_state commented out and set explicitly to "no" in clients.conf, radiusd.conf, proxy.conf and like in pre 3.2.5 versions and it didn't change the behaviour... still stalls, just because I thought that would be the potential issue, but no. The OpenSSL version is: 3.0.0b dev Mon Jul 15 08:15:31 2024 : Debug: Server was built with: Mon Jul 15 08:15:31 2024 : Debug: accounting : yes Mon Jul 15 08:15:31 2024 : Debug: authentication : yes Mon Jul 15 08:15:31 2024 : Debug: ascend-binary-attributes : yes Mon Jul 15 08:15:31 2024 : Debug: coa : yes Mon Jul 15 08:15:31 2024 : Debug: recv-coa-from-home-server : no Mon Jul 15 08:15:31 2024 : Debug: control-socket : yes Mon Jul 15 08:15:31 2024 : Debug: detail : yes Mon Jul 15 08:15:31 2024 : Debug: dhcp : yes Mon Jul 15 08:15:31 2024 : Debug: dynamic-clients : yes Mon Jul 15 08:15:31 2024 : Debug: osfc2 : no Mon Jul 15 08:15:31 2024 : Debug: proxy : yes Mon Jul 15 08:15:31 2024 : Debug: regex-pcre : no Mon Jul 15 08:15:31 2024 : Debug: regex-posix : yes Mon Jul 15 08:15:31 2024 : Debug: regex-posix-extended : yes Mon Jul 15 08:15:31 2024 : Debug: session-management : yes Mon Jul 15 08:15:31 2024 : Debug: stats : yes Mon Jul 15 08:15:31 2024 : Debug: systemd : no Mon Jul 15 08:15:31 2024 : Debug: tcp : yes Mon Jul 15 08:15:31 2024 : Debug: threads : yes Mon Jul 15 08:15:31 2024 : Debug: tls : yes Mon Jul 15 08:15:31 2024 : Debug: unlang : yes Mon Jul 15 08:15:31 2024 : Debug: vmps : yes Mon Jul 15 08:15:31 2024 : Debug: developer : no Mon Jul 15 08:15:31 2024 : Debug: Server core libs: Mon Jul 15 08:15:31 2024 : Debug: freeradius-server : 3.2.5 Mon Jul 15 08:15:31 2024 : Debug: talloc : 2.3.* Mon Jul 15 08:15:31 2024 : Debug: ssl : 3.0.0b dev Mon Jul 15 08:15:31 2024 : Debug: Endianness: Mon Jul 15 08:15:31 2024 : Debug: little Thanks On Sun, 14 Jul 2024 at 22:23, James Wood <james.wood@purplewifi.com> wrote:
After upgrading from 3.2.3 to 3.2.5, when proxying to third party home servers, the request stalls and after 30 seconds gives up.
Two examples are below, both different servers depending on the realm. One is Google's radsec server and one is WBA's OpenRoaming radsec server. I've tried multiple clients, Android, iOS and Windows with the same result
Example 1:
Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 18:33:21 2024 : Debug: (0) Starting proxy to home server 146.148.44.172 port 2083 Sun Jul 14 18:33:21 2024 : Debug: (0) server default { Sun Jul 14 18:33:21 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 18:33:21 2024 : Debug: (0) pre-proxy { Sun Jul 14 18:33:21 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 18:33:21 2024 : Debug: (0) } Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 18:33:21 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Requiring Server certificate Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083)' Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 18:33:21 2024 : Debug: Listening on proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: allocating destination 146.148.44.172 port 2083 - Id 160 Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying request to home server 146.148.44.172 port 2083 (TLS) timeout 30.000000 Sun Jul 14 18:33:21 2024 : Debug: (0) Sent Access-Request Id 160 from 10.210.0.17:49473 to 146.148.44.172:2083 length 457 Sun Jul 14 18:33:21 2024 : Debug: (0) User-Name = " anonymous@openroaming.goog" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 18:33:21 2024 : Debug: (0) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 18:33:21 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port = 2 Sun Jul 14 18:33:21 2024 : Debug: (0) Calling-Station-Id := "7A-74-DB-94-B9-B9" Sun Jul 14 18:33:21 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Session-Id = "436F6F1202EEE66A" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Multi-Session-Id = "80C9B13F6851715F" Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 18:33:21 2024 : Debug: (0) EAP-Message = 0x0263001f01616e6f6e796d6f7573406f70656e726f616d696e672e676f6f67 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 18:33:21 2024 : Debug: (0) Message-Authenticator = 0x291dcaa493772a756028e8807f7966f6 Sun Jul 14 18:33:21 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 18:33:21 UTC" Sun Jul 14 18:33:21 2024 : Debug: (0) Proxy-State = 0x323134 Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 18:33:21 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 18:33:21 2024 : Debug: (0) Expecting proxy response no later than 29.671359 seconds from now Sun Jul 14 18:33:21 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 18:33:22 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:22 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 18:33:23 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:23 2024 : Debug: Waking up in 28.0 seconds.
Example 2:
Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying due to Home-Server-Name Sun Jul 14 21:19:02 2024 : Debug: (3) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:19:02 2024 : Debug: (3) server default { Sun Jul 14 21:19:02 2024 : Debug: (3) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:02 2024 : Debug: (3) pre-proxy { Sun Jul 14 21:19:02 2024 : Debug: (3) } # pre-proxy = noop Sun Jul 14 21:19:02 2024 : Debug: (3) } Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to open a new listener to the home server Sun Jul 14 21:19:02 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Requiring Server certificate Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:19:02 2024 : Debug: Listening on proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: request is now in proxy hash Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: allocating destination 34.71.27.162 port 2083 - Id 129 Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:19:02 2024 : Debug: (3) Sent Access-Request Id 129 from 10.210.0.17:58915 to 34.71.27.162:2083 length 459 Sun Jul 14 21:19:02 2024 : Debug: (3) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:19:02 2024 : Debug: (3) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:19:02 2024 : Debug: (3) Service-Type = Framed-User Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:19:02 2024 : Debug: (3) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Session-Id = "D603341511C2BCD5" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Multi-Session-Id = "8E65FAC05F4D0058" Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Framed-MTU = 1400 Sun Jul 14 21:19:02 2024 : Debug: (3) EAP-Message = 0x02fa002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-AP-Version = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:19:02 2024 : Debug: (3) Message-Authenticator = 0xaca57ed0829ccbef818ef945142ee620 Sun Jul 14 21:19:02 2024 : Debug: (3) Event-Timestamp = "Jul 14 2024 21:19:02 UTC" Sun Jul 14 21:19:02 2024 : Debug: (3) Proxy-State = 0x313238 Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) has 0 bytes in the buffer Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) Saving 459 bytes of RADIUS traffic for later (total 459) Sun Jul 14 21:19:02 2024 : Debug: Thread 2 waiting to be assigned a request Sun Jul 14 21:19:02 2024 : Debug: (3) Expecting proxy response no later than 29.673344 seconds from now Sun Jul 14 21:19:02 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:19:03 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:03 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 21:19:04 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:04 2024 : Debug: Waking up in 28.0 seconds. Sun Jul 14 21:19:32 2024 : Debug: (3) No proxy response, giving up on request and marking it done Sun Jul 14 21:19:32 2024 : Proxy: Marking home server 34.71.27.162 port 2083 as zombie (it has not responded in 30.000000 seconds). Sun Jul 14 21:19:32 2024 : ERROR: (3) Failing proxied request for user " anonymous@test.orportal.org", due to lack of any response from home server 34.71.27.162 port 2083 Sun Jul 14 21:19:32 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:32 2024 : Debug: Thread 1 got semaphore Sun Jul 14 21:19:32 2024 : Debug: Thread 1 handling request 3, (1 handled so far) Sun Jul 14 21:19:32 2024 : Debug: (3) Clearing existing &reply: attributes Sun Jul 14 21:19:32 2024 : Debug: (3) Found Post-Proxy-Type Fail-Authentication Sun Jul 14 21:19:32 2024 : Debug: (3) server default { Sun Jul 14 21:19:32 2024 : Debug: (3) Post-Proxy-Type sub-section not found. Ignoring. Sun Jul 14 21:19:32 2024 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:32 2024 : Debug: (3) } Sun Jul 14 21:19:32 2024 : Auth: (3) Login incorrect (Home Server failed to respond): [anonymous@test.orportal.org/<via Auth-Type = eap>] (from client 158.115.148.241 port 1 cli 92-D4-9F-CE-0B-03)
However, sometimes, after a long delay, when the AP sends another request/retry, it will work:
Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 21:12:33 2024 : Debug: (0) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:33 2024 : Debug: (0) server default { Sun Jul 14 21:12:33 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:33 2024 : Debug: (0) pre-proxy { Sun Jul 14 21:12:33 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 21:12:33 2024 : Debug: (0) } Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 21:12:33 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: Requiring Server certificate Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: allocating destination 34.71.27.162 port 2083 - Id 125 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:33 2024 : Debug: (0) Sent Access-Request Id 125 from 10.210.0.17:52075 to 34.71.27.162:2083 length 457 Sun Jul 14 21:12:33 2024 : Debug: (0) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:33 2024 : Debug: (0) Called-Station-Id := "EA-CB-BC-8A-1A-6E" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:33 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:33 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11n / RSSI: 66 / Channel: 11" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Session-Id = "C761770D256A61C9" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Multi-Session-Id = "6004A9491042AF0E" Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Network-Name = "WiFi SDK" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 21:12:33 2024 : Debug: (0) EAP-Message = 0x024c002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: Listening on proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:33 2024 : Debug: (0) Message-Authenticator = 0x682d40e95aad80a327255abd7a299545 Sun Jul 14 21:12:33 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 21:12:33 UTC" Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: (0) Login-IP-Host := 158.115.148.241 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxy-State = 0x3931 Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 21:12:33 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 21:12:33 2024 : Debug: (0) Expecting proxy response no later than 29.670882 seconds from now Sun Jul 14 21:12:33 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:12:34 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:34 2024 : Debug: Waking up in 29.1 seconds. Sun Jul 14 21:12:35 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:35 2024 : Debug: Waking up in 28.1 seconds.
[delay of approx 11 seconds]
Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying due to Home-Server-Name Sun Jul 14 21:12:46 2024 : Debug: (1) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:46 2024 : Debug: (1) server default { Sun Jul 14 21:12:46 2024 : Debug: (1) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:46 2024 : Debug: (1) pre-proxy { Sun Jul 14 21:12:46 2024 : Debug: (1) } # pre-proxy = noop Sun Jul 14 21:12:46 2024 : Debug: (1) } Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: request is now in proxy hash Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: allocating destination 34.71.27.162 port 2083 - Id 218 Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:46 2024 : Debug: (1) Sent Access-Request Id 218 from 10.210.0.17:52075 to 34.71.27.162:2083 length 459 Sun Jul 14 21:12:46 2024 : Debug: (1) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:46 2024 : Debug: (1) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:46 2024 : Debug: (1) Service-Type = Framed-User Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:46 2024 : Debug: (1) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 59 / Channel: 40" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Session-Id = "61F9B0FCE7763CE0" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Multi-Session-Id = "8549D73EAF2A1D02" Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Framed-MTU = 1400 Sun Jul 14 21:12:46 2024 : Debug: (1) EAP-Message = 0x0244002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-AP-Version = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:46 2024 : Debug: (1) Message-Authenticator = 0xc65d316989bbd3bf645feb05d9cd5633 Sun Jul 14 21:12:46 2024 : Debug: (1) Event-Timestamp = "Jul 14 2024 21:12:46 UTC" Sun Jul 14 21:12:46 2024 : Debug: (1) Proxy-State = 0x313133 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) has 457 bytes in the buffer Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) Saving 459 bytes of RADIUS traffic for later (total 916) Sun Jul 14 21:12:46 2024 : Debug: Thread 4 waiting to be assigned a request Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ServerHello Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, EncryptedExtensions Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TREE] - Client TLSv1.3 read encrypted extensions (38) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateRequest Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server certificate request Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.2 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 4 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 3 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 3 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 2 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /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 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain
and the rest works.... auth is successful.
When I restore back to 3.2.3 with the exact same config, it works the first time, every time.
I have tested against 4 different proxy home servers and they all have similar behaviour so it must be some local issue. Any thoughts?
Thanks,
James
Any more thoughts on this one? We really want to upgrade to 3.2.5 for obvious reasons but without proxying working we're a little stuck. Thanks James On Mon, 15 Jul 2024 at 09:23, James Wood <james.wood@purplewifi.com> wrote:
One more question... is the 3.2.3 and 3.2.5 on the same system? Or are they on different systems?
Other tests we've done indicate that the issue is related to a newer version of OpenSSL. i.e. OpenSSL 3.? fails, and OpenSSL <3.? works.
So which OpenSSL version(s) are being used? You can do this on both systems:
radiusd -vvx | grep -iw ssl
And then see what it prints. On my system, I get
Yes, exact same system, just configure/make/make install between the different versions whilst re-using the same config.
I also tested with the message_authenticator and limit_proxy_state commented out and set explicitly to "no" in clients.conf, radiusd.conf, proxy.conf and like in pre 3.2.5 versions and it didn't change the behaviour... still stalls, just because I thought that would be the potential issue, but no.
The OpenSSL version is: 3.0.0b dev
Mon Jul 15 08:15:31 2024 : Debug: Server was built with: Mon Jul 15 08:15:31 2024 : Debug: accounting : yes Mon Jul 15 08:15:31 2024 : Debug: authentication : yes Mon Jul 15 08:15:31 2024 : Debug: ascend-binary-attributes : yes Mon Jul 15 08:15:31 2024 : Debug: coa : yes Mon Jul 15 08:15:31 2024 : Debug: recv-coa-from-home-server : no Mon Jul 15 08:15:31 2024 : Debug: control-socket : yes Mon Jul 15 08:15:31 2024 : Debug: detail : yes Mon Jul 15 08:15:31 2024 : Debug: dhcp : yes Mon Jul 15 08:15:31 2024 : Debug: dynamic-clients : yes Mon Jul 15 08:15:31 2024 : Debug: osfc2 : no Mon Jul 15 08:15:31 2024 : Debug: proxy : yes Mon Jul 15 08:15:31 2024 : Debug: regex-pcre : no Mon Jul 15 08:15:31 2024 : Debug: regex-posix : yes Mon Jul 15 08:15:31 2024 : Debug: regex-posix-extended : yes Mon Jul 15 08:15:31 2024 : Debug: session-management : yes Mon Jul 15 08:15:31 2024 : Debug: stats : yes Mon Jul 15 08:15:31 2024 : Debug: systemd : no Mon Jul 15 08:15:31 2024 : Debug: tcp : yes Mon Jul 15 08:15:31 2024 : Debug: threads : yes Mon Jul 15 08:15:31 2024 : Debug: tls : yes Mon Jul 15 08:15:31 2024 : Debug: unlang : yes Mon Jul 15 08:15:31 2024 : Debug: vmps : yes Mon Jul 15 08:15:31 2024 : Debug: developer : no Mon Jul 15 08:15:31 2024 : Debug: Server core libs: Mon Jul 15 08:15:31 2024 : Debug: freeradius-server : 3.2.5 Mon Jul 15 08:15:31 2024 : Debug: talloc : 2.3.* Mon Jul 15 08:15:31 2024 : Debug: ssl : 3.0.0b dev Mon Jul 15 08:15:31 2024 : Debug: Endianness: Mon Jul 15 08:15:31 2024 : Debug: little
Thanks
On Sun, 14 Jul 2024 at 22:23, James Wood <james.wood@purplewifi.com> wrote:
After upgrading from 3.2.3 to 3.2.5, when proxying to third party home servers, the request stalls and after 30 seconds gives up.
Two examples are below, both different servers depending on the realm. One is Google's radsec server and one is WBA's OpenRoaming radsec server. I've tried multiple clients, Android, iOS and Windows with the same result
Example 1:
Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 18:33:21 2024 : Debug: (0) Starting proxy to home server 146.148.44.172 port 2083 Sun Jul 14 18:33:21 2024 : Debug: (0) server default { Sun Jul 14 18:33:21 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 18:33:21 2024 : Debug: (0) pre-proxy { Sun Jul 14 18:33:21 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 18:33:21 2024 : Debug: (0) } Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 18:33:21 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Requiring Server certificate Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083)' Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 18:33:21 2024 : Debug: Listening on proxy (10.210.0.17, 49473) -> home_server (146.148.44.172, 2083) Sun Jul 14 18:33:21 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 18:33:21 2024 : Debug: (0) proxy: allocating destination 146.148.44.172 port 2083 - Id 160 Sun Jul 14 18:33:21 2024 : Debug: (0) Proxying request to home server 146.148.44.172 port 2083 (TLS) timeout 30.000000 Sun Jul 14 18:33:21 2024 : Debug: (0) Sent Access-Request Id 160 from 10.210.0.17:49473 to 146.148.44.172:2083 length 457 Sun Jul 14 18:33:21 2024 : Debug: (0) User-Name = " anonymous@openroaming.goog" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 18:33:21 2024 : Debug: (0) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 18:33:21 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 18:33:21 2024 : Debug: (0) NAS-Port = 2 Sun Jul 14 18:33:21 2024 : Debug: (0) Calling-Station-Id := "7A-74-DB-94-B9-B9" Sun Jul 14 18:33:21 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Session-Id = "436F6F1202EEE66A" Sun Jul 14 18:33:21 2024 : Debug: (0) Acct-Multi-Session-Id = "80C9B13F6851715F" Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 18:33:21 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 18:33:21 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 18:33:21 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 18:33:21 2024 : Debug: (0) EAP-Message = 0x0263001f01616e6f6e796d6f7573406f70656e726f616d696e672e676f6f67 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 18:33:21 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 18:33:21 2024 : Debug: (0) Message-Authenticator = 0x291dcaa493772a756028e8807f7966f6 Sun Jul 14 18:33:21 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 18:33:21 UTC" Sun Jul 14 18:33:21 2024 : Debug: (0) Proxy-State = 0x323134 Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 18:33:21 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 18:33:21 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 18:33:21 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 18:33:21 2024 : Debug: (0) Expecting proxy response no later than 29.671359 seconds from now Sun Jul 14 18:33:21 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 18:33:22 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:22 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 18:33:23 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 146.148.44.172 port 2083 proto TCP - ID: 160 Sun Jul 14 18:33:23 2024 : Debug: Waking up in 28.0 seconds.
Example 2:
Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying due to Home-Server-Name Sun Jul 14 21:19:02 2024 : Debug: (3) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:19:02 2024 : Debug: (3) server default { Sun Jul 14 21:19:02 2024 : Debug: (3) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:02 2024 : Debug: (3) pre-proxy { Sun Jul 14 21:19:02 2024 : Debug: (3) } # pre-proxy = noop Sun Jul 14 21:19:02 2024 : Debug: (3) } Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to open a new listener to the home server Sun Jul 14 21:19:02 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Requiring Server certificate Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:19:02 2024 : Debug: Listening on proxy (10.210.0.17, 58915) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:19:02 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: request is now in proxy hash Sun Jul 14 21:19:02 2024 : Debug: (3) proxy: allocating destination 34.71.27.162 port 2083 - Id 129 Sun Jul 14 21:19:02 2024 : Debug: (3) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:19:02 2024 : Debug: (3) Sent Access-Request Id 129 from 10.210.0.17:58915 to 34.71.27.162:2083 length 459 Sun Jul 14 21:19:02 2024 : Debug: (3) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:19:02 2024 : Debug: (3) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:19:02 2024 : Debug: (3) Service-Type = Framed-User Sun Jul 14 21:19:02 2024 : Debug: (3) NAS-Port = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:19:02 2024 : Debug: (3) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 66 / Channel: 40" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Session-Id = "D603341511C2BCD5" Sun Jul 14 21:19:02 2024 : Debug: (3) Acct-Multi-Session-Id = "8E65FAC05F4D0058" Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:19:02 2024 : Debug: (3) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:19:02 2024 : Debug: (3) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:19:02 2024 : Debug: (3) Framed-MTU = 1400 Sun Jul 14 21:19:02 2024 : Debug: (3) EAP-Message = 0x02fa002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-AP-Version = 1 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:19:02 2024 : Debug: (3) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:19:02 2024 : Debug: (3) Message-Authenticator = 0xaca57ed0829ccbef818ef945142ee620 Sun Jul 14 21:19:02 2024 : Debug: (3) Event-Timestamp = "Jul 14 2024 21:19:02 UTC" Sun Jul 14 21:19:02 2024 : Debug: (3) Proxy-State = 0x313238 Sun Jul 14 21:19:02 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:19:02 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) has 0 bytes in the buffer Sun Jul 14 21:19:02 2024 : Debug: (3) (TLS) Saving 459 bytes of RADIUS traffic for later (total 459) Sun Jul 14 21:19:02 2024 : Debug: Thread 2 waiting to be assigned a request Sun Jul 14 21:19:02 2024 : Debug: (3) Expecting proxy response no later than 29.673344 seconds from now Sun Jul 14 21:19:02 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:19:03 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:03 2024 : Debug: Waking up in 29.0 seconds. Sun Jul 14 21:19:04 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 129 Sun Jul 14 21:19:04 2024 : Debug: Waking up in 28.0 seconds. Sun Jul 14 21:19:32 2024 : Debug: (3) No proxy response, giving up on request and marking it done Sun Jul 14 21:19:32 2024 : Proxy: Marking home server 34.71.27.162 port 2083 as zombie (it has not responded in 30.000000 seconds). Sun Jul 14 21:19:32 2024 : ERROR: (3) Failing proxied request for user " anonymous@test.orportal.org", due to lack of any response from home server 34.71.27.162 port 2083 Sun Jul 14 21:19:32 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:19:32 2024 : Debug: Thread 1 got semaphore Sun Jul 14 21:19:32 2024 : Debug: Thread 1 handling request 3, (1 handled so far) Sun Jul 14 21:19:32 2024 : Debug: (3) Clearing existing &reply: attributes Sun Jul 14 21:19:32 2024 : Debug: (3) Found Post-Proxy-Type Fail-Authentication Sun Jul 14 21:19:32 2024 : Debug: (3) server default { Sun Jul 14 21:19:32 2024 : Debug: (3) Post-Proxy-Type sub-section not found. Ignoring. Sun Jul 14 21:19:32 2024 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:19:32 2024 : Debug: (3) } Sun Jul 14 21:19:32 2024 : Auth: (3) Login incorrect (Home Server failed to respond): [anonymous@test.orportal.org/<via Auth-Type = eap>] (from client 158.115.148.241 port 1 cli 92-D4-9F-CE-0B-03)
However, sometimes, after a long delay, when the AP sends another request/retry, it will work:
Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying due to Home-Server-Name Sun Jul 14 21:12:33 2024 : Debug: (0) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:33 2024 : Debug: (0) server default { Sun Jul 14 21:12:33 2024 : Debug: (0) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:33 2024 : Debug: (0) pre-proxy { Sun Jul 14 21:12:33 2024 : Debug: (0) } # pre-proxy = noop Sun Jul 14 21:12:33 2024 : Debug: (0) } Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to open a new listener to the home server Sun Jul 14 21:12:33 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: Requiring Server certificate Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0) Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ClientHello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - tls_new_client_session WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: Opened new proxy socket 'proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083)' Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: Trying to allocate ID (1/2) Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: request is now in proxy hash Sun Jul 14 21:12:33 2024 : Debug: (0) proxy: allocating destination 34.71.27.162 port 2083 - Id 125 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:33 2024 : Debug: (0) Sent Access-Request Id 125 from 10.210.0.17:52075 to 34.71.27.162:2083 length 457 Sun Jul 14 21:12:33 2024 : Debug: (0) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:33 2024 : Debug: (0) Called-Station-Id := "EA-CB-BC-8A-1A-6E" Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:33 2024 : Debug: (0) Service-Type = Framed-User Sun Jul 14 21:12:33 2024 : Debug: (0) NAS-Port = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:33 2024 : Debug: (0) Connect-Info = "CONNECT 54.00 Mbps / 802.11n / RSSI: 66 / Channel: 11" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Session-Id = "C761770D256A61C9" Sun Jul 14 21:12:33 2024 : Debug: (0) Acct-Multi-Session-Id = "6004A9491042AF0E" Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:33 2024 : Debug: (0) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Network-Name = "WiFi SDK" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:33 2024 : Debug: (0) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:33 2024 : Debug: (0) Framed-MTU = 1400 Sun Jul 14 21:12:33 2024 : Debug: (0) EAP-Message = 0x024c002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-AP-Version = 1 Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: Listening on proxy (10.210.0.17, 52075) -> home_server (34.71.27.162, 2083) Sun Jul 14 21:12:33 2024 : Debug: (0) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:33 2024 : Debug: (0) Message-Authenticator = 0x682d40e95aad80a327255abd7a299545 Sun Jul 14 21:12:33 2024 : Debug: (0) Event-Timestamp = "Jul 14 2024 21:12:33 UTC" Sun Jul 14 21:12:33 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:33 2024 : Debug: (0) Login-IP-Host := 158.115.148.241 Sun Jul 14 21:12:33 2024 : Debug: (0) Proxy-State = 0x3931 Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to write more data: SSLv3/TLS write client hello Sun Jul 14 21:12:33 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) has 0 bytes in the buffer Sun Jul 14 21:12:33 2024 : Debug: (0) (TLS) Saving 457 bytes of RADIUS traffic for later (total 457) Sun Jul 14 21:12:33 2024 : Debug: Thread 5 waiting to be assigned a request Sun Jul 14 21:12:33 2024 : Debug: (0) Expecting proxy response no later than 29.670882 seconds from now Sun Jul 14 21:12:33 2024 : Debug: Waking up in 29.6 seconds. Sun Jul 14 21:12:34 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:34 2024 : Debug: Waking up in 29.1 seconds. Sun Jul 14 21:12:35 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 34.71.27.162 port 2083 proto TCP - ID: 125 Sun Jul 14 21:12:35 2024 : Debug: Waking up in 28.1 seconds.
[delay of approx 11 seconds]
Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying due to Home-Server-Name Sun Jul 14 21:12:46 2024 : Debug: (1) Starting proxy to home server 34.71.27.162 port 2083 Sun Jul 14 21:12:46 2024 : Debug: (1) server default { Sun Jul 14 21:12:46 2024 : Debug: (1) # Executing section pre-proxy from file /usr/local/etc/raddb/sites-enabled/default Sun Jul 14 21:12:46 2024 : Debug: (1) pre-proxy { Sun Jul 14 21:12:46 2024 : Debug: (1) } # pre-proxy = noop Sun Jul 14 21:12:46 2024 : Debug: (1) } Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: Trying to allocate ID (0/2) Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: request is now in proxy hash Sun Jul 14 21:12:46 2024 : Debug: (1) proxy: allocating destination 34.71.27.162 port 2083 - Id 218 Sun Jul 14 21:12:46 2024 : Debug: (1) Proxying request to home server 34.71.27.162 port 2083 (TLS) timeout 30.000000 Sun Jul 14 21:12:46 2024 : Debug: (1) Sent Access-Request Id 218 from 10.210.0.17:52075 to 34.71.27.162:2083 length 459 Sun Jul 14 21:12:46 2024 : Debug: (1) User-Name = " anonymous@test.orportal.org" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-IP-Address = 192.168.1.116 Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Identifier = "E0-CB-BC-8A-1A-6E:vap2" Sun Jul 14 21:12:46 2024 : Debug: (1) Called-Station-Id := "EA-CB-AC-8A-1A-6E" Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port-Type = Wireless-802.11 Sun Jul 14 21:12:46 2024 : Debug: (1) Service-Type = Framed-User Sun Jul 14 21:12:46 2024 : Debug: (1) NAS-Port = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) Calling-Station-Id := "92-D4-9F-CE-0B-03" Sun Jul 14 21:12:46 2024 : Debug: (1) Connect-Info = "CONNECT 54.00 Mbps / 802.11ac / RSSI: 59 / Channel: 40" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Session-Id = "61F9B0FCE7763CE0" Sun Jul 14 21:12:46 2024 : Debug: (1) Acct-Multi-Session-Id = "8549D73EAF2A1D02" Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Pairwise-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-Group-Cipher = 1027076 Sun Jul 14 21:12:46 2024 : Debug: (1) WLAN-AKM-Suite = 1027073 Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Ap-Tags = " recently-added " Sun Jul 14 21:12:46 2024 : Debug: (1) Meraki-Device-Name = "meraki-mr42-test-ap" Sun Jul 14 21:12:46 2024 : Debug: (1) Framed-MTU = 1400 Sun Jul 14 21:12:46 2024 : Debug: (1) EAP-Message = 0x0244002001616e6f6e796d6f757340746573742e6f72706f7274616c2e6f7267 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-AP-Version = 1 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Mobile-Device-Version = 0x010000 Sun Jul 14 21:12:46 2024 : Debug: (1) HS20-Roaming-Consortium = 0x5a03ba0000 Sun Jul 14 21:12:46 2024 : Debug: (1) Message-Authenticator = 0xc65d316989bbd3bf645feb05d9cd5633 Sun Jul 14 21:12:46 2024 : Debug: (1) Event-Timestamp = "Jul 14 2024 21:12:46 UTC" Sun Jul 14 21:12:46 2024 : Debug: (1) Proxy-State = 0x313133 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) has 457 bytes in the buffer Sun Jul 14 21:12:46 2024 : Debug: (1) (TLS) Saving 459 bytes of RADIUS traffic for later (total 916) Sun Jul 14 21:12:46 2024 : Debug: Thread 4 waiting to be assigned a request Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.3 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ServerHello Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, EncryptedExtensions Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TREE] - Client TLSv1.3 read encrypted extensions (38) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateRequest Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server certificate request Sun Jul 14 21:12:46 2024 : Debug: (TLS) SSL_connect() returned WANT_READ Sun Jul 14 21:12:46 2024 : Debug: Waking up in 0.2 seconds. Sun Jul 14 21:12:46 2024 : Debug: Proxy SSL socket has data to read Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7) Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 4 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 3 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 3 certificate in chain Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) chain-depth : 2 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) error : 0 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) common name : openroaming.org Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) subject : /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 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) issuer : /C=US/ST=California/L=San Jose/O=Cisco Systems, Inc./OU=Openroaming/CN= openroaming.org/emailAddress=enb-devops@cisco.com Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) verify return : 1 Sun Jul 14 21:12:46 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from 2 certificate in chain
and the rest works.... auth is successful.
When I restore back to 3.2.3 with the exact same config, it works the first time, every time.
I have tested against 4 different proxy home servers and they all have similar behaviour so it must be some local issue. Any thoughts?
Thanks,
James
On Jul 17, 2024, at 8:38 AM, James Wood via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
Any more thoughts on this one? We really want to upgrade to 3.2.5 for obvious reasons but without proxying working we're a little stuck.
We've pushed some patches and it should now be fixed. Alan DeKok.
Please help. I need freeradius-utils to be installed on this server (RHEL 7.9). I have already added networkradius.repo, but the installation failed. --skip-broken and yum install perl-CPAN cpan -i Convert::Base32 Crypt::URandom yum install perl-Convert-Base32 perl-Crypt-URandom perl-DBI can’t work as well. Please help. Thanks. # yum install freeradius-utils Loaded plugins: langpacks, ulninfo networkradius | 3.0 kB 00:00:00 Resolving Dependencies --> Running transaction check ---> Package freeradius-utils.x86_64 0:3.2.5-1.el7 will be installed --> Processing Dependency: perl(Convert::Base32) for package: freeradius-utils-3.2.5-1.el7.x86_64 --> Processing Dependency: perl(Crypt::URandom) for package: freeradius-utils-3.2.5-1.el7.x86_64 --> Processing Dependency: perl(DBI) for package: freeradius-utils-3.2.5-1.el7.x86_64 --> Running transaction check ---> Package freeradius-utils.x86_64 0:3.2.5-1.el7 will be installed --> Processing Dependency: perl(Convert::Base32) for package: freeradius-utils-3.2.5-1.el7.x86_64 --> Processing Dependency: perl(Crypt::URandom) for package: freeradius-utils-3.2.5-1.el7.x86_64 ---> Package perl-DBI.x86_64 0:1.627-4.el7 will be installed --> Finished Dependency Resolution Error: Package: freeradius-utils-3.2.5-1.el7.x86_64 (networkradius) Requires: perl(Crypt::URandom) Error: Package: freeradius-utils-3.2.5-1.el7.x86_64 (networkradius) Requires: perl(Convert::Base32) You could try using --skip-broken to work around the problem You could try running: rpm -Va --nofiles --nodigest # more /etc/redhat-release Red Hat Enterprise Linux Server release 7.9 (Maipo) /etc/yum.repos.d/networkradius.repo [networkradius] name=NetworkRADIUS-$releasever baseurl=http://packages.networkradius.com/freeradius-3.2/centos/$releasever/ enabled=1 gpgcheck=1 gpgkey=https://packages.networkradius.com/pgp/packages%40networkradius.com # yum search freeradius Loaded plugins: langpacks, ulninfo ============================================================ N/S matched: freeradius ============================================================= freeradius-config.x86_64 : FreeRADIUS config files freeradius-debuginfo.x86_64 : Debug information for package freeradius freeradius-devel.i686 : FreeRADIUS development files freeradius-devel.x86_64 : FreeRADIUS development files freeradius-doc.x86_64 : FreeRADIUS documentation freeradius-freetds.x86_64 : FreeTDS support for FreeRADIUS freeradius-krb5.x86_64 : Kerberos 5 support for FreeRADIUS freeradius-ldap.x86_64 : LDAP support for FreeRADIUS freeradius-mysql.x86_64 : MySQL support for FreeRADIUS freeradius-perl.x86_64 : Perl support for FreeRADIUS freeradius-perl-util.x86_64 : FreeRADIUS Perl utilities freeradius-postgresql.x86_64 : PostgreSQL support for FreeRADIUS freeradius-python.x86_64 : Python support for FreeRADIUS freeradius-redis.x86_64 : Redis support for FreeRADIUS freeradius-rest.x86_64 : REST and JSON support for FreeRADIUS freeradius-sqlite.x86_64 : SQLite support for FreeRADIUS freeradius-unbound.x86_64 : Unbound DNS support for FreeRADIUS freeradius-unixODBC.x86_64 : unixODBC support for FreeRADIUS freeradius-utils.x86_64 : FreeRADIUS utilities freeradius-yubikey.x86_64 : YubiCloud support for FreeRADIUS freeradius.x86_64 : High-performance and highly configurable free RADIUS server Name and summary matches only, use "search all" for everything.
Initial tests show this now appears to be working as expected, so I will continue to test various other scenarios and all being well we should be all good. I wanted to express my thanks for jumping on this in a timely manner. It doesn't go unnoticed. Thanks, James On Sat, 20 Jul 2024 at 15:25, Alan DeKok <aland@deployingradius.com> wrote:
On Jul 17, 2024, at 8:38 AM, James Wood via Freeradius-Users < freeradius-users@lists.freeradius.org> wrote:
Any more thoughts on this one? We really want to upgrade to 3.2.5 for obvious reasons but without proxying working we're a little stuck.
We've pushed some patches and it should now be fixed.
Alan DeKok.
participants (3)
-
(null) (null) -
Alan DeKok -
James Wood