search

FreeRADIUS / freeradius-server

FreeRADIUS - A multi-protocol policy server.
http://freeradius.org
GNU General Public License v2.0
2.11k stars 1.08k forks source link

[defect]: PROXY protocol crash #4168

Closed gk-fschubert closed 3 years ago

gk-fschubert commented 3 years ago

What type of defect/bug is this?

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

How can the issue be reproduced?

To reproduce the bug you'll have to run your RADIUS server behind a load balancer which supports PROXY Protocol(version 1).

Build your Server(Ubuntu 20.04):

apt update -yq
apt install -yq git gcc make 

git clone --depth 1 --single-branch --branch v3.0.x https://github.com/FreeRADIUS/freeradius-server
cd freeradius-server

apt install -yq libc-dev libtalloc-dev
apt install -yq openssl libssl-dev
apt install -yq linux-headers-generic
apt install -yq libpcre3-dev libidn11-dev krb5-multidev samba samba-dev libcurl4-openssl-dev libjson-c-dev libwbclient-sssd
apt update -yq && apt upgrade -yq && apt update --fix-missing -yq
apt install -yq python3-pip musl-dev python3-dev libffi-dev  python3 

./configure --with-rlm-python3=yes --with-rlm-python3-config-bin=$(which python3-config)  --with-openssl=yes 
make -j2
make install

apt update -yq  && apt upgrade -yq

Enable tls(RadSec), set 'proxy_protocol' to yes in your tls file and make sure your RadSec client is allowed to connect.

Ensure that your TCP forwareder is forwarding the requests via PROXY protocol to FreeRADIUS.

Start connecting multiple RadSec clients to your FreeRADIUS server. After a while it should break.

Log output from the FreeRADIUS daemon

$ radiusd -fxx -l stdout

