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