Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

[defect]: Radsec home server openssl "Client : Error in SSLv3/TLS write client hello" #5310

Open
haegar opened this issue Mar 14, 2024 · 2 comments
Labels
defect category: a defect or misbehaviour

Comments

@haegar
Copy link

haegar commented Mar 14, 2024

What type of defect/bug is this?

Unexpected behaviour (obvious or verified by project member)

How can the issue be reproduced?

Setup is freeradius 3.2 git 66e6389 listening on udp port, and trying to forward all requests received there via radsec/tcp+tls to homeserver.
The setup in a slightly more complex config than in this reproduction is used for forward authentication from devices which can't do tls radius (aka switches) via such radius proxies encrypted over the internet to our datacenter.

Establishing connection to tls homeserver fails with "ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello". Same setup works with freeradius 3.2.1, and works "sometimes" with 3.2.3 release, where it sometimes breaks with slightly different ssl error messages, and sometimes seems to work - was unable to figure out a scheme, so I tried with the latest git snapshot I am reporting about here.

Both radsec server (tested with freeradius 3.2.1 and with radiator) and this freeradius client use a custom private CA, which generated the server and client certificates.

Accessing the radsec server via openssl s_client also works just fine and establishes the ssl connection.

This problem may be similar to #5308, but I don't listen for TLS connections, and don't get assertion failed or crashes - just the outbound TLS connection fails to get established.

Tried both
tls_min_version = "1.2"
tls_max_version = "1.2"
(where freeradius tries to use tls 1.2)
and
tls_min_version = "1.2"
tls_max_version = "1.3"
where it tries to use tls 1.3 fail in absolutely the same way.

Log output from the FreeRADIUS daemon

$ /usr/sbin/freeradius -f -d /home/haegar/freeradius-testing/ -l stdout -Xx