FreeRADIUS Version 3.0.24
Copyright (C) 1999-2021 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT
Starting - reading configuration files ...
including dictionary file /usr/local/share/freeradius/dictionary
including dictionary file /usr/local/share/freeradius/dictionary.dhcp
including dictionary file /usr/local/share/freeradius/dictionary.vqp
including dictionary file /usr/local/etc/raddb/dictionary
including configuration file /usr/local/etc/raddb/radiusd.conf
including configuration file /usr/local/etc/raddb/mods-available/always
including configuration file /usr/local/etc/raddb/mods-available/attr_filter
including configuration file /usr/local/etc/raddb/mods-available/date
including configuration file /usr/local/etc/raddb/mods-available/detail
including configuration file /usr/local/etc/raddb/mods-available/detail.log
including configuration file /usr/local/etc/raddb/mods-available/eap
including configuration file /usr/local/etc/raddb/mods-available/echo
including configuration file /usr/local/etc/raddb/mods-available/exec
including configuration file /usr/local/etc/raddb/mods-available/expiration
including configuration file /usr/local/etc/raddb/mods-available/expr
including configuration file /usr/local/etc/raddb/mods-available/logintime
including configuration file /usr/local/etc/raddb/mods-available/preprocess
including configuration file /usr/local/etc/raddb/mods-available/unix
including configuration file /usr/local/etc/raddb/mods-available/utf8
including configuration file /usr/local/etc/raddb/mods-available/linelog
including configuration file /usr/local/etc/raddb/mods-available/rest
including configuration file /usr/local/etc/raddb/mods-available/python3
including configuration file /usr/local/etc/raddb/mods-available/inner-eap
including configuration file /usr/local/etc/raddb/mods-available/mschap
including configuration file /usr/local/etc/raddb/policy.d/accounting
including configuration file /usr/local/etc/raddb/policy.d/debug
including configuration file /usr/local/etc/raddb/policy.d/eap
including configuration file /usr/local/etc/raddb/sites-available/check-eap-tls
including configuration file /usr/local/etc/raddb/sites-available/virt-serv
including configuration file /usr/local/etc/raddb/sites-available/radsec-serv
including configuration file /usr/local/etc/raddb/sites-available/inner-tunnel
main {
 security {
    allow_core_dumps = yes
 }
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
}
Core dumps are enabled
main {
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    sbindir = "/usr/local/sbin"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
    libdir = "/usr/local/lib"
    radacctdir = "/var/log/freeradius/accounting"
    hostname_lookups = no
    max_request_time = 30
    cleanup_delay = 5
    max_requests = 5300000
    postauth_client_lost = no
    pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
    checkrad = "/usr/local/sbin/checkrad"
    debug_level = 0
    proxy_requests = no
 log {
    stripped_names = no
    auth = yes
    auth_badpass = yes
    auth_goodpass = no
    colourise = yes
    msg_denied = "You are already logged in - access denied"
 }
 resources {
 }
 security {
    max_attributes = 200
    reject_delay = 0.000000
    status_server = no
    allow_vulnerable_openssl = "CVE-2016-6304"
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
Debugger not attached
 # Creating Auth-Type = eap
 # Creating Auth-Type = inner-eap
 # Creating Auth-Type = MS-CHAP
radiusd: #### Instantiating modules ####
 modules {
  # Loaded module rlm_always
  # Loading module "reject" from file /usr/local/etc/raddb/mods-available/always
  always reject {
    rcode = "reject"
    simulcount = 0
    mpp = no
  }
  # Loading module "fail" from file /usr/local/etc/raddb/mods-available/always
  always fail {
    rcode = "fail"
    simulcount = 0
    mpp = no
  }
  # Loading module "ok" from file /usr/local/etc/raddb/mods-available/always
  always ok {
    rcode = "ok"
    simulcount = 0
    mpp = no
  }
  # Loading module "handled" from file /usr/local/etc/raddb/mods-available/always
  always handled {
    rcode = "handled"
    simulcount = 0
    mpp = no
  }
  # Loading module "invalid" from file /usr/local/etc/raddb/mods-available/always
  always invalid {
    rcode = "invalid"
    simulcount = 0
    mpp = no
  }
  # Loading module "userlock" from file /usr/local/etc/raddb/mods-available/always
  always userlock {
    rcode = "userlock"
    simulcount = 0
    mpp = no
  }
  # Loading module "notfound" from file /usr/local/etc/raddb/mods-available/always
  always notfound {
    rcode = "notfound"
    simulcount = 0
    mpp = no
  }
  # Loading module "noop" from file /usr/local/etc/raddb/mods-available/always
  always noop {
    rcode = "noop"
    simulcount = 0
    mpp = no
  }
  # Loading module "updated" from file /usr/local/etc/raddb/mods-available/always
  always updated {
    rcode = "updated"
    simulcount = 0
    mpp = no
  }
  # Loaded module rlm_attr_filter
  # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.post-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.pre-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_reject {
    filename = "/etc/raddb/mods-config/attr_filter/access_reject"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_challenge {
    filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.accounting_response {
    filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.coa {
    filename = "/etc/raddb/mods-config/attr_filter/coa"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loaded module rlm_date
  # Loading module "date" from file /usr/local/etc/raddb/mods-available/date
  date {
    format = "%b %e %Y %H:%M:%S %Z"
    utc = no
  }
  # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-available/date
  date wispr2date {
    format = "%Y-%m-%dT%H:%M:%S"
    utc = no
  }
  # Loaded module rlm_detail
  # Loading module "detail" from file /usr/local/etc/raddb/mods-available/detail
  detail {
    filename = "/var/log/freeradius/accounting/%{%{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 "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
  detail auth_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail reply_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail pre_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail post_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 module rlm_eap
  # Loading module "eap" from file /usr/local/etc/raddb/mods-available/eap
  eap {
    default_eap_type = "tls"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_exec
  # Loading module "echo" from file /usr/local/etc/raddb/mods-available/echo
  exec echo {
    wait = yes
    program = "/bin/echo %{User-Name}"
    input_pairs = "request"
    output_pairs = "reply"
    shell_escape = yes
  }
  # Loading module "exec" from file /usr/local/etc/raddb/mods-available/exec
  exec {
    wait = no
    input_pairs = "request"
    shell_escape = yes
    timeout = 10
  }
  # Loaded module rlm_expiration
  # Loading module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Loaded module rlm_expr
  # Loading module "expr" from file /usr/local/etc/raddb/mods-available/expr
  expr {
    safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
  }
  # Loaded module rlm_logintime
  # Loading module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  logintime {
    minimum_timeout = 60
  }
  # Loaded module rlm_preprocess
  # Loading module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
  preprocess {
    huntgroups = "/etc/raddb/mods-config/preprocess/huntgroups"
    hints = "/etc/raddb/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 module rlm_unix
  # Loading module "unix" from file /usr/local/etc/raddb/mods-available/unix
  unix {
    radwtmp = "/var/log/freeradius/radwtmp"
  }
Creating attribute Unix-Group
  # Loaded module rlm_utf8
  # Loading module "utf8" from file /usr/local/etc/raddb/mods-available/utf8
  # Loaded module rlm_linelog
  # Loading module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_reply {
    filename = "/var/log/freeradius/radius-felix-detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{reply:Packet-Type}:-format}"
  }
  # Loading module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_general_message {
    filename = "/var/log/freeradius/radius-felix-detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{Packet-Type}:-format}"
  }
  # Loaded module rlm_rest
  # Loading module "rest" from file /usr/local/etc/raddb/mods-available/rest
  rest {
    connect_timeout = 4.000000
    http_negotiation = "default"
  }
  # Loaded module rlm_python3
  # Loading module "python3" from file /usr/local/etc/raddb/mods-available/python3
  python3 {
    mod_instantiate = "python-magic"
    func_instantiate = "instantiate"
    mod_authorize = "python-magic"
    func_authorize = "authorize"
    mod_authenticate = "python-magic"
    func_authenticate = "authenticate"
    mod_post_auth = "python-magic"
    func_post_auth = "post_auth"
    python_path = "/etc/raddb/mods-config/python3"
    cext_compat = yes
    pass_all_vps = no
    pass_all_vps_dict = yes
  }
  # Loading module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
  eap inner-eap {
    default_eap_type = "mschapv2"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_mschap
  # Loading module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
  mschap {
    use_mppe = yes
    require_encryption = yes
    require_strong = yes
    with_ntdomain_hack = yes
   passchange {
   }
    allow_retry = yes
    winbind_retry_with_normalised_username = no
  }
  # Instantiating module "reject" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "fail" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "ok" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "handled" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "noop" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "updated" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
  # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
  # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
  # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
  # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
  # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/coa
  # Instantiating module "detail" from file /usr/local/etc/raddb/mods-available/detail
  # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
  # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "eap" from file /usr/local/etc/raddb/mods-available/eap
   # Linked to sub-module rlm_eap_md5
   # Linked to sub-module rlm_eap_tls
   tls {
    tls = "tls-common"
    virtual_server = "check-eap-tls"
   }
   tls-config tls-common {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert.key"
    certificate_file = "/etc/raddb/servercert.pem"
    ca_file = "/etc/raddb/ca.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
   # Linked to sub-module rlm_eap_ttls
   ttls {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    virtual_server = "inner-tunnel"
    include_length = yes
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
   # Linked to sub-module rlm_eap_peap
   peap {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    proxy_tunneled_request_as_eap = yes
    virtual_server = "inner-tunnel"
    soh = no
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
  # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
reading pairlist file /etc/raddb/mods-config/preprocess/huntgroups
reading pairlist file /etc/raddb/mods-config/preprocess/hints
  # Instantiating module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "rest" from file /usr/local/etc/raddb/mods-available/rest
rlm_rest: libcurl version: libcurl/7.68.0 OpenSSL/1.1.1f zlib/1.2.11 brotli/1.0.7 libidn2/2.2.0 libpsl/0.21.0 (+libidn2/2.2.0) libssh/0.9.3/openssl/zlib nghttp2/1.40.0 librtmp/2.3
rlm_rest (rest): Initialising connection pool
   pool {
    start = 5
    min = 5
    max = 10
    spare = 3
    uses = 0
    lifetime = 0
    cleanup_interval = 30
    idle_timeout = 60
    retry_delay = 1
    spread = no
   }
rlm_rest (rest): Opening additional connection (0), 1 of 10 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (1), 1 of 9 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (2), 1 of 8 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (3), 1 of 7 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (4), 1 of 6 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
  # Instantiating module "python3" from file /usr/local/etc/raddb/mods-available/python3
Python version: 3.8.10 (default, Jun  2 2021, 10:49:15)  [GCC 9.4.0]
  # Instantiating module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
   # Linked to sub-module rlm_eap_mschapv2
   mschapv2 {
    with_ntdomain_hack = no
    send_error = no
   }
  # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
rlm_mschap (mschap): using internal authentication
 } # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /usr/local/etc/raddb/radiusd.conf
} # server
server check-eap-tls { # from file /usr/local/etc/raddb/sites-available/check-eap-tls
 # Loading authorize {...}
} # server check-eap-tls
server felix { # from file /usr/local/etc/raddb/sites-available/virt-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server felix
server felix-radsec { # from file /usr/local/etc/raddb/sites-available/radsec-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server felix-radsec
server inner-tunnel { # from file /usr/local/etc/raddb/sites-available/inner-tunnel
 # Loading authenticate {...}
Compiling Auth-Type MS-CHAP for attr Auth-Type
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
} # server inner-tunnel
 thread pool {
    start_servers = 3
    max_servers = 32
    min_spare_servers = 3
    max_spare_servers = 10
    max_requests_per_server = 300
    cleanup_delay = 5
    max_queue_size = 65536
    auto_limit_acct = no
 }
Thread spawned new child 1. Total threads in pool: 1
Thread 1 waiting to be assigned a request
Thread spawned new child 2. Total threads in pool: 2
Thread 2 waiting to be assigned a request
Thread spawned new child 3. Total threads in pool: 3
Thread pool initialized
radiusd: #### Opening IP addresses and Ports ####
Thread 3 waiting to be assigned a request
listen {
    type = "auth"
    ipaddr = *
    port = 1812
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client felix {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    shortname = "felix"
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "acct"
    ipaddr = *
    port = 1813
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
}
listen {
    type = "auth+acct"
    ipaddr = *
    port = 2083
    proto = "tcp"
    proxy_protocol = yes
   tls {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert-radsec.key"
    certificate_file = "/etc/raddb/servercert-radsec.pem"
    ca_file = "/etc/raddb/ca-radsec.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    require_client_cert = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
    check_client_connections = no
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client felix-radsec {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    proto = "tls"
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "auth"
    ipaddr = 127.0.0.1
    port = 18120
}
Listening on auth address * port 1812 bound to server felix
Listening on acct address * port 1813 bound to server felix
Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server felix-radsec
Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Ready to process requests
 ... new connection request on TCP socket
Listening on auth+acct from client (10.244.6.116, 52382) -> (*, 2083, virtual-server=felix-radsec)
Waking up in 0.2 seconds.
(0) (TLS) Initiating new session
(0) (TLS) Setting verify mode to require certificate from client
(0) (TLS) Received PROXY protocol connection from client 77.47.68.110:33021 -> 10.244.6.116:2083, via proxy 10.244.6.116:52382 -> 0.0.0.0:2083
(0) (TLS) Handshake state - before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) recv TLS 1.3 Handshake, ClientHello
(0) (TLS) Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) send TLS 1.2 Handshake, ServerHello
(0) (TLS) Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) send TLS 1.2 Handshake, Certificate
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) send TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS write key exchange
(0) (TLS) send TLS 1.2 Handshake, CertificateRequest
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) send TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) Server : Need to read more data: SSLv3/TLS write server done
(0) (TLS) In Handshake Phase
Waking up in 0.2 seconds.
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) recv TLS 1.2 Handshake, Certificate
(0) (TLS) Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "0fc40d25cf3141d795f4d3a26dd7d9ae"
(0)   TLS-Client-Cert-Expiration := "220310102259Z"
(0)   TLS-Client-Cert-Valid-Since := "210310101259Z"
(0)   TLS-Client-Cert-Subject := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Issuer := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Common-Name := "Proxycertificate"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "proxy.felix.net"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB\n"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB"
Certificate chain - 0 cert(s) untrusted
(TLS) untrusted certificate with depth [0] subject name /CN=Proxycertificate
(0) Starting OCSP Request
(0) WARNING: ocsp: No OCSP URL in certificate.  Not doing OCSP
(0) WARNING: ocsp: Unable to check certificate, assuming it's valid
(0) WARNING: ocsp: This may be insecure
(0) (TLS) Server : Need to read more data: SSLv3/TLS read client certificate
(0) (TLS) In Handshake Phase
(0) (TLS) Application data.
 ... shutting down socket auth+acct from client (77.47.68.110, 33021) -> (10.244.6.116, 2083, virtual-server=felix-radsec)
Waking up in 2.9 seconds.

REMOVED ALL LINES BETWEEN

Waking up in 0.1 seconds.
... cleaning up socket auth+acct from client (77.47.68.110, 33021) -> (10.244.6.116, 2083, virtual-server=felix-radsec)
Bad talloc magic value - unknown value

talloc abort: Bad talloc magic value - unknown value

Backtrace of last 8 frames:
/usr/local/lib/libfreeradius-radius.so(+0xe661)[0x7f6b7d5a0661]
/lib/x86_64-linux-gnu/libtalloc.so.2(+0x3ac8)[0x7f6b7d214ac8]
radiusd(+0x56329)[0x556953ff7329]
/usr/local/lib/libfreeradius-radius.so(fr_event_loop+0x658)[0x7f6b7d5cb20a]
radiusd(radius_event_process+0x2a)[0x556953ff9596]
radiusd(main+0xcb5)[0x556953fe0edf]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f6b7cfe00b3]
radiusd(_start+0x2e)[0x556953fb8c3e]

Relevant log output from client utilities

No response

Backtrace from LLDB or GDB

Id   Target Id                        Frame 
* 1    Thread 0x7f6b7cf41740 (LWP 1014) __GI_raise (sig=sig@entry=6)
    at ../sysdeps/unix/sysv/linux/raise.c:50
  2    Thread 0x7f6b75ea9700 (LWP 1017) futex_abstimed_wait_cancelable (
    private=0, abstime=0x0, clockid=0, expected=0, 
    futex_word=0x55695403f508 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320
  3    Thread 0x7f6b756a8700 (LWP 1018) futex_abstimed_wait_cancelable (
    private=0, abstime=0x0, clockid=0, expected=0, 
    futex_word=0x55695403f508 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320
  4    Thread 0x7f6b74ea7700 (LWP 1019) futex_abstimed_wait_cancelable (
    private=0, abstime=0x0, clockid=0, expected=0, 
    futex_word=0x55695403f508 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320

Thread 4 (Thread 0x7f6b74ea7700 (LWP 1019)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55695403f508 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6b7d1f94e8 in __new_sem_wait_slow (sem=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6b7d1f93a0 <__sem_wait_cleanup>, __arg = 0x55695403f508 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 8589934592
#3  0x0000556953fe98c1 in request_handler_thread (arg=0x556955e7e300) at src/main/threads.c:755
        self = 0x556955e7e300
#4  0x00007f6b7d1ef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140099499751168, 2223224236032550123, 140729138657102, 140729138657103, 140729138657104, 140099499749312, -2302303144366676757, -2302323935416392469}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6b7d0db293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 3 (Thread 0x7f6b756a8700 (LWP 1018)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55695403f508 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6b7d1f94e8 in __new_sem_wait_slow (sem=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6b7d1f93a0 <__sem_wait_cleanup>, __arg = 0x55695403f508 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 4294967296
#3  0x0000556953fe98c1 in request_handler_thread (arg=0x556955e786c0) at src/main/threads.c:755
        self = 0x556955e786c0
#4  0x00007f6b7d1ef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140099508143872, 2223224236032550123, 140729138657102, 140729138657103, 140729138657104, 140099508142016, -2302306442364689173, -2302323935416392469}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6b7d0db293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 2 (Thread 0x7f6b75ea9700 (LWP 1017)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55695403f508 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6b7d1f94e8 in __new_sem_wait_slow (sem=0x55695403f508 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6b7d1f93a0 <__sem_wait_cleanup>, __arg = 0x55695403f508 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 0
#3  0x0000556953fe98c1 in request_handler_thread (arg=0x556956164880) at src/main/threads.c:755
        self = 0x556956164880
#4  0x00007f6b7d1ef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140099516536576, 2223224236032550123, 140729138657102, 140729138657103, 140729138657104, 140099516534720, -2302305344463674133, -2302323935416392469}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6b7d0db293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 1 (Thread 0x7f6b7cf41740 (LWP 1014)):
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {0, 0, 0, 0, 4294967295, 93910868921360, 4611686018427387904, 140099637109920, 0, 140099641935066, 0, 93910868921406, 128, 0, 140729138655280, 140099636540864}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007f6b7cfde859 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x7f6b7d171be4, sa_sigaction = 0x7f6b7d171be4}, sa_mask = {__val = {1, 140099636899851, 3, 140729138655460, 12, 140099636899855, 2, 4122541012101055520, 7292281315463148341, 93910898364848, 7291999831140186608, 0, 5066268401146631936, 140729138655552, 93910869289888, 140729138656640}}, sa_flags = 1438437808, sa_restorer = 0x556954012ba0 <__libc_csu_init>}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007f6b7d5a06aa in _fr_talloc_fault_simple (reason=0x7f6b7d21e070 "Bad talloc magic value - unknown value") at src/lib/debug.c:848
No locals.
#3  0x00007f6b7d214ac8 in ?? () from /lib/x86_64-linux-gnu/libtalloc.so.2
No symbol table info available.
#4  0x0000556953ff7329 in event_socket_handler (xel=0x556955df0e80, fd=11, ctx=0x556955bcd1b0) at src/main/process.c:5088
        listener = 0x556956433350
#5  0x00007f6b7d5cb20a in fr_event_loop (el=0x556955df0e80) at src/lib/event.c:649
        ef = 0x556955df0f30
        i = 5
        rcode = 2
        when = {tv_sec = 1628011858, tv_usec = 892415}
        wake = 0x7ffe0e51b750
        maxfd = 12
        read_fds = {fds_bits = {6144, 0 <repeats 15 times>}}
        master_fds = {fds_bits = {8096, 0 <repeats 15 times>}}
#6  0x0000556953ff9596 in radius_event_process () at src/main/process.c:6264
No locals.
#7  0x0000556953fe0edf in main (argc=4, argv=0x7ffe0e51b9f8) at src/main/radiusd.c:641
        rcode = 0
        status = 32766
        argval = -1
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        p = 0x0
        state = 0x55695403ee00 <global_state>
        autofree = 0x556955ba5300
alandekok commented 3 years ago

Is this with the latest code from v3.0.x?

Because the server should not be printing out Ready to process requests 50,000 times in a row.

I don't see that in my tests. I've added scripts/ci/haproxy.conf as a simple haproxy configuration. There's also scripts/ci/stunnel.conf. And with a bit of minor config edits, you can get radclient -P tcp ... to stunnel, to haproxy, and then to FreeRADIUS.

That works for me.

gk-fschubert commented 3 years ago

Yes it's with the latest version, build 3 hours ago. It also don't happen if just one client get's connected. But at some point if two radsec clients (https://radsecproxy.github.io/) which are using the same certificates, it happens after a while.

alandekok commented 3 years ago

I've been unable to reproduce this issue here. Any additional information you can give would help.

gk-fschubert commented 3 years ago

After your message i've builded a new lab outside of k8s in lxc containers. Supprisingly everything is working if all components are beside each other. So i've created a new VPS on DigitalOcean. If FreeRADIUS is running on a remote machine, things start to crash.

My configs:

Traefik:

docker-compose.yml

version: "3.7"

services:
  traefik:
    image: "traefik:v2.4"
    container_name: "traefik"
    hostname: "traefik"
    ports:
      - "81:80"
      - "8081:8080"
      - "2083:2083"
    volumes:
      - "/var/run/docker.sock:/var/run/docker.sock:ro"
      - "./traefik.yml:/traefik.yml:ro"
      - "./config.yml:/config/config.yml"

traefik.yml

log:
  level: DEBUG

api:
  insecure: true
  dashboard: true

entryPoints:
  radsec:
    address: ":2083"

providers:
  file:
    directory: /config

config.yml

tcp:
  services:
    radsec:
      loadBalancer:
        servers:
        - address: "IP_OF_YOUR_RADIUS_SERVER:2083"
        proxyProtocol:
          version: 1
  routers:
    radsec:
      entrypoints:
        - "radsec"
      rule: "HostSNI(`*`)"
      service: radsec
      tls:
        passthrough: true

RadSec Proxy:

setup:

apk update && apk upgrade
apk add g++ gcc openssl openssl-dev make nettle-dev curl

curl -Lo radsecproxy.tar.gz  https://github.com/radsecproxy/radsecproxy/releases/download/1.8.2/radsecproxy-1.8.2.tar.gz && \
    mkdir radsecproxy && \
    tar xvf radsecproxy.tar.gz -C radsecproxy --strip 1 && \
    cd radsecproxy && \
    ./configure --prefix=/opt && \
    make && \
    make install

RadSec Proxy conf

ListenUDP       *:1812
ListenUDP       *:1813

tls default {
    CACertificateFile = /etc/ca.crt
    CertificateFile = /etc/servercert.pem
    CertificateKeyFile = /etc/servercert.key
}

client 0.0.0.0/0 {
    type udp
    secret << secret >>
}

server server-tls {
    host IP_OF_YOUR_TRAEFIK_ROUTER
    port 2083
    type tls
    secret radsec
    CertificateNameCheck off
}

realm * {
    server server-tls
    accountingserver server-tls
    accountingresponse on
}

Radius gdb output

i've catched the log this time with the panic options

  Id   Target Id                                   Frame 
* 1    Thread 0x7f6ab2085740 (LWP 49308) "radiusd" 0x00007f6ab21e2dff in __GI___wait4 (pid=49314, stat_loc=stat_loc@entry=0x7ffeae93fe78, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
  2    Thread 0x7f6aaaa11700 (LWP 49311) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
  3    Thread 0x7f6aaa210700 (LWP 49312) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
  4    Thread 0x7f6aa9a0f700 (LWP 49313) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
Undefined command: "tread".  Try "help".

Thread 4 (Thread 0x7f6aa9a0f700 (LWP 49313)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 64
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6ab233d4e8 in __new_sem_wait_slow (sem=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6ab233d3a0 <__sem_wait_cleanup>, __arg = 0x559f80a613a8 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 0
#3  0x0000559f80a0cc47 in request_handler_thread (arg=0x559f826aa820) at src/main/threads.c:755
        self = 0x559f826aa820
#4  0x00007f6ab2333609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140096089159424, -2756022518797141806, 140731827358318, 140731827358319, 140731827358320, 140096089157568, 2816429128714975442, 2816368769750563026}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6ab221f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 3 (Thread 0x7f6aaa210700 (LWP 49312)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 64
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6ab233d4e8 in __new_sem_wait_slow (sem=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6ab233d3a0 <__sem_wait_cleanup>, __arg = 0x559f80a613a8 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 4294967296
#3  0x0000559f80a0cc47 in request_handler_thread (arg=0x559f826a0900) at src/main/threads.c:755
        self = 0x559f826a0900
#4  0x00007f6ab2333609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140096097552128, -2756022518797141806, 140731827358318, 140731827358319, 140731827358320, 140096097550272, 2816421432670451922, 2816368769750563026}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6ab221f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 2 (Thread 0x7f6aaaa11700 (LWP 49311)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x559f80a613a8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f6ab233d4e8 in __new_sem_wait_slow (sem=0x559f80a613a8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f6ab233d3a0 <__sem_wait_cleanup>, __arg = 0x559f80a613a8 <thread_pool+168>, __canceltype = 0, __prev = 0x0}
        err = <optimized out>
        d = 8589934592
#3  0x0000559f80a0cc47 in request_handler_thread (arg=0x559f826a9fa0) at src/main/threads.c:755
        self = 0x559f826a9fa0
#4  0x00007f6ab2333609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140096105944832, -2756022518797141806, 140731827358318, 140731827358319, 140731827358320, 140096105942976, 2816422524129016018, 2816368769750563026}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f6ab221f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 1 (Thread 0x7f6ab2085740 (LWP 49308)):
#0  0x00007f6ab21e2dff in __GI___wait4 (pid=49314, stat_loc=stat_loc@entry=0x7ffeae93fe78, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
        resultvar = 18446744073709551104
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
#1  0x00007f6ab21e2d7b in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffeae93fe78, options=options@entry=0) at waitpid.c:38
No locals.
#2  0x00007f6ab21520e7 in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:172
        __result = <optimized out>
        _buffer = {__routine = 0x7f6ab2152290 <cancel_handler>, __arg = 0x7ffeae93fe80, __canceltype = 0, __prev = 0x0}
        _avail = 1
        cancel_args = {quit = 0x7f6ab22eb200 <quit>, intr = 0x7f6ab22eb2a0 <intr>, pid = 49314}
        status = -1
        ret = 0
        pid = 49314
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0xffffffff}
        omask = {__val = {0, 0, 140096232662176, 17056991190078823168, 94143546347136, 140731827355424, 27, 140096231227213, 0, 0, 18446744073709551360, 0, 18446744073709551360, 0, 0, 94143545986064}}
        reset = {__val = {6, 0 <repeats 15 times>}}
        spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 0 <repeats 15 times>}}, __ss = {__val = {0, 0, 140096232662176, 17056991190078823168, 94143546347136, 140731827355424, 27, 140096231227213, 0, 0, 18446744073709551360, 0, 18446744073709551360, 0, 0, 94143545986064}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
        __cnt = <optimized out>
        __set = <optimized out>
        __cnt = <optimized out>
        __set = <optimized out>
#3  0x00007f6ab26e7532 in fr_fault (sig=6) at src/lib/debug.c:791
        disable = false
        cmd = "gdb radiusd 49308", '\000' <repeats 514 times>
        out = 0x7ffeae940671 ""
        left = 515
        ret = 17
        p = 0x7f6ab27283ae <panic_action+14> ""
        q = 0x0
        code = 0
#4  0x00007f6ab26e76dc in _fr_talloc_fault (reason=0x7f6ab2362070 "Bad talloc magic value - unknown value") at src/lib/debug.c:864
No locals.
#5  0x00007f6ab2358ac8 in ?? () from /lib/x86_64-linux-gnu/libtalloc.so.2
No symbol table info available.
#6  0x0000559f80a1a163 in event_socket_handler (xel=0x559f82620680, fd=12, ctx=0x559f82cf1dc0) at src/main/process.c:5100
        listener = 0x559f82cf1dc0
#7  0x00007f6ab271220a in fr_event_loop (el=0x559f82620680) at src/lib/event.c:649
        ef = 0x559f82620730
        i = 5
        rcode = 1
        when = {tv_sec = 1628262799, tv_usec = 500000}
        wake = 0x7ffeae940a70
        maxfd = 13
        read_fds = {fds_bits = {4096, 0 <repeats 15 times>}}
        master_fds = {fds_bits = {14240, 0 <repeats 15 times>}}
#8  0x0000559f80a1c275 in radius_event_process () at src/main/process.c:6276
No locals.
#9  0x0000559f80a0426a in main (argc=4, argv=0x7ffeae940d18) at src/main/radiusd.c:641
        rcode = 0
        status = 1
        argval = -1
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        p = 0x0
        state = 0x559f80a60ca0 <global_state>
        autofree = 0x559f823d4300
Not confirmed.
Detaching from program: /usr/local/sbin/radiusd, process 49308
[Inferior 1 (process 49308) detached]
alandekok commented 3 years ago

If you can rebuild with ./configure --enable-address-sanitizer --enable-leak-sanitizer, that would help a lot.

That will give us the exact place where the memory was freed and then later used.

gk-fschubert commented 3 years ago

sure. I don't see any markable difference between the previous build and with --enable-address-sanitizer --enable-leak-sanitizer But the configure log says it's enabled:

./configure: line 11728: AX_CC_SANITZE_ADDRESS_USE_AFTER_SCOPE_FLAG: command not found                                                                                               
checking sanitizer/lsan_interface.h usability... yes                                                                                                                                                                                                                                                                                                                      
checking sanitizer/lsan_interface.h presence... yes                                                                                                                                  
checking for sanitizer/lsan_interface.h... yes                                                                                                                                                                                                                                                                                                                            
configure: Developer CFLAGS are "-fsanitize=address,leak -Wshadow -Wpointer-arith -Wcast-qual -Wcast-align -Wwrite-strings -Wstrict-prototypes -Wmissing-prototypes -Wmissing-declarations -Wnested-externs -W -Wredundant-decls -Wundef -Wformat-y2k -Wno-format-extra-args -Wno-format-zero-length -Wno-cast-align -Wformat-nonliteral -Wformat-security -Wformat=2 -DWI
TH_VERIFY_PTR=1 -fno-omit-frame-pointer -fno-optimize-sibling-calls"
configure: Developer LDFLAGS are "-fsanitize=address,leak"
configure: is developer build, enabling experimental modules implicitly, disable with --without-experimental-modules

Has it build correctly?

radius debug:

FreeRADIUS Version 3.0.24
Copyright (C) 1999-2021 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT
Starting - reading configuration files ...
including dictionary file /usr/local/share/freeradius/dictionary
including dictionary file /usr/local/share/freeradius/dictionary.dhcp
including dictionary file /usr/local/share/freeradius/dictionary.vqp
including dictionary file /usr/local/etc/raddb/dictionary
including configuration file /usr/local/etc/raddb/radiusd.conf
including configuration file /usr/local/etc/raddb/mods-available/always
including configuration file /usr/local/etc/raddb/mods-available/attr_filter
including configuration file /usr/local/etc/raddb/mods-available/date
including configuration file /usr/local/etc/raddb/mods-available/detail
including configuration file /usr/local/etc/raddb/mods-available/detail.log
including configuration file /usr/local/etc/raddb/mods-available/eap
including configuration file /usr/local/etc/raddb/mods-available/echo
including configuration file /usr/local/etc/raddb/mods-available/exec
including configuration file /usr/local/etc/raddb/mods-available/expiration
including configuration file /usr/local/etc/raddb/mods-available/expr
including configuration file /usr/local/etc/raddb/mods-available/logintime
including configuration file /usr/local/etc/raddb/mods-available/preprocess
including configuration file /usr/local/etc/raddb/mods-available/unix
including configuration file /usr/local/etc/raddb/mods-available/utf8
including configuration file /usr/local/etc/raddb/mods-available/linelog
including configuration file /usr/local/etc/raddb/mods-available/rest
including configuration file /usr/local/etc/raddb/mods-available/python3
including configuration file /usr/local/etc/raddb/mods-available/inner-eap
including configuration file /usr/local/etc/raddb/mods-available/mschap
including configuration file /usr/local/etc/raddb/policy.d/accounting
including configuration file /usr/local/etc/raddb/policy.d/debug
including configuration file /usr/local/etc/raddb/policy.d/eap
including configuration file /usr/local/etc/raddb/sites-available/check-eap-tls
including configuration file /usr/local/etc/raddb/sites-available/virt-serv
including configuration file /usr/local/etc/raddb/sites-available/radsec-serv
including configuration file /usr/local/etc/raddb/sites-available/inner-tunnel
main {
 security {
    allow_core_dumps = no
 }
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
}
main {
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    sbindir = "/usr/local/sbin"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
    libdir = "/usr/local/lib"
    radacctdir = "/var/log/freeradius/accounting"
    panic_action = "gdb %e %p"
    hostname_lookups = no
    max_request_time = 30
    cleanup_delay = 5
    max_requests = 5300000
    postauth_client_lost = no
    pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
    checkrad = "/usr/local/sbin/checkrad"
    debug_level = 0
    proxy_requests = no
 log {
    stripped_names = no
    auth = yes
    auth_badpass = yes
    auth_goodpass = no
    colourise = yes
    msg_denied = "You are already logged in - access denied"
 }
 resources {
 }
 security {
    max_attributes = 200
    reject_delay = 0.000000
    status_server = no
    allow_vulnerable_openssl = "CVE-2016-6304"
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
Debugger not attached
 # Creating Auth-Type = eap
 # Creating Auth-Type = inner-eap
 # Creating Auth-Type = MS-CHAP
radiusd: #### Instantiating modules ####
 modules {
  # Loaded module rlm_always
  # Loading module "reject" from file /usr/local/etc/raddb/mods-available/always
  always reject {
    rcode = "reject"
    simulcount = 0
    mpp = no
  }
  # Loading module "fail" from file /usr/local/etc/raddb/mods-available/always
  always fail {
    rcode = "fail"
    simulcount = 0
    mpp = no
  }
  # Loading module "ok" from file /usr/local/etc/raddb/mods-available/always
  always ok {
    rcode = "ok"
    simulcount = 0
    mpp = no
  }
  # Loading module "handled" from file /usr/local/etc/raddb/mods-available/always
  always handled {
    rcode = "handled"
    simulcount = 0
    mpp = no
  }
  # Loading module "invalid" from file /usr/local/etc/raddb/mods-available/always
  always invalid {
    rcode = "invalid"
    simulcount = 0
    mpp = no
  }
  # Loading module "userlock" from file /usr/local/etc/raddb/mods-available/always
  always userlock {
    rcode = "userlock"
    simulcount = 0
    mpp = no
  }
  # Loading module "notfound" from file /usr/local/etc/raddb/mods-available/always
  always notfound {
    rcode = "notfound"
    simulcount = 0
    mpp = no
  }
  # Loading module "noop" from file /usr/local/etc/raddb/mods-available/always
  always noop {
    rcode = "noop"
    simulcount = 0
    mpp = no
  }
  # Loading module "updated" from file /usr/local/etc/raddb/mods-available/always
  always updated {
    rcode = "updated"
    simulcount = 0
    mpp = no
  }
  # Loaded module rlm_attr_filter
  # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.post-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.pre-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_reject {
    filename = "/etc/raddb/mods-config/attr_filter/access_reject"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_challenge {
    filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.accounting_response {
    filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.coa {
    filename = "/etc/raddb/mods-config/attr_filter/coa"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loaded module rlm_date
  # Loading module "date" from file /usr/local/etc/raddb/mods-available/date
  date {
    format = "%b %e %Y %H:%M:%S %Z"
    utc = no
  }
  # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-available/date
  date wispr2date {
    format = "%Y-%m-%dT%H:%M:%S"
    utc = no
  }
  # Loaded module rlm_detail
  # Loading module "detail" from file /usr/local/etc/raddb/mods-available/detail
  detail {
    filename = "/var/log/freeradius/accounting/%{%{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 "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
  detail auth_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail reply_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail pre_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail post_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 module rlm_eap
  # Loading module "eap" from file /usr/local/etc/raddb/mods-available/eap
  eap {
    default_eap_type = "tls"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_exec
  # Loading module "echo" from file /usr/local/etc/raddb/mods-available/echo
  exec echo {
    wait = yes
    program = "/bin/echo %{User-Name}"
    input_pairs = "request"
    output_pairs = "reply"
    shell_escape = yes
  }
  # Loading module "exec" from file /usr/local/etc/raddb/mods-available/exec
  exec {
    wait = no
    input_pairs = "request"
    shell_escape = yes
    timeout = 10
  }
  # Loaded module rlm_expiration
  # Loading module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Loaded module rlm_expr
  # Loading module "expr" from file /usr/local/etc/raddb/mods-available/expr
  expr {
    safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
  }
  # Loaded module rlm_logintime
  # Loading module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  logintime {
    minimum_timeout = 60
  }
  # Loaded module rlm_preprocess
  # Loading module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
  preprocess {
    huntgroups = "/etc/raddb/mods-config/preprocess/huntgroups"
    hints = "/etc/raddb/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 module rlm_unix
  # Loading module "unix" from file /usr/local/etc/raddb/mods-available/unix
  unix {
    radwtmp = "/var/log/freeradius/radwtmp"
  }
Creating attribute Unix-Group
  # Loaded module rlm_utf8
  # Loading module "utf8" from file /usr/local/etc/raddb/mods-available/utf8
  # Loaded module rlm_linelog
  # Loading module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_reply {
    filename = "/var/log/freeradius/radius--detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{reply:Packet-Type}:-format}"
  }
  # Loading module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_general_message {
    filename = "/var/log/freeradius/radius--detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{Packet-Type}:-format}"
  }
  # Loaded module rlm_rest
  # Loading module "rest" from file /usr/local/etc/raddb/mods-available/rest
  rest {
    connect_timeout = 4.000000
    http_negotiation = "default"
  }
  # Loaded module rlm_python3
  # Loading module "python3" from file /usr/local/etc/raddb/mods-available/python3
  python3 {
    mod_instantiate = "python-magic"
    func_instantiate = "instantiate"
    mod_authorize = "python-magic"
    func_authorize = "authorize"
    mod_authenticate = "python-magic"
    func_authenticate = "authenticate"
    mod_post_auth = "python-magic"
    func_post_auth = "post_auth"
    python_path = "/etc/raddb/mods-config/python3"
    cext_compat = yes
    pass_all_vps = no
    pass_all_vps_dict = yes
  }
  # Loading module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
  eap inner-eap {
    default_eap_type = "mschapv2"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_mschap
  # Loading module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
  mschap {
    use_mppe = yes
    require_encryption = yes
    require_strong = yes
    with_ntdomain_hack = yes
   passchange {
   }
    allow_retry = yes
    winbind_retry_with_normalised_username = no
  }
  # Instantiating module "reject" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "fail" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "ok" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "handled" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "noop" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "updated" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
  # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
  # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
  # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
  # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
  # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/coa
  # Instantiating module "detail" from file /usr/local/etc/raddb/mods-available/detail
  # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
  # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "eap" from file /usr/local/etc/raddb/mods-available/eap
   # Linked to sub-module rlm_eap_md5
   # Linked to sub-module rlm_eap_tls
   tls {
    tls = "tls-common"
    virtual_server = "check-eap-tls"
   }
   tls-config tls-common {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert.key"
    certificate_file = "/etc/raddb/servercert.pem"
    ca_file = "/etc/raddb/ca.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
   # Linked to sub-module rlm_eap_ttls
   ttls {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    virtual_server = "inner-tunnel"
    include_length = yes
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
   # Linked to sub-module rlm_eap_peap
   peap {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    proxy_tunneled_request_as_eap = yes
    virtual_server = "inner-tunnel"
    soh = no
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
  # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
reading pairlist file /etc/raddb/mods-config/preprocess/huntgroups
reading pairlist file /etc/raddb/mods-config/preprocess/hints
  # Instantiating module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "rest" from file /usr/local/etc/raddb/mods-available/rest
rlm_rest: libcurl version: libcurl/7.68.0 OpenSSL/1.1.1f zlib/1.2.11 brotli/1.0.7 libidn2/2.2.0 libpsl/0.21.0 (+libidn2/2.2.0) libssh/0.9.3/openssl/zlib nghttp2/1.40.0 librtmp/2.3
rlm_rest (rest): Initialising connection pool
   pool {
    start = 5
    min = 5
    max = 10
    spare = 3
    uses = 0
    lifetime = 0
    cleanup_interval = 30
    idle_timeout = 60
    retry_delay = 1
    spread = no
   }
rlm_rest (rest): Opening additional connection (0), 1 of 10 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (1), 1 of 9 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (2), 1 of 8 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (3), 1 of 7 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (4), 1 of 6 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
  # Instantiating module "python3" from file /usr/local/etc/raddb/mods-available/python3
Python version: 3.8.10 (default, Jun  2 2021, 10:49:15)  [GCC 9.4.0]
  # Instantiating module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
   # Linked to sub-module rlm_eap_mschapv2
   mschapv2 {
    with_ntdomain_hack = no
    send_error = no
   }
  # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
rlm_mschap (mschap): using internal authentication
 } # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /usr/local/etc/raddb/radiusd.conf
} # server
server check-eap-tls { # from file /usr/local/etc/raddb/sites-available/check-eap-tls
 # Loading authorize {...}
} # server check-eap-tls
server  { # from file /usr/local/etc/raddb/sites-available/virt-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server 
server -radsec { # from file /usr/local/etc/raddb/sites-available/radsec-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server -radsec
server inner-tunnel { # from file /usr/local/etc/raddb/sites-available/inner-tunnel
 # Loading authenticate {...}
Compiling Auth-Type MS-CHAP for attr Auth-Type
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
} # server inner-tunnel
 thread pool {
    start_servers = 3
    max_servers = 32
    min_spare_servers = 3
    max_spare_servers = 10
    max_requests_per_server = 300
    cleanup_delay = 5
    max_queue_size = 65536
    auto_limit_acct = no
 }
Thread 1 waiting to be assigned a request
Thread spawned new child 1. Total threads in pool: 1
Thread 2 waiting to be assigned a request
Thread spawned new child 2. Total threads in pool: 2
Thread 3 waiting to be assigned a request
Thread spawned new child 3. Total threads in pool: 3
Thread pool initialized
radiusd: #### Opening IP addresses and Ports ####
listen {
    type = "auth"
    ipaddr = *
    port = 1812
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client  {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    shortname = ""
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "acct"
    ipaddr = *
    port = 1813
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
}
listen {
    type = "auth+acct"
    ipaddr = *
    port = 2083
    proto = "tcp"
    proxy_protocol = yes
   tls {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert-radsec.key"
    certificate_file = "/etc/raddb/servercert-radsec.pem"
    ca_file = "/etc/raddb/ca-radsec.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    require_client_cert = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
    check_client_connections = no
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client -radsec {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    proto = "tls"
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "auth"
    ipaddr = 127.0.0.1
    port = 18120
}
Listening on auth address * port 1812 bound to server 
Listening on acct address * port 1813 bound to server 
Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server -radsec
Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Ready to process requests
 ... new connection request on TCP socket
Listening on auth+acct from client (77.47.68.110, 46254) -> (*, 2083, virtual-server=-radsec)
Waking up in 0.6 seconds.
(0) (TLS) Initiating new session
(0) (TLS) Setting verify mode to require certificate from client
(0) (TLS) Received PROXY protocol connection from client 172.23.100.1:33911 -> 172.18.0.2:2083, via proxy 77.47.68.110:46254 -> 0.0.0.0:2083
(0) (TLS) Handshake state - before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) recv TLS 1.3 Handshake, ClientHello
(0) (TLS) Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) send TLS 1.2 Handshake, ServerHello
(0) (TLS) Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) send TLS 1.2 Handshake, Certificate
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) send TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS write key exchange
(0) (TLS) send TLS 1.2 Handshake, CertificateRequest
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) send TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) Server : Need to read more data: SSLv3/TLS write server done
(0) (TLS) In Handshake Phase
Waking up in 0.6 seconds.
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) recv TLS 1.2 Handshake, Certificate
(0) (TLS) Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "0fc40d25cf3141d795f4d3a26dd7d9ae"
(0)   TLS-Client-Cert-Expiration := "220310102259Z"
(0)   TLS-Client-Cert-Valid-Since := "210310101259Z"
(0)   TLS-Client-Cert-Subject := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Issuer := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Common-Name := "Proxycertificate"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "proxy.felix.net"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB\n"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB"
Certificate chain - 0 cert(s) untrusted
(TLS) untrusted certificate with depth [0] subject name /CN=Proxycertificate
(0) Starting OCSP Request
(0) WARNING: ocsp: No OCSP URL in certificate.  Not doing OCSP
(0) WARNING: ocsp: Unable to check certificate, assuming it's valid
(0) WARNING: ocsp: This may be insecure
(0) (TLS) Server : Need to read more data: SSLv3/TLS read client certificate
(0) (TLS) In Handshake Phase
(0) (TLS) Application data.
 ... shutting down socket auth+acct from client (172.23.100.1, 33911) -> (172.18.0.2, 2083, virtual-server=-radsec)
Waking up in 2.9 seconds.

REMOVED ALL LINES BETWEEN

Waking up in 0.1 seconds.
... cleaning up socket auth+acct from client (172.23.100.1, 33911) -> (172.18.0.2, 2083, virtual-server=-radsec)
Bad talloc magic value - unknown value

talloc abort: Bad talloc magic value - unknown value
Backtrace of last 10 frames:
/lib/x86_64-linux-gnu/libasan.so.5(+0x6cd30)[0x7f58307e8d30]
/usr/local/lib/libfreeradius-radius.so(fr_fault+0x1ee)[0x7f58305f8c96]
/usr/local/lib/libfreeradius-radius.so(+0x30152)[0x7f58305f9152]
/lib/x86_64-linux-gnu/libtalloc.so.2(+0x3ac8)[0x7f5830251ac8]
radiusd(+0xf6fe2)[0x55ad47696fe2]
/usr/local/lib/libfreeradius-radius.so(fr_event_loop+0xfe7)[0x7f5830665683]
radiusd(radius_event_process+0x2a)[0x55ad4769b7f9]
radiusd(main+0x22b3)[0x55ad4765cd2b]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f583001d0b3]
radiusd(_start+0x2e)[0x55ad4760107e]
Calling: gdb radiusd 170663

gdb: 

  Id   Target Id                                    Frame 
* 1    Thread 0x7f582fe0b540 (LWP 170663) "radiusd" 0x00007f58300dbdff in __GI___wait4 (pid=170670, stat_loc=stat_loc@entry=0x7ffe71aa07c8, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
  2    Thread 0x7f582568f700 (LWP 170667) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
  3    Thread 0x7f5824e80700 (LWP 170668) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
  4    Thread 0x7f5824669700 (LWP 170669) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320

Thread 4 (Thread 0x7f5824669700 (LWP 170669)):
Undefined command: "by".  Try "help".

Thread 4 (Thread 0x7f5824669700 (LWP 170669)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f58302364e8 in __new_sem_wait_slow (sem=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f58302363a0 <__sem_wait_cleanup>, __arg = 0x55ad47774da8 <thread_pool+168>, __canceltype = 602316800, __prev = 0x0}
        err = <optimized out>
        d = 8589934592
#3  0x000055ad47672159 in request_handler_thread (arg=0x606000007ac0) at src/main/threads.c:755
        self = 0x606000007ac0
#4  0x00007f583022c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140016544552704, -7991950892532686073, 140730805390494, 140730805390495, 140730805390496, 140016544550720, 8045306680113177351, 8045262113219486471}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f5830118293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 3 (Thread 0x7f5824e80700 (LWP 170668)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f58302364e8 in __new_sem_wait_slow (sem=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f58302363a0 <__sem_wait_cleanup>, __arg = 0x55ad47774da8 <thread_pool+168>, __canceltype = 610799616, __prev = 0x0}
        err = <optimized out>
        d = 4294967296
#3  0x000055ad47672159 in request_handler_thread (arg=0x606000007a60) at src/main/threads.c:755
        self = 0x606000007a60
#4  0x00007f583022c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140016553035520, -7991950892532686073, 140730805390494, 140730805390495, 140730805390496, 140016553033536, 8045305587580871431, 8045262113219486471}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f5830118293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 2 (Thread 0x7f582568f700 (LWP 170667)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ad47774da8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f58302364e8 in __new_sem_wait_slow (sem=0x55ad47774da8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f58302363a0 <__sem_wait_cleanup>, __arg = 0x55ad47774da8 <thread_pool+168>, __canceltype = 619249664, __prev = 0x0}
        err = <optimized out>
        d = 0
#3  0x000055ad47672159 in request_handler_thread (arg=0x606000007a00) at src/main/threads.c:755
        self = 0x606000007a00
#4  0x00007f583022c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140016561485568, -7991950892532686073, 140730805390494, 140730805390495, 140730805390496, 140016561483584, 8045304497196049159, 8045262113219486471}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f5830118293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 1 (Thread 0x7f582fe0b540 (LWP 170663)):
#0  0x00007f58300dbdff in __GI___wait4 (pid=170670, stat_loc=stat_loc@entry=0x7ffe71aa07c8, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
        resultvar = 18446744073709551104
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
#1  0x00007f58300dbd7b in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffe71aa07c8, options=options@entry=0) at waitpid.c:38
No locals.
#2  0x00007f583004b0e7 in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:172
        __result = <optimized out>
        _buffer = {__routine = 0x7f583004b290 <cancel_handler>, __arg = 0x7ffe71aa07d0, __canceltype = 0, __prev = 0x0}
        _avail = 1
        cancel_args = {quit = 0x7f58301e4200 <quit>, intr = 0x7f58301e42a0 <intr>, pid = 170670}
        status = -1
        ret = 0
        pid = 170670
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x2}
        omask = {__val = {0, 0, 0, 0, 0, 140016741131712, 0, 0, 0, 18446744069414649600, 0, 18446744069414584320, 0, 94202715181136, 0, 0}}
        reset = {__val = {6, 0 <repeats 15 times>}}
        spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 0 <repeats 15 times>}}, __ss = {__val = {0, 0, 0, 0, 0, 140016741131712, 0, 0, 0, 18446744069414649600, 0, 18446744069414584320, 0, 94202715181136, 0, 0}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
        __cnt = <optimized out>
        __set = <optimized out>
        __cnt = <optimized out>
        __set = <optimized out>
#3  0x00007f58305f8ed6 in fr_fault (sig=6) at src/lib/debug.c:791
        disable = false
        cmd = "gdb radiusd 170663", '\000' <repeats 513 times>
        out = 0x7ffe71aa1062 ""
        left = 514
        ret = 18
        p = 0x7f58306adf0e <panic_action+14> ""
        q = 0x0
        code = 32766
#4  0x00007f58305f9152 in _fr_talloc_fault (reason=0x7f583025b070 "Bad talloc magic value - unknown value") at src/lib/debug.c:864
No locals.
#5  0x00007f5830251ac8 in ?? () from /lib/x86_64-linux-gnu/libtalloc.so.2
No symbol table info available.
#6  0x000055ad47696fe2 in event_socket_handler (xel=0x627000000160, fd=11, ctx=0x6140000136a0) at src/main/process.c:5100
        listener = 0x614000014ea0
#7  0x00007f5830665683 in fr_event_loop (el=0x627000000160) at src/lib/event.c:649
        ef = 0x627000000210
        i = 5
        rcode = 2
        when = {tv_sec = 1628267795, tv_usec = 411714}
        wake = 0x7ffe71aa15c0
        maxfd = 12
        read_fds = {fds_bits = {6144, 0 <repeats 15 times>}}
        master_fds = {fds_bits = {8096, 0 <repeats 15 times>}}
#8  0x000055ad4769b7f9 in radius_event_process () at src/main/process.c:6276
No locals.
#9  0x000055ad4765cd2b in main (argc=4, argv=0x7ffe71aa1978) at src/main/radiusd.c:641
        rcode = 0
        status = 0
        argval = -1
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        p = 0x0
        state = 0x55ad47774480 <global_state>
        autofree = 0x608000000080
Detaching from program: /usr/local/sbin/radiusd, process 170663
[Inferior 1 (process 170663) detached]
alandekok commented 3 years ago

You can check Make.inc to see if it has the -fsanitize=leak,address options. That should be in both CFLAGS and LDFLAGS.

You can also set environment variables for ASAN:

export ASAN_OPTIONS="malloc_context_size=50 detect_leaks=1 symbolize=1"

It should then print out any issues with leaks or access after free.

When you say:

REMOVED ALL LINES BETWEEN

Is that just waiting hours doing nothing, and then it crashes? Or is the server busy-looping for 30s and then it crashes?

The server should not be busy looping. If it's doing that, then that's a serious problem, and likely the cause of the crash.

And does this issue occur with just radsecproxy, and not the PROXY protocol?

Or maybe the issue is with the Traefik load balancer somehow doing something weird with the TCP connection?

gk-fschubert commented 3 years ago

You can check Make.inc to see if it has the -fsanitize=leak,address options. That should be in both CFLAGS and LDFLAGS.

it wasn't set in the previous build so i started again from scratch and it's set now. If i'm starting the server now and interupt him (CTRL + C) it says something like this: 

istening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Ready to process requests
^CEXIT(2) CALLED src/main/radiusd.c[778].  Last error was: 

=================================================================
==80780==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 3778094 byte(s) in 2470 object(s) allocated from:
    #0 0x7f78d4588bc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x7f78cf8f69d7  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x25a9d7)

Direct leak of 16699 byte(s) in 19 object(s) allocated from:
    #0 0x7f78d4588bc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x7f78cf8f6172  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x25a172)

Direct leak of 7290 byte(s) in 8 object(s) allocated from:
    #0 0x7f78d4588dc6 in calloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10ddc6)
    #1 0x7f78cf8f647a  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x25a47a)

Direct leak of 5040 byte(s) in 7 object(s) allocated from:
    #0 0x7f78d4588ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
    #1 0x7f78cf807c78 in _PyObject_GC_Resize (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x16bc78)

Direct leak of 4304 byte(s) in 2 object(s) allocated from:
    #0 0x7f78d4588ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
    #1 0x7f78cf922c73 in PyList_Append (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x286c73)

Direct leak of 3875 byte(s) in 6 object(s) allocated from:
    #0 0x7f78d4588ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
    #1 0x7f78cf8d1794  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x235794)

Direct leak of 608 byte(s) in 19 object(s) allocated from:
    #0 0x7f78d4588bc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x7f78cf8199f9 in PyThread_allocate_lock (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x17d9f9)

Indirect leak of 2420146 byte(s) in 2052 object(s) allocated from:
    #0 0x7f78d4588bc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x7f78cf8f69d7  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x25a9d7)

Indirect leak of 132918 byte(s) in 29 object(s) allocated from:
    #0 0x7f78d4588ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
    #1 0x7f78cf8d1794  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x235794)

Indirect leak of 4584 byte(s) in 6 object(s) allocated from:
    #0 0x7f78d4588bc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x7f78cf8f6172  (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x25a172)

Indirect leak of 2352 byte(s) in 3 object(s) allocated from:
    #0 0x7f78d4588ffe in __interceptor_realloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dffe)
    #1 0x7f78cf807c78 in _PyObject_GC_Resize (/lib/x86_64-linux-gnu/libpython3.8.so.1.0+0x16bc78)

SUMMARY: AddressSanitizer: 6375910 byte(s) leaked in 4621 allocation(s).

So it should work in general. But i don't see any messages like this when the server crashes.

Back to the problem.

Is that just waiting hours doing nothing, and then it crashes? Or is the server busy-looping for 30s and then it crashes?

It don't take 30s. It's something between 2-10 seconds while it's printing 'Waking up in x.x seconds.' than it crashes.

And does this issue occur with just radsecproxy, and not the PROXY protocol?

No, it's working fine without the PROXY protocoll.

Logs and traces for the last result(checked that fsanitize are set)

radius: 

FreeRADIUS Version 3.0.24
Copyright (C) 1999-2021 The FreeRADIUS server project and contributors
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License
For more information about these matters, see the file named COPYRIGHT
Starting - reading configuration files ...
including dictionary file /usr/local/share/freeradius/dictionary
including dictionary file /usr/local/share/freeradius/dictionary.dhcp
including dictionary file /usr/local/share/freeradius/dictionary.vqp
including dictionary file /usr/local/etc/raddb/dictionary
including configuration file /usr/local/etc/raddb/radiusd.conf
including configuration file /usr/local/etc/raddb/mods-available/always
including configuration file /usr/local/etc/raddb/mods-available/attr_filter
including configuration file /usr/local/etc/raddb/mods-available/date
including configuration file /usr/local/etc/raddb/mods-available/detail
including configuration file /usr/local/etc/raddb/mods-available/detail.log
including configuration file /usr/local/etc/raddb/mods-available/eap
including configuration file /usr/local/etc/raddb/mods-available/echo
including configuration file /usr/local/etc/raddb/mods-available/exec
including configuration file /usr/local/etc/raddb/mods-available/expiration
including configuration file /usr/local/etc/raddb/mods-available/expr
including configuration file /usr/local/etc/raddb/mods-available/logintime
including configuration file /usr/local/etc/raddb/mods-available/preprocess
including configuration file /usr/local/etc/raddb/mods-available/unix
including configuration file /usr/local/etc/raddb/mods-available/utf8
including configuration file /usr/local/etc/raddb/mods-available/linelog
including configuration file /usr/local/etc/raddb/mods-available/rest
including configuration file /usr/local/etc/raddb/mods-available/python3
including configuration file /usr/local/etc/raddb/mods-available/inner-eap
including configuration file /usr/local/etc/raddb/mods-available/mschap
including configuration file /usr/local/etc/raddb/policy.d/accounting
including configuration file /usr/local/etc/raddb/policy.d/debug
including configuration file /usr/local/etc/raddb/policy.d/eap
including configuration file /usr/local/etc/raddb/sites-available/check-eap-tls
including configuration file /usr/local/etc/raddb/sites-available/virt-serv
including configuration file /usr/local/etc/raddb/sites-available/radsec-serv
including configuration file /usr/local/etc/raddb/sites-available/inner-tunnel
main {
 security {
    allow_core_dumps = yes
 }
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
}
Core dumps are enabled
main {
    name = "radiusd"
    prefix = "/usr/local"
    localstatedir = "/usr/local/var"
    sbindir = "/usr/local/sbin"
    logdir = "/var/log/freeradius"
    run_dir = "/usr/local/var/run/radiusd"
    libdir = "/usr/local/lib"
    radacctdir = "/var/log/freeradius/accounting"
    panic_action = "gdb %e %p"
    hostname_lookups = no
    max_request_time = 30
    cleanup_delay = 5
    max_requests = 5300000
    postauth_client_lost = no
    pidfile = "/usr/local/var/run/radiusd/radiusd.pid"
    checkrad = "/usr/local/sbin/checkrad"
    debug_level = 0
    proxy_requests = no
 log {
    stripped_names = no
    auth = yes
    auth_badpass = yes
    auth_goodpass = no
    colourise = yes
    msg_denied = "You are already logged in - access denied"
 }
 resources {
 }
 security {
    max_attributes = 200
    reject_delay = 0.000000
    status_server = no
    allow_vulnerable_openssl = "CVE-2016-6304"
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####
Debugger not attached
 # Creating Auth-Type = eap
 # Creating Auth-Type = inner-eap
 # Creating Auth-Type = MS-CHAP
radiusd: #### Instantiating modules ####
 modules {
  # Loaded module rlm_always
  # Loading module "reject" from file /usr/local/etc/raddb/mods-available/always
  always reject {
    rcode = "reject"
    simulcount = 0
    mpp = no
  }
  # Loading module "fail" from file /usr/local/etc/raddb/mods-available/always
  always fail {
    rcode = "fail"
    simulcount = 0
    mpp = no
  }
  # Loading module "ok" from file /usr/local/etc/raddb/mods-available/always
  always ok {
    rcode = "ok"
    simulcount = 0
    mpp = no
  }
  # Loading module "handled" from file /usr/local/etc/raddb/mods-available/always
  always handled {
    rcode = "handled"
    simulcount = 0
    mpp = no
  }
  # Loading module "invalid" from file /usr/local/etc/raddb/mods-available/always
  always invalid {
    rcode = "invalid"
    simulcount = 0
    mpp = no
  }
  # Loading module "userlock" from file /usr/local/etc/raddb/mods-available/always
  always userlock {
    rcode = "userlock"
    simulcount = 0
    mpp = no
  }
  # Loading module "notfound" from file /usr/local/etc/raddb/mods-available/always
  always notfound {
    rcode = "notfound"
    simulcount = 0
    mpp = no
  }
  # Loading module "noop" from file /usr/local/etc/raddb/mods-available/always
  always noop {
    rcode = "noop"
    simulcount = 0
    mpp = no
  }
  # Loading module "updated" from file /usr/local/etc/raddb/mods-available/always
  always updated {
    rcode = "updated"
    simulcount = 0
    mpp = no
  }
  # Loaded module rlm_attr_filter
  # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.post-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/post-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.pre-proxy {
    filename = "/etc/raddb/mods-config/attr_filter/pre-proxy"
    key = "%{Realm}"
    relaxed = no
  }
  # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_reject {
    filename = "/etc/raddb/mods-config/attr_filter/access_reject"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.access_challenge {
    filename = "/etc/raddb/mods-config/attr_filter/access_challenge"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.accounting_response {
    filename = "/etc/raddb/mods-config/attr_filter/accounting_response"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loading module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
  attr_filter attr_filter.coa {
    filename = "/etc/raddb/mods-config/attr_filter/coa"
    key = "%{User-Name}"
    relaxed = no
  }
  # Loaded module rlm_date
  # Loading module "date" from file /usr/local/etc/raddb/mods-available/date
  date {
    format = "%b %e %Y %H:%M:%S %Z"
    utc = no
  }
  # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-available/date
  date wispr2date {
    format = "%Y-%m-%dT%H:%M:%S"
    utc = no
  }
  # Loaded module rlm_detail
  # Loading module "detail" from file /usr/local/etc/raddb/mods-available/detail
  detail {
    filename = "/var/log/freeradius/accounting/%{%{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 "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
  detail auth_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail reply_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail pre_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 /usr/local/etc/raddb/mods-available/detail.log
  detail post_proxy_log {
    filename = "/var/log/freeradius/accounting/%{%{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 module rlm_eap
  # Loading module "eap" from file /usr/local/etc/raddb/mods-available/eap
  eap {
    default_eap_type = "tls"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_exec
  # Loading module "echo" from file /usr/local/etc/raddb/mods-available/echo
  exec echo {
    wait = yes
    program = "/bin/echo %{User-Name}"
    input_pairs = "request"
    output_pairs = "reply"
    shell_escape = yes
  }
  # Loading module "exec" from file /usr/local/etc/raddb/mods-available/exec
  exec {
    wait = no
    input_pairs = "request"
    shell_escape = yes
    timeout = 10
  }
  # Loaded module rlm_expiration
  # Loading module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Loaded module rlm_expr
  # Loading module "expr" from file /usr/local/etc/raddb/mods-available/expr
  expr {
    safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ"
  }
  # Loaded module rlm_logintime
  # Loading module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  logintime {
    minimum_timeout = 60
  }
  # Loaded module rlm_preprocess
  # Loading module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
  preprocess {
    huntgroups = "/etc/raddb/mods-config/preprocess/huntgroups"
    hints = "/etc/raddb/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 module rlm_unix
  # Loading module "unix" from file /usr/local/etc/raddb/mods-available/unix
  unix {
    radwtmp = "/var/log/freeradius/radwtmp"
  }
Creating attribute Unix-Group
  # Loaded module rlm_utf8
  # Loading module "utf8" from file /usr/local/etc/raddb/mods-available/utf8
  # Loaded module rlm_linelog
  # Loading module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_reply {
    filename = "/var/log/freeradius/radius--detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{reply:Packet-Type}:-format}"
  }
  # Loading module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  linelog log_general_message {
    filename = "/var/log/freeradius/radius--detail-log.json"
    escape_filenames = no
    syslog_severity = "info"
    permissions = 420
    format = "%t Log for %{jsonquote:%{User-Name}}"
    reference = "messages.%{%{Packet-Type}:-format}"
  }
  # Loaded module rlm_rest
  # Loading module "rest" from file /usr/local/etc/raddb/mods-available/rest
  rest {
    connect_timeout = 4.000000
    http_negotiation = "default"
  }
  # Loaded module rlm_python3
  # Loading module "python3" from file /usr/local/etc/raddb/mods-available/python3
  python3 {
    mod_instantiate = "python-magic"
    func_instantiate = "instantiate"
    mod_authorize = "python-magic"
    func_authorize = "authorize"
    mod_authenticate = "python-magic"
    func_authenticate = "authenticate"
    mod_post_auth = "python-magic"
    func_post_auth = "post_auth"
    python_path = "/etc/raddb/mods-config/python3"
    cext_compat = yes
    pass_all_vps = no
    pass_all_vps_dict = yes
  }
  # Loading module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
  eap inner-eap {
    default_eap_type = "mschapv2"
    timer_expire = 60
    ignore_unknown_eap_types = no
    cisco_accounting_username_bug = no
    max_sessions = 5300000
  }
  # Loaded module rlm_mschap
  # Loading module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
  mschap {
    use_mppe = yes
    require_encryption = yes
    require_strong = yes
    with_ntdomain_hack = yes
   passchange {
   }
    allow_retry = yes
    winbind_retry_with_normalised_username = no
  }
  # Instantiating module "reject" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "fail" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "ok" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "handled" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "noop" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "updated" from file /usr/local/etc/raddb/mods-available/always
  # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/post-proxy
  # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/pre-proxy
  # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_reject
  # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/access_challenge
  # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/accounting_response
  # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-available/attr_filter
reading pairlist file /etc/raddb/mods-config/attr_filter/coa
  # Instantiating module "detail" from file /usr/local/etc/raddb/mods-available/detail
  # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-available/detail.log
rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output
  # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-available/detail.log
  # Instantiating module "eap" from file /usr/local/etc/raddb/mods-available/eap
   # Linked to sub-module rlm_eap_md5
   # Linked to sub-module rlm_eap_tls
   tls {
    tls = "tls-common"
    virtual_server = "check-eap-tls"
   }
   tls-config tls-common {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert.key"
    certificate_file = "/etc/raddb/servercert.pem"
    ca_file = "/etc/raddb/ca.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
   # Linked to sub-module rlm_eap_ttls
   ttls {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    virtual_server = "inner-tunnel"
    include_length = yes
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
   # Linked to sub-module rlm_eap_peap
   peap {
    tls = "tls-common"
    default_eap_type = "mschapv2"
    copy_request_to_tunnel = no
    use_tunneled_reply = yes
    proxy_tunneled_request_as_eap = yes
    virtual_server = "inner-tunnel"
    soh = no
    require_client_cert = no
   }
tls: Using cached TLS configuration from previous invocation
  # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-available/expiration
  # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-available/logintime
  # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-available/preprocess
reading pairlist file /etc/raddb/mods-config/preprocess/huntgroups
reading pairlist file /etc/raddb/mods-config/preprocess/hints
  # Instantiating module "log_reply" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "log_general_message" from file /usr/local/etc/raddb/mods-available/linelog
  # Instantiating module "rest" from file /usr/local/etc/raddb/mods-available/rest
rlm_rest: libcurl version: libcurl/7.68.0 OpenSSL/1.1.1f zlib/1.2.11 brotli/1.0.7 libidn2/2.2.0 libpsl/0.21.0 (+libidn2/2.2.0) libssh/0.9.3/openssl/zlib nghttp2/1.40.0 librtmp/2.3
rlm_rest (rest): Initialising connection pool
   pool {
    start = 5
    min = 5
    max = 10
    spare = 3
    uses = 0
    lifetime = 0
    cleanup_interval = 30
    idle_timeout = 60
    retry_delay = 1
    spread = no
   }
rlm_rest (rest): Opening additional connection (0), 1 of 10 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (1), 1 of 9 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (2), 1 of 8 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (3), 1 of 7 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
rlm_rest (rest): Opening additional connection (4), 1 of 6 pending slots used
rlm_rest (rest): Skipping pre-connect, connect_uri not specified
  # Instantiating module "python3" from file /usr/local/etc/raddb/mods-available/python3
Python version: 3.8.10 (default, Jun  2 2021, 10:49:15)  [GCC 9.4.0]
  # Instantiating module "inner-eap" from file /usr/local/etc/raddb/mods-available/inner-eap
   # Linked to sub-module rlm_eap_mschapv2
   mschapv2 {
    with_ntdomain_hack = no
    send_error = no
   }
  # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-available/mschap
rlm_mschap (mschap): using internal authentication
 } # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /usr/local/etc/raddb/radiusd.conf
} # server
server check-eap-tls { # from file /usr/local/etc/raddb/sites-available/check-eap-tls
 # Loading authorize {...}
} # server check-eap-tls
server  { # from file /usr/local/etc/raddb/sites-available/virt-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server 
server -radsec { # from file /usr/local/etc/raddb/sites-available/radsec-serv
 # Loading authenticate {...}
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading preacct {...}
 # Loading accounting {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
Compiling Post-Auth-Type Challenge for attr Post-Auth-Type
} # server -radsec
server inner-tunnel { # from file /usr/local/etc/raddb/sites-available/inner-tunnel
 # Loading authenticate {...}
Compiling Auth-Type MS-CHAP for attr Auth-Type
Compiling Auth-Type eap for attr Auth-Type
 # Loading authorize {...}
 # Loading post-auth {...}
Compiling Post-Auth-Type REJECT for attr Post-Auth-Type
} # server inner-tunnel
 thread pool {
    start_servers = 3
    max_servers = 32
    min_spare_servers = 3
    max_spare_servers = 10
    max_requests_per_server = 300
    cleanup_delay = 5
    max_queue_size = 65536
    auto_limit_acct = no
 }
Thread 1 waiting to be assigned a request
Thread spawned new child 1. Total threads in pool: 1
Thread 2 waiting to be assigned a request
Thread spawned new child 2. Total threads in pool: 2
Thread 3 waiting to be assigned a request
Thread spawned new child 3. Total threads in pool: 3
Thread pool initialized
radiusd: #### Opening IP addresses and Ports ####
listen {
    type = "auth"
    ipaddr = *
    port = 1812
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client  {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    shortname = ""
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "acct"
    ipaddr = *
    port = 1813
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
}
listen {
    type = "auth+acct"
    ipaddr = *
    port = 2083
    proto = "tcp"
    proxy_protocol = yes
   tls {
    verify_depth = 0
    pem_file_type = yes
    private_key_file = "/etc/raddb/servercert-radsec.key"
    certificate_file = "/etc/raddb/servercert-radsec.pem"
    ca_file = "/etc/raddb/ca-radsec.crt"
    dh_file = "/etc/raddb/certs/dh"
    fragment_size = 1024
    include_length = yes
    auto_chain = yes
    check_crl = no
    check_all_crl = no
    ca_path_reload_interval = 0
    cipher_list = "HIGH"
    cipher_server_preference = yes
    require_client_cert = yes
    reject_unknown_intermediate_ca = no
    ecdh_curve = "secp384r1"
    tls_max_version = "1.2"
    tls_min_version = "1.2"
    cache {
        enable = no
        lifetime = 24
        max_entries = 255
    }
    verify {
        skip_if_ocsp_ok = no
    }
    ocsp {
        enable = yes
        override_cert_url = no
        use_nonce = yes
        timeout = 2
        softfail = yes
    }
   }
    check_client_connections = no
   limit {
    max_connections = 0
    lifetime = 0
    idle_timeout = 30
   }
  client -radsec {
    ipaddr = *
    require_message_authenticator = yes
    secret = <<< secret >>>
    proto = "tls"
   limit {
    max_connections = 16
    lifetime = 0
    idle_timeout = 30
   }
  }
}
listen {
    type = "auth"
    ipaddr = 127.0.0.1
    port = 18120
}
Listening on auth address * port 1812 bound to server 
Listening on acct address * port 1813 bound to server 
Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server -radsec
Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel
Ready to process requests
 ... new connection request on TCP socket
Listening on auth+acct from client (77.47.68.110, 49922) -> (*, 2083, virtual-server=-radsec)
Waking up in 0.5 seconds.
(0) (TLS) Initiating new session
(0) (TLS) Setting verify mode to require certificate from client
(0) (TLS) Received PROXY protocol connection from client 172.23.100.1:38895 -> 172.18.0.2:2083, via proxy 77.47.68.110:49922 -> 0.0.0.0:2083
(0) (TLS) Handshake state - before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) recv TLS 1.3 Handshake, ClientHello
(0) (TLS) Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) send TLS 1.2 Handshake, ServerHello
(0) (TLS) Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) send TLS 1.2 Handshake, Certificate
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) send TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS write key exchange
(0) (TLS) send TLS 1.2 Handshake, CertificateRequest
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) send TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) Server : Need to read more data: SSLv3/TLS write server done
(0) (TLS) In Handshake Phase
Waking up in 0.4 seconds.
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) recv TLS 1.2 Handshake, Certificate
(0) (TLS) Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "0fc40d25cf3141d795f4d3a26dd7d9ae"
(0)   TLS-Client-Cert-Expiration := "220310102259Z"
(0)   TLS-Client-Cert-Valid-Since := "210310101259Z"
(0)   TLS-Client-Cert-Subject := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Issuer := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Common-Name := "Proxycertificate"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "proxy.felix.net"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB\n"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB"
Certificate chain - 0 cert(s) untrusted
(TLS) untrusted certificate with depth [0] subject name /CN=Proxycertificate
(0) Starting OCSP Request
(0) WARNING: ocsp: No OCSP URL in certificate.  Not doing OCSP
(0) WARNING: ocsp: Unable to check certificate, assuming it's valid
(0) WARNING: ocsp: This may be insecure
(0) (TLS) Handshake state - Server SSLv3/TLS read client certificate
(0) (TLS) recv TLS 1.2 Handshake, ClientKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS read client key exchange
(0) (TLS) recv TLS 1.2 Handshake, CertificateVerify
(0) (TLS) Handshake state - Server SSLv3/TLS read certificate verify
(0) (TLS) Handshake state - Server SSLv3/TLS read change cipher spec
(0) (TLS) recv TLS 1.2 Handshake, Finished
(0) (TLS) Handshake state - Server SSLv3/TLS read finished
(0) (TLS) send TLS 1.2 ChangeCipherSpec
(0) (TLS) Handshake state - Server SSLv3/TLS write change cipher spec
(0) (TLS) send TLS 1.2 Handshake, Finished
(0) (TLS) Handshake state - Server SSLv3/TLS write finished
(0) (TLS) Handshake state - SSL negotiation finished successfully
(0) (TLS) Connection Established
(0)   TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384"
(0)   TLS-Session-Version = "TLS 1.2"
Waking up in 0.4 seconds.
Waking up in 29.4 seconds.
Reached idle timeout on socket auth+acct from client (172.23.100.1, 38895) -> (172.18.0.2, 2083, virtual-server=-radsec)
 ... shutting down socket auth+acct from client (172.23.100.1, 38895) -> (172.18.0.2, 2083, virtual-server=-radsec)
Waking up in 2.9 seconds.
 ... new connection request on TCP socket
Listening on auth+acct from client (77.47.68.110, 50124) -> (*, 2083, virtual-server=-radsec)
Waking up in 0.4 seconds.
(0) (TLS) Initiating new session
(0) (TLS) Setting verify mode to require certificate from client
(0) (TLS) Received PROXY protocol connection from client 172.23.100.1:40685 -> 172.18.0.2:2083, via proxy 77.47.68.110:50124 -> 0.0.0.0:2083
(0) (TLS) Handshake state - before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) recv TLS 1.3 Handshake, ClientHello
(0) (TLS) Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) send TLS 1.2 Handshake, ServerHello
(0) (TLS) Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) send TLS 1.2 Handshake, Certificate
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) send TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS write key exchange
(0) (TLS) send TLS 1.2 Handshake, CertificateRequest
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) send TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) Server : Need to read more data: SSLv3/TLS write server done
(0) (TLS) In Handshake Phase
Waking up in 0.4 seconds.
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) recv TLS 1.2 Handshake, Certificate
(0) (TLS) Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "0fc40d25cf3141d795f4d3a26dd7d9ae"
(0)   TLS-Client-Cert-Expiration := "220310102259Z"
(0)   TLS-Client-Cert-Valid-Since := "210310101259Z"
(0)   TLS-Client-Cert-Subject := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Issuer := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Common-Name := "Proxycertificate"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "proxy.felix.net"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB\n"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB"
Certificate chain - 0 cert(s) untrusted
(TLS) untrusted certificate with depth [0] subject name /CN=Proxycertificate
(0) Starting OCSP Request
(0) WARNING: ocsp: No OCSP URL in certificate.  Not doing OCSP
(0) WARNING: ocsp: Unable to check certificate, assuming it's valid
(0) WARNING: ocsp: This may be insecure
(0) (TLS) Server : Need to read more data: SSLv3/TLS read client certificate
(0) (TLS) In Handshake Phase
(0) (TLS) Application data.
 ... shutting down socket auth+acct from client (172.23.100.1, 40685) -> (172.18.0.2, 2083, virtual-server=-radsec)
Waking up in 2.9 seconds.

REMOVED ALL LINES BETWEEN

Waking up in 0.8 seconds.
Waking up in 0.8 seconds.
Waking up in 0.8 seconds.
Waking up in 0.8 seconds.
 ... new connection request on TCP socket
Listening on auth+acct from client (77.47.68.110, 50126) -> (*, 2083, virtual-server=-radsec)
Waking up in 0.3 seconds.
(0) (TLS) Initiating new session
(0) (TLS) Setting verify mode to require certificate from client
(0) (TLS) Received PROXY protocol connection from client 172.23.100.1:38727 -> 172.18.0.2:2083, via proxy 77.47.68.110:50126 -> 0.0.0.0:2083
(0) (TLS) Handshake state - before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) Handshake state - Server before SSL initialization
(0) (TLS) recv TLS 1.3 Handshake, ClientHello
(0) (TLS) Handshake state - Server SSLv3/TLS read client hello
(0) (TLS) send TLS 1.2 Handshake, ServerHello
(0) (TLS) Handshake state - Server SSLv3/TLS write server hello
(0) (TLS) send TLS 1.2 Handshake, Certificate
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate
(0) (TLS) send TLS 1.2 Handshake, ServerKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS write key exchange
(0) (TLS) send TLS 1.2 Handshake, CertificateRequest
(0) (TLS) Handshake state - Server SSLv3/TLS write certificate request
(0) (TLS) send TLS 1.2 Handshake, ServerHelloDone
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) Server : Need to read more data: SSLv3/TLS write server done
(0) (TLS) In Handshake Phase
Waking up in 0.3 seconds.

REMOVED ALL LINES BETWEEN

Waking up in 0.3 seconds.
(0) (TLS) Handshake state - Server SSLv3/TLS write server done
(0) (TLS) recv TLS 1.2 Handshake, Certificate
(0) (TLS) Creating attributes from client certificate
(0)   TLS-Client-Cert-Serial := "0fc40d25cf3141d795f4d3a26dd7d9ae"
(0)   TLS-Client-Cert-Expiration := "220310102259Z"
(0)   TLS-Client-Cert-Valid-Since := "210310101259Z"
(0)   TLS-Client-Cert-Subject := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Issuer := "/CN=Proxycertificate"
(0)   TLS-Client-Cert-Common-Name := "Proxycertificate"
(0)   TLS-Client-Cert-Subject-Alt-Name-Dns := "proxy.felix.net"
(0)   TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE"
(0)   TLS-Client-Cert-X509v3-Authority-Key-Identifier += "keyid:F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB\n"
(0)   TLS-Client-Cert-X509v3-Subject-Key-Identifier += "F3:93:AF:2A:A9:1A:D9:DC:B9:92:A0:F4:44:B1:D7:E6:DF:17:1A:AB"
Certificate chain - 0 cert(s) untrusted
(TLS) untrusted certificate with depth [0] subject name /CN=Proxycertificate
(0) Starting OCSP Request
(0) WARNING: ocsp: No OCSP URL in certificate.  Not doing OCSP
(0) WARNING: ocsp: Unable to check certificate, assuming it's valid
(0) WARNING: ocsp: This may be insecure
(0) (TLS) Handshake state - Server SSLv3/TLS read client certificate
(0) (TLS) recv TLS 1.2 Handshake, ClientKeyExchange
(0) (TLS) Handshake state - Server SSLv3/TLS read client key exchange
(0) (TLS) recv TLS 1.2 Handshake, CertificateVerify
(0) (TLS) Handshake state - Server SSLv3/TLS read certificate verify
(0) (TLS) Handshake state - Server SSLv3/TLS read change cipher spec
(0) (TLS) recv TLS 1.2 Handshake, Finished
(0) (TLS) Handshake state - Server SSLv3/TLS read finished
(0) (TLS) send TLS 1.2 ChangeCipherSpec
(0) (TLS) Handshake state - Server SSLv3/TLS write change cipher spec
(0) (TLS) send TLS 1.2 Handshake, Finished
(0) (TLS) Handshake state - Server SSLv3/TLS write finished
(0) (TLS) Handshake state - SSL negotiation finished successfully
(0) (TLS) Connection Established
(0)   TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384"
(0)   TLS-Session-Version = "TLS 1.2"
Waking up in 0.3 seconds.

REMOVED ALL LINES BETWEEN

Waking up in 0.1 seconds.
... cleaning up socket auth+acct from client (172.23.100.1, 38895) -> (172.18.0.2, 2083, virtual-server=-radsec)
... cleaning up socket auth+acct from client (172.23.100.1, 40685) -> (172.18.0.2, 2083, virtual-server=-radsec)
Bad talloc magic value - unknown value

talloc abort: Bad talloc magic value - unknown value
CAUGHT SIGNAL: Aborted
27  ../sysdeps/unix/sysv/linux/wait4.c: No such file or directory.
Backtrace of last 10 frames:                                                              
/lib/x86_64-linux-gnu/libasan.so.5(+0x6cd30)[0x7f40382b1d30]
/usr/local/lib/libfreeradius-radius.so(fr_fault+0x1ee)[0x7f40380c1c96]
/usr/local/lib/libfreeradius-radius.so(+0x30152)[0x7f40380c2152]
/lib/x86_64-linux-gnu/libtalloc.so.2(+0x3ac8)[0x7f4037d1aac8]
radiusd(+0xf6fe2)[0x55ab6390cfe2]                                                         
/usr/local/lib/libfreeradius-radius.so(fr_event_loop+0xfe7)[0x7f403812e683]
radiusd(radius_event_process+0x2a)[0x55ab639117f9]
radiusd(main+0x22b3)[0x55ab638d2d2b]                                                      
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f4037ae60b3]
radiusd(_start+0x2e)[0x55ab6387707e]                                                      
Calling: gdb radiusd 80581

gdb: 

  Id   Target Id                                   Frame 
* 1    Thread 0x7f40378d4540 (LWP 80581) "radiusd" 0x00007f4037ba4dff in __GI___wait4 (pid=80593, stat_loc=stat_loc@entry=0x7ffd88ab0598, options=options@entry=0, 
    usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
  2    Thread 0x7f402d198700 (LWP 80585) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320
  3    Thread 0x7f402c989700 (LWP 80586) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320
  4    Thread 0x7f402c172700 (LWP 80587) "radiusd" futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>)
    at ../sysdeps/nptl/futex-internal.h:320

Thread 4 (Thread 0x7f402c172700 (LWP 80587)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f4037cff4e8 in __new_sem_wait_slow (sem=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f4037cff3a0 <__sem_wait_cleanup>, __arg = 0x55ab639ebde8 <thread_pool+168>, __canceltype = 731328512, __prev = 0x0}
        err = <optimized out>
        d = 8589934592
#3  0x000055ab638e8159 in request_handler_thread (arg=0x606000005a20) at src/main/threads.c:755
        self = 0x606000005a20
#4  0x00007f4037cf5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139913594349312, 331644156087926463, 140726896364142, 140726896364143, 140726896364144, 139913594347328, -424916488723071297, -424935934025892161}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f4037be1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 3 (Thread 0x7f402c989700 (LWP 80586)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f4037cff4e8 in __new_sem_wait_slow (sem=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f4037cff3a0 <__sem_wait_cleanup>, __arg = 0x55ab639ebde8 <thread_pool+168>, __canceltype = 739811328, __prev = 0x0}
        err = <optimized out>
        d = 4294967296
#3  0x000055ab638e8159 in request_handler_thread (arg=0x6060000059c0) at src/main/threads.c:755
        self = 0x6060000059c0
#4  0x00007f4037cf5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139913602832128, 331644156087926463, 140726896364142, 140726896364143, 140726896364144, 139913602830144, -424915428403020097, -424935934025892161}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f4037be1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 2 (Thread 0x7f402d198700 (LWP 80585)):
#0  futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x55ab639ebde8 <thread_pool+168>) at ../sysdeps/nptl/futex-internal.h:320
        __ret = -512
        op = 393
        __ret = <optimized out>
        oldtype = 0
        err = <optimized out>
        oldtype = <optimized out>
        err = <optimized out>
        __ret = <optimized out>
        clockbit = <optimized out>
        op = <optimized out>
        __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  do_futex_wait (sem=sem@entry=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:112
        err = <optimized out>
#2  0x00007f4037cff4e8 in __new_sem_wait_slow (sem=0x55ab639ebde8 <thread_pool+168>, abstime=0x0, clockid=0) at sem_waitcommon.c:184
        _buffer = {__routine = 0x7f4037cff3a0 <__sem_wait_cleanup>, __arg = 0x55ab639ebde8 <thread_pool+168>, __canceltype = 748261376, __prev = 0x0}
        err = <optimized out>
        d = 0
#3  0x000055ab638e8159 in request_handler_thread (arg=0x606000005960) at src/main/threads.c:755
        self = 0x606000005960
#4  0x00007f4037cf5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
        ret = <optimized out>
        pd = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139913611282176, 331644156087926463, 140726896364142, 140726896364143, 140726896364144, 139913611280192, -424914340165681473, -424935934025892161}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#5  0x00007f4037be1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.

Thread 1 (Thread 0x7f40378d4540 (LWP 80581)):
#0  0x00007f4037ba4dff in __GI___wait4 (pid=80593, stat_loc=stat_loc@entry=0x7ffd88ab0598, options=options@entry=0, usage=usage@entry=0x0) at ../sysdeps/unix/sysv/linux/wait4.c:27
        resultvar = 18446744073709551104
        sc_cancel_oldtype = 0
        sc_ret = <optimized out>
#1  0x00007f4037ba4d7b in __GI___waitpid (pid=<optimized out>, stat_loc=stat_loc@entry=0x7ffd88ab0598, options=options@entry=0) at waitpid.c:38
No locals.
#2  0x00007f4037b140e7 in do_system (line=<optimized out>) at ../sysdeps/posix/system.c:172
        __result = <optimized out>
        _buffer = {__routine = 0x7f4037b14290 <cancel_handler>, __arg = 0x7ffd88ab05a0, __canceltype = 0, __prev = 0x0}
        _avail = 1
        cancel_args = {quit = 0x7f4037cad200 <quit>, intr = 0x7f4037cad2a0 <intr>, pid = 80593}
        status = -1
        ret = 0
        pid = 80593
        sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {65536, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x7ffd88ab0920}
        omask = {__val = {0, 0, 0, 0, 0, 139913790666176, 549755813889, 8109952527594625536, 140726896361472, 0, 18446744073709551615, 140726896363776, 0, 0, 0, 18446744069414649600}}
        reset = {__val = {6, 0 <repeats 15 times>}}
        spawn_attr = {__flags = 12, __pgrp = 0, __sd = {__val = {6, 0 <repeats 15 times>}}, __ss = {__val = {0, 0, 0, 0, 0, 139913790666176, 549755813889, 8109952527594625536, 140726896361472, 0, 18446744073709551615, 140726896363776, 0, 0, 0, 18446744069414649600}}, __sp = {sched_priority = 0}, __policy = 0, __pad = {0 <repeats 16 times>}}
        __cnt = <optimized out>
        __set = <optimized out>
        __cnt = <optimized out>
        __set = <optimized out>
#3  0x00007f40380c1ed6 in fr_fault (sig=6) at src/lib/debug.c:791
        disable = false
        cmd = "gdb radiusd 80581", '\000' <repeats 514 times>
        out = 0x7ffd88ab0e31 ""
        left = 515
        ret = 17
        p = 0x7f4038176f0e <panic_action+14> ""
        q = 0x0
        code = 32765
#4  0x00007f40380c2152 in _fr_talloc_fault (reason=0x7f4037d24070 "Bad talloc magic value - unknown value") at src/lib/debug.c:864
No locals.
#5  0x00007f4037d1aac8 in ?? () from /lib/x86_64-linux-gnu/libtalloc.so.2
No symbol table info available.
#6  0x000055ab6390cfe2 in event_socket_handler (xel=0x627000000160, fd=12, ctx=0x614000014aa0) at src/main/process.c:5100
        listener = 0x614000014aa0
#7  0x00007f403812e683 in fr_event_loop (el=0x627000000160) at src/lib/event.c:649
        ef = 0x627000000210
        i = 5
        rcode = 1
        when = {tv_sec = 1628503653, tv_usec = 500000}
        wake = 0x7ffd88ab1390
        maxfd = 13
        read_fds = {fds_bits = {4096, 0 <repeats 15 times>}}
        master_fds = {fds_bits = {14240, 0 <repeats 15 times>}}
#8  0x000055ab639117f9 in radius_event_process () at src/main/process.c:6276
No locals.
#9  0x000055ab638d2d2b in main (argc=4, argv=0x7ffd88ab1748) at src/main/radiusd.c:641
        rcode = 0
        status = 0
        argval = -1
        spawn_flag = true
        display_version = false
        flag = 0
        from_child = {-1, -1}
        p = 0x0
        state = 0x55ab639eb4c0 <global_state>
        autofree = 0x608000000080
Detaching from program: /usr/local/sbin/radiusd, process 80581
[Inferior 1 (process 80581) detached]

Or maybe the issue is with the Traefik load balancer somehow doing something weird with the TCP connection?

sure that's possible. So i tried it with haproxy also and the result is the same :(. If there are beside each other, everthing is working great. If the radius server is in the public internet, it crashes.

alandekok commented 3 years ago

The talloc error is because the listen data structure is no longer valid for some reason. The address / leak sanitizer should catch the typical "use after free" error.

But what concerns me here (again) is why the server busy-loops. This is a major problem, and is likely the source of the issue. We need to find out why it's busy looping.

The issue is that the proxy_protocol checks happen long before the busy loop occurs. The proxy protocol checks happen only when the socket first opens. After about 100 bytes are read, the code is exactly the same for both RadSec, and for the proxy protocol. The only difference is the haproxy or traefik proxy itself.

So there's something about those systems which makes the TCP connection different.

Maybe try configuring them to not use the proxy protocol, but instead pass the TLS connection straight through to FreeRADIUS. If that still fails, then there are weird issues with the proxies.

gk-fschubert commented 3 years ago

We need to find out why it's busy looping.

is there something i can do to help, find out what is causing the issue?

Maybe try configuring them to not use the proxy protocol, but instead pass the TLS connection straight through to FreeRADIUS. > If that still fails, then there are weird issues with the proxies.

Without using the PROXY protocol, passing the traffic straight to FreeRADIUS, everything is working fine.

alandekok commented 3 years ago

For the busy loop issue, maybe look at strace output, and/or packet traces?

If there's no traffic coming to the server, then the issue is in FreeRADIUS. If there is traffic, then maybe the proxy is sending TCP keepalives or something like that...

alandekok commented 3 years ago

Maybe also run it under radiusd -Xxx, where it should dump out all of the TLS data in hex, and print out some more about its internal state.

Barring that, add log lines to various places (where they don't exist) to try to get a better idea about what it's doing.

terryburton commented 3 years ago

@gk-fschubert As a useful data point, does reverting the following improve things:

git revert 75620b2fb9e7eb4f7853373fe3ffc2f67e97bb22
alandekok commented 3 years ago

I've pushed some changes which should fix it. Please check.

gk-fschubert commented 3 years ago

Great, it's fixed. Thanks!