Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[defect]: 3.2.x assertion failed while proxying request to home server with radsec #5308

Open
olivierbeytrison opened this issue Mar 13, 2024 · 8 comments
Open

[defect]: 3.2.x assertion failed while proxying request to home server with radsec #5308

olivierbeytrison opened this issue Mar 13, 2024 · 8 comments
Labels
defect category: a defect or misbehaviour

Comments

@olivierbeytrison
Copy link
Contributor

What type of defect/bug is this?

Crash or memory corruption (segv, abort, etc...)

How can the issue be reproduced?

This was a working configuration of a test IDP eduroam server to test radsec communication with the FTLR servers.

Pulled and compiled a fresh code this morning (commit cd6534934d1056bac4ad1c01baf99e93fb4d4ed0 (HEAD -> v3.2.x, origin/v3.2.x))

service started with sbin/radiusd -fxx -l stdout

sites-available/eduroam-tls as follow :

######################################################################
# radsec eduroam CH FTLR configuration
######################################################################

listen {
    ipaddr = *
    port = 2083
    type = auth+acct
    proto = tcp
    virtual_server = eduroam
    clients = radsec
    nonblock = yes
    limit {
          max_connections = 16
          lifetime = 0
          idle_timeout = 30
    }

    tls {
        private_key_password = <redacted>
        private_key_file = ${certdir}/eduroam-radsec-dev.key
        certificate_file = ${certdir}/eduroam-radsec-dev.pem
        ca_file = ${cadir}/edupki-ca.pem
        fragment_size = 8192
        ca_path = ${cadir}
        ca_path_reload_interval = 3600
        check_cert_issuer = "/DC=org/DC=edupki/CN=eduPKI CA G 01"
        cipher_list = "DEFAULT"
        cipher_server_preference = no
        tls_min_version = "1.2"
        tls_max_version = "1.3"
        cache {
              enable = yes
              lifetime = 24 # hours
              persist_dir = "${logdir}/tlscache"
        }
        require_client_cert = yes
        verify {
        }

    }
}

clients radsec {

############## Clients for TLD Swtich ###########################   
    client ftlr1.eduroam.ch {
        ipaddr                          = 130.59.31.24
        secret                          = radsec
        require_message_authenticator   = no
        proto                           = tls
        shortname                       = eduroam-ftlr1
        nas_type                        = other
        virtual_server                  = eduroam
        location                        = 'ROAMING'
        local                           = 'N'
        add_attributes                  = no
        add_cui                         = yes
    }

    client ftlr2.eduroam.ch {
        ipaddr                          = 130.59.31.25
        secret                          = radsec
        require_message_authenticator   = no
        proto                           = tls
        shortname                       = eduroam-ftlr2
        nas_type                        = other
        virtual_server                  = eduroam
        location                        = 'ROAMING'
        local                           = 'N'
        add_attributes                  = no
        add_cui                         = yes
    }
}

############## Home servers for TLD Swtich ###########################  

home_server ftlr1.eduroam.ch {
    
    type                    = auth+acct
    ipaddr                  = 130.59.31.24
    port                    = 2083
    proto                   = tcp
    secret                  = radsec
    require_message_authenticator = yes
    nonblock                = yes
    response_window         = 20
    zombie_period           = 40
    revive_interval         = 60
    status_check            = status-server
    check_interval          = 30
    num_answers_to_alive    = 3
    max_outstanding         = 65536
    tls {
        private_key_password = <redacted>
        private_key_file = ${certdir}/eduroam-radsec-dev.key
        certificate_file = ${certdir}/eduroam-radsec-dev.pem
        ca_file = ${cadir}/edupki-ca.pem
        fragment_size = 8192
        cipher_list = "DEFAULT"
        connect_timeout = 30
    }
}

home_server ftlr2.eduroam.ch {
    
    type                    = auth+acct
    ipaddr                  = 130.59.31.25
    port                    = 2083
    proto                   = tcp
    secret                  = radsec
    require_message_authenticator = yes
    nonblock                = yes
    response_window         = 20
    zombie_period           = 40
    revive_interval         = 60
    status_check            = status-server
    check_interval          = 30
    num_answers_to_alive    = 3
    max_outstanding         = 65536
    
    tls {
        private_key_password = <redacted>
        private_key_file = ${certdir}/eduroam-radsec-dev.key
        certificate_file = ${certdir}/eduroam-radsec-dev.pem
        ca_file = ${cadir}/edupki-ca.pem
        fragment_size = 8192
        cipher_list = "DEFAULT"
        connect_timeout = 30
    }
}

############## Home servers pool for TLD Swtich ########################### 

home_server_pool EDUROAM-FTLR {
    Type            = fail-over
    home_server     = ftlr1.eduroam.ch
    home_server     = ftlr2.eduroam.ch
}

Log output from the FreeRADIUS daemon

Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server eduroam
Listening on auth address * port 1812 bound to server eduroam
Listening on acct address * port 1813 bound to server eduroam
Ready to process requests
 ... new connection request on TCP socket
