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]: FreeRADIUS 3.2.3 container crashes after sending status-server messages #5326

Closed
rtblossom opened this issue May 28, 2024 · 8 comments
Closed

[defect]: FreeRADIUS 3.2.3 container crashes after sending status-server messages #5326

rtblossom opened this issue May 28, 2024 · 8 comments
Labels
defect category: a defect or misbehaviour

Comments

@rtblossom
Copy link

rtblossom commented May 28, 2024 •
edited
Loading

What type of defect/bug is this?

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

How can the issue be reproduced?

I created a repository to help in reproducing the issue. It contains a docker-compose file that builds a set of containers and then runs the test. The crash will then be easy to replicate.

https://github.com/rtblossom/fr-status-server-issue

Just clone the repository and run "docker-compose up --build".

The scenario is FreeRADIUS timing out proxied authentication messages over RadSec and then sending status-server messages to the RadSec server. FreeRADIUS eventually exits after TLS and talloc errors.

Log output from the FreeRADIUS daemon

I removed some of the logs due to the 65536 char limit. Full log is in the rtblossom/fr-status-server-issue repo.

 Server was built with:
   accounting                : yes
   authentication            : yes
   ascend-binary-attributes  : yes
   coa                       : yes
   recv-coa-from-home-server : yes
   control-socket            : yes
   detail                    : yes
   dhcp                      : yes
   dynamic-clients           : yes
   osfc2                     : no
   proxy                     : yes
   regex-pcre                : no
   regex-posix               : yes
   regex-posix-extended      : yes
   session-management        : yes
   stats                     : yes
   systemd                   : yes
   tcp                       : yes
   threads                   : yes
   tls                       : yes
   unlang                    : yes
   vmps                      : yes
   developer                 : no
 Server core libs:
   freeradius-server         : 3.2.3
   talloc                    : 2.3.*
   ssl                       : 3.0.0b dev
 Endianness:
   little
 Compilation flags:
   cppflags : -Wdate-time -D_FORTIFY_SOURCE=2
   cflags   : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -g -O2 -ffile-prefix-map=/usr/local/src/repositories/freeradius-server=. -flto=auto -ffat-lto-objects -flto=auto -ffat-lto-objects -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1
   ldflags  :  -Wl,-Bsymbolic-functions -flto=auto -ffat-lto-objects -flto=auto -Wl,-z,relro -Wl,-z,now
   libs     : -lcrypto -lssl -ltalloc -latomic -lcap -lnsl -lresolv -ldl -lpthread -lreadline

Info: FreeRADIUS Version 3.2.3
Info: Copyright (C) 1999-2022 The FreeRADIUS server project and contributors
Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Info: PARTICULAR PURPOSE
Info: You may redistribute copies of FreeRADIUS under the terms of the
Info: GNU General Public License
Info: For more information about these matters, see the file named COPYRIGHT
Info: Starting - reading configuration files ...
 including dictionary file /usr/share/freeradius/dictionary
 including dictionary file /usr/share/freeradius/dictionary.dhcp
 including dictionary file /usr/share/freeradius/dictionary.vqp
 including dictionary file /etc/freeradius/dictionary
 including configuration file /etc/freeradius/radiusd.conf
 including configuration file /etc/freeradius/proxy.common.conf
 including files in directory /etc/freeradius/mods-enabled/
 including configuration file /etc/freeradius/mods-enabled/utf8
 including configuration file /etc/freeradius/mods-enabled/preprocess
 including configuration file /etc/freeradius/mods-enabled/expiration
 including configuration file /etc/freeradius/mods-enabled/mschap
 including configuration file /etc/freeradius/mods-enabled/radutmp
 including configuration file /etc/freeradius/mods-enabled/detail.log
 including configuration file /etc/freeradius/mods-enabled/totp
 including configuration file /etc/freeradius/mods-enabled/unpack
 including configuration file /etc/freeradius/mods-enabled/realm
 including configuration file /etc/freeradius/mods-enabled/ntlm_auth
 including configuration file /etc/freeradius/mods-enabled/replicate
 including configuration file /etc/freeradius/mods-enabled/pap
 including configuration file /etc/freeradius/mods-enabled/dynamic_clients
 including configuration file /etc/freeradius/mods-enabled/expr
 including configuration file /etc/freeradius/mods-enabled/chap
 including configuration file /etc/freeradius/mods-enabled/unix
 including configuration file /etc/freeradius/mods-enabled/exec
 including configuration file /etc/freeradius/mods-enabled/echo
 including configuration file /etc/freeradius/mods-enabled/files
 including configuration file /etc/freeradius/mods-enabled/digest
 including configuration file /etc/freeradius/mods-enabled/logintime
 including configuration file /etc/freeradius/mods-enabled/attr_filter
 including configuration file /etc/freeradius/mods-enabled/linelog
 including configuration file /etc/freeradius/mods-enabled/date
 including configuration file /etc/freeradius/mods-enabled/soh
 including configuration file /etc/freeradius/mods-enabled/passwd
 including configuration file /etc/freeradius/mods-enabled/always
 including configuration file /etc/freeradius/mods-enabled/detail
 including configuration file /etc/freeradius/mods-enabled/sradutmp
 including files in directory /etc/freeradius/sites-enabled/
 including configuration file /etc/freeradius/sites-enabled/status
 including configuration file /etc/freeradius/sites-enabled/openroaming
 including files in directory /etc/freeradius/policy.d/
 including configuration file /etc/freeradius/policy.d/dhcp
 including configuration file /etc/freeradius/policy.d/eap
 including configuration file /etc/freeradius/policy.d/moonshot-targeted-ids
 including configuration file /etc/freeradius/policy.d/cui
 OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
 OPTIMIZING (no == yes) --> FALSE
 OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
 OPTIMIZING (no == yes) --> FALSE
 including configuration file /etc/freeradius/policy.d/operator-name
 including configuration file /etc/freeradius/policy.d/debug
 including configuration file /etc/freeradius/policy.d/filter
 including configuration file /etc/freeradius/policy.d/abfab-tr
 including configuration file /etc/freeradius/policy.d/canonicalization
 including configuration file /etc/freeradius/policy.d/accounting
 including configuration file /etc/freeradius/policy.d/rfc7542
 including configuration file /etc/freeradius/policy.d/control
 main {
  security {
   user = "root"
   group = "root"
   allow_core_dumps = yes
Warning: /etc/freeradius/radiusd.conf[533]: The item 'max_attributes' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[551]: The item 'reject_delay' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[571]: The item 'status_server' is defined, but is unused by the configuration
  }
   name = "freeradius"
   prefix = "/usr"
   localstatedir = "/var"
   logdir = "/var/log/freeradius"
   run_dir = "/var/run/freeradius"
Warning: /etc/freeradius/radiusd.conf[85]: The item 'sysconfdir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[99]: The item 'pkidir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[101]: The item 'cadirclient' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[105]: The item 'db_dir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[140]: The item 'libdir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[151]: The item 'pidfile' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[172]: The item 'correct_escapes' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[226]: The item 'max_request_time' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[247]: The item 'cleanup_delay' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[266]: The item 'max_requests' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[284]: The item 'hostname_lookups' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[389]: The item 'checkrad' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[592]: The item 'proxy_requests' is defined, but is unused by the configuration
 }
Info: Core dumps are enabled
 main {
   name = "freeradius"
   prefix = "/usr"
   localstatedir = "/var"
   sbindir = "/usr/sbin"
   logdir = "/var/log/freeradius"
   run_dir = "/var/run/freeradius"
   libdir = "/usr/lib/freeradius"
   radacctdir = "/var/log/freeradius/radacct"
   hostname_lookups = no
   max_request_time = 10
   cleanup_delay = 5
   max_requests = 16384
   postauth_client_lost = no
   pidfile = "/var/run/freeradius/freeradius.pid"
   checkrad = "/usr/sbin/checkrad"
   debug_level = 0
   proxy_requests = yes
  log {
   stripped_names = no
   auth = no
   auth_accept = no
   auth_reject = no
   auth_badpass = no
   auth_goodpass = no
   colourise = yes
   msg_denied = "You are already logged in - access denied"
Warning: /etc/freeradius/radiusd.conf[303]: The item 'destination' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[320]: The item 'file' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[328]: The item 'syslog_facility' is defined, but is unused by the configuration
  }
  resources {
  }
  security {
   max_attributes = 200
   reject_delay = 1.000000
   status_server = yes
  }
Warning: /etc/freeradius/radiusd.conf[85]: The item 'sysconfdir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[99]: The item 'pkidir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[101]: The item 'cadirclient' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[105]: The item 'db_dir' is defined, but is unused by the configuration
Warning: /etc/freeradius/radiusd.conf[172]: The item 'correct_escapes' is defined, but is unused by the configuration
 }
 radiusd: #### Loading Realms and Home Servers ####
  proxy server {
   retry_delay = 5
   retry_count = 3
   default_fallback = no
   dead_time = 120
   wake_all_if_all_dead = no
  }
  home_server radsec1 {
   nonblock = no
   ipaddr = test_endpoint1 IPv4 address [192.168.0.3]
   port = 2083
   type = "auth+acct"
   proto = "tcp"
   secret = "radsec"
   response_window = 7.000000
   response_timeouts = 5
   max_outstanding = 65536
   zombie_period = 40
   status_check = "status-server"
   ping_interval = 30
   check_interval = 10
   check_timeout = 1
   num_answers_to_alive = 3
   revive_interval = 300
   limit {
           max_connections = 128
           max_requests = 0
           lifetime = 0
           idle_timeout = 0
Warning: /etc/freeradius/proxy.common.conf[65]: The item 'idle-timeout' is defined, but is unused by the configuration
   }
   coa {
           irt = 2
           mrt = 16
           mrc = 5
           mrd = 30
   }
   recv_coa {
   }
  }
   tls {
           verify_depth = 0
           pem_file_type = yes
           private_key_file = "/pki/client.key"
           certificate_file = "/pki/client.crt"
           ca_file = "/pki/ca/ca.crt"
           fragment_size = 8192
           include_length = yes
           check_crl = no
           ca_path_reload_interval = 0
           ecdh_curve = "prime256v1"
           tls_min_version = "1.2"
   }
  home_server radsec2 {
   nonblock = no
   ipaddr = test_endpoint2 IPv4 address [192.168.0.2]
   port = 2083
   type = "auth+acct"
   proto = "tcp"
   secret = "radsec"
   response_window = 7.000000
   response_timeouts = 5
   max_outstanding = 65536
   zombie_period = 40
   status_check = "status-server"
   ping_interval = 30
   check_interval = 10
   check_timeout = 1
   num_answers_to_alive = 3
   revive_interval = 300
   limit {
           max_connections = 128
           max_requests = 0
           lifetime = 0
           idle_timeout = 0
Warning: /etc/freeradius/proxy.common.conf[92]: The item 'idle-timeout' is defined, but is unused by the configuration
   }
   coa {
           irt = 2
           mrt = 16
           mrc = 5
           mrd = 30
   }
   recv_coa {
   }
  }
   tls {
           verify_depth = 0
           pem_file_type = yes
           private_key_file = "/pki/client.key"
           certificate_file = "/pki/client.crt"
           ca_file = "/pki/ca/ca.crt"
           fragment_size = 8192
           include_length = yes
           check_crl = no
           ca_path_reload_interval = 0
           ecdh_curve = "prime256v1"
           tls_min_version = "1.2"
   }
  home_server_pool radsec_pool {
   type = keyed-balance
   home_server = radsec1
   home_server = radsec2
  }
  home_server_pool radsec_pool {
   type = keyed-balance
   home_server = radsec1
   home_server = radsec2
  }
  realm DEFAULT {
   auth_pool = radsec_pool
   acct_pool = radsec_pool
   nostrip
  }
 radiusd: #### Loading Clients ####
