Issue with home server proxy after upgrading from 3.2.3 to 3.2.5
James Wood
james.wood at purplewifi.com
Sun Jul 14 21:23:36 UTC 2024
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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
More information about the Freeradius-Users
mailing list