Listening on auth+acct from client (130.59.31.25, 38035) -> (*, 2083, virtual-server=eduroam)
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS -Initiating new session
(0) (TLS) RADIUS/TLS - Setting verify mode to require certificate from client
(0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write change cipher spec
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data
(0) (TLS) RADIUS/TLS - In Handshake Phase
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, EncryptedExtensions
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write encrypted extensions
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateRequest
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write server certificate verify
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data
(0) (TLS) RADIUS/TLS - In Handshake Phase
Waking up in 0.8 seconds.
 ... new connection request on TCP socket
Listening on auth+acct from client (130.59.31.24, 38419) -> (*, 2083, virtual-server=eduroam)
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS -Initiating new session
(0) (TLS) RADIUS/TLS - Setting verify mode to require certificate from client
(0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write change cipher spec
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data
(0) (TLS) RADIUS/TLS - In Handshake Phase
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Creating attributes from server certificate
(0)   TLS-Cert-Serial := "01"
(0)   TLS-Cert-Expiration := "301103101536Z"
(0)   TLS-Cert-Valid-Since := "101108101536Z"
(0)   TLS-Cert-Subject := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Common-Name := "eduPKI CA G 01"
(0) (TLS) RADIUS/TLS - Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "231a75d9aee192074cfae6bc"
(0)   TLS-Client-Cert-Expiration := "250629083106Z"
(0)   TLS-Client-Cert-Valid-Since := "200630083106Z"
(0)   TLS-Client-Cert-Subject := "/DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr2.eduroam.ch"
(0)   TLS-Client-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Client-Cert-Common-Name := "ftlr2.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ftlr2.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "maat.switch.ch"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication, TLS Web Server Authentication"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "16:ED:C8:62:35:FC:66:C6:B3:9A:74:D4:EF:6C:FF:40:C6:99:0C:3A"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "D2:F2:23:BD:4A:A1:7F:CF:A0:58:84:EB:FC:E6:5B:08:B3:CD:B4:E4"
(0)   TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.27262.1.13.1.1\nPolicy: 1.3.6.1.4.1.27262.1.13.1.1.1.4\nPolicy: 1.3.6.1.4.1.25178.3.1.1\nPolicy: 1.3.6.1.4.1.25178.3.1.2\nPolicy: 1.3.6.1.4.1.27262.1.13.2.1.1.8"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.2"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Certificate chain - 1 intermediate CA cert(s) untrusted
To forbid these certificates see 'reject_unknown_intermediate_ca'
(TLS) untrusted certificate with depth [1] subject name /DC=org/DC=edupki/CN=eduPKI CA G 01
(TLS) untrusted certificate with depth [0] subject name /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr2.eduroam.ch
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client certificate
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read certificate verify
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read finished
(0) (TLS) RADIUS/TLS - Handshake state - SSLv3/TLS write session ticket
(0) Serialising session 8a336d959bcfe32b1c472416c87ca6aec1c988c6c059f6455304ed537c447c2a, and storing in cache
(0) WARNING: (TLS) RADIUS/TLS - Wrote session 8a336d959bcfe32b1c472416c87ca6aec1c988c6c059f6455304ed537c447c2a to /srv/freeradius/var/log/radius/tlscache/8a336d959bcfe32b1c472416c87ca6aec1c988c6c059f6455304ed537c447c2a.asn1 (1477 bytes)
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, NewSessionTicket
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write session ticket
(0) (TLS) RADIUS/TLS - Connection Established
(0)   TLS-Session-Cipher-Suite = "TLS_AES_256_GCM_SHA384"
(0)   TLS-Session-Version = "TLS 1.3"
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, EncryptedExtensions
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write encrypted extensions
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateRequest
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write server certificate verify
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data
(0) (TLS) RADIUS/TLS - In Handshake Phase
Waking up in 0.8 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Creating attributes from server certificate
(0)   TLS-Cert-Serial := "01"
(0)   TLS-Cert-Expiration := "301103101536Z"
(0)   TLS-Cert-Valid-Since := "101108101536Z"
(0)   TLS-Cert-Subject := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Common-Name := "eduPKI CA G 01"
(0) (TLS) RADIUS/TLS - Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "231a75d9361f9ea038f29422"
(0)   TLS-Client-Cert-Expiration := "250629083105Z"
(0)   TLS-Client-Cert-Valid-Since := "200630083105Z"
(0)   TLS-Client-Cert-Subject := "/DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Client-Cert-Common-Name := "ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ozza.switch.ch"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication, TLS Web Server Authentication"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "CE:A9:9C:51:B2:A5:FB:7E:5D:1D:9F:B4:FB:0F:A1:33:13:7A:D0:BA"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "D2:F2:23:BD:4A:A1:7F:CF:A0:58:84:EB:FC:E6:5B:08:B3:CD:B4:E4"
(0)   TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.27262.1.13.1.1\nPolicy: 1.3.6.1.4.1.27262.1.13.1.1.1.4\nPolicy: 1.3.6.1.4.1.25178.3.1.1\nPolicy: 1.3.6.1.4.1.25178.3.1.2\nPolicy: 1.3.6.1.4.1.27262.1.13.2.1.1.8"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.2"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Certificate chain - 1 intermediate CA cert(s) untrusted
To forbid these certificates see 'reject_unknown_intermediate_ca'
(TLS) untrusted certificate with depth [1] subject name /DC=org/DC=edupki/CN=eduPKI CA G 01
(TLS) untrusted certificate with depth [0] subject name /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client certificate
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read certificate verify
(0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read finished
(0) (TLS) RADIUS/TLS - Handshake state - SSLv3/TLS write session ticket
(0) Serialising session fc49a18ec6026fee0037485db308f19b5e1008261301d240d3054870cf01cbac, and storing in cache
(0) WARNING: (TLS) RADIUS/TLS - Wrote session fc49a18ec6026fee0037485db308f19b5e1008261301d240d3054870cf01cbac to /srv/freeradius/var/log/radius/tlscache/fc49a18ec6026fee0037485db308f19b5e1008261301d240d3054870cf01cbac.asn1 (1477 bytes)
(0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, NewSessionTicket
(0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write session ticket
(0) (TLS) RADIUS/TLS - Connection Established
(0)   TLS-Session-Cipher-Suite = "TLS_AES_256_GCM_SHA384"
(0)   TLS-Session-Version = "TLS 1.3"
Waking up in 0.8 seconds.
Waking up in 29.4 seconds.
Threads: total/active/spare threads = 5/0/5
Waking up in 0.3 seconds.
Thread 4 got semaphore
Thread 4 handling request 0, (1 handled so far)
(0) Received Access-Request Id 0 from 127.0.0.1:50572 to 127.0.0.1:1812 length 154
(0)   User-Name = "hefr@test.eduroam.ch"
(0)   NAS-IP-Address = 127.0.0.1
(0)   Calling-Station-Id = "02-00-00-00-00-01"
(0)   Framed-MTU = 1400
(0)   NAS-Port-Type = Wireless-802.11
(0)   Service-Type = Framed-User
(0)   Connect-Info = "CONNECT 11Mbps 802.11b"
(0)   EAP-Message = 0x02af0019016865667240746573742e656475726f616d2e6368
(0)   Message-Authenticator = 0xe8b3f49071a55001faa6de24a424d4d0
(0) # Executing section authorize from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
(0)   authorize {
(0)     [preprocess] = ok
(0) auth_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
(0) auth_log:    --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
(0) auth_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
(0) auth_log: EXPAND %t
(0) auth_log:    --> Wed Mar 13 14:36:29 2024
(0)     [auth_log] = ok
(0)     if ("%{client:location}" == 'ROAMING') {
(0)     EXPAND %{client:location}
(0)        --> RORG-HEFR
(0)     if ("%{client:location}" == 'ROAMING')  -> FALSE
(0)     policy operator-name.authorize {
(0)       if ("%{client:Operator-Name}") {
(0)       EXPAND %{client:Operator-Name}
(0)          --> 1hes-so.ch
(0)       if ("%{client:Operator-Name}")  -> TRUE
(0)       if ("%{client:Operator-Name}")  {
(0)         update request {
(0)           EXPAND %{client:Operator-Name}
(0)              --> 1hes-so.ch
(0)           &Operator-Name = 1hes-so.ch
(0)         } # update request = noop
(0)       } # if ("%{client:Operator-Name}")  = noop
(0)     } # policy operator-name.authorize = noop
(0)     policy cui.authorize {
(0)       if ("%{client:add_cui}" == 'yes') {
(0)       EXPAND %{client:add_cui}
(0)          --> yes
(0)       if ("%{client:add_cui}" == 'yes')  -> TRUE
(0)       if ("%{client:add_cui}" == 'yes')  {
(0)         update request {
(0)           &Chargeable-User-Identity := 0x00
(0)         } # update request = noop
(0)       } # if ("%{client:add_cui}" == 'yes')  = noop
(0)     } # policy cui.authorize = noop
(0)     policy parse_realm {
(0)       policy split_username_nai {
(0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) {
(0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  -> TRUE
(0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  {
(0)           update request {
(0)             EXPAND %{1}
(0)                --> hefr
(0)             &Stripped-User-Name := hefr
(0)           } # update request = noop
(0)           if ("%{3}" != '') {
(0)           EXPAND %{3}
(0)              --> test.eduroam.ch
(0)           if ("%{3}" != '')  -> TRUE
(0)           if ("%{3}" != '')  {
(0)             update request {
(0)               EXPAND %{3}
(0)                  --> test.eduroam.ch
(0)               &Stripped-User-Domain = test.eduroam.ch
(0)             } # update request = noop
(0)           } # if ("%{3}" != '')  = noop
(0)           [updated] = updated
(0)         } # if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  = updated
(0)         ... skipping else: Preceding "if" was taken
(0)       } # policy split_username_nai = updated
(0)       if (&Stripped-User-Domain) {
(0)       if (&Stripped-User-Domain)  -> TRUE
(0)       if (&Stripped-User-Domain)  {
(0)         if ((&Stripped-User-Domain == 'test.hes-so.ch') || 		   (&Stripped-User-Domain == 'hes-so.ch') || 		   (&Stripped-User-Domain == 'hefr.ch')) {
(0)         if ((&Stripped-User-Domain == 'test.hes-so.ch') || 		   (&Stripped-User-Domain == 'hes-so.ch') || 		   (&Stripped-User-Domain == 'hefr.ch'))  -> FALSE
(0)         elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/) {
(0)         elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/)  -> FALSE
(0)         else {
(0)           update {
(0)             request:Realm := 'EDUROAM'
(0)             control:Proxy-To-Realm := 'EDUROAM'
(0)           } # update = noop
(0)         } # else = noop
(0)       } # if (&Stripped-User-Domain)  = noop
(0)       ... skipping else: Preceding "if" was taken
(0)     } # policy parse_realm = updated
(0)     policy set_location {
(0)       if (!&request:HESSO-Location && "%{client:location}") {
(0)       EXPAND %{client:location}
(0)          --> RORG-HEFR
(0)       if (!&request:HESSO-Location && "%{client:location}")  -> TRUE
(0)       if (!&request:HESSO-Location && "%{client:location}")  {
(0)         update request {
(0)           EXPAND %{client:location}
(0)              --> RORG-HEFR
(0)           HESSO-Location := RORG-HEFR
(0)         } # update request = noop
(0)       } # if (!&request:HESSO-Location && "%{client:location}")  = noop
(0)     } # policy set_location = noop
(0)     if (&Stripped-User-Domain == 'hefr.ch') {
(0)     if (&Stripped-User-Domain == 'hefr.ch')  -> FALSE
(0)     else {
(0) eap: Request is supposed to be proxied to Realm EDUROAM. Not doing EAP.
(0)       [eap] = noop
(0)     } # else = noop
(0)   } # authorize = updated
(0) Starting proxy to home server 130.59.31.24 port 2083
(0) server eduroam {
(0)   # Executing section pre-proxy from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
(0)     pre-proxy {
(0) pre_proxy_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
(0) pre_proxy_log:    --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
(0) pre_proxy_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
(0) pre_proxy_log: EXPAND %t
(0) pre_proxy_log:    --> Wed Mar 13 14:36:29 2024
(0)       [pre_proxy_log] = ok
(0)       policy operator-name.pre-proxy {
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") {
(0)         EXPAND %{request:Packet-Type}
(0)            --> Access-Request
(0)         EXPAND %{client:Operator-Name}
(0)            --> 1hes-so.ch
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  -> TRUE
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  {
(0)           update proxy-request {
(0)             EXPAND %{client:Operator-Name}
(0)                --> 1hes-so.ch
(0)             &Operator-Name := 1hes-so.ch
(0)           } # update proxy-request = noop
(0)         } # if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  = noop
(0)       } # policy operator-name.pre-proxy = noop
(0)       policy cui.pre-proxy {
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) {
(0)         EXPAND %{request:Packet-Type}
(0)            --> Access-Request
(0)         EXPAND %{client:add_cui}
(0)            --> yes
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  -> TRUE
(0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  {
(0)           update proxy-request {
(0)             &Chargeable-User-Identity = 0x00
(0)           } # update proxy-request = noop
(0)         } # if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  = noop
(0)       } # policy cui.pre-proxy = noop
(0) attr_filter.pre-proxy: EXPAND %{Realm}
(0) attr_filter.pre-proxy:    --> EDUROAM
(0)       [attr_filter.pre-proxy] = noop
(0)     } # pre-proxy = ok
(0) }
(TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (130.59.31.24, 2083)
Requiring Server certificate
(0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization
(0) (TLS) RADIUS/TLS - Handshake state - Client before SSL initialization
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
(0) ERROR: (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
(0) Proxying request to home server 130.59.31.24 port 2083 (TLS) timeout 20.000000
(0) Sent Access-Request Id 158 from 160.98.240.25:54379 to 130.59.31.24:2083 length 195
(0)   User-Name = "hefr@test.eduroam.ch"
(0)   NAS-IP-Address = 127.0.0.1
(0)   Calling-Station-Id = "02-00-00-00-00-01"
(0)   Framed-MTU = 1400
(0)   NAS-Port-Type = Wireless-802.11
(0)   Service-Type = Framed-User
(0)   Connect-Info = "CONNECT 11Mbps 802.11b"
(0)   EAP-Message = 0x02af0019016865667240746573742e656475726f616d2e6368
(0)   Message-Authenticator = 0xe8b3f49071a55001faa6de24a424d4d0
(0)   Event-Timestamp = "Mar 13 2024 14:36:29 CET"
(0)   Operator-Name := "1hes-so.ch"
(0)   Chargeable-User-Identity := 0x00
(0)   HESSO-Location := "RORG-HEFR"
(0)   Proxy-State = 0x30
(0) ERROR: (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Thread 4 waiting to be assigned a request
Listening on proxy (160.98.240.25, 54379) -> home_server (130.59.31.24, 2083)
Waking up in 0.3 seconds.
(0) Expecting proxy response no later than 19.668105 seconds from now
Waking up in 19.6 seconds.
Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 158
Waking up in 17.0 seconds.
Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 158
Waking up in 10.9 seconds.
(0) No proxy response, giving up on request and marking it done
Marking home server 130.59.31.24 port 2083 as zombie (it has not responded in 20.000000 seconds).
PING: Waiting 4 seconds for response to ping
(1) Sent Status-Server Id 191 from 160.98.240.25:54379 to 130.59.31.24:2083 length 70
(1)   Message-Authenticator := 0x00
(1)   NAS-Identifier := "Status Check 0. Are you alive?"
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
PING: Next status packet in 30 seconds
(0) ERROR: Failing proxied request for user "hefr", due to lack of any response from home server 130.59.31.24 port 2083
Waking up in 0.3 seconds.
Thread 5 got semaphore
Thread 5 handling request 0, (1 handled so far)
(0) Clearing existing &reply: attributes
(0) Found Post-Proxy-Type Fail-Authentication
(0) server eduroam {
(0)   Post-Proxy-Type sub-section not found.  Ignoring.
(0)   # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
(0) }
(0) Login incorrect (Home Server failed to respond): [hefr@test.eduroam.ch] (from client loopback port 0 cli 02-00-00-00-00-01)
(0) There was no response configured: rejecting request
(0) Using Post-Auth-Type Reject
(0) # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
(0)   Post-Auth-Type REJECT {
(0)     if ("%{Packet-Type}" == 'Status-Server'){
(0)     EXPAND %{Packet-Type}
(0)        --> Access-Request
(0)     if ("%{Packet-Type}" == 'Status-Server') -> FALSE
(0)   } # Post-Auth-Type REJECT = noop
(0) Sent Access-Reject Id 0 from 127.0.0.1:1812 to 127.0.0.1:50572 length 20
(0) Finished request
Thread 5 waiting to be assigned a request
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client hello
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHello
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server hello
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Creating attributes from server certificate
(0)   TLS-Cert-Serial := "01"
(0)   TLS-Cert-Expiration := "301103101536Z"
(0)   TLS-Cert-Valid-Since := "101108101536Z"
(0)   TLS-Cert-Subject := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Cert-Common-Name := "eduPKI CA G 01"
(0) (TLS) RADIUS/TLS - Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "231a75d9361f9ea038f29422"
(0)   TLS-Client-Cert-Expiration := "250629083105Z"
(0)   TLS-Client-Cert-Valid-Since := "200630083105Z"
(0)   TLS-Client-Cert-Subject := "/DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
(0)   TLS-Client-Cert-Common-Name := "ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ftlr1.eduroam.ch"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ozza.switch.ch"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication, TLS Web Server Authentication"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "CE:A9:9C:51:B2:A5:FB:7E:5D:1D:9F:B4:FB:0F:A1:33:13:7A:D0:BA"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "D2:F2:23:BD:4A:A1:7F:CF:A0:58:84:EB:FC:E6:5B:08:B3:CD:B4:E4"
(0)   TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.27262.1.13.1.1\nPolicy: 1.3.6.1.4.1.27262.1.13.1.1.1.4\nPolicy: 1.3.6.1.4.1.25178.3.1.1\nPolicy: 1.3.6.1.4.1.25178.3.1.2\nPolicy: 1.3.6.1.4.1.27262.1.13.2.1.1.8"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.2"
(0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Certificate chain - 1 intermediate CA cert(s) untrusted
To forbid these certificates see 'reject_unknown_intermediate_ca'
(TLS) untrusted certificate with depth [1] subject name /DC=org/DC=edupki/CN=eduPKI CA G 01
(TLS) untrusted certificate with depth [0] subject name /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server certificate
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server key exchange
Waking up in 0.3 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server key exchange
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, CertificateRequest
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server certificate request
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read server done
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Certificate
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client certificate
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientKeyExchange
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write client key exchange
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, CertificateVerify
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write certificate verify
(0) (TLS) RADIUS/TLS - send TLS 1.2 ChangeCipherSpec
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write change cipher spec
(0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Waking up in 0.3 seconds.
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS write finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read change cipher spec
(0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Finished
(0) (TLS) RADIUS/TLS - Handshake state - Client SSLv3/TLS read finished
(0) (TLS) RADIUS/TLS - Handshake state - SSL negotiation finished successfully
Waking up in 0.3 seconds.
(1) Marking home server 130.59.31.24 port 2083 alive
(1) Received response to status check 1 ID 191 (1 in current sequence)
ASSERT FAILED src/main/process.c[3892]: !request->in_proxy_hash
CAUGHT SIGNAL: Aborted
Backtrace of last 12 frames:
/srv/freeradius/lib/libfreeradius-radius.so(fr_fault+0x139)[0x7efedf35c3f8]
/srv/freeradius/lib/libfreeradius-server.so(rad_assert_fail+0x4d)[0x7efedf3c83f0]
sbin/radiusd(+0x544aa)[0x555f00f984aa]
sbin/radiusd(request_proxy_reply+0x71c)[0x555f00f96122]
sbin/radiusd(proxy_tls_recv+0x3b6)[0x555f00fb9320]
sbin/radiusd(+0x58761)[0x555f00f9c761]
/srv/freeradius/lib/libfreeradius-radius.so(fr_event_loop+0x60d)[0x7efedf388313]
sbin/radiusd(radius_event_process+0x2a)[0x555f00f9ea1c]
sbin/radiusd(main+0xd18)[0x555f00f84f14]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7efedec16d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7efedec16e40]
sbin/radiusd(_start+0x25)[0x555f00f5bda5]
Calling: gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3770720 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3770720.log
Temporarily setting PR_DUMPABLE to 1
Resetting PR_DUMPABLE to 0
Panic action exited with 0
_EXIT(0) CALLED src/lib/debug.c[811]

Relevant log output from client utilities

simple eapol_test from local server

Backtrace from LLDB or GDB

Reading symbols from sbin/radiusd...
Attaching to program: /srv/freeradius/sbin/radiusd, process 3770720
[New LWP 3770722]
[New LWP 3770723]
[New LWP 3770724]
[New LWP 3770725]
[New LWP 3770726]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007efedecd742f in __GI___wait4 (pid=3771275, stat_loc=stat_loc@entry=0x7ffd4a64deb8, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
30      ../sysdeps/unix/sysv/linux/wait4.c: No such file or directory.
sc_ret = -512
sc_cancel_oldtype = 0
sc_ret = <optimized out>
pid = 3771275
stat_loc = 0x7ffd4a64deb8
options = 0
usage = 0x0

Thread 6 (Thread 0x7efed9cfb640 (LWP 3770726) "radiusd"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:57
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        resultvar = <optimized out>
        __arg6 = <optimized out>
        __arg5 = <optimized out>
        __arg4 = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a6 = <optimized out>
        _a5 = <optimized out>
        _a4 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
#1  __futex_abstimed_wait_common (cancel=true, private=<optimized out>, abstime=0x0, clockid=0, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:87
        err = <optimized out>
        clockbit = 256
        op = 393
        err = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x555f00fe7688 <thread_pool+168>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007efedec89bdf in do_futex_wait (sem=sem@entry=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007efedec89c78 in __new_sem_wait_slow64 (sem=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7efedec89bb0 <__sem_wait_cleanup>, __arg = 0x555f00fe7688 <thread_pool+168>, __canceltype = -640700848, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x0000555f00f8e326 in request_handler_thread (arg=0x555f02fbbf10) at src/main/threads.c:741
        self = 0x555f02fbbf10
#6  0x00007efedec81ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140725851581440, 228770415193222977, 139633041061440, 0, 139633124448208, 140725851581792, -85160592881094847, -85149568291311807}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#7  0x00007efeded13850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 5 (Thread 0x7efeda4fc640 (LWP 3770725) "radiusd"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:57
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        resultvar = <optimized out>
        __arg6 = <optimized out>
        __arg5 = <optimized out>
        __arg4 = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a6 = <optimized out>
        _a5 = <optimized out>
        _a4 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
#1  __futex_abstimed_wait_common (cancel=true, private=<optimized out>, abstime=0x0, clockid=0, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:87
        err = <optimized out>
        clockbit = 256
        op = 393
        err = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x555f00fe7688 <thread_pool+168>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007efedec89bdf in do_futex_wait (sem=sem@entry=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007efedec89c78 in __new_sem_wait_slow64 (sem=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7efedec89bb0 <__sem_wait_cleanup>, __arg = 0x555f00fe7688 <thread_pool+168>, __canceltype = -632308144, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x0000555f00f8e326 in request_handler_thread (arg=0x555f02fbbd80) at src/main/threads.c:741
        self = 0x555f02fbbd80
#6  0x00007efedec81ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140725851581440, 228770415193222977, 139633049454144, 0, 139633124448208, 140725851581792, -85157293809340607, -85149568291311807}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#7  0x00007efeded13850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 4 (Thread 0x7efedacfd640 (LWP 3770724) "radiusd"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:57
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        resultvar = <optimized out>
        __arg6 = <optimized out>
        __arg5 = <optimized out>
        __arg4 = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a6 = <optimized out>
        _a5 = <optimized out>
        _a4 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
#1  __futex_abstimed_wait_common (cancel=true, private=<optimized out>, abstime=0x0, clockid=0, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:87
        err = <optimized out>
        clockbit = 256
        op = 393
        err = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x555f00fe7688 <thread_pool+168>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007efedec89bdf in do_futex_wait (sem=sem@entry=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007efedec89c78 in __new_sem_wait_slow64 (sem=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7efedec89bb0 <__sem_wait_cleanup>, __arg = 0x555f00fe7688 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 8589934592
#5  0x0000555f00f8e326 in request_handler_thread (arg=0x555f02f63b60) at src/main/threads.c:741
        self = 0x555f02f63b60
#6  0x00007efedec81ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140725851581440, 228770415193222977, 139633057846848, 0, 139633124448208, 140725851581792, -85158392784097471, -85149568291311807}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#7  0x00007efeded13850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 3 (Thread 0x7efedb4fe640 (LWP 3770723) "radiusd"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:57
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        resultvar = <optimized out>
        __arg6 = <optimized out>
        __arg5 = <optimized out>
        __arg4 = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a6 = <optimized out>
        _a5 = <optimized out>
        _a4 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
#1  __futex_abstimed_wait_common (cancel=true, private=<optimized out>, abstime=0x0, clockid=0, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:87
        err = <optimized out>
        clockbit = 256
        op = 393
        err = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x555f00fe7688 <thread_pool+168>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007efedec89bdf in do_futex_wait (sem=sem@entry=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007efedec89c78 in __new_sem_wait_slow64 (sem=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7efedec89bb0 <__sem_wait_cleanup>, __arg = 0x555f00fe7688 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 4294967296
#5  0x0000555f00f8e326 in request_handler_thread (arg=0x555f02f63110) at src/main/threads.c:741
        self = 0x555f02f63110
#6  0x00007efedec81ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140725851581440, 228770415193222977, 139633066239552, 0, 139633124448208, 140725851581792, -85155093712343231, -85149568291311807}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#7  0x00007efeded13850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 2 (Thread 0x7efedbcff640 (LWP 3770722) "radiusd"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:57
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
        resultvar = <optimized out>
        __arg6 = <optimized out>
        __arg5 = <optimized out>
        __arg4 = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a6 = <optimized out>
        _a5 = <optimized out>
        _a4 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
#1  __futex_abstimed_wait_common (cancel=true, private=<optimized out>, abstime=0x0, clockid=0, expected=0, futex_word=0x555f00fe7688 <thread_pool+168>) at ./nptl/futex-internal.c:87
        err = <optimized out>
        clockbit = 256
        op = 393
        err = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x555f00fe7688 <thread_pool+168>, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007efedec89bdf in do_futex_wait (sem=sem@entry=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007efedec89c78 in __new_sem_wait_slow64 (sem=0x555f00fe7688 <thread_pool+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7efedec89bb0 <__sem_wait_cleanup>, __arg = 0x555f00fe7688 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 0
#5  0x0000555f00f8e326 in request_handler_thread (arg=0x555f02f67c20) at src/main/threads.c:741
        self = 0x555f02f67c20
#6  0x00007efedec81ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140725851581440, 228770415193222977, 139633074632256, 0, 139633124448208, 140725851581792, -85156192687100095, -85149568291311807}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#7  0x00007efeded13850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 1 (Thread 0x7efedebea740 (LWP 3770720) "radiusd"):
#0  0x00007efedecd742f in __GI___wait4 (pid=3771275, stat_loc=stat_loc@entry=0x7ffd4a64deb8, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
        sc_ret = -512
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
#1  0x00007efedecd73ab in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffd4a64deb8, options=options@entry=0) at ./posix/waitpid.c:38
No locals.
#2  0x00007efedec3dbdb in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:171
        __result = <optimized out>
        _cleanup_start_doit = true
        _buffer = {__routine = 0x7efedec3dc60 <cancel_handler>, __arg = 0x7ffd4a64dec0, __canceltype = 0, __prev = 0x0}
        _cleanup_routine = 0x7efedec3dc60 <cancel_handler>
        cancel_args = {quit = 0x7efedee097a0 <quit>, intr = 0x7efedee09840 <intr>, pid = 3771275}
        status = -1
        ret = 0
        pid = 3771275
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0, 0, 1207876242631144978, 11325978573957524813, 9141651871902349159, 8030812534177542412, 0, 0, 0, 0, 0, 0, 0, 0, 0}}, sa_flags = 0, sa_restorer = 0x0}
        omask = {__val = {0, 0, 0, 0, 8319671766489378663, 7233188015783569199, 3978705065856955753, 7453294853954352944, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307}}
        reset = {__val = {6, 0, 0, 0, 7234802330899472752, 8227916443131519074, 3684054942242923617, 3611939893383542583, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667}}
        spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 0, 0, 0, 7234802330899472752, 8227916443131519074, 3684054942242923617, 3611939893383542583, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667}}, __ss = {__val = {0, 0, 0, 0, 8319671766489378663, 7233188015783569199, 3978705065856955753, 7453294853954352944, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
#3  0x00007efedf35c61e in fr_fault (sig=6) at src/lib/debug.c:793
        disable = true
        cmd = "gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3770720 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3770720.log", '\000' <repeats 394 times>
        out = 0x7ffd4a64e735 ".log"
        left = 399
        ret = 62
        p = 0x7efedf39e41b <panic_action+123> ".log"
        q = 0x0
        code = 32510
#4  0x00007efedf3c83f0 in rad_assert_fail (file=0x555f00fcd002 "src/main/process.c", line=3892, expr=0x555f00fcd11b "!request->in_proxy_hash") at src/main/util.c:557
No locals.
#5  0x0000555f00f984aa in request_ping (request=0x555f03002940, action=5) at src/main/process.c:3892
        home = 0x555f02cc7900
        buffer = "130.59.31.24\000U\000\000\340\362\377\002_U\000\000 3\000\003_U\000\000\000\000\000\000 ", '\000' <repeats 19 times>, "\204\206\000\003_U\000\000`\352dJ\375\177\000\000:%\f\337\376~\000\000Nv \000\000\000\000\000,\000\000\000\000\000\000\000p\000\000\000k\000\000\000\240\246\276\336\376~\000\000\001\000\000\000\000\000\000\000\371\177\345\336\376~\000"
        __FUNCTION__ = "request_ping"
#6  0x0000555f00f96122 in request_proxy_reply (packet=0x555f03003320) at src/main/process.c:2954
        proxy_p = 0x555f030029a8
        request = 0x555f03002940
        now = {tv_sec = 1710337009, tv_usec = 835830}
        buffer = "`\352dJ\375\177\000\000S$9\337\376~\000\000\300\352dJ\375\177\000\000\230", '\000' <repeats 15 times>, " 3\000\003_U\000\000\024\000\000\000\000\000\000\000\200m\345\336\376~\000\000\300\062\000\003_U\000\000\000\303Ljf\004\274\351\300\352dJ\375\177\000\000\060\212\375\000_U\000\000 \354dJ\375\177\000\000\210\360dJ\375\177\000\000\374A\370\000_U\000\000x\373\375\000_U\000"
#7  0x0000555f00fb9320 in proxy_tls_recv (listener=0x7efed400c1f0) at src/main/tls_listen.c:1351
        sock = 0x7efed4002190
        buffer = "0\353dJ\375\177\000\000\001\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000\200`P\335\376~\000\000\000aP\335\376~\000\000\000aP\335\376~\000\000\001", '\000' <repeats 15 times>, "\200`P\335\376~\000\000\000aP\335\376~\000\000\320\353dJ\375\177\000\000\000\303Ljf\004\274\351\260\353dJ\375\177\000\000\226\337\370\000_U\000\000\260\353dJ\375\177\000\000\340\346\376\002_U\000\000\260\353dJ\375\177\000\000\032\000\371\000_U\000\000\000\000\000\000\000\000\000\000\254v\376\000_U\000\000\260v\376\000_U\000\000\000\303Ljf\004\274\351\000\354dJ\375\177\000\000X\035\371\000_U\000\000Dc\371\000_U\000\000"...
        packet = 0x555f03003320
        data = 0x555f0300c950 "\002\277"
        data_len = 20
#8  0x0000555f00f9c761 in event_socket_handler (xel=0x555f02eac610, fd=23, ctx=0x7efed400c1f0) at src/main/process.c:5303
        listener = 0x7efed400c1f0
#9  0x00007efedf388313 in fr_event_loop (el=0x555f02eac610) at src/lib/event.c:710
        ef = 0x555f02eac808
        i = 6
        rcode = 1
        when = {tv_sec = 1710337010, tv_usec = 145059}
        wake = 0x7ffd4a64edb0
        read_fds = {fds_bits = {8388608, 0 <repeats 15 times>}}
        write_fds = {fds_bits = {0 <repeats 16 times>}}
#10 0x0000555f00f9ea1c in radius_event_process () at src/main/process.c:6487
No locals.
#11 0x0000555f00f84f14 in main (argc=4, argv=0x7ffd4a64f088) at src/main/radiusd.c:641
        rcode = 0
        status = 0
        argval = -1
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        p = 0x7ffd4a64f7de "/radiusd"
        state = 0x555f00fe6f60 <global_state>
        autofree = 0x555f02aae300
A debugging session is active.

        Inferior 1 [process 3770720] will be detached.

Quit anyway? (y or n) [answered Y; input not from terminal]
[Inferior 1 (process 3770720) detached]
@olivierbeytrison olivierbeytrison added the defect category: a defect or misbehaviour label Mar 13, 2024
alandekok added a commit that referenced this issue Mar 13, 2024
@alandekok
better handle all actions. Fixes #5308
66e6389
@alandekok
Copy link
Member

I've pushed a fix. Please verify.

@olivierbeytrison
Copy link
Contributor Author

no luck unfortunately, still the same behaviour. Crash on status-request after the previously failed proxied request.

radiusd: FreeRADIUS Version 3.2.4 (git #66e638978), for host x86_64-pc-linux-gnu, built on Mar 13 2024 at 15:49:23
FreeRADIUS Version 3.2.4
Copyright (C) 1999-2023 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT

Thread 1 (Thread 0x7feb69d75740 (LWP 3841245) "radiusd"):
#0  0x00007feb69e6242f in __GI___wait4 (pid=3841705, stat_loc=stat_loc@entry=0x7ffc075de628, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:30
        sc_ret = -512
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
#1  0x00007feb69e623ab in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffc075de628, options=options@entry=0) at ./posix/waitpid.c:38
No locals.
#2  0x00007feb69dc8bdb in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:171
        __result = <optimized out>
        _cleanup_start_doit = true
        _buffer = {__routine = 0x7feb69dc8c60 <cancel_handler>, __arg = 0x7ffc075de630, __canceltype = 0, __prev = 0x0}
        _cleanup_routine = 0x7feb69dc8c60 <cancel_handler>
        cancel_args = {quit = 0x7feb69f947a0 <quit>, intr = 0x7feb69f94840 <intr>, pid = 3841705}
        status = -1
        ret = 0
        pid = 3841705
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x0}
        omask = {__val = {0, 7453294854038368817, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307, 0, 0, 0, 0, 7234802330899472752, 8227916443131519074}}
        reset = {__val = {6, 3611945399447794744, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667, 0, 0, 0, 0, 3900939194679983122, 3464635662526412429}}
        spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 3611945399447794744, 0, 0, 0, 0, 8299888338792379502, 8243106234986624626, 8387162053985002593, 3414401849794637667, 0, 0, 0, 0, 3900939194679983122, 3464635662526412429}}, __ss = {__val = {0, 7453294854038368817, 0, 0, 0, 0, 7310503812617283134, 7363234149704867941, 8460403744686040434, 8028844404002664307, 0, 0, 0, 0, 7234802330899472752, 8227916443131519074}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
#3  0x00007feb6a4e761e in fr_fault (sig=6) at src/lib/debug.c:793
        disable = true
        cmd = "gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3841245 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3841245.log", '\000' <repeats 394 times>
        out = 0x7ffc075deea5 ".log"
        left = 399
        ret = 62
        p = 0x7feb6a52941b <panic_action+123> ".log"
        q = 0x0
        code = 0
#4  0x00007feb6a5533f0 in rad_assert_fail (file=0x55b04a978002 "src/main/process.c", line=3894, expr=0x55b04a97811b "!request->in_proxy_hash") at src/main/util.c:557
No locals.
#5  0x000055b04a9434c8 in request_ping (request=0x55b04c17e260, action=5) at src/main/process.c:3894
        home = 0x55b04be48700
        buffer = "130.59.31.24\000U\000\000\000l\025L\260U\000\000\240:\030L\260U\000\000\000\000\000\000 ", '\000' <repeats 19 times>, "t\b\025L\260U\000\000\320\361]\a\374\177\000\000:\325$j\353\177\000\000Nv \000\000\000\000\000,\000\000\000\000\000\000\000p\000\000\000k\000\000\000\240V\327i\353\177\000\000\001\000\000\000\000\000\000\000\371/\376i\353\177\000"
        __FUNCTION__ = "request_ping"
#6  0x000055b04a941122 in request_proxy_reply (packet=0x55b04c183aa0) at src/main/process.c:2954
        proxy_p = 0x55b04c17e2c8
        request = 0x55b04c17e260
        now = {tv_sec = 1710341443, tv_usec = 187274}
        buffer = "\320\361]\a\374\177\000\000S\324Qj\353\177\000\000\060\362]\a\374\177\000\000\230", '\000' <repeats 15 times>, "\240:\030L\260U\000\000\024\000\000\000\000\000\000\000\200\035\376i\353\177\000\000@:\030L\260U\000\000\000h\002\204\313\"\305_0\362]\a\374\177\000\000\060:\230J\260U\000\000\220\363]\a\374\177\000\000\370\367]\a\374\177\000\000\374\361\222J\260U\000\000x\253\230J\260U\000"
#7  0x000055b04a964341 in proxy_tls_recv (listener=0x7feb6000c1f0) at src/main/tls_listen.c:1351
        sock = 0x7feb60002190
        buffer = "\240\362]\a\374\177\000\000\001\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000\200\020ih\353\177\000\000\000\021ih\353\177\000\000\000\021ih\353\177\000\000\001", '\000' <repeats 15 times>, "\200\020ih\353\177\000\000\000\021ih\353\177\000\000@\363]\a\374\177\000\000\000h\002\204\313\"\305_ \363]\a\374\177\000\000\226\217\223J\260U\000\000 \363]\a\374\177\000\000\200t\026L\260U\000\000 \363]\a\374\177\000\000\032\260\223J\260U\000\000\000\000\000\000\000\000\000\000\254&\231J\260U\000\000\260&\231J\260U\000\000\000h\002\204\313\"\305_p\363]\a\374\177\000\000X͓J\260U\000\000D\023\224J\260U\000\000\200"...
        packet = 0x55b04c183aa0   
        data = 0x55b04c20f5c0 <incomplete sequence \375>
        data_len = 20
#8  0x000055b04a947782 in event_socket_handler (xel=0x55b04c02da80, fd=22, ctx=0x7feb6000c1f0) at src/main/process.c:5305
        listener = 0x7feb6000c1f0 
#9  0x00007feb6a513313 in fr_event_loop (el=0x55b04c02da80) at src/lib/event.c:710
        ef = 0x55b04c02dc78
        i = 6
        rcode = 1
        when = {tv_sec = 1710341443, tv_usec = 493392}
        wake = 0x7ffc075df520
        read_fds = {fds_bits = {4194304, 0 <repeats 15 times>}}
        write_fds = {fds_bits = {0 <repeats 16 times>}}
#10 0x000055b04a949a3d in radius_event_process () at src/main/process.c:6489
No locals.
#11 0x000055b04a92ff14 in main (argc=4, argv=0x7ffc075df7f8) at src/main/radiusd.c:641
        rcode = 0
        status = 0
        argval = -1
        spawn_flag = true
        display_version = false   
        flag = 0
        from_child = {-1, -1}
        p = 0x7ffc075e07e3 "/radiusd"
        state = 0x55b04a991f60 <global_state>
        autofree = 0x55b04bc2f300 

Waking up in 0.3 seconds.
(1) Marking home server 130.59.31.24 port 2083 alive
(1) Received response to status check 1 ID 253 (1 in current sequence)
ASSERT FAILED src/main/process.c[3894]: !request->in_proxy_hash
CAUGHT SIGNAL: Aborted
Backtrace of last 12 frames:
/srv/freeradius/lib/libfreeradius-radius.so(fr_fault+0x139)[0x7feb6a4e73f8]
/srv/freeradius/lib/libfreeradius-server.so(rad_assert_fail+0x4d)[0x7feb6a5533f0]
sbin/radiusd(+0x544c8)[0x55b04a9434c8]
sbin/radiusd(request_proxy_reply+0x71c)[0x55b04a941122]
sbin/radiusd(proxy_tls_recv+0x3b6)[0x55b04a964341]
sbin/radiusd(+0x58782)[0x55b04a947782]
/srv/freeradius/lib/libfreeradius-radius.so(fr_event_loop+0x60d)[0x7feb6a513313]
sbin/radiusd(radius_event_process+0x2a)[0x55b04a949a3d]
sbin/radiusd(main+0xd18)[0x55b04a92ff14]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7feb69da1d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7feb69da1e40]
sbin/radiusd(_start+0x25)[0x55b04a906da5]

@alandekok
Copy link
Member

That's more than a little weird. All of the code paths which reach that assertion call the remove_from_proxy_hash() function, which makes sure that the request isn't in the proxy hash. So the assertion should pass.

can you run it with -Xx? That will print out more information about the state transitions it goes through

@olivierbeytrison
Copy link
Contributor Author

well I can't run it with -X because tls requires threading :s

I added more "x" which gave some more output

Wed Mar 13 16:32:48 2024 : Debug: Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server eduroam
Wed Mar 13 16:32:48 2024 : Debug: Listening on auth address * port 1812 bound to server eduroam
Wed Mar 13 16:32:48 2024 : Debug: Listening on acct address * port 1813 bound to server eduroam
Wed Mar 13 16:32:48 2024 : Info: Ready to process requests
Wed Mar 13 16:32:59 2024 : Debug: Threads: total/active/spare threads = 5/0/5
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 got semaphore
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 handling request 0, (1 handled so far)
Wed Mar 13 16:32:59 2024 : Debug: (0) Received Access-Request Id 0 from 127.0.0.1:46698 to 127.0.0.1:1812 length 154
Wed Mar 13 16:32:59 2024 : Debug: (0)   User-Name = "hefr@test.eduroam.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0)   NAS-IP-Address = 127.0.0.1
Wed Mar 13 16:32:59 2024 : Debug: (0)   Calling-Station-Id = "02-00-00-00-00-01"
Wed Mar 13 16:32:59 2024 : Debug: (0)   Framed-MTU = 1400
Wed Mar 13 16:32:59 2024 : Debug: (0)   NAS-Port-Type = Wireless-802.11
Wed Mar 13 16:32:59 2024 : Debug: (0)   Service-Type = Framed-User
Wed Mar 13 16:32:59 2024 : Debug: (0)   Connect-Info = "CONNECT 11Mbps 802.11b"
Wed Mar 13 16:32:59 2024 : Debug: (0)   EAP-Message = 0x02610019016865667240746573742e656475726f616d2e6368
Wed Mar 13 16:32:59 2024 : Debug: (0)   Message-Authenticator = 0xd361b1ce115a55f9a7ad25ee430b20e3
Wed Mar 13 16:32:59 2024 : Debug: (0) session-state: No State attribute
Wed Mar 13 16:32:59 2024 : Debug: (0) # Executing section authorize from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:32:59 2024 : Debug: (0)   authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0)     modsingle[authorize]: calling preprocess (rlm_preprocess)
Wed Mar 13 16:32:59 2024 : Debug: (0)     modsingle[authorize]: returned from preprocess (rlm_preprocess)
Wed Mar 13 16:32:59 2024 : Debug: (0)     [preprocess] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0)     modsingle[authorize]: calling auth_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: literal --> /srv/freeradius/var/log/radius/radacct/
Wed Mar 13 16:32:59 2024 : Debug: XLAT-IF {
Wed Mar 13 16:32:59 2024 : Debug: 	attribute --> Packet-Src-IP-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: XLAT-ELSE {
Wed Mar 13 16:32:59 2024 : Debug: 	attribute --> Packet-Src-IPv6-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: literal --> /auth-detail-
Wed Mar 13 16:32:59 2024 : Debug: percent --> Y
Wed Mar 13 16:32:59 2024 : Debug: percent --> m
Wed Mar 13 16:32:59 2024 : Debug: percent --> d
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log:    --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/auth-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: %t
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: percent --> t
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log: EXPAND %t
Wed Mar 13 16:32:59 2024 : Debug: (0) auth_log:    --> Wed Mar 13 16:32:59 2024
Wed Mar 13 16:32:59 2024 : Debug: (0)     modsingle[authorize]: returned from auth_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: (0)     [auth_log] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0)     if ("%{client:location}" == 'ROAMING') {
Wed Mar 13 16:32:59 2024 : Debug: (0)     EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0)        --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0)     if ("%{client:location}" == 'ROAMING')  -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0)     policy operator-name.authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: (0)       EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0)          --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:Operator-Name}")  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:Operator-Name}")  {
Wed Mar 13 16:32:59 2024 : Debug: (0)         update request {
Wed Mar 13 16:32:59 2024 : Debug: (0)           EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0)              --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)           &Operator-Name = 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # if ("%{client:Operator-Name}")  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # policy operator-name.authorize = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     policy cui.authorize {
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:add_cui}" == 'yes') {
Wed Mar 13 16:32:59 2024 : Debug: (0)       EXPAND %{client:add_cui}
Wed Mar 13 16:32:59 2024 : Debug: (0)          --> yes
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:add_cui}" == 'yes')  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)       if ("%{client:add_cui}" == 'yes')  {
Wed Mar 13 16:32:59 2024 : Debug: (0)         update request {
Wed Mar 13 16:32:59 2024 : Debug: (0)           &Chargeable-User-Identity := 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # if ("%{client:add_cui}" == 'yes')  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # policy cui.authorize = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     policy parse_realm {
Wed Mar 13 16:32:59 2024 : Debug: (0)       policy split_username_nai {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/)) {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  {
Wed Mar 13 16:32:59 2024 : Debug: (0)           update request {
Wed Mar 13 16:32:59 2024 : Debug: (0)             EXPAND %{1}
Wed Mar 13 16:32:59 2024 : Debug: (0)                --> hefr
Wed Mar 13 16:32:59 2024 : Debug: (0)             &Stripped-User-Name := hefr
Wed Mar 13 16:32:59 2024 : Debug: (0)           } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)           if ("%{3}" != '') {
Wed Mar 13 16:32:59 2024 : Debug: (0)           EXPAND %{3}
Wed Mar 13 16:32:59 2024 : Debug: (0)              --> test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)           if ("%{3}" != '')  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)           if ("%{3}" != '')  {
Wed Mar 13 16:32:59 2024 : Debug: (0)             update request {
Wed Mar 13 16:32:59 2024 : Debug: (0)               EXPAND %{3}
Wed Mar 13 16:32:59 2024 : Debug: (0)                  --> test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)               &Stripped-User-Domain = test.eduroam.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)             } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)           } # if ("%{3}" != '')  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)           modsingle[authorize]: calling updated (rlm_always)
Wed Mar 13 16:32:59 2024 : Debug: (0)           modsingle[authorize]: returned from updated (rlm_always)
Wed Mar 13 16:32:59 2024 : Debug: (0)           [updated] = updated
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # if (&User-Name && (&User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/))  = updated
Wed Mar 13 16:32:59 2024 : Debug: (0)         ... skipping else: Preceding "if" was taken
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # policy split_username_nai = updated
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (&Stripped-User-Domain) {
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (&Stripped-User-Domain)  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (&Stripped-User-Domain)  {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if ((&Stripped-User-Domain == 'test.hes-so.ch') || 		   (&Stripped-User-Domain == 'hes-so.ch') || 		   (&Stripped-User-Domain == 'hefr.ch')) {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if ((&Stripped-User-Domain == 'test.hes-so.ch') || 		   (&Stripped-User-Domain == 'hes-so.ch') || 		   (&Stripped-User-Domain == 'hefr.ch'))  -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0)         elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/) {
Wed Mar 13 16:32:59 2024 : Debug: (0)         elsif (&Stripped-User-Domain !~ /^([-a-z0-9]+\.)+[-a-z0-9]+/)  -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0)         else {
Wed Mar 13 16:32:59 2024 : Debug: (0)           update {
Wed Mar 13 16:32:59 2024 : Debug: (0)             request:Realm := 'EDUROAM'
Wed Mar 13 16:32:59 2024 : Debug: (0)             control:Proxy-To-Realm := 'EDUROAM'
Wed Mar 13 16:32:59 2024 : Debug: (0)           } # update = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # else = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # if (&Stripped-User-Domain)  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       ... skipping else: Preceding "if" was taken
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # policy parse_realm = updated
Wed Mar 13 16:32:59 2024 : Debug: (0)     policy set_location {
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (!&request:HESSO-Location && "%{client:location}") {
Wed Mar 13 16:32:59 2024 : Debug: (0)       EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0)          --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (!&request:HESSO-Location && "%{client:location}")  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)       if (!&request:HESSO-Location && "%{client:location}")  {
Wed Mar 13 16:32:59 2024 : Debug: (0)         update request {
Wed Mar 13 16:32:59 2024 : Debug: (0)           EXPAND %{client:location}
Wed Mar 13 16:32:59 2024 : Debug: (0)              --> RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0)           HESSO-Location := RORG-HEFR
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # update request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # if (!&request:HESSO-Location && "%{client:location}")  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # policy set_location = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     if (&Stripped-User-Domain == 'hefr.ch') {
Wed Mar 13 16:32:59 2024 : Debug: (0)     if (&Stripped-User-Domain == 'hefr.ch')  -> FALSE
Wed Mar 13 16:32:59 2024 : Debug: (0)     else {
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[authorize]: calling eap (rlm_eap)
Wed Mar 13 16:32:59 2024 : Debug: (0) eap: Request is supposed to be proxied to Realm EDUROAM. Not doing EAP.
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[authorize]: returned from eap (rlm_eap)
Wed Mar 13 16:32:59 2024 : Debug: (0)       [eap] = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # else = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)   } # authorize = updated
Wed Mar 13 16:32:59 2024 : Debug: Using home pool auth for realm EDUROAM
Wed Mar 13 16:32:59 2024 : Debug: (0) Starting proxy to home server 130.59.31.24 port 2083
Wed Mar 13 16:32:59 2024 : Debug: (0) server eduroam {
Wed Mar 13 16:32:59 2024 : Debug: (0)   # Executing section pre-proxy from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:32:59 2024 : Debug: (0)     pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: literal --> /srv/freeradius/var/log/radius/radacct/
Wed Mar 13 16:32:59 2024 : Debug: XLAT-IF {
Wed Mar 13 16:32:59 2024 : Debug: 	attribute --> Packet-Src-IP-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: XLAT-ELSE {
Wed Mar 13 16:32:59 2024 : Debug: 	attribute --> Packet-Src-IPv6-Address
Wed Mar 13 16:32:59 2024 : Debug: }
Wed Mar 13 16:32:59 2024 : Debug: literal --> /pre-proxy-detail-
Wed Mar 13 16:32:59 2024 : Debug: percent --> Y
Wed Mar 13 16:32:59 2024 : Debug: percent --> m
Wed Mar 13 16:32:59 2024 : Debug: percent --> d
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: EXPAND /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log:    --> /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: /srv/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d expands to /srv/freeradius/var/log/radius/radacct/127.0.0.1/pre-proxy-detail-20240313
Wed Mar 13 16:32:59 2024 : Debug: %t
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: percent --> t
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log: EXPAND %t
Wed Mar 13 16:32:59 2024 : Debug: (0) pre_proxy_log:    --> Wed Mar 13 16:32:59 2024
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail)
Wed Mar 13 16:32:59 2024 : Debug: (0)       [pre_proxy_log] = ok
Wed Mar 13 16:32:59 2024 : Debug: (0)       policy operator-name.pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}") {
Wed Mar 13 16:32:59 2024 : Debug: %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:32:59 2024 : Debug: (0)         EXPAND %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: (0)            --> Access-Request
Wed Mar 13 16:32:59 2024 : Debug: (0)         EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0)            --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  {
Wed Mar 13 16:32:59 2024 : Debug: (0)           update proxy-request {
Wed Mar 13 16:32:59 2024 : Debug: (0)             EXPAND %{client:Operator-Name}
Wed Mar 13 16:32:59 2024 : Debug: (0)                --> 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)             &Operator-Name := 1hes-so.ch
Wed Mar 13 16:32:59 2024 : Debug: (0)             Overwriting value "1hes-so.ch" with "1hes-so.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0)           } # update proxy-request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # if (("%{request:Packet-Type}" == 'Access-Request') && "%{client:Operator-Name}")  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # policy operator-name.pre-proxy = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       policy cui.pre-proxy {
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes')) {
Wed Mar 13 16:32:59 2024 : Debug: %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:32:59 2024 : Debug: (0)         EXPAND %{request:Packet-Type}
Wed Mar 13 16:32:59 2024 : Debug: (0)            --> Access-Request
Wed Mar 13 16:32:59 2024 : Debug: (0)         EXPAND %{client:add_cui}
Wed Mar 13 16:32:59 2024 : Debug: (0)            --> yes
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  -> TRUE
Wed Mar 13 16:32:59 2024 : Debug: (0)         if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  {
Wed Mar 13 16:32:59 2024 : Debug: (0)           update proxy-request {
Wed Mar 13 16:32:59 2024 : Debug: (0)             &Chargeable-User-Identity = 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0)             Refusing to overwrite (use :=)
Wed Mar 13 16:32:59 2024 : Debug: (0)           } # update proxy-request = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)         } # if (("%{request:Packet-Type}" == 'Access-Request') && ("%{client:add_cui}" == 'yes'))  = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       } # policy cui.pre-proxy = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[pre-proxy]: calling attr_filter.pre-proxy (rlm_attr_filter)
Wed Mar 13 16:32:59 2024 : Debug: %{Realm}
Wed Mar 13 16:32:59 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:32:59 2024 : Debug: attribute --> Realm
Wed Mar 13 16:32:59 2024 : Debug: (0) attr_filter.pre-proxy: EXPAND %{Realm}
Wed Mar 13 16:32:59 2024 : Debug: (0) attr_filter.pre-proxy:    --> EDUROAM
Wed Mar 13 16:32:59 2024 : Debug: (0)       modsingle[pre-proxy]: returned from attr_filter.pre-proxy (rlm_attr_filter)
Wed Mar 13 16:32:59 2024 : Debug: (0)       [attr_filter.pre-proxy] = noop
Wed Mar 13 16:32:59 2024 : Debug: (0)     } # pre-proxy = ok
Wed Mar 13 16:32:59 2024 : Debug: (0) }
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Wed Mar 13 16:32:59 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (130.59.31.24, 2083)
Wed Mar 13 16:32:59 2024 : Debug: Requiring Server certificate
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Wed Mar 13 16:32:59 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Wed Mar 13 16:32:59 2024 : Debug: Opened new proxy socket 'proxy (160.98.240.25, 49795) -> home_server (130.59.31.24, 2083)'
Wed Mar 13 16:32:59 2024 : Debug: Listening on proxy (160.98.240.25, 49795) -> home_server (130.59.31.24, 2083)
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: request is now in proxy hash
Wed Mar 13 16:32:59 2024 : Debug: (0) proxy: allocating destination 130.59.31.24 port 2083 - Id 76
Wed Mar 13 16:32:59 2024 : Debug: (0) Proxying request to home server 130.59.31.24 port 2083 (TLS) timeout 20.000000
Wed Mar 13 16:32:59 2024 : Debug: (0) Sent Access-Request Id 76 from 160.98.240.25:49795 to 130.59.31.24:2083 length 195
Wed Mar 13 16:32:59 2024 : Debug: (0)   User-Name = "hefr@test.eduroam.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0)   NAS-IP-Address = 127.0.0.1
Wed Mar 13 16:32:59 2024 : Debug: (0)   Calling-Station-Id = "02-00-00-00-00-01"
Wed Mar 13 16:32:59 2024 : Debug: (0)   Framed-MTU = 1400
Wed Mar 13 16:32:59 2024 : Debug: (0)   NAS-Port-Type = Wireless-802.11
Wed Mar 13 16:32:59 2024 : Debug: (0)   Service-Type = Framed-User
Wed Mar 13 16:32:59 2024 : Debug: (0)   Connect-Info = "CONNECT 11Mbps 802.11b"
Wed Mar 13 16:32:59 2024 : Debug: (0)   EAP-Message = 0x02610019016865667240746573742e656475726f616d2e6368
Wed Mar 13 16:32:59 2024 : Debug: (0)   Message-Authenticator = 0xd361b1ce115a55f9a7ad25ee430b20e3
Wed Mar 13 16:32:59 2024 : Debug: (0)   Event-Timestamp = "Mar 13 2024 16:32:59 CET"
Wed Mar 13 16:32:59 2024 : Debug: (0)   Operator-Name := "1hes-so.ch"
Wed Mar 13 16:32:59 2024 : Debug: (0)   Chargeable-User-Identity := 0x00
Wed Mar 13 16:32:59 2024 : Debug: (0)   HESSO-Location := "RORG-HEFR"
Wed Mar 13 16:32:59 2024 : Debug: (0)   Proxy-State = 0x30
Wed Mar 13 16:32:59 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Wed Mar 13 16:32:59 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Wed Mar 13 16:32:59 2024 : Debug: (0) (TLS) Writing 195 bytes for later (total 195)
Wed Mar 13 16:32:59 2024 : Debug: Thread 3 waiting to be assigned a request
Wed Mar 13 16:32:59 2024 : Debug: (0) Expecting proxy response no later than 19.668950 seconds from now
Wed Mar 13 16:32:59 2024 : Debug: Waking up in 19.6 seconds.
Wed Mar 13 16:33:02 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 76
Wed Mar 13 16:33:02 2024 : Debug: Waking up in 17.0 seconds.
Wed Mar 13 16:33:08 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 130.59.31.24 port 2083 proto TCP - ID: 76
Wed Mar 13 16:33:08 2024 : Debug: Waking up in 11.0 seconds.
Wed Mar 13 16:33:19 2024 : Debug: (0) No proxy response, giving up on request and marking it done
Wed Mar 13 16:33:19 2024 : Proxy: Marking home server 130.59.31.24 port 2083 as zombie (it has not responded in 20.000000 seconds).
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: Trying to allocate ID (0/2)
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: request is now in proxy hash
Wed Mar 13 16:33:19 2024 : Debug: (1) proxy: allocating destination 130.59.31.24 port 2083 - Id 25
Wed Mar 13 16:33:19 2024 : Debug: PING: Waiting 4 seconds for response to ping
Wed Mar 13 16:33:19 2024 : Debug: (1) Sent Status-Server Id 25 from 160.98.240.25:49795 to 130.59.31.24:2083 length 70
Wed Mar 13 16:33:19 2024 : Debug: (1)   Message-Authenticator := 0x00
Wed Mar 13 16:33:19 2024 : Debug: (1)   NAS-Identifier := "Status Check 0. Are you alive?"
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write client hello
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: (1) (TLS) Writing 70 bytes for later (total 265)
Wed Mar 13 16:33:19 2024 : Debug: PING: Next status packet in 30 seconds
Wed Mar 13 16:33:19 2024 : ERROR: (0) Failing proxied request for user "hefr", due to lack of any response from home server 130.59.31.24 port 2083
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 got semaphore
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 handling request 0, (1 handled so far)
Wed Mar 13 16:33:19 2024 : Debug: (0) Clearing existing &reply: attributes
Wed Mar 13 16:33:19 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Wed Mar 13 16:33:19 2024 : Debug: (0) server eduroam {
Wed Mar 13 16:33:19 2024 : Debug: (0)   Post-Proxy-Type sub-section not found.  Ignoring.
Wed Mar 13 16:33:19 2024 : Debug: (0)   # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:33:19 2024 : Debug: (0) }
Wed Mar 13 16:33:19 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [hefr@test.eduroam.ch] (from client loopback port 0 cli 02-00-00-00-00-01)
Wed Mar 13 16:33:19 2024 : Debug: (0) There was no response configured: rejecting request
Wed Mar 13 16:33:19 2024 : Debug: (0) Using Post-Auth-Type Reject
Wed Mar 13 16:33:19 2024 : Debug: (0) # Executing group from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Wed Mar 13 16:33:19 2024 : Debug: (0)   Post-Auth-Type REJECT {
Wed Mar 13 16:33:19 2024 : Debug: (0)     if ("%{Packet-Type}" == 'Status-Server'){
Wed Mar 13 16:33:19 2024 : Debug: %{Packet-Type}
Wed Mar 13 16:33:19 2024 : Debug: Parsed xlat tree:
Wed Mar 13 16:33:19 2024 : Debug: attribute --> Packet-Type
Wed Mar 13 16:33:19 2024 : Debug: (0)     EXPAND %{Packet-Type}
Wed Mar 13 16:33:19 2024 : Debug: (0)        --> Access-Request
Wed Mar 13 16:33:19 2024 : Debug: (0)     if ("%{Packet-Type}" == 'Status-Server') -> FALSE
Wed Mar 13 16:33:19 2024 : Debug: (0)   } # Post-Auth-Type REJECT = noop
Wed Mar 13 16:33:19 2024 : Debug: (0) Sent Access-Reject Id 0 from 127.0.0.1:1812 to 127.0.0.1:46698 length 20
Wed Mar 13 16:33:19 2024 : Debug: (0) Finished request
Wed Mar 13 16:33:19 2024 : Debug: Thread 2 waiting to be assigned a request
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHello
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSH] - Client SSLv3/TLS read server hello (3)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from server certificate
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Serial := "01"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Expiration := "301103101536Z"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Valid-Since := "101108101536Z"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Subject := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Cert-Common-Name := "eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) chain-depth   : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) error         : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) common name   : eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) subject       : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) issuer        : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) verify return : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from client certificate
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Serial := "231a75d9361f9ea038f29422"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Expiration := "250629083105Z"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Valid-Since := "200630083105Z"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Subject := "/DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Issuer := "/DC=org/DC=edupki/CN=eduPKI CA G 01"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Common-Name := "ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ftlr1.eduroam.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "ozza.switch.ch"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
Wed Mar 13 16:33:19 2024 : Debug: (0)   Skipping TLS-Client-Cert-X509v3-Key-Usage += 'Digital Signature, Key Encipherment'.  Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication, TLS Web Server Authentication"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "CE:A9:9C:51:B2:A5:FB:7E:5D:1D:9F:B4:FB:0F:A1:33:13:7A:D0:BA"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "D2:F2:23:BD:4A:A1:7F:CF:A0:58:84:EB:FC:E6:5B:08:B3:CD:B4:E4"
Wed Mar 13 16:33:19 2024 : Debug: (0)   Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:ftlr1.eduroam.ch, DNS:ozza.switch.ch'.  Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Certificate-Policies += "Policy: 1.3.6.1.4.1.27262.1.13.1.1\nPolicy: 1.3.6.1.4.1.27262.1.13.1.1.1.4\nPolicy: 1.3.6.1.4.1.25178.3.1.1\nPolicy: 1.3.6.1.4.1.25178.3.1.2\nPolicy: 1.3.6.1.4.1.27262.1.13.2.1.1.8"
Wed Mar 13 16:33:19 2024 : Debug: (0)   Skipping TLS-Client-Cert-X509v3-CRL-Distribution-Points += 'Full Name:   URI:http://cdp.edupki.org/edupki-ca/pub/crl/cacrl.crl'.  Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0)   Skipping TLS-Client-Cert-Authority-Information-Access += 'OCSP - URI:http://ocsp.edupki.org/OCSP-Server/OCSP CA Issuers - URI:http://cdp.edupki.org/edupki-ca/pub/cacert/cacert.crt'.  Please check that both the attribute and value are defined in the dictionaries
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.2"
Wed Mar 13 16:33:19 2024 : Debug: (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Wed Mar 13 16:33:19 2024 : Warning: Certificate chain - 1 intermediate CA cert(s) untrusted
Wed Mar 13 16:33:19 2024 : Warning: To forbid these certificates see 'reject_unknown_intermediate_ca'
Wed Mar 13 16:33:19 2024 : Warning: (TLS) untrusted certificate with depth [1] subject name /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Warning: (TLS) untrusted certificate with depth [0] subject name /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) chain-depth   : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) error         : 0
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) common name   : ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) subject       : /DC=net/DC=geant/DC=eduroam/C=CH/O=SWITCH/CN=ftlr1.eduroam.ch
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) issuer        : /DC=org/DC=edupki/CN=eduPKI CA G 01
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) verify return : 1
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerKeyExchange
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS read server key exchange
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (6)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, CertificateRequest
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, ServerHelloDone
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRSD] - Client SSLv3/TLS read server done (8)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Certificate
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCC] - Client SSLv3/TLS write client certificate (13)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientKeyExchange
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (14)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, CertificateVerify
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (15)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 ChangeCipherSpec
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (16)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, Finished
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Client : Need to read more data: SSLv3/TLS write finished
Wed Mar 13 16:33:19 2024 : Debug: (TLS) SSL_connect() returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (10)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.2 Handshake, Finished
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRFIN] - Client SSLv3/TLS read finished (11)
Wed Mar 13 16:33:19 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [SSLOK] - SSL negotiation finished successfully (1)
Wed Mar 13 16:33:19 2024 : Debug: (TLS) proxy writing 265 to socket
Wed Mar 13 16:33:19 2024 : Debug: (TLS) OpenSSL returned WANT_READ
Wed Mar 13 16:33:19 2024 : Debug: Waking up in 0.3 seconds.
Wed Mar 13 16:33:19 2024 : Debug: Proxy SSL socket has data to read
Wed Mar 13 16:33:19 2024 : Debug: Proxy received header saying we have a packet of 20 bytes
Wed Mar 13 16:33:19 2024 : Proxy: (1) Marking home server 130.59.31.24 port 2083 alive
Wed Mar 13 16:33:19 2024 : Proxy: (1) Received response to status check 1 ID 25 (1 in current sequence)
Wed Mar 13 16:33:19 2024 : Error: ASSERT FAILED src/main/process.c[3894]: !request->in_proxy_hash
CAUGHT SIGNAL: Aborted
Backtrace of last 12 frames:
/srv/freeradius/lib/libfreeradius-radius.so(fr_fault+0x139)[0x7f809543a3f8]
/srv/freeradius/lib/libfreeradius-server.so(rad_assert_fail+0x4d)[0x7f80954a63f0]
sbin/radiusd(+0x544c8)[0x55f4d18ea4c8]
sbin/radiusd(request_proxy_reply+0x71c)[0x55f4d18e8122]
sbin/radiusd(proxy_tls_recv+0x3b6)[0x55f4d190b341]
sbin/radiusd(+0x58782)[0x55f4d18ee782]
/srv/freeradius/lib/libfreeradius-radius.so(fr_event_loop+0x60d)[0x7f8095466313]
sbin/radiusd(radius_event_process+0x2a)[0x55f4d18f0a3d]
sbin/radiusd(main+0xd18)[0x55f4d18d6f14]
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7f8094cf4d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7f8094cf4e40]
sbin/radiusd(_start+0x25)[0x55f4d18adda5]
Calling: gdb -silent -x /srv/freeradius/etc/raddb/panic.gdb sbin/radiusd 3862912 2>&1 | tee /srv/freeradius/var/log/radius/gdb-radiusd-3862912.log
Temporarily setting PR_DUMPABLE to 1
Resetting PR_DUMPABLE to 0
Panic action exited with 0
_EXIT(0) CALLED src/lib/debug.c[811]

@alandekok
Copy link
Member

You can run in threaded mode with radiusd -sf -xxx -l stdout.

I'll see if I can reproduce this here, but it might take a bit. I'm busy for the next while.

@olivierbeytrison
Copy link
Contributor Author

You can run in threaded mode with radiusd -sf -xxx -l stdout.

Yeah that's what I did.
btw is status-server supported/wanted with radsec or shall I try to turn it off and see if it happens again ?

@alandekok
Copy link
Member

If you just use tcp or udp, it should work. So yes, please try without radsec.

@olivierbeytrison
Copy link
Contributor Author

olivierbeytrison commented Mar 13, 2024 •
edited

Well it was working fine with radius/udp before, but we're in the process to move to radsec with our ftlr and that's when this issue arose. Still I'll try a few more things, and also I'll double check with the NREN if everything is correctly working on their side.

@haegar haegar mentioned this issue Mar 14, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
defect category: a defect or misbehaviour
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@alandekok @olivierbeytrison