Info: Debugger not attached
Info: systemd watchdog is disabled
  # Creating Autz-Type = Status-Server
 radiusd: #### Instantiating modules ####
  modules {
 Loaded rlm_utf8, checking if it's valid
   # Loaded module rlm_utf8
   # Loading module "utf8" from file /etc/freeradius/mods-enabled/utf8
 Loaded rlm_preprocess, checking if it's valid
   # Loaded module rlm_preprocess
   # Loading module "preprocess" from file /etc/freeradius/mods-enabled/preprocess
   preprocess {
           huntgroups = "/etc/freeradius/mods-config/preprocess/huntgroups"
           hints = "/etc/freeradius/mods-config/preprocess/hints"
           with_ascend_hack = no
           ascend_channels_per_line = 23
           with_ntdomain_hack = no
           with_specialix_jetstream_hack = no
           with_cisco_vsa_hack = no
           with_alvarion_vsa_hack = no
   }
 Loaded rlm_expiration, checking if it's valid
   # Loaded module rlm_expiration
   # Loading module "expiration" from file /etc/freeradius/mods-enabled/expiration
 Loaded rlm_mschap, checking if it's valid
   # Loaded module rlm_mschap
   # Loading module "mschap" from file /etc/freeradius/mods-enabled/mschap
   mschap {
           use_mppe = yes
           require_encryption = no
           require_strong = no
           with_ntdomain_hack = yes
    passchange {
    }
           allow_retry = yes
           winbind_retry_with_normalised_username = no
   }
 Loaded rlm_radutmp, checking if it's valid
   # Loaded module rlm_radutmp
   # Loading module "radutmp" from file /etc/freeradius/mods-enabled/radutmp
   radutmp {
           filename = "/var/log/freeradius/radutmp"
           username = "%{User-Name}"
           case_sensitive = yes
           check_with_nas = yes
           permissions = 384
           caller_id = yes
   }
 Loaded rlm_detail, checking if it's valid
   # Loaded module rlm_detail
   # Loading module "auth_log" from file /etc/freeradius/mods-enabled/detail.log
   detail auth_log {
           filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d"
           header = "%t"
           permissions = 384
           locking = no
           escape_filenames = no
           log_packet_header = no
   }
   # Loading module "reply_log" from file /etc/freeradius/mods-enabled/detail.log
   detail reply_log {
           filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d"
           header = "%t"
           permissions = 384
           locking = no
           escape_filenames = no
           log_packet_header = no
   }
   # Loading module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log
   detail pre_proxy_log {
           filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d"
           header = "%t"
           permissions = 384
           locking = no
           escape_filenames = no
           log_packet_header = no
   }
   # Loading module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log
   detail post_proxy_log {
           filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d"
           header = "%t"
           permissions = 384
           locking = no
           escape_filenames = no
           log_packet_header = no
   }
 Loaded rlm_totp, checking if it's valid
   # Loaded module rlm_totp
   # Loading module "totp" from file /etc/freeradius/mods-enabled/totp
 Loaded rlm_unpack, checking if it's valid
   # Loaded module rlm_unpack
   # Loading module "unpack" from file /etc/freeradius/mods-enabled/unpack
 Loaded rlm_realm, checking if it's valid
   # Loaded module rlm_realm
   # Loading module "IPASS" from file /etc/freeradius/mods-enabled/realm
   realm IPASS {
           format = "prefix"
           delimiter = "/"
           ignore_default = no
           ignore_null = no
   }
   # Loading module "suffix" from file /etc/freeradius/mods-enabled/realm
   realm suffix {
           format = "suffix"
           delimiter = "@"
           ignore_default = no
           ignore_null = no
   }
   # Loading module "bangpath" from file /etc/freeradius/mods-enabled/realm
   realm bangpath {
           format = "prefix"
           delimiter = "!"
           ignore_default = no
           ignore_null = no
   }
   # Loading module "realmpercent" from file /etc/freeradius/mods-enabled/realm
   realm realmpercent {
           format = "suffix"
           delimiter = "%"
           ignore_default = no
           ignore_null = no
   }
   # Loading module "ntdomain" from file /etc/freeradius/mods-enabled/realm
   realm ntdomain {
           format = "prefix"
           delimiter = "\\"
           ignore_default = no
           ignore_null = no
   }
 Loaded rlm_exec, checking if it's valid
   # Loaded module rlm_exec
   # Loading module "ntlm_auth" from file /etc/freeradius/mods-enabled/ntlm_auth
   exec ntlm_auth {
           wait = yes
           program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}"
           shell_escape = yes
   }
 Loaded rlm_replicate, checking if it's valid
   # Loaded module rlm_replicate
   # Loading module "replicate" from file /etc/freeradius/mods-enabled/replicate
 Loaded rlm_pap, checking if it's valid
   # Loaded module rlm_pap
   # Loading module "pap" from file /etc/freeradius/mods-enabled/pap
   pap {
           normalise = yes
   }
 Loaded rlm_dynamic_clients, checking if it's valid
   # Loaded module rlm_dynamic_clients
   # Loading module "dynamic_clients" from file /etc/freeradius/mods-enabled/dynamic_clients
 Loaded rlm_expr, checking if it's valid
   # Loaded module rlm_expr
   # Loading module "expr" from file /etc/freeradius/mods-enabled/expr
   expr {
           safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
   }
 Loaded rlm_chap, checking if it's valid
   # Loaded module rlm_chap
   # Loading module "chap" from file /etc/freeradius/mods-enabled/chap
 Loaded rlm_unix, checking if it's valid
   # Loaded module rlm_unix
   # Loading module "unix" from file /etc/freeradius/mods-enabled/unix
   unix {
           radwtmp = "/var/log/freeradius/radwtmp"
   }
 Creating attribute Unix-Group
   # Loading module "exec" from file /etc/freeradius/mods-enabled/exec
   exec {
           wait = yes
           input_pairs = "request"
           shell_escape = yes
           timeout = 10
   }
   # Loading module "echo" from file /etc/freeradius/mods-enabled/echo
   exec echo {
           wait = yes
           program = "/bin/echo %{User-Name}"
           input_pairs = "request"
           output_pairs = "reply"
           shell_escape = yes
   }
 Loaded rlm_files, checking if it's valid
   # Loaded module rlm_files
   # Loading module "files" from file /etc/freeradius/mods-enabled/files
   files {
           filename = "/etc/freeradius/mods-config/files/authorize"
           acctusersfile = "/etc/freeradius/mods-config/files/accounting"
           preproxy_usersfile = "/etc/freeradius/mods-config/files/pre-proxy"
   }
 Loaded rlm_digest, checking if it's valid
   # Loaded module rlm_digest
   # Loading module "digest" from file /etc/freeradius/mods-enabled/digest
 Loaded rlm_logintime, checking if it's valid
   # Loaded module rlm_logintime
   # Loading module "logintime" from file /etc/freeradius/mods-enabled/logintime
   logintime {
           minimum_timeout = 60
   }
 Loaded rlm_attr_filter, checking if it's valid
   # Loaded module rlm_attr_filter
   # Loading module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.post-proxy {
           filename = "/etc/freeradius/mods-config/attr_filter/post-proxy"
           key = "%{Realm}"
           relaxed = no
   }
   # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.pre-proxy {
           filename = "/etc/freeradius/mods-config/attr_filter/pre-proxy"
           key = "%{Realm}"
           relaxed = no
   }
   # Loading module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.access_reject {
           filename = "/etc/freeradius/mods-config/attr_filter/access_reject"
           key = "%{User-Name}"
           relaxed = no
   }
   # Loading module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.access_challenge {
           filename = "/etc/freeradius/mods-config/attr_filter/access_challenge"
           key = "%{User-Name}"
           relaxed = no
   }
   # Loading module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.accounting_response {
           filename = "/etc/freeradius/mods-config/attr_filter/accounting_response"
           key = "%{User-Name}"
           relaxed = no
   }
   # Loading module "attr_filter.coa" from file /etc/freeradius/mods-enabled/attr_filter
   attr_filter attr_filter.coa {
           filename = "/etc/freeradius/mods-config/attr_filter/coa"
           key = "%{User-Name}"
           relaxed = no
   }
 Loaded rlm_linelog, checking if it's valid
   # Loaded module rlm_linelog
   # Loading module "linelog" from file /etc/freeradius/mods-enabled/linelog
   linelog {
           filename = "/var/log/freeradius/linelog"
           escape_filenames = no
           syslog_severity = "info"
           permissions = 384
           format = "This is a log message for %{User-Name}"
           reference = "messages.%{%{reply:Packet-Type}:-default}"
   }
   # Loading module "log_accounting" from file /etc/freeradius/mods-enabled/linelog
   linelog log_accounting {
           filename = "/var/log/freeradius/linelog-accounting"
           escape_filenames = no
           syslog_severity = "info"
           permissions = 384
           format = ""
           reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}"
   }
 Loaded rlm_date, checking if it's valid
   # Loaded module rlm_date
   # Loading module "date" from file /etc/freeradius/mods-enabled/date
   date {
           format = "%b %e %Y %H:%M:%S %Z"
           utc = no
   }
   # Loading module "wispr2date" from file /etc/freeradius/mods-enabled/date
   date wispr2date {
           format = "%Y-%m-%dT%H:%M:%S"
           utc = no
   }
 Loaded rlm_soh, checking if it's valid
   # Loaded module rlm_soh
   # Loading module "soh" from file /etc/freeradius/mods-enabled/soh
   soh {
           dhcp = yes
   }
 Loaded rlm_passwd, checking if it's valid
   # Loaded module rlm_passwd
   # Loading module "etc_passwd" from file /etc/freeradius/mods-enabled/passwd
   passwd etc_passwd {
           filename = "/etc/passwd"
           format = "*User-Name:Crypt-Password:"
           delimiter = ":"
           ignore_nislike = no
           ignore_empty = yes
           allow_multiple_keys = no
           hash_size = 100
   }
 Loaded rlm_always, checking if it's valid
   # Loaded module rlm_always
   # Loading module "reject" from file /etc/freeradius/mods-enabled/always
   always reject {
           rcode = "reject"
           simulcount = 0
           mpp = no
   }
   # Loading module "fail" from file /etc/freeradius/mods-enabled/always
   always fail {
           rcode = "fail"
           simulcount = 0
           mpp = no
   }
   # Loading module "ok" from file /etc/freeradius/mods-enabled/always
   always ok {
           rcode = "ok"
           simulcount = 0
           mpp = no
   }
   # Loading module "handled" from file /etc/freeradius/mods-enabled/always
   always handled {
           rcode = "handled"
           simulcount = 0
           mpp = no
   }
   # Loading module "invalid" from file /etc/freeradius/mods-enabled/always
   always invalid {
           rcode = "invalid"
           simulcount = 0
           mpp = no
   }
   # Loading module "userlock" from file /etc/freeradius/mods-enabled/always
   always userlock {
           rcode = "userlock"
           simulcount = 0
           mpp = no
   }
   # Loading module "notfound" from file /etc/freeradius/mods-enabled/always
   always notfound {
           rcode = "notfound"
           simulcount = 0
           mpp = no
   }
   # Loading module "noop" from file /etc/freeradius/mods-enabled/always
   always noop {
           rcode = "noop"
           simulcount = 0
           mpp = no
   }
   # Loading module "updated" from file /etc/freeradius/mods-enabled/always
   always updated {
           rcode = "updated"
           simulcount = 0
           mpp = no
   }
   # Loading module "detail" from file /etc/freeradius/mods-enabled/detail
   detail {
           filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
           header = "%t"
           permissions = 384
           locking = no
           escape_filenames = no
           log_packet_header = no
   }
   # Loading module "sradutmp" from file /etc/freeradius/mods-enabled/sradutmp
   radutmp sradutmp {
           filename = "/var/log/freeradius/sradutmp"
           username = "%{User-Name}"
           case_sensitive = yes
           check_with_nas = yes
           permissions = 420
           caller_id = no
   }
   # Instantiating module "preprocess" from file /etc/freeradius/mods-enabled/preprocess
 reading pairlist file /etc/freeradius/mods-config/preprocess/huntgroups
 reading pairlist file /etc/freeradius/mods-config/preprocess/hints
   # Instantiating module "expiration" from file /etc/freeradius/mods-enabled/expiration
   # Instantiating module "mschap" from file /etc/freeradius/mods-enabled/mschap
 rlm_mschap (mschap): using internal authentication
   # Instantiating module "auth_log" from file /etc/freeradius/mods-enabled/detail.log
 rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
   # Instantiating module "reply_log" from file /etc/freeradius/mods-enabled/detail.log
   # Instantiating module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log
   # Instantiating module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log
   # Instantiating module "IPASS" from file /etc/freeradius/mods-enabled/realm
   # Instantiating module "suffix" from file /etc/freeradius/mods-enabled/realm
   # Instantiating module "bangpath" from file /etc/freeradius/mods-enabled/realm
   # Instantiating module "realmpercent" from file /etc/freeradius/mods-enabled/realm
   # Instantiating module "ntdomain" from file /etc/freeradius/mods-enabled/realm
   # Instantiating module "pap" from file /etc/freeradius/mods-enabled/pap
   # Instantiating module "files" from file /etc/freeradius/mods-enabled/files
 reading pairlist file /etc/freeradius/mods-config/files/authorize
 reading pairlist file /etc/freeradius/mods-config/files/accounting
 reading pairlist file /etc/freeradius/mods-config/files/pre-proxy
   # Instantiating module "logintime" from file /etc/freeradius/mods-enabled/logintime
   # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/post-proxy
   # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/pre-proxy
   # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/access_reject
   # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/access_challenge
   # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/accounting_response
   # Instantiating module "attr_filter.coa" from file /etc/freeradius/mods-enabled/attr_filter
 reading pairlist file /etc/freeradius/mods-config/attr_filter/coa
   # Instantiating module "linelog" from file /etc/freeradius/mods-enabled/linelog
   # Instantiating module "log_accounting" from file /etc/freeradius/mods-enabled/linelog
   # Instantiating module "etc_passwd" from file /etc/freeradius/mods-enabled/passwd
 rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no
   # Instantiating module "reject" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "fail" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "ok" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "handled" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "invalid" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "userlock" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "notfound" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "noop" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "updated" from file /etc/freeradius/mods-enabled/always
   # Instantiating module "detail" from file /etc/freeradius/mods-enabled/detail
  } # modules
 radiusd: #### Loading Virtual Servers ####
 server { # from file /etc/freeradius/radiusd.conf
 } # server
 server status { # from file /etc/freeradius/sites-enabled/status
  # Loading authorize {...}
   ok
 Compiling Autz-Type Status-Server for attr Autz-Type
 } # server status
 server openroaming { # from file /etc/freeradius/sites-enabled/openroaming
  # Loading authenticate {...}
 Compiling Auth-Type reject for attr Auth-Type
  # Loading authorize {...}
   update {
    &control:Load-Balance-Key := &Calling-Station-Id
   }
   update {
    &control:Proxy-To-Realm := ""
   }
  # Loading preacct {...}
   update {
    &control:Load-Balance-Key := &Calling-Station-Id
   }
   update {
    &control:Proxy-To-Realm := ""
   }
  # Loading accounting {...}
   ok
 } # server openroaming
  thread pool {
   start_servers = 5
   max_servers = 32
   min_spare_servers = 3
   max_spare_servers = 10
   max_requests_per_server = 0
   cleanup_delay = 5
   max_queue_size = 65536
   auto_limit_acct = no
  }
 Thread spawned new child 1. Total threads in pool: 1
 Thread spawned new child 2. Total threads in pool: 2
 Thread 1 waiting to be assigned a request
 Thread spawned new child 3. Total threads in pool: 3
 Thread spawned new child 4. Total threads in pool: 4
 Thread spawned new child 5. Total threads in pool: 5
 Thread pool initialized
 radiusd: #### Opening IP addresses and Ports ####
 Thread 2 waiting to be assigned a request
 Thread 5 waiting to be assigned a request
 Thread 4 waiting to be assigned a request
 listen {
   type = "auth"
   virtual_server = "openroaming"
   ipaddr = *
   port = 0
   proto = "udp"
 Thread 3 waiting to be assigned a request
   clients = "udp_clients"
   client any {
           ipaddr = 0.0.0.0/0
           require_message_authenticator = no
           secret = "secret"
           proto = "udp"
    limit {
           max_connections = 16
           lifetime = 0
           idle_timeout = 30
    }
   }
 Adding client 0.0.0.0/0 (0.0.0.0) to prefix tree 0
 }
 listen {
   type = "acct"
   virtual_server = "openroaming"
   ipaddr = *
   port = 0
   proto = "udp"
   clients = "udp_clients"
 }
 listen {
   type = "auth+acct"
   virtual_server = "openroaming"
   ipaddr = *
   port = 2083
   proto = "tcp"
   tls {
           verify_depth = 0
           pem_file_type = yes
           private_key_file = "/pki/server.key"
           certificate_file = "/pki/server.crt"
           ca_file = "/pki/ca/ca.crt"
           fragment_size = 8192
           include_length = yes
           auto_chain = yes
           check_crl = no
           check_all_crl = no
           ca_path_reload_interval = 0
           cipher_list = "DEFAULT"
           cipher_server_preference = no
           require_client_cert = yes
           reject_unknown_intermediate_ca = no
           ecdh_curve = ""
           tls_max_version = "1.3"
           tls_min_version = "1.2"
    cache {
           enable = no
           lifetime = 24
           max_entries = 255
    }
    verify {
           skip_if_ocsp_ok = no
    }
    ocsp {
           enable = no
           override_cert_url = no
           use_nonce = yes
           timeout = 0
           softfail = no
    }
   }
   check_client_connections = no
   limit {
           max_connections = 0
           lifetime = 0
           idle_timeout = 30
   }
   clients = "openroaming_radsec_clients"
   client any {
           ipaddr = 0.0.0.0/0
           require_message_authenticator = no
           secret = "radsec"
           proto = "tls"
    limit {
           max_connections = 0
           lifetime = 0
           idle_timeout = 30
    }
   }
 Adding client 0.0.0.0/0 (0.0.0.0) to prefix tree 0
 }
 listen {
   type = "auth+acct"
   virtual_server = "openroaming"
   ipaddr = *
   port = 3083
   proto = "tcp"
   tls {
           verify_depth = 0
           pem_file_type = yes
           private_key_file = "/pki/server.key"
           certificate_file = "/pki/server.crt"
           ca_file = "/pki/ca/ca.crt"
           fragment_size = 8192
           include_length = yes
           auto_chain = yes
           check_crl = no
           check_all_crl = no
           ca_path_reload_interval = 0
           cipher_list = "DEFAULT"
           cipher_server_preference = no
           require_client_cert = yes
           reject_unknown_intermediate_ca = no
           ecdh_curve = ""
           tls_max_version = "1.3"
           tls_min_version = "1.2"
    cache {
           enable = no
           lifetime = 24
           max_entries = 255
    }
    verify {
           skip_if_ocsp_ok = no
    }
    ocsp {
           enable = no
           override_cert_url = no
           use_nonce = yes
           timeout = 0
           softfail = no
    }
   }
   check_client_connections = no
   limit {
           max_connections = 0
           lifetime = 0
           idle_timeout = 30
   }
   clients = "openroaming_radsec_clients"
 }
 listen {
           type = "status"
           ipaddr = 0.0.0.0
           port = 18121
   client admin {
           ipaddr = 0.0.0.0
           require_message_authenticator = no
           secret = "secret"
    limit {
           max_connections = 16
           lifetime = 0
           idle_timeout = 30
    }
   }
 Adding client 0.0.0.0/0 (0.0.0.0) to prefix tree 0
 }
 Listening on auth address * port 1812 bound to server openroaming
 Listening on acct address * port 1813 bound to server openroaming
 Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server openroaming
 Listening on auth+acct proto tcp address * port 3083 (TLS) bound to server openroaming
 Listening on status address * port 18121 bound to server status