Thu Mar 14 16:15:34 2024 : Debug: Server was built with: 
Thu Mar 14 16:15:34 2024 : Debug:   accounting                : yes
Thu Mar 14 16:15:34 2024 : Debug:   authentication            : yes
Thu Mar 14 16:15:34 2024 : Debug:   ascend-binary-attributes  : yes
Thu Mar 14 16:15:34 2024 : Debug:   coa                       : yes
Thu Mar 14 16:15:34 2024 : Debug:   recv-coa-from-home-server : no
Thu Mar 14 16:15:34 2024 : Debug:   control-socket            : yes
Thu Mar 14 16:15:34 2024 : Debug:   detail                    : yes
Thu Mar 14 16:15:34 2024 : Debug:   dhcp                      : yes
Thu Mar 14 16:15:34 2024 : Debug:   dynamic-clients           : yes
Thu Mar 14 16:15:34 2024 : Debug:   osfc2                     : no
Thu Mar 14 16:15:34 2024 : Debug:   proxy                     : yes
Thu Mar 14 16:15:34 2024 : Debug:   regex-pcre                : yes
Thu Mar 14 16:15:34 2024 : Debug:   regex-posix               : no
Thu Mar 14 16:15:34 2024 : Debug:   regex-posix-extended      : no
Thu Mar 14 16:15:34 2024 : Debug:   session-management        : yes
Thu Mar 14 16:15:34 2024 : Debug:   stats                     : yes
Thu Mar 14 16:15:34 2024 : Debug:   systemd                   : yes
Thu Mar 14 16:15:34 2024 : Debug:   tcp                       : yes
Thu Mar 14 16:15:34 2024 : Debug:   threads                   : yes
Thu Mar 14 16:15:34 2024 : Debug:   tls                       : yes
Thu Mar 14 16:15:34 2024 : Debug:   unlang                    : yes
Thu Mar 14 16:15:34 2024 : Debug:   vmps                      : yes
Thu Mar 14 16:15:34 2024 : Debug:   developer                 : no
Thu Mar 14 16:15:34 2024 : Debug: Server core libs:
Thu Mar 14 16:15:34 2024 : Debug:   freeradius-server         : 3.2.3
Thu Mar 14 16:15:34 2024 : Debug:   talloc                    : 2.4.*
Thu Mar 14 16:15:34 2024 : Debug:   ssl                       : 3.0.0k dev
Thu Mar 14 16:15:34 2024 : Debug:   pcre                      : 8.39 2016-06-14
Thu Mar 14 16:15:34 2024 : Debug: Endianness:
Thu Mar 14 16:15:34 2024 : Debug:   little
Thu Mar 14 16:15:34 2024 : Debug: Compilation flags:
Thu Mar 14 16:15:34 2024 : Debug:   cppflags : -Wdate-time -D_FORTIFY_SOURCE=2
Thu Mar 14 16:15:34 2024 : Debug:   cflags   : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g -O2 -ffile-prefix-map=/home/haegar/compile/freeradius/freeradius-3.2.3=. -fstack-protector-strong -Wformat -Werror=format-security -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1
Thu Mar 14 16:15:34 2024 : Debug:   ldflags  :  -Wl,-z,relro -Wl,-z,now 
Thu Mar 14 16:15:34 2024 : Debug:   libs     : -lcrypto -lssl -ltalloc -latomic -lpcre -lcap -lnsl -lresolv -ldl -lpthread -lreadline
Thu Mar 14 16:15:34 2024 : Debug:   
Thu Mar 14 16:15:34 2024 : Info: FreeRADIUS Version 3.2.3
Thu Mar 14 16:15:34 2024 : Info: Copyright (C) 1999-2023 The FreeRADIUS server project and contributors
Thu Mar 14 16:15:34 2024 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Thu Mar 14 16:15:34 2024 : Info: PARTICULAR PURPOSE
Thu Mar 14 16:15:34 2024 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Thu Mar 14 16:15:34 2024 : Info: GNU General Public License
Thu Mar 14 16:15:34 2024 : Info: For more information about these matters, see the file named COPYRIGHT
Thu Mar 14 16:15:34 2024 : Info: Starting - reading configuration files ...
Thu Mar 14 16:15:34 2024 : Debug: including dictionary file /usr/share/freeradius/dictionary
Thu Mar 14 16:15:34 2024 : Debug: including dictionary file /usr/share/freeradius/dictionary.dhcp
Thu Mar 14 16:15:34 2024 : Debug: including dictionary file /usr/share/freeradius/dictionary.vqp
Thu Mar 14 16:15:34 2024 : Debug: including dictionary file /home/haegar/freeradius-testing//dictionary
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//radiusd.conf
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//proxy.conf
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//clients.conf
Thu Mar 14 16:15:34 2024 : Debug: including files in directory /home/haegar/freeradius-testing//mods-enabled/
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/expr
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/pap
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/preprocess
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug: including files in directory /home/haegar/freeradius-testing//policy.d/
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/abfab-tr
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/accounting
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/canonicalization
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/control
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/cui
Thu Mar 14 16:15:34 2024 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
Thu Mar 14 16:15:34 2024 : Debug: OPTIMIZING (no == yes) --> FALSE
Thu Mar 14 16:15:34 2024 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE
Thu Mar 14 16:15:34 2024 : Debug: OPTIMIZING (no == yes) --> FALSE
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/debug
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/dhcp
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/eap
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/filter
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/moonshot-targeted-ids
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/operator-name
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//policy.d/rfc7542
Thu Mar 14 16:15:34 2024 : Debug: including files in directory /home/haegar/freeradius-testing//sites-enabled/
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 16:15:34 2024 : Debug: including configuration file /home/haegar/freeradius-testing//sites-enabled/status
Thu Mar 14 16:15:34 2024 : Debug: main {
Thu Mar 14 16:15:34 2024 : Debug:       name = "freeradius"
Thu Mar 14 16:15:34 2024 : Debug:       prefix = "/usr"
Thu Mar 14 16:15:34 2024 : Debug:       localstatedir = "/var"
Thu Mar 14 16:15:34 2024 : Debug:       sbindir = "/usr/sbin"
Thu Mar 14 16:15:34 2024 : Debug:       logdir = "/var/log/freeradius"
Thu Mar 14 16:15:34 2024 : Debug:       run_dir = "/var/run/freeradius"
Thu Mar 14 16:15:34 2024 : Debug:       libdir = "/usr/lib/freeradius"
Thu Mar 14 16:15:34 2024 : Debug:       radacctdir = "/var/log/freeradius/radacct"
Thu Mar 14 16:15:34 2024 : Debug:       hostname_lookups = no
Thu Mar 14 16:15:34 2024 : Debug:       max_request_time = 30
Thu Mar 14 16:15:34 2024 : Debug:       proxy_dedup_window = 1
Thu Mar 14 16:15:34 2024 : Debug:       cleanup_delay = 5
Thu Mar 14 16:15:34 2024 : Debug:       max_requests = 16384
Thu Mar 14 16:15:34 2024 : Debug:       postauth_client_lost = no
Thu Mar 14 16:15:34 2024 : Debug:       pidfile = "/var/run/freeradius/freeradius.pid"
Thu Mar 14 16:15:34 2024 : Debug:       checkrad = "/usr/sbin/checkrad"
Thu Mar 14 16:15:34 2024 : Debug:       debug_level = 0
Thu Mar 14 16:15:34 2024 : Debug:       proxy_requests = yes
Thu Mar 14 16:15:34 2024 : Debug:  log {
Thu Mar 14 16:15:34 2024 : Debug:       stripped_names = no
Thu Mar 14 16:15:34 2024 : Debug:       auth = yes
Thu Mar 14 16:15:34 2024 : Debug:       auth_badpass = no
Thu Mar 14 16:15:34 2024 : Debug:       auth_goodpass = no
Thu Mar 14 16:15:34 2024 : Debug:       colourise = yes
Thu Mar 14 16:15:34 2024 : Debug:       msg_denied = "You are already logged in - access denied"
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[38]: The item 'destination' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[40]: The item 'file' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[41]: The item 'syslog_facility' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  resources {
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  security {
Thu Mar 14 16:15:34 2024 : Debug:       max_attributes = 0
Thu Mar 14 16:15:34 2024 : Debug:       reject_delay = 1.000000
Thu Mar 14 16:15:34 2024 : Debug:       status_server = yes
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[54]: The item 'allow_core_dumps' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[5]: The item 'sysconfdir' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[15]: The item 'confdir' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[17]: The item 'certdir' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[18]: The item 'cadir' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[22]: The item 'db_dir' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//radiusd.conf[27]: The item 'correct_escapes' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: radiusd: #### Loading Realms and Home Servers ####
Thu Mar 14 16:15:34 2024 : Debug:  home_server home_tcp_172_16_9_102_2083 {
Thu Mar 14 16:15:34 2024 : Debug:       nonblock = yes
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 172.16.9.102
Thu Mar 14 16:15:34 2024 : Debug:       port = 2083
Thu Mar 14 16:15:34 2024 : Debug:       type = "auth+acct"
Thu Mar 14 16:15:34 2024 : Debug:       proto = "tcp"
Thu Mar 14 16:15:34 2024 : Debug:       secret = "radsec"
Thu Mar 14 16:15:34 2024 : Debug:       response_window = 10.000000
Thu Mar 14 16:15:34 2024 : Debug:       response_timeouts = 2
Thu Mar 14 16:15:34 2024 : Debug:       max_outstanding = 250
Thu Mar 14 16:15:34 2024 : Debug:       zombie_period = 30
Thu Mar 14 16:15:34 2024 : Debug:       status_check = "status-server"
Thu Mar 14 16:15:34 2024 : Debug:       ping_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_timeout = 5
Thu Mar 14 16:15:34 2024 : Debug:       num_answers_to_alive = 3
Thu Mar 14 16:15:34 2024 : Debug:       revive_interval = 300
Thu Mar 14 16:15:34 2024 : Debug:       username = "server_test_user_please_reject_me"
Thu Mar 14 16:15:34 2024 : Debug:       password = "this is not really secret and always wrong"
Thu Mar 14 16:15:34 2024 : Debug:   limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 8
Thu Mar 14 16:15:34 2024 : Debug:       max_requests = 0
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 86400
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 180
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   coa {
Thu Mar 14 16:15:34 2024 : Debug:       irt = 2
Thu Mar 14 16:15:34 2024 : Debug:       mrt = 16
Thu Mar 14 16:15:34 2024 : Debug:       mrc = 5
Thu Mar 14 16:15:34 2024 : Debug:       mrd = 30
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:   tls {
Thu Mar 14 16:15:34 2024 : Debug:       verify_depth = 0
Thu Mar 14 16:15:34 2024 : Debug:       pem_file_type = yes
Thu Mar 14 16:15:34 2024 : Debug:       private_key_file = "certs/ssl-cert-11-auth1.key.pem"
Thu Mar 14 16:15:34 2024 : Debug:       certificate_file = "certs/ssl-cert-11-auth1.all.pem"
Thu Mar 14 16:15:34 2024 : Debug:       ca_file = "certs/ssl-cert-11-auth1.ca.pem"
Thu Mar 14 16:15:34 2024 : Debug:       random_file = "/dev/urandom"
Thu Mar 14 16:15:34 2024 : Debug:       fragment_size = 8192
Thu Mar 14 16:15:34 2024 : Debug:       include_length = yes
Thu Mar 14 16:15:34 2024 : Debug:       check_crl = no
Thu Mar 14 16:15:34 2024 : Debug:       cipher_list = "DEFAULT"
Thu Mar 14 16:15:34 2024 : Debug:       ca_path_reload_interval = 0
Thu Mar 14 16:15:34 2024 : Debug:       fix_cert_order = yes
Thu Mar 14 16:15:34 2024 : Debug:       ecdh_curve = "prime256v1"
Thu Mar 14 16:15:34 2024 : Debug:       tls_max_version = "1.2"
Thu Mar 14 16:15:34 2024 : Debug:       tls_min_version = "1.2"
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//proxy.conf[36]: The item 'connect_timeout' is defined, but is unused by the configuration
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:       connect_timeout = 5
Thu Mar 14 16:15:34 2024 : Debug:  home_server home_udp_172_16_8_102_20390 {
Thu Mar 14 16:15:34 2024 : Debug:       nonblock = no
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 83.97.120.102
Thu Mar 14 16:15:34 2024 : Debug:       port = 20390
Thu Mar 14 16:15:34 2024 : Debug:       type = "auth"
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       secret = "Sp7xyDrk"
Thu Mar 14 16:15:34 2024 : Debug:       response_window = 10.000000
Thu Mar 14 16:15:34 2024 : Debug:       response_timeouts = 1
Thu Mar 14 16:15:34 2024 : Debug:       max_outstanding = 250
Thu Mar 14 16:15:34 2024 : Debug:       zombie_period = 30
Thu Mar 14 16:15:34 2024 : Debug:       status_check = "request"
Thu Mar 14 16:15:34 2024 : Debug:       ping_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_timeout = 5
Thu Mar 14 16:15:34 2024 : Debug:       num_answers_to_alive = 3
Thu Mar 14 16:15:34 2024 : Debug:       revive_interval = 300
Thu Mar 14 16:15:34 2024 : Debug:       username = "server_test_user_please_reject_me"
Thu Mar 14 16:15:34 2024 : Debug:       password = "this is not really secret and always wrong"
Thu Mar 14 16:15:34 2024 : Debug:   limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 16
Thu Mar 14 16:15:34 2024 : Debug:       max_requests = 0
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 0
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 0
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   coa {
Thu Mar 14 16:15:34 2024 : Debug:       irt = 2
Thu Mar 14 16:15:34 2024 : Debug:       mrt = 16
Thu Mar 14 16:15:34 2024 : Debug:       mrc = 5
Thu Mar 14 16:15:34 2024 : Debug:       mrd = 30
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  home_server home_udp_172_16_8_102_20391 {
Thu Mar 14 16:15:34 2024 : Debug:       nonblock = no
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 172.16.8.102
Thu Mar 14 16:15:34 2024 : Debug:       port = 20391
Thu Mar 14 16:15:34 2024 : Debug:       type = "acct"
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       secret = "Sp7xyDrk"
Thu Mar 14 16:15:34 2024 : Debug:       response_window = 10.000000
Thu Mar 14 16:15:34 2024 : Debug:       response_timeouts = 1
Thu Mar 14 16:15:34 2024 : Debug:       max_outstanding = 250
Thu Mar 14 16:15:34 2024 : Debug:       zombie_period = 30
Thu Mar 14 16:15:34 2024 : Debug:       status_check = "request"
Thu Mar 14 16:15:34 2024 : Debug:       ping_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_interval = 10
Thu Mar 14 16:15:34 2024 : Debug:       check_timeout = 5
Thu Mar 14 16:15:34 2024 : Debug:       num_answers_to_alive = 3
Thu Mar 14 16:15:34 2024 : Debug:       revive_interval = 300
Thu Mar 14 16:15:34 2024 : Debug:       username = "server_test_user_please_reject_me"
Thu Mar 14 16:15:34 2024 : Debug:       password = "this is not really secret and always wrong"
Thu Mar 14 16:15:34 2024 : Debug:   limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 16
Thu Mar 14 16:15:34 2024 : Debug:       max_requests = 0
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 0
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 0
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   coa {
Thu Mar 14 16:15:34 2024 : Debug:       irt = 2
Thu Mar 14 16:15:34 2024 : Debug:       mrt = 16
Thu Mar 14 16:15:34 2024 : Debug:       mrc = 5
Thu Mar 14 16:15:34 2024 : Debug:       mrd = 30
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  home_server_pool failover_auth_shs {
Thu Mar 14 16:15:34 2024 : Debug:       type = fail-over
Thu Mar 14 16:15:34 2024 : Debug:       home_server = home_tcp_172_16_9_102_2083
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  home_server_pool failover_acct_shs {
Thu Mar 14 16:15:34 2024 : Debug:       type = fail-over
Thu Mar 14 16:15:34 2024 : Debug:       home_server = home_tcp_172_16_9_102_2083
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug:  realm shs {
Thu Mar 14 16:15:34 2024 : Debug:       auth_pool = failover_auth_shs
Thu Mar 14 16:15:34 2024 : Debug:       acct_pool = failover_acct_shs
Thu Mar 14 16:15:34 2024 : Debug:       nostrip
Thu Mar 14 16:15:34 2024 : Debug:  }
Thu Mar 14 16:15:34 2024 : Debug: radiusd: #### Loading Clients ####
Thu Mar 14 16:15:34 2024 : Info: Debug state unknown (cap_sys_ptrace capability not set)
Thu Mar 14 16:15:34 2024 : Info: systemd watchdog is disabled
Thu Mar 14 16:15:34 2024 : Debug:  # Creating Auth-Type = PAP
Thu Mar 14 16:15:34 2024 : Debug:  # Creating Autz-Type = Status-Server
Thu Mar 14 16:15:34 2024 : Debug: radiusd: #### Instantiating modules ####
Thu Mar 14 16:15:34 2024 : Debug:  modules {
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_always, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_always
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "reject" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always reject {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "reject"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "fail" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always fail {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "fail"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "ok" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always ok {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "ok"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "handled" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always handled {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "handled"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "invalid" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always invalid {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "invalid"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "userlock" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always userlock {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "userlock"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "notfound" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always notfound {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "notfound"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "noop" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always noop {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "noop"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "updated" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   always updated {
Thu Mar 14 16:15:34 2024 : Debug:       rcode = "updated"
Thu Mar 14 16:15:34 2024 : Debug:       simulcount = 0
Thu Mar 14 16:15:34 2024 : Debug:       mpp = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_attr_filter, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "attr_filter.post-proxy" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   attr_filter attr_filter.post-proxy {
Thu Mar 14 16:15:34 2024 : Debug:       filename = "/home/haegar/freeradius-testing//mods-config/attr_filter/post-proxy"
Thu Mar 14 16:15:34 2024 : Debug:       key = "%{Realm}"
Thu Mar 14 16:15:34 2024 : Debug:       relaxed = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "attr_filter.pre-proxy" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   attr_filter attr_filter.pre-proxy {
Thu Mar 14 16:15:34 2024 : Debug:       filename = "/home/haegar/freeradius-testing//mods-config/attr_filter/pre-proxy"
Thu Mar 14 16:15:34 2024 : Debug:       key = "%{Realm}"
Thu Mar 14 16:15:34 2024 : Debug:       relaxed = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "attr_filter.access_reject" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   attr_filter attr_filter.access_reject {
Thu Mar 14 16:15:34 2024 : Debug:       filename = "/home/haegar/freeradius-testing//mods-config/attr_filter/access_reject"
Thu Mar 14 16:15:34 2024 : Debug:       key = "%{User-Name}"
Thu Mar 14 16:15:34 2024 : Debug:       relaxed = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "attr_filter.access_challenge" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   attr_filter attr_filter.access_challenge {
Thu Mar 14 16:15:34 2024 : Debug:       filename = "/home/haegar/freeradius-testing//mods-config/attr_filter/access_challenge"
Thu Mar 14 16:15:34 2024 : Debug:       key = "%{User-Name}"
Thu Mar 14 16:15:34 2024 : Debug:       relaxed = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "attr_filter.accounting_response" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug:   attr_filter attr_filter.accounting_response {
Thu Mar 14 16:15:34 2024 : Debug:       filename = "/home/haegar/freeradius-testing//mods-config/attr_filter/accounting_response"
Thu Mar 14 16:15:34 2024 : Debug:       key = "%{User-Name}"
Thu Mar 14 16:15:34 2024 : Debug:       relaxed = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_expr, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_expr
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "expr" from file /home/haegar/freeradius-testing//mods-enabled/expr
Thu Mar 14 16:15:34 2024 : Debug:   expr {
Thu Mar 14 16:15:34 2024 : Debug:       safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /???????????????????a??????????????????????"
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_pap, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_pap
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "pap" from file /home/haegar/freeradius-testing//mods-enabled/pap
Thu Mar 14 16:15:34 2024 : Debug:   pap {
Thu Mar 14 16:15:34 2024 : Debug:       normalise = yes
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_preprocess, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_preprocess
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "preprocess" from file /home/haegar/freeradius-testing//mods-enabled/preprocess
Thu Mar 14 16:15:34 2024 : Debug:   preprocess {
Thu Mar 14 16:15:34 2024 : Debug:       huntgroups = "/home/haegar/freeradius-testing//mods-config/preprocess/huntgroups"
Thu Mar 14 16:15:34 2024 : Debug:       hints = "/home/haegar/freeradius-testing//mods-config/preprocess/hints"
Thu Mar 14 16:15:34 2024 : Debug:       with_ascend_hack = no
Thu Mar 14 16:15:34 2024 : Debug:       ascend_channels_per_line = 23
Thu Mar 14 16:15:34 2024 : Debug:       with_ntdomain_hack = no
Thu Mar 14 16:15:34 2024 : Debug:       with_specialix_jetstream_hack = no
Thu Mar 14 16:15:34 2024 : Debug:       with_cisco_vsa_hack = no
Thu Mar 14 16:15:34 2024 : Debug:       with_alvarion_vsa_hack = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Loaded rlm_realm, checking if it's valid
Thu Mar 14 16:15:34 2024 : Debug:   # Loaded module rlm_realm
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "IPASS" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   realm IPASS {
Thu Mar 14 16:15:34 2024 : Debug:       format = "prefix"
Thu Mar 14 16:15:34 2024 : Debug:       delimiter = "/"
Thu Mar 14 16:15:34 2024 : Debug:       ignore_default = no
Thu Mar 14 16:15:34 2024 : Debug:       ignore_null = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "suffix" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   realm suffix {
Thu Mar 14 16:15:34 2024 : Debug:       format = "suffix"
Thu Mar 14 16:15:34 2024 : Debug:       delimiter = "@"
Thu Mar 14 16:15:34 2024 : Debug:       ignore_default = no
Thu Mar 14 16:15:34 2024 : Debug:       ignore_null = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "bangpath" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   realm bangpath {
Thu Mar 14 16:15:34 2024 : Debug:       format = "prefix"
Thu Mar 14 16:15:34 2024 : Debug:       delimiter = "!"
Thu Mar 14 16:15:34 2024 : Debug:       ignore_default = no
Thu Mar 14 16:15:34 2024 : Debug:       ignore_null = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "realmpercent" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   realm realmpercent {
Thu Mar 14 16:15:34 2024 : Debug:       format = "suffix"
Thu Mar 14 16:15:34 2024 : Debug:       delimiter = "%"
Thu Mar 14 16:15:34 2024 : Debug:       ignore_default = no
Thu Mar 14 16:15:34 2024 : Debug:       ignore_null = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Loading module "ntdomain" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   realm ntdomain {
Thu Mar 14 16:15:34 2024 : Debug:       format = "prefix"
Thu Mar 14 16:15:34 2024 : Debug:       delimiter = "\"
Thu Mar 14 16:15:34 2024 : Debug:       ignore_default = no
Thu Mar 14 16:15:34 2024 : Debug:       ignore_null = no
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   instantiate {
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "reject" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "fail" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "ok" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "handled" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "invalid" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "userlock" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "notfound" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "noop" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "updated" from file /home/haegar/freeradius-testing//mods-enabled/always
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "attr_filter.post-proxy" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/attr_filter/post-proxy
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "attr_filter.pre-proxy" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/attr_filter/pre-proxy
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "attr_filter.access_reject" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/attr_filter/access_reject
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "attr_filter.access_challenge" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/attr_filter/access_challenge
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "attr_filter.accounting_response" from file /home/haegar/freeradius-testing//mods-enabled/attr_filter
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/attr_filter/accounting_response
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "pap" from file /home/haegar/freeradius-testing//mods-enabled/pap
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "preprocess" from file /home/haegar/freeradius-testing//mods-enabled/preprocess
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/preprocess/huntgroups
Thu Mar 14 16:15:34 2024 : Debug: reading pairlist file /home/haegar/freeradius-testing//mods-config/preprocess/hints
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "IPASS" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "suffix" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "bangpath" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "realmpercent" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:   # Instantiating module "ntdomain" from file /home/haegar/freeradius-testing//mods-enabled/realm
Thu Mar 14 16:15:34 2024 : Debug:  } # modules
Thu Mar 14 16:15:34 2024 : Debug: radiusd: #### Loading Virtual Servers ####
Thu Mar 14 16:15:34 2024 : Debug: server { # from file /home/haegar/freeradius-testing//radiusd.conf
Thu Mar 14 16:15:34 2024 : Debug: } # server
Thu Mar 14 16:15:34 2024 : Debug: server caradius { # from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 16:15:34 2024 : Debug:  # Loading authenticate {...}
Thu Mar 14 16:15:34 2024 : Debug: Compiling Auth-Type PAP for attr Auth-Type
Thu Mar 14 16:15:34 2024 : Debug:   reject
Thu Mar 14 16:15:34 2024 : Debug:  # Loading authorize {...}
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[59]: Please change attribute reference to '&Proxy-To-Realm = ...'
Thu Mar 14 16:15:34 2024 : Debug:   update {
Thu Mar 14 16:15:34 2024 : Debug:    &control:Proxy-To-Realm = 'shs'
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[62]: Please change attribute reference to '&SCES-Tmp-Packet-Type := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[63]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IP-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[64]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IPv6-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[65]: Please change attribute reference to '&SCES-Tmp-Event-Timestamp := ...'
Thu Mar 14 16:15:34 2024 : Debug:   update {
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Type := "%{request:Packet-Type}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Src-IP-Address := "%{request:Packet-Src-IP-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Src-IPv6-Address := "%{request:Packet-Src-IPv6-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Event-Timestamp := "%{integer:request:Event-Timestamp}"
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:   pap
Thu Mar 14 16:15:34 2024 : Debug: Compiling Autz-Type Status-Server for attr Autz-Type
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[72]: Please change attribute reference to '&Reply-Message = ...'
Thu Mar 14 16:15:34 2024 : Debug:  # Loading preacct {...}
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[95]: Please change attribute reference to '&SCES-Tmp-Packet-Type := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[96]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IP-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[97]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IPv6-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[98]: Please change attribute reference to '&SCES-Tmp-Event-Timestamp := ...'
Thu Mar 14 16:15:34 2024 : Debug:   update {
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Type := "%{request:Packet-Type}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Src-IP-Address := "%{request:Packet-Src-IP-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Packet-Src-IPv6-Address := "%{request:Packet-Src-IPv6-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &SCES-Tmp-Event-Timestamp := "%{integer:request:Event-Timestamp}"
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:  # Loading accounting {...}
Thu Mar 14 16:15:34 2024 : Debug:   reject
Thu Mar 14 16:15:34 2024 : Debug:  # Loading pre-proxy {...}
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[108]: Please change attribute reference to '&SCES-Tmp-Packet-Type := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[109]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IP-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[110]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IPv6-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[111]: Please change attribute reference to '&SCES-Tmp-Event-Timestamp := ...'
Thu Mar 14 16:15:34 2024 : Debug:   update {
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-request:SCES-Tmp-Packet-Type := "%{request:Packet-Type}"
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-request:SCES-Tmp-Packet-Src-IP-Address := "%{request:Packet-Src-IP-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-request:SCES-Tmp-Packet-Src-IPv6-Address := "%{request:Packet-Src-IPv6-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-request:SCES-Tmp-Event-Timestamp := "%{integer:request:Event-Timestamp}"
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug:  # Loading post-proxy {...}
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[119]: Please change attribute reference to '&SCES-Tmp-Packet-Type := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[120]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IP-Address := ...'
Thu Mar 14 16:15:34 2024 : Warning: /home/haegar/freeradius-testing//sites-enabled/caradius-forward[121]: Please change attribute reference to '&SCES-Tmp-Packet-Src-IPv6-Address := ...'
Thu Mar 14 16:15:34 2024 : Debug:   update {
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-reply:SCES-Tmp-Packet-Type := "%{proxy-reply:Packet-Type}"
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-reply:SCES-Tmp-Packet-Src-IP-Address := "%{proxy-reply:Packet-Src-IP-Address}"
Thu Mar 14 16:15:34 2024 : Debug:    &proxy-reply:SCES-Tmp-Packet-Src-IPv6-Address := "%{proxy-reply:Packet-Src-IPv6-Address}"
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: } # server caradius
Thu Mar 14 16:15:34 2024 : Debug: server status { # from file /home/haegar/freeradius-testing//sites-enabled/status
Thu Mar 14 16:15:34 2024 : Debug:  # Loading authorize {...}
Thu Mar 14 16:15:34 2024 : Debug:   ok
Thu Mar 14 16:15:34 2024 : Debug: Compiling Autz-Type Status-Server for attr Autz-Type
Thu Mar 14 16:15:34 2024 : Debug: } # server status
Thu Mar 14 16:15:34 2024 : Debug: radiusd: #### Opening IP addresses and Ports ####
Thu Mar 14 16:15:34 2024 : Debug: listen {
Thu Mar 14 16:15:34 2024 : Debug:       type = "auth"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = *
Thu Mar 14 16:15:34 2024 : Debug:       port = 3812
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       clients = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:   client caradius-world4 {
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 0.0.0.0/0
Thu Mar 14 16:15:34 2024 : Debug:       require_message_authenticator = no
Thu Mar 14 16:15:34 2024 : Debug:       secret = "test123"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:    limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 16
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 0
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 30
Thu Mar 14 16:15:34 2024 : Debug:    }
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Adding client 0.0.0.0/0 (0.0.0.0) to prefix tree 0
Thu Mar 14 16:15:34 2024 : Debug:   client caradius-world6 {
Thu Mar 14 16:15:34 2024 : Debug:       ipv6addr = ::/0
Thu Mar 14 16:15:34 2024 : Debug:       require_message_authenticator = no
Thu Mar 14 16:15:34 2024 : Debug:       secret = "test123"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:    limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 16
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 0
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 30
Thu Mar 14 16:15:34 2024 : Debug:    }
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Adding client ::/0 (::) to prefix tree 0
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: listen {
Thu Mar 14 16:15:34 2024 : Debug:       type = "acct"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = *
Thu Mar 14 16:15:34 2024 : Debug:       port = 3813
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       clients = "caradius"
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: listen {
Thu Mar 14 16:15:34 2024 : Debug:       type = "auth"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:       ipv6addr = ::
Thu Mar 14 16:15:34 2024 : Debug:       port = 3812
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       clients = "caradius"
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: listen {
Thu Mar 14 16:15:34 2024 : Debug:       type = "acct"
Thu Mar 14 16:15:34 2024 : Debug:       virtual_server = "caradius"
Thu Mar 14 16:15:34 2024 : Debug:       ipv6addr = ::
Thu Mar 14 16:15:34 2024 : Debug:       port = 3813
Thu Mar 14 16:15:34 2024 : Debug:       proto = "udp"
Thu Mar 14 16:15:34 2024 : Debug:       clients = "caradius"
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: listen {
Thu Mar 14 16:15:34 2024 : Debug:       type = "status"
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 127.0.0.1
Thu Mar 14 16:15:34 2024 : Debug:       port = 18121
Thu Mar 14 16:15:34 2024 : Debug:   client admin {
Thu Mar 14 16:15:34 2024 : Debug:       ipaddr = 127.0.0.1
Thu Mar 14 16:15:34 2024 : Debug:       require_message_authenticator = no
Thu Mar 14 16:15:34 2024 : Debug:       secret = "spsroot1"
Thu Mar 14 16:15:34 2024 : Debug:    limit {
Thu Mar 14 16:15:34 2024 : Debug:       max_connections = 16
Thu Mar 14 16:15:34 2024 : Debug:       lifetime = 0
Thu Mar 14 16:15:34 2024 : Debug:       idle_timeout = 30
Thu Mar 14 16:15:34 2024 : Debug:    }
Thu Mar 14 16:15:34 2024 : Debug:   }
Thu Mar 14 16:15:34 2024 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32
Thu Mar 14 16:15:34 2024 : Debug: }
Thu Mar 14 16:15:34 2024 : Debug: Listening on auth address * port 3812 bound to server caradius
Thu Mar 14 16:15:34 2024 : Debug: Listening on acct address * port 3813 bound to server caradius
Thu Mar 14 16:15:34 2024 : Debug: Listening on auth address :: port 3812 bound to server caradius
Thu Mar 14 16:15:34 2024 : Debug: Listening on acct address :: port 3813 bound to server caradius
Thu Mar 14 16:15:34 2024 : Debug: Listening on status address 127.0.0.1 port 18121 bound to server status
Thu Mar 14 16:15:34 2024 : Debug: Opened new proxy socket 'proxy address * port 40698'
Thu Mar 14 16:15:34 2024 : Debug: Listening on proxy address * port 40698
Thu Mar 14 16:15:34 2024 : Debug: Opened new proxy socket 'proxy address :: port 47883'
Thu Mar 14 16:15:34 2024 : Debug: Listening on proxy address :: port 47883
Thu Mar 14 16:15:34 2024 : Info: Ready to process requests


Here now I starting a client request, expecting a "reject" from the home server, as I give wrong username and password - instead I get the SSL error and proxy timeout:

$ radtest -d /home/haegar/freeradius-testing/ -t pap test test 127.0.0.1:3812 23 test123

Thu Mar 14 16:19:30 2024 : Debug: (0) Received Access-Request Id 82 from 127.0.0.1:38876 to 127.0.0.1:3812 length 74
Thu Mar 14 16:19:30 2024 : Debug: (0)   User-Name = "test"
Thu Mar 14 16:19:30 2024 : Debug: (0)   User-Password = "test"
Thu Mar 14 16:19:30 2024 : Debug: (0)   NAS-IP-Address = 127.0.1.1
Thu Mar 14 16:19:30 2024 : Debug: (0)   NAS-Port = 23
Thu Mar 14 16:19:30 2024 : Debug: (0)   Message-Authenticator = 0xc8f1447b36773f180cc653d61afb2301
Thu Mar 14 16:19:30 2024 : Debug: (0) session-state: No State attribute
Thu Mar 14 16:19:30 2024 : Debug: (0) # Executing section authorize from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 16:19:30 2024 : Debug: (0)   authorize {
Thu Mar 14 16:19:30 2024 : Debug: (0)     update control {
Thu Mar 14 16:19:30 2024 : Debug: (0)       Proxy-To-Realm = 'shs'
Thu Mar 14 16:19:30 2024 : Debug: (0)     } # update control = noop
Thu Mar 14 16:19:30 2024 : Debug: (0)     update request {
Thu Mar 14 16:19:30 2024 : Debug: (0)       EXPAND %{request:Packet-Type}
Thu Mar 14 16:19:30 2024 : Debug: (0)          --> Access-Request
Thu Mar 14 16:19:30 2024 : Debug: (0)       SCES-Tmp-Packet-Type := Access-Request
Thu Mar 14 16:19:30 2024 : Debug: (0)       EXPAND %{request:Packet-Src-IP-Address}
Thu Mar 14 16:19:30 2024 : Debug: (0)          --> 127.0.0.1
Thu Mar 14 16:19:30 2024 : Debug: (0)       SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Thu Mar 14 16:19:30 2024 : Debug: (0)       EXPAND %{request:Packet-Src-IPv6-Address}
Thu Mar 14 16:19:30 2024 : Debug: (0)          --> 
Thu Mar 14 16:19:30 2024 : Debug: (0)       SCES-Tmp-Packet-Src-IPv6-Address := 
Thu Mar 14 16:19:30 2024 : Debug: (0)       EXPAND %{integer:request:Event-Timestamp}
Thu Mar 14 16:19:30 2024 : Debug: (0)          --> 
Thu Mar 14 16:19:30 2024 : Debug: (0)       SCES-Tmp-Event-Timestamp := 
Thu Mar 14 16:19:30 2024 : Debug: (0)     } # update request = noop
Thu Mar 14 16:19:30 2024 : Debug: (0)     modsingle[authorize]: calling pap (rlm_pap)
Thu Mar 14 16:19:30 2024 : Debug: (0)     modsingle[authorize]: returned from pap (rlm_pap)
Thu Mar 14 16:19:30 2024 : Debug: (0)     [pap] = noop
Thu Mar 14 16:19:30 2024 : Debug: (0)   } # authorize = noop
Thu Mar 14 16:19:30 2024 : Debug: Using home pool auth for realm shs
Thu Mar 14 16:19:30 2024 : Debug: (0) Starting proxy to home server 172.16.9.102 port 2083
Thu Mar 14 16:19:30 2024 : Debug: (0) server caradius {
Thu Mar 14 16:19:30 2024 : Debug: (0)   # Executing section pre-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 16:19:30 2024 : Debug: (0)     pre-proxy {
Thu Mar 14 16:19:30 2024 : Debug: (0)       update proxy-request {
Thu Mar 14 16:19:30 2024 : Debug: (0)         EXPAND %{request:Packet-Type}
Thu Mar 14 16:19:30 2024 : Debug: (0)            --> Access-Request
Thu Mar 14 16:19:30 2024 : Debug: (0)         SCES-Tmp-Packet-Type := Access-Request
Thu Mar 14 16:19:30 2024 : Debug: (0)         Overwriting value "Access-Request" with "Access-Request"
Thu Mar 14 16:19:30 2024 : Debug: (0)         EXPAND %{request:Packet-Src-IP-Address}
Thu Mar 14 16:19:30 2024 : Debug: (0)            --> 127.0.0.1
Thu Mar 14 16:19:30 2024 : Debug: (0)         SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Thu Mar 14 16:19:30 2024 : Debug: (0)         Overwriting value "127.0.0.1" with "127.0.0.1"
Thu Mar 14 16:19:30 2024 : Debug: (0)         EXPAND %{request:Packet-Src-IPv6-Address}
Thu Mar 14 16:19:30 2024 : Debug: (0)            --> 
Thu Mar 14 16:19:30 2024 : Debug: (0)         SCES-Tmp-Packet-Src-IPv6-Address := 
Thu Mar 14 16:19:30 2024 : Debug: (0)         Overwriting value "" with ""
Thu Mar 14 16:19:30 2024 : Debug: (0)         EXPAND %{integer:request:Event-Timestamp}
Thu Mar 14 16:19:30 2024 : Debug: (0)            --> 
Thu Mar 14 16:19:30 2024 : Debug: (0)         SCES-Tmp-Event-Timestamp := 
Thu Mar 14 16:19:30 2024 : Debug: (0)         Overwriting value "" with ""
Thu Mar 14 16:19:30 2024 : Debug: (0)       } # update proxy-request = noop
Thu Mar 14 16:19:30 2024 : Debug: (0)     } # pre-proxy = noop
Thu Mar 14 16:19:30 2024 : Debug: (0) }
Thu Mar 14 16:19:30 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Thu Mar 14 16:19:30 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Thu Mar 14 16:19:30 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.102, 2083)
Thu Mar 14 16:19:30 2024 : Debug: Requiring Server certificate
Thu Mar 14 16:19:30 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Thu Mar 14 16:19:30 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Thu Mar 14 16:19:30 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Thu Mar 14 16:19:30 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Thu Mar 14 16:19:30 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 43791) -> home_server (172.16.9.102, 2083)'
Thu Mar 14 16:19:30 2024 : Debug: Listening on proxy (10.113.0.10, 43791) -> home_server (172.16.9.102, 2083)
Thu Mar 14 16:19:30 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Thu Mar 14 16:19:30 2024 : Debug: (0) proxy: request is now in proxy hash
Thu Mar 14 16:19:30 2024 : Debug: (0) proxy: allocating destination 172.16.9.102 port 2083 - Id 194
Thu Mar 14 16:19:30 2024 : Debug: (0) Proxying request to home server 172.16.9.102 port 2083 (TLS) timeout 10.000000
Thu Mar 14 16:19:30 2024 : Debug: (0) Sent Access-Request Id 194 from 10.113.0.10:43791 to 172.16.9.102:2083 length 117
Thu Mar 14 16:19:30 2024 : Debug: (0)   User-Name = "test"
Thu Mar 14 16:19:30 2024 : Debug: (0)   User-Password = "test"
Thu Mar 14 16:19:30 2024 : Debug: (0)   NAS-IP-Address = 127.0.1.1
Thu Mar 14 16:19:30 2024 : Debug: (0)   NAS-Port = 23
Thu Mar 14 16:19:30 2024 : Debug: (0)   Message-Authenticator = 0xc8f1447b36773f180cc653d61afb2301
Thu Mar 14 16:19:30 2024 : Debug: (0)   SCES-Tmp-Packet-Type := "Access-Request"
Thu Mar 14 16:19:30 2024 : Debug: (0)   SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1"
Thu Mar 14 16:19:30 2024 : Debug: (0)   SCES-Tmp-Packet-Src-IPv6-Address := ""
Thu Mar 14 16:19:30 2024 : Debug: (0)   SCES-Tmp-Event-Timestamp := ""
Thu Mar 14 16:19:30 2024 : Debug: (0)   Proxy-State = 0x3832
Thu Mar 14 16:19:30 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Thu Mar 14 16:19:30 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Thu Mar 14 16:19:30 2024 : Debug: (0) (TLS) Writing 117 bytes for later (total 117)
Thu Mar 14 16:19:30 2024 : Debug: Waking up in 0.3 seconds.
Thu Mar 14 16:19:30 2024 : Debug: (0) Expecting proxy response no later than 9.666688 seconds from now
Thu Mar 14 16:19:30 2024 : Debug: Waking up in 0.3 seconds.
Thu Mar 14 16:19:30 2024 : Debug: Waking up in 9.2 seconds.
Thu Mar 14 16:19:35 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 172.16.9.102 port 2083 proto TCP - ID: 194
Thu Mar 14 16:19:35 2024 : Debug: Waking up in 4.9 seconds.
Thu Mar 14 16:19:40 2024 : Debug: (0) No proxy response, giving up on request and marking it done
Thu Mar 14 16:19:40 2024 : ERROR: (0) Failing proxied request for user "test", due to lack of any response from home server 172.16.9.102 port 2083
Thu Mar 14 16:19:40 2024 : Debug: (0) Clearing existing &reply: attributes
Thu Mar 14 16:19:40 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Thu Mar 14 16:19:40 2024 : Debug: (0) server caradius {
Thu Mar 14 16:19:40 2024 : Debug: (0)   Post-Proxy-Type sub-section not found.  Ignoring.
Thu Mar 14 16:19:40 2024 : Debug: (0)   # Executing group from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 16:19:40 2024 : Debug: (0) }
Thu Mar 14 16:19:40 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [test] (from client caradius-world4 port 23)
Thu Mar 14 16:19:40 2024 : Debug: (0) There was no response configured: rejecting request
Thu Mar 14 16:19:40 2024 : Debug: (0) Using Post-Auth-Type Reject
Thu Mar 14 16:19:40 2024 : Debug: (0) Post-Auth-Type sub-section not found.  Ignoring.
Thu Mar 14 16:19:40 2024 : Auth: (0) Login incorrect (Failing proxied request for user "test", due to lack of any response from home server 172.16.9.102 port 2083): [test] (from client caradius-world4 port 23)
Thu Mar 14 16:19:40 2024 : Debug: (0) Sent Access-Reject Id 82 from 127.0.0.1:3812 to 127.0.0.1:38876 length 20
Thu Mar 14 16:19:40 2024 : Debug: (0) Finished request
Thu Mar 14 16:19:40 2024 : Debug: Waking up in 4.9 seconds.
Thu Mar 14 16:19:40 2024 : Debug: (0) Sending duplicate reply to client caradius-world4 port 38876 - ID: 82
Thu Mar 14 16:19:40 2024 : Debug: Waking up in 9.9 seconds.
Thu Mar 14 16:19:50 2024 : Debug: (0) Cleaning up request packet ID 82 with timestamp +236 due to cleanup_delay was reached
Thu Mar 14 16:19:50 2024 : Debug: Waking up in 160.2 seconds.

Relevant log output from client utilities

The client output it relatively useless, just showing that it tries to send the auth requests three times, and then receives the reject sent by freeradius because of "Auth: (0) Login incorrect (Failing proxied request for user "test", due to lack of any response from home server 172.16.9.102 port 2083): [test] (from client caradius-world4 port 23)"

$ radtest -d /home/haegar/freeradius-testing/ -t pap test test 127.0.0.1:3812 23 test123

Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74
User-Name = "test"
User-Password = "test"
NAS-IP-Address = 127.0.1.1
NAS-Port = 23
Message-Authenticator = 0x00
Cleartext-Password = "test"
Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74
User-Name = "test"
User-Password = "test"
NAS-IP-Address = 127.0.1.1
NAS-Port = 23
Message-Authenticator = 0x00
Cleartext-Password = "test"
Sent Access-Request Id 82 from 0.0.0.0:97dc to 127.0.0.1:3812 length 74
User-Name = "test"
User-Password = "test"
NAS-IP-Address = 127.0.1.1
NAS-Port = 23
Message-Authenticator = 0x00
Cleartext-Password = "test"
Received Access-Reject Id 82 from 127.0.0.1:ee4 to 127.0.0.1:38876 length 20
(0) -: Expected Access-Accept got Access-Reject
radclient: Received reply to request we did not send. (id=82 socket 3)

Backtrace from LLDB or GDB

No crash, no backtrace available
@haegar haegar added the defect category: a defect or misbehaviour label Mar 14, 2024
@alandekok
Copy link
Member

Please try this patch, and run with -sf -l stdout -xxx. It won't fix the problem, but it adds more debug output which may help to track it down.

Please post the debug output here.

patch.gz

I may not have time to look at this in more detail for a week or so.

@haegar
Copy link
Author

haegar commented Mar 14, 2024

Moin,

Thankks for the quick response.

Testing with your debug patch applied and executing

$ /usr/sbin/freeradius -d /home/haegar/freeradius-testing/ -sf -l stdout -xxx

Skipped the startup messages, they are similar to the bug report itself.

Messages from freeradius when client requests come in:

Thu Mar 14 22:01:05 2024 : Debug: (0) Received Access-Request Id 115 from 127.0.0.1:59607 to 127.0.0.1:3812 length 78
Thu Mar 14 22:01:05 2024 : Debug: (0) User-Name = "test@shs"
Thu Mar 14 22:01:05 2024 : Debug: (0) User-Password = "test"
Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-Port = 23
Thu Mar 14 22:01:05 2024 : Debug: (0) Message-Authenticator = 0x134d0021047f9de7740da15a1c0666e3
Thu Mar 14 22:01:05 2024 : Debug: (0) session-state: No State attribute
Thu Mar 14 22:01:05 2024 : Debug: (0) # Executing section authorize from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 22:01:05 2024 : Debug: (0) authorize {
Thu Mar 14 22:01:05 2024 : Debug: (0) update control {
Thu Mar 14 22:01:05 2024 : Debug: (0) Proxy-To-Realm = 'shs'
Thu Mar 14 22:01:05 2024 : Debug: (0) } # update control = noop
Thu Mar 14 22:01:05 2024 : Debug: (0) update request {
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Thu Mar 14 22:01:05 2024 : Debug: (0) --> Access-Request
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := Access-Request
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address}
Thu Mar 14 22:01:05 2024 : Debug: (0) --> 127.0.0.1
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address}
Thu Mar 14 22:01:05 2024 : Debug: (0) -->
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address :=
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp}
Thu Mar 14 22:01:05 2024 : Debug: (0) -->
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp :=
Thu Mar 14 22:01:05 2024 : Debug: (0) } # update request = noop
Thu Mar 14 22:01:05 2024 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap)
Thu Mar 14 22:01:05 2024 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap)
Thu Mar 14 22:01:05 2024 : Debug: (0) [pap] = noop
Thu Mar 14 22:01:05 2024 : Debug: (0) } # authorize = noop
Thu Mar 14 22:01:05 2024 : Debug: Using home pool auth for realm shs
Thu Mar 14 22:01:05 2024 : Debug: (0) Starting proxy to home server 172.16.9.102 port 2083
Thu Mar 14 22:01:05 2024 : Debug: (0) server caradius {
Thu Mar 14 22:01:05 2024 : Debug: (0) # Executing section pre-proxy from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 22:01:05 2024 : Debug: (0) pre-proxy {
Thu Mar 14 22:01:05 2024 : Debug: (0) update proxy-request {
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Type}
Thu Mar 14 22:01:05 2024 : Debug: (0) --> Access-Request
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := Access-Request
Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "Access-Request" with "Access-Request"
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IP-Address}
Thu Mar 14 22:01:05 2024 : Debug: (0) --> 127.0.0.1
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := 127.0.0.1
Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "127.0.0.1" with "127.0.0.1"
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{request:Packet-Src-IPv6-Address}
Thu Mar 14 22:01:05 2024 : Debug: (0) -->
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address :=
Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "" with ""
Thu Mar 14 22:01:05 2024 : Debug: (0) EXPAND %{integer:request:Event-Timestamp}
Thu Mar 14 22:01:05 2024 : Debug: (0) -->
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp :=
Thu Mar 14 22:01:05 2024 : Debug: (0) Overwriting value "" with ""
Thu Mar 14 22:01:05 2024 : Debug: (0) } # update proxy-request = noop
Thu Mar 14 22:01:05 2024 : Debug: (0) } # pre-proxy = noop
Thu Mar 14 22:01:05 2024 : Debug: (0) }
Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to allocate ID (0/2)
Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to open a new listener to the home server
Thu Mar 14 22:01:05 2024 : Debug: (TLS) Trying new outgoing proxy connection to proxy (0.0.0.0, 0) -> home_server (172.16.9.102, 2083)
Thu Mar 14 22:01:05 2024 : Debug: Requiring Server certificate
Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0)
Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Client before SSL initialization (0)
Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.2 Handshake, ClientHello
Thu Mar 14 22:01:05 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Thu Mar 14 22:01:05 2024 : Debug: Opened new proxy socket 'proxy (10.113.0.10, 40477) -> home_server (172.16.9.102, 2083)'
Thu Mar 14 22:01:05 2024 : Debug: Listening on proxy (10.113.0.10, 40477) -> home_server (172.16.9.102, 2083)
Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: Trying to allocate ID (1/2)
Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: request is now in proxy hash
Thu Mar 14 22:01:05 2024 : Debug: (0) proxy: allocating destination 172.16.9.102 port 2083 - Id 115
Thu Mar 14 22:01:05 2024 : Debug: (0) Proxying request to home server 172.16.9.102 port 2083 (TLS) timeout 10.000000
Thu Mar 14 22:01:05 2024 : Debug: (0) Sent Access-Request Id 115 from 10.113.0.10:40477 to 172.16.9.102:2083 length 122
Thu Mar 14 22:01:05 2024 : Debug: (0) User-Name = "test@shs"
Thu Mar 14 22:01:05 2024 : Debug: (0) User-Password = "test"
Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-IP-Address = 127.0.1.1
Thu Mar 14 22:01:05 2024 : Debug: (0) NAS-Port = 23
Thu Mar 14 22:01:05 2024 : Debug: (0) Message-Authenticator = 0x134d0021047f9de7740da15a1c0666e3
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Type := "Access-Request"
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IP-Address := "127.0.0.1"
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Packet-Src-IPv6-Address := ""
Thu Mar 14 22:01:05 2024 : Debug: (0) SCES-Tmp-Event-Timestamp := ""
Thu Mar 14 22:01:05 2024 : Debug: (0) Proxy-State = 0x313135
Thu Mar 14 22:01:05 2024 : ERROR: (0) (TLS) RADIUS/TLS - Client : Error in SSLv3/TLS write client hello
Thu Mar 14 22:01:05 2024 : Debug: (TLS) SSL_connect() returned WANT_WRITE
Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) has 0 bytes in the buffer
Thu Mar 14 22:01:05 2024 : Debug: (0) (TLS) Saving 122 bytes of RADIUS traffic for later (total 122)
Thu Mar 14 22:01:05 2024 : Debug: Waking up in 0.3 seconds.
Thu Mar 14 22:01:05 2024 : Debug: (0) Expecting proxy response no later than 9.666745 seconds from now
Thu Mar 14 22:01:05 2024 : Debug: Waking up in 0.5 seconds.
Thu Mar 14 22:01:06 2024 : Debug: Waking up in 9.1 seconds.
Thu Mar 14 22:01:10 2024 : Debug: Suppressing duplicate proxied request (tcp) to home server 172.16.9.102 port 2083 proto TCP - ID: 115
Thu Mar 14 22:01:10 2024 : Debug: Waking up in 4.9 seconds.
Thu Mar 14 22:01:15 2024 : Debug: (0) No proxy response, giving up on request and marking it done
Thu Mar 14 22:01:15 2024 : ERROR: (0) Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.102 port 2083
Thu Mar 14 22:01:15 2024 : Debug: (0) Clearing existing &reply: attributes
Thu Mar 14 22:01:15 2024 : Debug: (0) Found Post-Proxy-Type Fail-Authentication
Thu Mar 14 22:01:15 2024 : Debug: (0) server caradius {
Thu Mar 14 22:01:15 2024 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring.
Thu Mar 14 22:01:15 2024 : Debug: (0) # Executing group from file /home/haegar/freeradius-testing//sites-enabled/caradius-forward
Thu Mar 14 22:01:15 2024 : Debug: (0) }
Thu Mar 14 22:01:15 2024 : Auth: (0) Login incorrect (Home Server failed to respond): [test@shs] (from client caradius-world4 port 23)
Thu Mar 14 22:01:15 2024 : Debug: (0) There was no response configured: rejecting request
Thu Mar 14 22:01:15 2024 : Debug: (0) Using Post-Auth-Type Reject
Thu Mar 14 22:01:15 2024 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring.
Thu Mar 14 22:01:15 2024 : Auth: (0) Login incorrect (Failing proxied request for user "test@shs", due to lack of any response from home server 172.16.9.102 port 2083): [test@shs] (from client caradius-world4 port 23)
Thu Mar 14 22:01:15 2024 : Debug: (0) Sent Access-Reject Id 115 from 127.0.0.1:3812 to 127.0.0.1:59607 length 20
Thu Mar 14 22:01:15 2024 : Debug: (0) Finished request
Thu Mar 14 22:01:15 2024 : Debug: Waking up in 4.9 seconds.
Thu Mar 14 22:01:20 2024 : Debug: (0) Cleaning up request packet ID 115 with timestamp +31 due to cleanup_delay was reached

The messages from your debug patch only appear way after the TLS client hello errors were already reported.

(And strangely freeradius reported "Sent Access-Request Id 115 ...", when clearly due to the TLS establishing error the request has not been sent to the server yet).

Greetings,
Haegar

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
defect category: a defect or misbehaviour
Projects
None yet
Development

No branches or pull requests

2 participants