Issue with home server proxy after upgrading from 3.2.3 to 3.2.5
James Wood
james.wood at purplewifi.com
Mon Jul 15 08:23:14 UTC 2024
> 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 at 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 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