Info: Ready to process requests
 Threads: total/active/spare threads = 5/0/5
 Waking up in 0.3 seconds.
 Thread 2 got semaphore
 Thread 2 handling request 0, (1 handled so far)
 (0) Received Access-Request Id 47 from 192.168.0.5:52203 to 192.168.0.4:1812 length 31
 (0)   User-Name = "test@user"
 (0) session-state: No State attribute
 (0) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (0)   authorize {
 (0)     update control {
 (0)       No attributes updated for RHS &Calling-Station-Id
 (0)     } # update control = noop
 (0)     update control {
 (0)       &Proxy-To-Realm := ""
 (0)     } # update control = noop
 (0)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (0) Starting proxy to home server 192.168.0.3 port 2083
 (0) server openroaming {
 (0)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (0) }
 (0) proxy: Trying to allocate ID (0/2)
 (0) proxy: Trying to open a new listener to the home server
 (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (192.168.0.3, 2083)
 Requiring Server certificate
 (0) (TLS) Handshake state [PINIT] - before SSL initialization (0)
 (0) (TLS) Handshake state [PINIT] - Client before SSL initialization (0)
 (0) (TLS) send TLS 1.2 Handshake, ClientHello
 (0) (TLS) Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
 (0) (TLS) Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
 (0) (TLS) recv TLS 1.2 Handshake, ServerHello
 (0) (TLS) Handshake state [TRSH] - Client SSLv3/TLS read server hello (3)
 (0) (TLS) recv TLS 1.2 Handshake, Certificate
 (0) (TLS) Creating attributes from server certificate
 (0)   TLS-Cert-Serial := "10b07c2c514073c3514ef8bea9782f92e00216f7"
 (0)   TLS-Cert-Expiration := "21210302182204Z"
 (0)   TLS-Cert-Valid-Since := "210326182204Z"
 (0)   TLS-Cert-Subject := "/CN=valid_ca"
 (0)   TLS-Cert-Issuer := "/CN=valid_ca"
 (0)   TLS-Cert-Common-Name := "valid_ca"
 (0) (TLS) chain-depth   : 1
 (0) (TLS) error         : 0
 (0) (TLS) common name   : valid_ca
 (0) (TLS) subject       : /CN=valid_ca
 (0) (TLS) issuer        : /CN=valid_ca
 (0) (TLS) verify return : 1
 (0) (TLS) Creating attributes from client certificate
 (0)   TLS-Client-Cert-Serial := "e966c4723931eef697e941e858faad6d"
 (0)   TLS-Client-Cert-Expiration := "21210302182244Z"
 (0)   TLS-Client-Cert-Valid-Since := "210326182244Z"
 (0)   TLS-Client-Cert-Subject := "/CN=valid_server"
 (0)   TLS-Client-Cert-Issuer := "/CN=valid_ca"
 (0)   TLS-Client-Cert-Common-Name := "valid_server"
 (0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "valid_server"
 (0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
 (0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "EE:CA:3B:69:D0:43:44:B8:74:C2:99:E1:61:5A:6C:02:F9:E1:2C:62"
 (0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:CC:0E:1E:EF:44:88:74:BF:E8:A6:63:DB:0C:1D:D5:33:8C:2C:30:D5\nDirName:/CN=valid_ca\nserial:10:B0:7C:2C:51:40:73:C3:51:4E:F8:BE:A9:78:2F:92:E0:02:16:F7"
 (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Server Authentication"
 (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
 (0)   Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:valid_server'.  Please check that both the attribute and value are defined in the dictionaries
 (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Warning: Certificate chain - 1 cert(s) untrusted
Warning: (TLS) untrusted certificate with depth [1] subject name /CN=valid_ca
Warning: (TLS) untrusted certificate with depth [0] subject name /CN=valid_server
 (0) (TLS) chain-depth   : 0
 (0) (TLS) error         : 0
 (0) (TLS) common name   : valid_server
 (0) (TLS) subject       : /CN=valid_server
 (0) (TLS) issuer        : /CN=valid_ca
 (0) (TLS) verify return : 1
 (0) (TLS) Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4)
 (0) (TLS) recv TLS 1.2 Handshake, ServerKeyExchange
 (0) (TLS) Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (6)
 (0) (TLS) recv TLS 1.2 Handshake, CertificateRequest
 (0) (TLS) Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7)
 (0) (TLS) recv TLS 1.2 Handshake, ServerHelloDone
 (0) (TLS) Handshake state [TRSD] - Client SSLv3/TLS read server done (8)
 (0) (TLS) send TLS 1.2 Handshake, Certificate
 (0) (TLS) Handshake state [TWCC] - Client SSLv3/TLS write client certificate (13)
 (0) (TLS) send TLS 1.2 Handshake, ClientKeyExchange
 (0) (TLS) Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (14)
 (0) (TLS) send TLS 1.2 Handshake, CertificateVerify
 (0) (TLS) Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (15)
 (0) (TLS) send TLS 1.2 ChangeCipherSpec
 (0) (TLS) Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (16)
 (0) (TLS) send TLS 1.2 Handshake, Finished
 (0) (TLS) Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
 (0) (TLS) Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
 (0) (TLS) Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (10)
 (0) (TLS) recv TLS 1.2 Handshake, Finished
 (0) (TLS) Handshake state [TRFIN] - Client SSLv3/TLS read finished (11)
 (0) (TLS) Handshake state [SSLOK] - SSL negotiation finished successfully (1)
 Opened new proxy socket 'proxy (192.168.0.4, 55545) -> home_server (192.168.0.3, 2083)'
 (0) proxy: Trying to allocate ID (1/2)
 Listening on proxy (192.168.0.4, 55545) -> home_server (192.168.0.3, 2083)
 Waking up in 0.2 seconds.
 (0) proxy: request is now in proxy hash
 (0) proxy: allocating destination 192.168.0.3 port 2083 - Id 148
 (0) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (0) Sent Access-Request Id 148 from 192.168.0.4:55545 to 192.168.0.3:2083 length 53
 (0)   User-Name = "test@user"
 (0)   Message-Authenticator := 0x00
 (0)   Proxy-State = 0x3437
 Proxy is writing 53 bytes to SSL
 Thread 2 waiting to be assigned a request
 (0) Expecting proxy response no later than 6.702940 seconds from now
 Waking up in 6.7 seconds.
 Suppressing duplicate proxied request (tcp) to home server 192.168.0.3 port 2083 proto TCP - ID: 148
 Waking up in 2.0 seconds.
 (0) No proxy response, giving up on request and marking it done
ERROR: (0) Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.3 port 2083
 Waking up in 0.3 seconds.
 Thread 1 got semaphore
 Thread 1 handling request 0, (1 handled so far)
 (0) Clearing existing &reply: attributes
 (0) Found Post-Proxy-Type Fail-Authentication
 (0) server openroaming {
 (0)   Post-Proxy-Type sub-section not found.  Ignoring.
 (0) }
Auth: (0) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
 (0) There was no response configured: rejecting request
 (0) Using Post-Auth-Type Reject
 (0) Post-Auth-Type sub-section not found.  Ignoring.
 (0) Sent Access-Reject Id 47 from 192.168.0.4:1812 to 192.168.0.5:52203 length 20
 (0) Finished request
 Thread 1 waiting to be assigned a request
 Waking up in 4.6 seconds.
 Waking up in 0.3 seconds.
 Thread 5 got semaphore
 Thread 5 handling request 1, (1 handled so far)
 (1) Received Access-Request Id 194 from 192.168.0.5:40426 to 192.168.0.4:1812 length 31
 (1)   User-Name = "test@user"
 (1) session-state: No State attribute
 (1) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (1)   authorize {
 (1)     update control {
 (1)       No attributes updated for RHS &Calling-Station-Id
 (1)     } # update control = noop
 (1)     update control {
 (1)       &Proxy-To-Realm := ""
 (1)     } # update control = noop
 (1)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (1) Starting proxy to home server 192.168.0.3 port 2083
 (1) server openroaming {
 (1)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (1) }
 (1) proxy: Trying to allocate ID (0/2)
 (1) proxy: request is now in proxy hash
 (1) proxy: allocating destination 192.168.0.3 port 2083 - Id 59
 (1) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (1) Sent Access-Request Id 59 from 192.168.0.4:55545 to 192.168.0.3:2083 length 54
 (1)   User-Name = "test@user"
 (1)   Message-Authenticator := 0x00
 (1)   Proxy-State = 0x313934
 Proxy is writing 54 bytes to SSL
 Thread 5 waiting to be assigned a request
 (1) Expecting proxy response no later than 6.661502 seconds from now
 Waking up in 3.6 seconds.
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 24 bytes
Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.3 port 2083 - ID 148
 Waking up in 1.9 seconds.
 (0) Cleaning up request packet ID 47 with timestamp +0 due to cleanup_delay was reached
 Waking up in 3.0 seconds.
 Suppressing duplicate proxied request (tcp) to home server 192.168.0.3 port 2083 proto TCP - ID: 59
 Waking up in 1.9 seconds.
 (1) No proxy response, giving up on request and marking it done
ERROR: (1) Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.3 port 2083
 Waking up in 0.3 seconds.
 Thread 4 got semaphore
 Thread 4 handling request 1, (1 handled so far)
 (1) Clearing existing &reply: attributes
 (1) Found Post-Proxy-Type Fail-Authentication
 (1) server openroaming {
 (1)   Post-Proxy-Type sub-section not found.  Ignoring.
 (1) }
Auth: (1) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
 (1) There was no response configured: rejecting request
 (1) Using Post-Auth-Type Reject
 (1) Post-Auth-Type sub-section not found.  Ignoring.
 (1) Sent Access-Reject Id 194 from 192.168.0.4:1812 to 192.168.0.5:40426 length 20
 (1) Finished request
 Thread 4 waiting to be assigned a request
 Waking up in 4.6 seconds.
 Waking up in 0.3 seconds.
 Thread 3 got semaphore
 Thread 3 handling request 2, (1 handled so far)
 (2) Received Access-Request Id 10 from 192.168.0.5:38097 to 192.168.0.4:1812 length 31
 (2)   User-Name = "test@user"
 (2) session-state: No State attribute
 (2) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (2)   authorize {
 (2)     update control {
 (2)       No attributes updated for RHS &Calling-Station-Id
 (2)     } # update control = noop
 (2)     update control {
 (2)       &Proxy-To-Realm := ""
 (2)     } # update control = noop
 (2)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (2) Starting proxy to home server 192.168.0.3 port 2083
 (2) server openroaming {
 (2)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (2) }
 (2) proxy: Trying to allocate ID (0/2)
 (2) proxy: request is now in proxy hash
 (2) proxy: allocating destination 192.168.0.3 port 2083 - Id 87
 (2) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (2) Sent Access-Request Id 87 from 192.168.0.4:55545 to 192.168.0.3:2083 length 53
 (2)   User-Name = "test@user"
 (2)   Message-Authenticator := 0x00
 (2)   Proxy-State = 0x3130
 Proxy is writing 53 bytes to SSL
 Thread 3 waiting to be assigned a request
 (2) Expecting proxy response no later than 6.661842 seconds from now
 Waking up in 3.6 seconds.
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 25 bytes
Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.3 port 2083 - ID 59
 Waking up in 1.8 seconds.
 (1) Cleaning up request packet ID 194 with timestamp +8 due to cleanup_delay was reached
 Waking up in 3.0 seconds.
 Suppressing duplicate proxied request (tcp) to home server 192.168.0.3 port 2083 proto TCP - ID: 87
 Waking up in 1.9 seconds.
 (2) No proxy response, giving up on request and marking it done
ERROR: (2) Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.3 port 2083
 Waking up in 0.3 seconds.
 Thread 2 got semaphore
 Thread 2 handling request 2, (2 handled so far)
 (2) Clearing existing &reply: attributes
 (2) Found Post-Proxy-Type Fail-Authentication
 (2) server openroaming {
 (2)   Post-Proxy-Type sub-section not found.  Ignoring.
 (2) }
Auth: (2) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
 (2) There was no response configured: rejecting request
 (2) Using Post-Auth-Type Reject
 (2) Post-Auth-Type sub-section not found.  Ignoring.
 (2) Sent Access-Reject Id 10 from 192.168.0.4:1812 to 192.168.0.5:38097 length 20
 (2) Finished request
 Thread 2 waiting to be assigned a request
 Waking up in 4.6 seconds.
 Waking up in 0.3 seconds.
 Thread 1 got semaphore
 Thread 1 handling request 3, (2 handled so far)
 (3) Received Access-Request Id 105 from 192.168.0.5:56674 to 192.168.0.4:1812 length 31
 (3)   User-Name = "test@user"
 (3) session-state: No State attribute
 (3) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (3)   authorize {
 (3)     update control {
 (3)       No attributes updated for RHS &Calling-Station-Id
 (3)     } # update control = noop
 (3)     update control {
 (3)       &Proxy-To-Realm := ""
 (3)     } # update control = noop
 (3)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (3) Starting proxy to home server 192.168.0.3 port 2083
 (3) server openroaming {
 (3)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (3) }
 (3) proxy: Trying to allocate ID (0/2)
 (3) proxy: request is now in proxy hash
 (3) proxy: allocating destination 192.168.0.3 port 2083 - Id 168
 (3) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (3) Sent Access-Request Id 168 from 192.168.0.4:55545 to 192.168.0.3:2083 length 54
 (3)   User-Name = "test@user"
 (3)   Message-Authenticator := 0x00
 (3)   Proxy-State = 0x313035
 Proxy is writing 54 bytes to SSL
 Thread 1 waiting to be assigned a request
 (3) Expecting proxy response no later than 6.663556 seconds from now
 Waking up in 3.6 seconds.
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 24 bytes
Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.3 port 2083 - ID 87
 Waking up in 1.8 seconds.
 (2) Cleaning up request packet ID 10 with timestamp +16 due to cleanup_delay was reached
 Waking up in 3.0 seconds.
 Suppressing duplicate proxied request (tcp) to home server 192.168.0.3 port 2083 proto TCP - ID: 168
 Waking up in 1.9 seconds.
 (3) No proxy response, giving up on request and marking it done
ERROR: (3) Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.3 port 2083
 Waking up in 0.3 seconds.
 Thread 5 got semaphore
 Thread 5 handling request 3, (2 handled so far)
 (3) Clearing existing &reply: attributes
 (3) Found Post-Proxy-Type Fail-Authentication
 (3) server openroaming {
 (3)   Post-Proxy-Type sub-section not found.  Ignoring.
 (3) }
Auth: (3) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
 (3) There was no response configured: rejecting request
 (3) Using Post-Auth-Type Reject
 (3) Post-Auth-Type sub-section not found.  Ignoring.
 (3) Sent Access-Reject Id 105 from 192.168.0.4:1812 to 192.168.0.5:56674 length 20
 (3) Finished request
 Thread 5 waiting to be assigned a request
 Waking up in 4.6 seconds.
 Waking up in 0.3 seconds.
 Thread 4 got semaphore
 Thread 4 handling request 4, (2 handled so far)
 (4) Received Access-Request Id 171 from 192.168.0.5:37520 to 192.168.0.4:1812 length 31
 (4)   User-Name = "test@user"
 (4) session-state: No State attribute
 (4) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (4)   authorize {
 (4)     update control {
 (4)       No attributes updated for RHS &Calling-Station-Id
 (4)     } # update control = noop
 (4)     update control {
 (4)       &Proxy-To-Realm := ""
 (4)     } # update control = noop
 (4)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (4) Starting proxy to home server 192.168.0.3 port 2083
 (4) server openroaming {
 (4)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (4) }
 (4) proxy: Trying to allocate ID (0/2)
 (4) proxy: request is now in proxy hash
 (4) proxy: allocating destination 192.168.0.3 port 2083 - Id 48
 (4) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (4) Sent Access-Request Id 48 from 192.168.0.4:55545 to 192.168.0.3:2083 length 54
 (4)   User-Name = "test@user"
 (4)   Message-Authenticator := 0x00
 (4)   Proxy-State = 0x313731
 Proxy is writing 54 bytes to SSL
 Thread 4 waiting to be assigned a request
 (4) Expecting proxy response no later than 6.664532 seconds from now
 Waking up in 3.6 seconds.
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 25 bytes
Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.3 port 2083 - ID 168
 Waking up in 1.8 seconds.
 (3) Cleaning up request packet ID 105 with timestamp +24 due to cleanup_delay was reached
 Waking up in 3.0 seconds.
 Suppressing duplicate proxied request (tcp) to home server 192.168.0.3 port 2083 proto TCP - ID: 48
 Waking up in 1.9 seconds.
 (4) No proxy response, giving up on request and marking it done
Proxy: Marking home server 192.168.0.3 port 2083 as zombie (it has not responded in 7.000000 seconds).
 (5) proxy: Trying to allocate ID (0/2)
 (5) proxy: request is now in proxy hash
 (5) proxy: allocating destination 192.168.0.3 port 2083 - Id 241
 PING: Waiting 1 seconds for response to ping
 (5) Sent Status-Server Id 241 from 192.168.0.4:55545 to 192.168.0.3:2083 length 70
 (5)   Message-Authenticator := 0x00
 (5)   NAS-Identifier := "Status Check 0. Are you alive?"
 Proxy is writing 70 bytes to SSL
 PING: Next status packet in 10 seconds
ERROR: (4) Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.3 port 2083
 Waking up in 0.3 seconds.
 Thread 3 got semaphore
 Thread 3 handling request 4, (2 handled so far)
 (4) Clearing existing &reply: attributes
 (4) Found Post-Proxy-Type Fail-Authentication
 (4) server openroaming {
 (4)   Post-Proxy-Type sub-section not found.  Ignoring.
 (4) }
Auth: (4) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
 (4) There was no response configured: rejecting request
 (4) Using Post-Auth-Type Reject
 (4) Post-Auth-Type sub-section not found.  Ignoring.
 (4) Sent Access-Reject Id 171 from 192.168.0.4:1812 to 192.168.0.5:37520 length 20
 (4) Finished request
 Thread 3 waiting to be assigned a request
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 20 bytes
Proxy: (5) Marking home server 192.168.0.3 port 2083 alive
Proxy: (5) Received response to status check 5 ID 241 (1 in current sequence)
 Waking up in 0.3 seconds.
 Waking up in 4.6 seconds.
 Waking up in 0.3 seconds.
 Thread 2 got semaphore
 Thread 2 handling request 6, (3 handled so far)
 (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (192.168.0.3, 2083)
 Requiring Server certificate
 (0) (TLS) Handshake state [PINIT] - before SSL initialization (0)
 (0) (TLS) Handshake state [PINIT] - Client before SSL initialization (0)
 (0) (TLS) send TLS 1.2 Handshake, ClientHello
 (0) (TLS) Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
 (0) (TLS) Handshake state [TWCH] - Client SSLv3/TLS write client hello (12)
 (0) (TLS) recv TLS 1.2 Handshake, ServerHello
 (0) (TLS) Handshake state [TRSH] - Client SSLv3/TLS read server hello (3)
 (0) (TLS) recv TLS 1.2 Handshake, Certificate
 (0) (TLS) Creating attributes from server certificate
 (0)   TLS-Cert-Serial := "10b07c2c514073c3514ef8bea9782f92e00216f7"
 (0)   TLS-Cert-Expiration := "21210302182204Z"
 (0)   TLS-Cert-Valid-Since := "210326182204Z"
 (0)   TLS-Cert-Subject := "/CN=valid_ca"
 (0)   TLS-Cert-Issuer := "/CN=valid_ca"
 (0)   TLS-Cert-Common-Name := "valid_ca"
 (0) (TLS) chain-depth   : 1
 (0) (TLS) error         : 0
 (0) (TLS) common name   : valid_ca
 (0) (TLS) subject       : /CN=valid_ca
 (0) (TLS) issuer        : /CN=valid_ca
 (0) (TLS) verify return : 1
 (0) (TLS) Creating attributes from client certificate
 (0)   TLS-Client-Cert-Serial := "e966c4723931eef697e941e858faad6d"
 (0)   TLS-Client-Cert-Expiration := "21210302182244Z"
 (0)   TLS-Client-Cert-Valid-Since := "210326182244Z"
 (0)   TLS-Client-Cert-Subject := "/CN=valid_server"
 (0)   TLS-Client-Cert-Issuer := "/CN=valid_ca"
 (0)   TLS-Client-Cert-Common-Name := "valid_server"
 (0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "valid_server"
 (0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
 (0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "EE:CA:3B:69:D0:43:44:B8:74:C2:99:E1:61:5A:6C:02:F9:E1:2C:62"
 (0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:CC:0E:1E:EF:44:88:74:BF:E8:A6:63:DB:0C:1D:D5:33:8C:2C:30:D5\nDirName:/CN=valid_ca\nserial:10:B0:7C:2C:51:40:73:C3:51:4E:F8:BE:A9:78:2F:92:E0:02:16:F7"
 (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Server Authentication"
 (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
 (0)   Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:valid_server'.  Please check that both the attribute and value are defined in the dictionaries
 (0)   TLS-Client-Cert-X509v3-Extended-Key-Usage-OID += "1.3.6.1.5.5.7.3.1"
Warning: Certificate chain - 1 cert(s) untrusted
Warning: (TLS) untrusted certificate with depth [1] subject name /CN=valid_ca
Warning: (TLS) untrusted certificate with depth [0] subject name /CN=valid_server
 (0) (TLS) chain-depth   : 0
 (0) (TLS) error         : 0
 (0) (TLS) common name   : valid_server
 (0) (TLS) subject       : /CN=valid_server
 (0) (TLS) issuer        : /CN=valid_ca
 (0) (TLS) verify return : 1
 (0) (TLS) Handshake state [TRSC] - Client SSLv3/TLS read server certificate (4)
 (0) (TLS) recv TLS 1.2 Handshake, ServerKeyExchange
 (0) (TLS) Handshake state [TRSKE] - Client SSLv3/TLS read server key exchange (6)
 (0) (TLS) recv TLS 1.2 Handshake, CertificateRequest
 (0) (TLS) Handshake state [TRCR] - Client SSLv3/TLS read server certificate request (7)
 (0) (TLS) recv TLS 1.2 Handshake, ServerHelloDone
 (0) (TLS) Handshake state [TRSD] - Client SSLv3/TLS read server done (8)
 (0) (TLS) send TLS 1.2 Handshake, Certificate
 (0) (TLS) Handshake state [TWCC] - Client SSLv3/TLS write client certificate (13)
 (0) (TLS) send TLS 1.2 Handshake, ClientKeyExchange
 (0) (TLS) Handshake state [TWCKE] - Client SSLv3/TLS write client key exchange (14)
 (0) (TLS) send TLS 1.2 Handshake, CertificateVerify
 (0) (TLS) Handshake state [TWCV] - Client SSLv3/TLS write certificate verify (15)
 (0) (TLS) send TLS 1.2 ChangeCipherSpec
 (0) (TLS) Handshake state [TWCCS] - Client SSLv3/TLS write change cipher spec (16)
 (0) (TLS) send TLS 1.2 Handshake, Finished
 (0) (TLS) Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
 (0) (TLS) Handshake state [TWFIN] - Client SSLv3/TLS write finished (18)
 (0) (TLS) Handshake state [TRCCS] - Client SSLv3/TLS read change cipher spec (10)
 (0) (TLS) recv TLS 1.2 Handshake, Finished
 (0) (TLS) Handshake state [TRFIN] - Client SSLv3/TLS read finished (11)
 (0) (TLS) Handshake state [SSLOK] - SSL negotiation finished successfully (1)
 Opened new proxy socket 'proxy (192.168.0.4, 51035) -> home_server (192.168.0.3, 2083)'
 (28) proxy: Trying to allocate ID (1/2)
ERROR: (28) proxy: Failed allocating Id for proxied request
Proxy: (28) Failed to insert request into the proxy list
 (28) There was no response configured: rejecting request
 (28) Using Post-Auth-Type Reject
 (28) Post-Auth-Type sub-section not found.  Ignoring.
 (28) Sent Access-Reject Id 18 from 192.168.0.4:1812 to 192.168.0.5:56866 length 20
 Listening on proxy (192.168.0.4, 51035) -> home_server (192.168.0.3, 2083)
 Waking up in 0.3 seconds.
 (28) Finished request
 Thread 1 waiting to be assigned a request
 Waking up in 2.5 seconds.
 Proxy SSL socket has data to read
 (0) (TLS) send TLS 1.2 Alert, fatal decode_error
ERROR: (0) (TLS) Alert write:fatal:decode error
 (TLS) Home server has closed the connection
 (TLS) Closing connection
Info:  ... shutting down socket proxy (192.168.0.4, 56965) -> home_server (192.168.0.3, 2083) (10 of 128)
 ... cleaning up socket proxy (192.168.0.4, 56965) -> home_server (192.168.0.3, 2083)
 Closing TLS socket to home server
 Waking up in 2.0 seconds.
 Proxy SSL socket has data to read
 Proxy received header saying we have a packet of 24 bytes
Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.3 port 2083 - ID 148
 Waking up in 1.8 seconds.
 Waking up in 0.3 seconds.
 Thread 5 got semaphore
 Thread 5 handling request 29, (9 handled so far)
 (29) Received Access-Request Id 17 from 192.168.0.5:50908 to 192.168.0.4:1812 length 31
 (29)   User-Name = "test@user"
 (29) session-state: No State attribute
 (29) # Executing section authorize from file /etc/freeradius/sites-enabled/openroaming
 (29)   authorize {
 (29)     update control {
 (29)       No attributes updated for RHS &Calling-Station-Id
 (29)     } # update control = noop
 (29)     update control {
 (29)       &Proxy-To-Realm := ""
 (29)     } # update control = noop
 (29)   } # authorize = noop
 Using home pool auth for realm DEFAULT
 (29) Starting proxy to home server 192.168.0.3 port 2083
 (29) server openroaming {
 (29)   Empty pre-proxy section in virtual server "openroaming".  Using default return values.
 (29) }
 (29) proxy: Trying to allocate ID (0/2)
 (29) proxy: request is now in proxy hash
 (29) proxy: allocating destination 192.168.0.3 port 2083 - Id 55
 (29) Proxying request to home server 192.168.0.3 port 2083 (TLS) timeout 7.000000
 (29) Sent Access-Request Id 55 from 192.168.0.4:51035 to 192.168.0.3:2083 length 53
 (29)   User-Name = "test@user"
 (29)   Message-Authenticator := 0x00
 (29)   Proxy-State = 0x3137
 Proxy is writing 53 bytes to SSL
 Thread 5 waiting to be assigned a request
 (29) Expecting proxy response no later than 6.665358 seconds from now
 Waking up in 1.5 seconds.
 Proxy SSL socket has data to read
 (0) (TLS) send TLS 1.2 Alert, fatal decode_error
ERROR: (0) (TLS) Alert write:fatal:decode error
 (TLS) Home server has closed the connection
 (TLS) Closing connection
 Closing TLS socket to home server
 Waking up in 0.1 seconds.
Bad talloc magic value - unknown value
talloc abort: Bad talloc magic value - unknown value
Aborted
system-under-test exited with code 134

Relevant log output from client utilities

No response

Backtrace from LLDB or GDB

No response
@rtblossom rtblossom added the defect category: a defect or misbehaviour label May 28, 2024
@alandekok
Copy link
Member

can you run it under gdb gdb --args radiusd ..., and then when it crashes, (gdb_ thread apply all bt full

that will let us know exactly which function and variable had the issue.

@rtblossom
Copy link
Author

rtblossom commented May 28, 2024 •
edited
Loading 

Thread 6 (Thread 0x7ffff2ecb640 (LWP 243) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+168>, expected=expected@entry=0, clockid=clo--Type <RET> for more, q to quit, c to continue without paging--c
ckid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
No locals.
#3  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c640) at src/main/threads.c:741
        self = 0x55555598c640
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488337968, -4503025715553589737, 140737268987456, 0, 140737345439696, 140737488338320, 4503014829358491159, 4503009253253490199}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 5 (Thread 0x7ffff36cc640 (LWP 242) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c4c0) at src/main/threads.c:741
        self = 0x55555598c4c0
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488337968, -4503025715553589737, 140737277380160, 0, 140737345439696, 140737488338320, 4503018128430245399, 4503009253253490199}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 4 (Thread 0x7ffff3ecd640 (LWP 241) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 1716932324, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c340) at src/main/threads.c:741
        self = 0x55555598c340
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488337968, -4503025715553589737, 140737285772864, 0, 140737345439696, 140737488338320, 4503017031602972183, 4503009253253490199}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 3 (Thread 0x7ffff46ce640 (LWP 240) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555597e1d0) at src/main/threads.c:741
        self = 0x55555597e1d0
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488337968, -4503025715553589737, 140737294165568, 0, 140737345439696, 140737488338320, 4503002738488682007, 4503009253253490199}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 2 (Thread 0x7ffff4ecf640 (LWP 239) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 1716932332, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x555555980a80) at src/main/threads.c:741
        self = 0x555555980a80
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488337968, -4503025715553589737, 140737302558272, 0, 140737345439696, 140737488338320, 4503001637366441495, 4503009253253490199}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 1 (Thread 0x7ffff73f57c0 (LWP 235) "freeradius"):
#0  __pthread_kill_implementation (no_tid=0, signo=5, threadid=140737341511616) at ./nptl/pthread_kill.c:44
        tid = <optimized out>
        ret = 0
        pd = 0x7ffff73f57c0
        old_mask = {__val = {206158430240, 140737488336848, 140737488336656, 140737345964223, 0, 140737488326128, 140737488336864, 93824996657472, 0, 140737488336432, 140737353793243, 93824996653216, 0, 93824992483343, 140737152893184, 981}}
        ret = <optimized out>
        pd = <optimized out>
        old_mask = <optimized out>
        ret = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
        resultvar = <optimized out>
        resultvar = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
        __futex = <optimized out>
        resultvar = <optimized out>
        __arg3 = <optimized out>
        __arg2 = <optimized out>
        __arg1 = <optimized out>
        _a3 = <optimized out>
        _a2 = <optimized out>
        _a1 = <optimized out>
        __futex = <optimized out>
        __private = <optimized out>
        __oldval = <optimized out>
        result = <optimized out>
#1  __pthread_kill_internal (signo=5, threadid=140737341511616) at ./nptl/pthread_kill.c:78
No locals.
#2  __GI___pthread_kill (threadid=140737341511616, signo=signo@entry=5) at ./nptl/pthread_kill.c:89
No locals.
#3  0x00007ffff7762476 in __GI_raise (sig=sig@entry=5) at ../sysdeps/posix/raise.c:26
        ret = <optimized out>
#4  0x00007ffff7f51893 in fr_debug_break (always=<optimized out>) at src/lib/debug.c:350
No locals.
#5  0x00007ffff7f518ae in _fr_exit (file=file@entry=0x5555555b5ac2 "src/main/process.c", line=line@entry=5783, status=status@entry=1) at src/lib/debug.c:1190
No locals.
#6  0x0000555555591056 in event_new_fd (this=0x7fffec01ed60) at src/main/process.c:5783
        home = 0x55555593a8a0
        devnull = <optimized out>
        buffer = "proxy (192.168.0.4, 60671) -> home_server (192.168.0.2, 2083)\000\067\330\b\325ZUUU\000\000\351g\255\367\377\177\000\000\000A\001\354\377\177\000\000\002D\365\367\377\177\000\000^\360[UUU\000\000p\200`\362\377\177\000\000@\030\234UUU\000\000\024 ZUUU\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000H\306[UUU\000\000\001\000\000\000\025\000\000\000\002", '\000' <repeats 47 times>...
        sock = 0x7fffec01ef50
#7  0x00005555555aa960 in tls_socket_close (listener=0x7fffec01ed60) at src/main/tls_listen.c:85
        sock = <optimized out>
#8  proxy_tls_recv (listener=0x7fffec01ed60) at src/main/tls_listen.c:1254
        sock = 0x7fffec01ef50
        buffer = "\347][U\000\000\000\000\000\300\262\033\345\067\067\330\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\210\221\224UUU\000\000\366\002YUUU\000\000\210\221\224UUU\000\000\260\275\377\377\377\177\000\000\350\223\224UUU\000\000\235\a\371\367\377\177\000\000 \000\000\000\060\000\000\000\200\275\377\377\377\177\000\000\300\274\377\377\377\177\000\000\000\300\262\033\345\067\067\330@P\245\367\377\177\000\000\000\000\000\000\000\000\000\000\002", '\000' <repeats 31 times>, "\300\377VUUU\000\000`\332\230UUU\000\000\340\203]UUU\000\000\200\345\230UUU\000\000\000\000\000\000\000\000\000\000"...
        packet = 0x7ffff7f6bf6e <fr_packet_cmp+110>
        data = <optimized out>
        data_len = <optimized out>
        is_request = false
        client = 0x0
#9  0x00007ffff7f6cec4 in fr_event_loop (el=0x555555949170) at src/lib/event.c:710
        ef = 0x5555559493a8
        i = 8
        rcode = <optimized out>
        when = {tv_sec = 1716932335, tv_usec = 648741}
        wake = <optimized out>
        read_fds = {fds_bits = {16384, 0 <repeats 15 times>}}
        write_fds = {fds_bits = {0 <repeats 16 times>}}
#10 0x000055555556c4dc in main (argc=<optimized out>, argv=<optimized out>) at src/main/radiusd.c:634
        rcode = 0
        status = <optimized out>
        argval = <optimized out>
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        state = 0x5555555d9520 <global_state.lto_priv>
        autofree = 0x5555555da330

@rtblossom
Copy link
Author

FreeRADIUS logs leading up to crash

Tue May 28 21:38:50 2024 : Debug: Proxy SSL socket has data to read
Tue May 28 21:38:50 2024 : Debug: Proxy received header saying we have a packet of 25 bytes
Tue May 28 21:38:50 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.2 port 2083 - ID 162
Tue May 28 21:38:50 2024 : Debug: Waking up in 1.9 seconds.
Tue May 28 21:38:52 2024 : Debug: (21) Cleaning up request packet ID 180 with timestamp +138 due to cleanup_delay was reached
Tue May 28 21:38:52 2024 : Debug: Waking up in 3.0 seconds.
Tue May 28 21:38:53 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 192.168.0.2 port 2083 proto TCP - ID: 54
Tue May 28 21:38:53 2024 : Debug: Waking up in 2.0 seconds.
Tue May 28 21:38:54 2024 : Debug: Proxy SSL socket has data to read
Tue May 28 21:38:54 2024 : Debug: (0) (TLS) send TLS 1.2 Alert, fatal decode_error
Tue May 28 21:38:54 2024 : ERROR: (0) (TLS) Alert write:fatal:decode error
Tue May 28 21:38:54 2024 : Debug: (TLS) Home server has closed the connection
Tue May 28 21:38:54 2024 : Debug: (TLS) Closing connection
Tue May 28 21:38:54 2024 : Info:  ... shutting down socket proxy (192.168.0.4, 60671) -> home_server (192.168.0.2, 2083) (4 of 128)
Tue May 28 21:38:54 2024 : Error: Fatal error removing socket proxy (192.168.0.4, 60671) -> home_server (192.168.0.2, 2083): socket is still in use
Debugger detected, raising SIGTRAP

Thread 1 "freeradius" received signal SIGTRAP, Trace/breakpoint trap.
__pthread_kill_implementation (no_tid=0, signo=5, threadid=140737341511616) at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
(gdb)
(gdb)

@rtblossom
Copy link
Author

Here is another gdb output I get. But this time, I received a segmentation fault. I also ran with gdb --args /usr/sbin/freeradius -fl stdout (no debug).


Tue May 28 21:57:45 2024 : Auth: (19) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
Tue May 28 21:57:48 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.2 port 2083 - ID 62
Tue May 28 21:57:53 2024 : ERROR: (20) ERROR: Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.2 port 2083
Tue May 28 21:57:53 2024 : Auth: (20) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
Tue May 28 21:57:56 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.2 port 2083 - ID 0
Tue May 28 21:58:01 2024 : ERROR: (21) ERROR: Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.2 port 2083
Tue May 28 21:58:01 2024 : Auth: (21) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
Tue May 28 21:58:09 2024 : ERROR: (22) ERROR: Failing proxied request for user "test@user", due to lack of any response from home server 192.168.0.2 port 2083
Tue May 28 21:58:09 2024 : Auth: (22) Login incorrect (Home Server failed to respond): [test@user] (from client any port 0)
Tue May 28 21:58:12 2024 : Proxy: No outstanding request was found for Access-Reject packet from host 192.168.0.2 port 2083 - ID 4
Tue May 28 21:58:17 2024 : Proxy: Marking home server 192.168.0.2 port 2083 as zombie (it has not responded in 7.000000 seconds).
Tue May 28 21:58:17 2024 : Info:  ... adding new socket proxy (192.168.0.4, 38961) -> home_server (192.168.0.2, 2083) (3 of 128)

Thread 1 "freeradius" received signal SIGSEGV, Segmentation fault.
fr_packet_cmp (a=0x5555559acc70, b=0x0) at src/lib/packet.c:44
44      src/lib/packet.c: No such file or directory.
(gdb) thread apply all bt full

Thread 6 (Thread 0x7ffff2ecb640 (LWP 259) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
--Type <RET> for more, q to quit, c to continue without paging--c
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c410) at src/main/threads.c:741
        self = 0x55555598c410
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488338000, 4161762943641330905, 140737268987456, 0, 140737345439696, 140737488338352, -4161774099214883623, -4161779404677962535}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 5 (Thread 0x7ffff36cc640 (LWP 258) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c290) at src/main/threads.c:741
        self = 0x55555598c290
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488338000, 4161762943641330905, 140737277380160, 0, 140737345439696, 140737488338352, -4161770801216871207, -4161779404677962535}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 4 (Thread 0x7ffff3ecd640 (LWP 257) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 1716933486, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555598c110) at src/main/threads.c:741
        self = 0x55555598c110
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488338000, 4161762943641330905, 140737285772864, 0, 140737345439696, 140737488338352, -4161771901265369895, -4161779404677962535}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 3 (Thread 0x7ffff46ce640 (LWP 256) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x55555597dfa0) at src/main/threads.c:741
        self = 0x55555597dfa0
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488338000, 4161762943641330905, 140737294165568, 0, 140737345439696, 140737488338352, -4161777399360379687, -4161779404677962535}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 2 (Thread 0x7ffff4ecf640 (LWP 255) "freeradius"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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=0x5555555d80e8 <thread_pool.lto_priv+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  0x00007ffff77bcbdf in do_futex_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
        err = <optimized out>
#4  0x00007ffff77bcc78 in __new_sem_wait_slow64 (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
        _buffer = {__routine = 0x7ffff77bcbb0 <__sem_wait_cleanup>, __arg = 0x5555555d80e8 <thread_pool.lto_priv+168>, __canceltype = 1716933494, __prev = 0x0}
        err = <optimized out>
        d = 17179869184
#5  0x00007ffff77bccf1 in __new_sem_wait (sem=sem@entry=0x5555555d80e8 <thread_pool.lto_priv+168>) at ./nptl/sem_wait.c:42
No locals.
#6  0x000055555558b1b0 in request_handler_thread (arg=0x555555980850) at src/main/threads.c:741
        self = 0x555555980850
        re_wait = <optimized out>
#7  0x00007ffff77b4ac3 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 = {140737488338000, 4161762943641330905, 140737302558272, 0, 140737345439696, 140737488338352, -4161778499408878375, -4161779404677962535}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#8  0x00007ffff7846850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.

Thread 1 (Thread 0x7ffff73f57c0 (LWP 251) "freeradius"):
#0  fr_packet_cmp (a=0x5555559acc70, b=0x0) at src/lib/packet.c:44
        rcode = <optimized out>
#1  0x00007ffff7f60662 in rbtree_insert_node (tree=0x55555598b670, data=0x5555559ad228) at src/lib/rbtree.c:275
        result = <optimized out>
        current = 0x5555559b07a0
        parent = 0x7ffff7f83020 <sentinel>
        x = <optimized out>
#2  0x00007ffff7f608cd in rbtree_insert (tree=<optimized out>, data=<optimized out>) at src/lib/rbtree.c:333
No locals.
#3  0x00007ffff7f6ca29 in fr_packet_list_id_alloc (pl=<optimized out>, proto=<optimized out>, request_p=request_p@entry=0x5555559ad228, pctx=pctx@entry=0x7fffffffbb78) at src/lib/packet.c:884
        i = 0
        j = 0
        k = 0
        fd = 0
        id = 154
        start_i = <optimized out>
        start_j = <optimized out>
        start_k = <optimized out>
        src_any = 1
        ps = 0x7ffff72dcba8
        request = 0x5555559acc70
#4  0x0000555555597905 in insert_into_proxy_hash (request=request@entry=0x5555559ad1c0) at src/main/process.c:2420
        this = <optimized out>
        sock = <optimized out>
        buf = "\000\000\000\000\000\000\000\000\300\321\232UUU\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\240\030\234UUU\000\000\000\031\234UUU\000\000H\001\000\000\000\000\000\000\305\037\367\367\377\177\000\000\300\321\232UUU\000\000\230\000\000\000\000\000\000\000\a\000\000\000\000\000\000\000\320\274\377\377\377\177\000\000#\b\000\000\000\000\000\000\270\020\245\367\377\177\000\000\020\314\232UUU\000\000\000{\026D1\364~\210"
        tries = 1
        success = false
        proxy_listener = 0x5555559ace00
        reverse_coa = false
#5  0x0000555555597f56 in ping_home_server (ctx=ctx@entry=0x55555593a670) at src/main/process.c:4020
        home = 0x55555593a670
        request = 0x5555559ad1c0
        vp = <optimized out>
        when = {tv_sec = 1716933527, tv_usec = 500000}
        now = {tv_sec = 1716933497, tv_usec = 782565}
#6  0x0000555555599963 in mark_home_server_zombie (response_window=<optimized out>, now=0x7fffffffbcc0, home=0x55555593a670) at src/main/process.c:4123
        start = <optimized out>
        buffer = "192.168.0.2\000\377\177\000\000\000P\245\367\377\177\000\000ST|\367\377\177\000\000\263\313ZUUU\000\000\244\002\245\367\377\177\000\000P\b\233UUU\000\000\000\000\000\000\000\000\000\000\317\067\367\367\377\177\000\000\244\002\245\367\377\177\000\000\300Y\232UUU\000\000\b", '\000' <repeats 15 times>, "hl\233UUU\000\000@\217\224UUU\000\000\001\000\000\000\000\000\000"
        start = <optimized out>
        buffer = <optimized out>
#7  proxy_wait_for_reply (request=0x5555559b6bc0, action=<optimized out>) at src/main/process.c:4449
        now = {tv_sec = 1716933497, tv_usec = 782218}
        when = {tv_sec = 1716933497, tv_usec = 776130}
        response_window = <optimized out>
        home = 0x55555593a670
        buffer = "192.168.0.2\000\377\177\000\000\000P\245\367\377\177\000\000ST|\367\377\177\000\000\263\313ZUUU\000\000\244\002\245\367\377\177\000\000P\b\233UUU\000\000\000\000\000\000\000\000\000\000\317\067\367\367\377\177\000\000\244\002\245\367\377\177\000\000\300Y\232UUU\000\000\b", '\000' <repeats 15 times>, "hl\233UUU\000\000@\217\224UUU\000\000\001\000\000\000\000\000\000"
        __FUNCTION__ = "proxy_wait_for_reply"
#8  0x00007ffff7f69c5b in fr_event_run (when=0x7fffffffbdd0, el=0x555555948f40) at src/lib/event.c:316
        callback = 0x555555587750 <request_timer>
        ctx = 0x5555559b6bc0
        ev = <optimized out>
        callback = <optimized out>
        ctx = <optimized out>
        ev = <optimized out>
#9  fr_event_run (el=el@entry=0x555555948f40, when=when@entry=0x7fffffffbdd0) at src/lib/event.c:273
        callback = <optimized out>
        ctx = <optimized out>
        ev = <optimized out>
#10 0x00007ffff7f6ce2f in fr_event_loop (el=0x555555948f40) at src/lib/event.c:686
        i = <optimized out>
        rcode = 0
        when = {tv_sec = 1716933497, tv_usec = 782206}
        wake = <optimized out>
        read_fds = {fds_bits = {0 <repeats 16 times>}}
        write_fds = {fds_bits = {0 <repeats 16 times>}}
#11 0x000055555556c4dc in main (argc=<optimized out>, argv=<optimized out>) at src/main/radiusd.c:634
        rcode = 0
        status = <optimized out>
        argval = <optimized out>
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        state = 0x5555555d9520 <global_state.lto_priv>
        autofree = 0x5555555da330

mcnewton added a commit that referenced this issue May 29, 2024
@mcnewton
remove TCP Status-Server requests from proxy hash as well
05a4bfc 
fixes #5326
@mcnewton
Copy link
Member

Thanks for the report (and helpful docker environment) - fixed in 05a4bfc

@rtblossom
Copy link
Author

Thanks for quickly fixing this! I see this issue in 3.0.26 as well. Should I open another defect? Or did your fix cover 3.0.26 as well?

@alandekok
Copy link
Member

We'll push a fix for 3.0, too.

mcnewton added a commit that referenced this issue May 29, 2024
@mcnewton
remove TCP Status-Server requests from proxy hash as well
dfe709d 
fixes #5326
@mcnewton
Copy link
Member

@rtblossom 3.0.x fix added as well. Was giving it a while to test.

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
3 participants
@alandekok @mcnewton @rtblossom