No auth requests through TLS tunnel if connection was checked
Hi there, I want to make some additional checks for RadSec connections. After I’ve set `check_client_connections` to `yes`, the server is handling the connection over the auth type "Autz-Type New-TLS-Connection”. So far so good but after the connection has accepted, no further traffic is reaching the radius server. I can see in packet captures that Access-Requests are send to the server and on the server netstat is also showing that packets are going to the socket which FreeRADIUS opens but only the queue is getting higher and never processed. After seeing this behaviour, of course also tested the behaviour with the default config. Just enabled tls, changed the `check_client_connections` and added a ip wildcard to the radsec clients. Since I haven’t found any open GitHub issue or something on this list I assume either no one is using the functionality or there is something I’ve overlooked. The radius server is running as docker container but that shouldn't make any difference. Output from $ netstat -apc: ``` Active UNIX domain sockets (servers and established) Proto RefCnt Flags Type State I-Node PID/Program name Path Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 0.0.0.0:2083 0.0.0.0:* LISTEN 61/radiusd tcp 468 0 ae7fb3711088:2083 192.168.215.1:19729 ESTABLISHED 61/radiusd udp 0 0 0.0.0.0:45552 0.0.0.0:* 61/radiusd udp 0 0 localhost:18120 0.0.0.0:* 61/radiusd udp 0 0 0.0.0.0:radius 0.0.0.0:* 61/radiusd udp 0 0 0.0.0.0:radius-acct 0.0.0.0:* 61/radiusd udp6 0 0 [::]:radius [::]:* 61/radiusd udp6 0 0 [::]:radius-acct [::]:* 61/radiusd udp6 0 0 [::]:52860 [::]:* 61/radiusd ``` FreeRADIUS debug log: FreeRADIUS Version 3.2.4 Copyright (C) 1999-2023 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT 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/proxy.conf including configuration file /usr/local/etc/raddb/clients.conf including files in directory /usr/local/etc/raddb/mods-enabled/ including configuration file /usr/local/etc/raddb/mods-enabled/always including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter including configuration file /usr/local/etc/raddb/mods-enabled/chap including configuration file /usr/local/etc/raddb/mods-enabled/date including configuration file /usr/local/etc/raddb/mods-enabled/detail including configuration file /usr/local/etc/raddb/mods-enabled/detail.log including configuration file /usr/local/etc/raddb/mods-enabled/digest including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients including configuration file /usr/local/etc/raddb/mods-enabled/eap including configuration file /usr/local/etc/raddb/mods-enabled/echo including configuration file /usr/local/etc/raddb/mods-enabled/exec including configuration file /usr/local/etc/raddb/mods-enabled/expiration including configuration file /usr/local/etc/raddb/mods-enabled/expr including configuration file /usr/local/etc/raddb/mods-enabled/files including configuration file /usr/local/etc/raddb/mods-enabled/linelog including configuration file /usr/local/etc/raddb/mods-enabled/logintime including configuration file /usr/local/etc/raddb/mods-enabled/mschap including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth including configuration file /usr/local/etc/raddb/mods-enabled/pap including configuration file /usr/local/etc/raddb/mods-enabled/passwd including configuration file /usr/local/etc/raddb/mods-enabled/preprocess including configuration file /usr/local/etc/raddb/mods-enabled/radutmp including configuration file /usr/local/etc/raddb/mods-enabled/realm including configuration file /usr/local/etc/raddb/mods-enabled/replicate including configuration file /usr/local/etc/raddb/mods-enabled/soh including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp including configuration file /usr/local/etc/raddb/mods-enabled/totp including configuration file /usr/local/etc/raddb/mods-enabled/unix including configuration file /usr/local/etc/raddb/mods-enabled/unpack including configuration file /usr/local/etc/raddb/mods-enabled/utf8 including files in directory /usr/local/etc/raddb/policy.d/ including configuration file /usr/local/etc/raddb/policy.d/abfab-tr including configuration file /usr/local/etc/raddb/policy.d/accounting including configuration file /usr/local/etc/raddb/policy.d/canonicalization including configuration file /usr/local/etc/raddb/policy.d/control including configuration file /usr/local/etc/raddb/policy.d/cui including configuration file /usr/local/etc/raddb/policy.d/debug including configuration file /usr/local/etc/raddb/policy.d/dhcp including configuration file /usr/local/etc/raddb/policy.d/eap including configuration file /usr/local/etc/raddb/policy.d/filter including configuration file /usr/local/etc/raddb/policy.d/moonshot-targeted-ids including configuration file /usr/local/etc/raddb/policy.d/operator-name including configuration file /usr/local/etc/raddb/policy.d/rfc7542 including files in directory /usr/local/etc/raddb/sites-enabled/ including configuration file /usr/local/etc/raddb/sites-enabled/default including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel including configuration file /usr/local/etc/raddb/sites-enabled/tls main { security { allow_core_dumps = no } name = "radiusd" prefix = "/usr/local" localstatedir = "/usr/local/var" logdir = "/usr/local/var/log/radius" run_dir = "/usr/local/var/run/radiusd" } main { name = "radiusd" prefix = "/usr/local" localstatedir = "/usr/local/var" sbindir = "/usr/local/sbin" logdir = "/usr/local/var/log/radius" run_dir = "/usr/local/var/run/radiusd" libdir = "/usr/local/lib" radacctdir = "/usr/local/var/log/radius/radacct" hostname_lookups = no max_request_time = 30 proxy_dedup_window = 1 cleanup_delay = 5 max_requests = 16384 postauth_client_lost = no pidfile = "/usr/local/var/run/radiusd/radiusd.pid" checkrad = "/usr/local/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 1.000000 status_server = yes allow_vulnerable_openssl = "no" } } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } home_server localhost { nonblock = no ipaddr = 127.0.0.1 port = 1812 type = "auth" secret = <<< secret >>> response_window = 20.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "status-server" ping_interval = 30 check_interval = 30 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 120 limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } home_server tls { nonblock = no ipaddr = 127.0.0.1 port = 2083 type = "auth" proto = "tcp" secret = <<< secret >>> response_window = 30.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "none" ping_interval = 30 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 300 limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } tls { verify_depth = 0 ca_path = "/usr/local/etc/raddb/certs" pem_file_type = yes private_key_file = "/usr/local/etc/raddb/certs/client.pem" certificate_file = "/usr/local/etc/raddb/certs/client.pem" ca_file = "/usr/local/etc/raddb/certs/ca.pem" private_key_password = <<< secret >>> fragment_size = 8192 include_length = yes check_crl = no cipher_list = "DEFAULT" ca_path_reload_interval = 0 ecdh_curve = "prime256v1" tls_min_version = "1.2" } connect_timeout = 30 home_server_pool my_auth_failover { type = fail-over home_server = localhost } realm example.com { auth_pool = my_auth_failover } realm LOCAL { } home_server_pool tls { type = fail-over home_server = tls } realm tls { auth_pool = tls } radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } client localhost_ipv6 { ipv6addr = ::1 require_message_authenticator = no secret = <<< secret >>> limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached # Creating Auth-Type = mschap # Creating Auth-Type = digest # Creating Auth-Type = eap # Creating Auth-Type = PAP # Creating Auth-Type = CHAP # Creating Auth-Type = MS-CHAP # Creating Autz-Type = New-TLS-Connection radiusd: #### Instantiating modules #### modules { # Loaded module rlm_always # Loading module "reject" from file /usr/local/etc/raddb/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /usr/local/etc/raddb/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /usr/local/etc/raddb/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /usr/local/etc/raddb/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /usr/local/etc/raddb/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /usr/local/etc/raddb/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /usr/local/etc/raddb/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /usr/local/etc/raddb/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /usr/local/etc/raddb/mods-enabled/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-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/usr/local/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-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/usr/local/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-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/usr/local/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-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/usr/local/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-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/usr/local/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-enabled/attr_filter attr_filter attr_filter.coa { filename = "/usr/local/etc/raddb/mods-config/attr_filter/coa" key = "%{User-Name}" relaxed = no } # Loaded module rlm_chap # Loading module "chap" from file /usr/local/etc/raddb/mods-enabled/chap # Loaded module rlm_date # Loading module "date" from file /usr/local/etc/raddb/mods-enabled/date date { format = "%b %e %Y %H:%M:%S %Z" utc = no } # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-enabled/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-enabled/detail detail { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" header = "%t" permissions = 384 locking = no dates_as_integer = no escape_filenames = no log_packet_header = no } # Loading module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail auth_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" header = "%t" permissions = 384 locking = no dates_as_integer = no escape_filenames = no log_packet_header = no } # Loading module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail reply_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" header = "%t" permissions = 384 locking = no dates_as_integer = no escape_filenames = no log_packet_header = no } # Loading module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail pre_proxy_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no dates_as_integer = no escape_filenames = no log_packet_header = no } # Loading module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail post_proxy_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no dates_as_integer = no escape_filenames = no log_packet_header = no } # Loaded module rlm_digest # Loading module "digest" from file /usr/local/etc/raddb/mods-enabled/digest # Loaded module rlm_dynamic_clients # Loading module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients # Loaded module rlm_eap # Loading module "eap" from file /usr/local/etc/raddb/mods-enabled/eap eap { default_eap_type = "md5" timer_expire = 60 max_eap_type = 52 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 16384 dedup_key = "" } # Loaded module rlm_exec # Loading module "echo" from file /usr/local/etc/raddb/mods-enabled/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-enabled/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-enabled/expiration # Loaded module rlm_expr # Loading module "expr" from file /usr/local/etc/raddb/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" } # Loaded module rlm_files # Loading module "files" from file /usr/local/etc/raddb/mods-enabled/files files { filename = "/usr/local/etc/raddb/mods-config/files/authorize" acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" } # Loaded module rlm_linelog # Loading module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog linelog { filename = "/usr/local/var/log/radius/linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{reply:Packet-Type}:-default}" } # Loading module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog linelog log_accounting { filename = "/usr/local/var/log/radius/linelog-accounting" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loaded module rlm_logintime # Loading module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime logintime { minimum_timeout = 60 } # Loaded module rlm_mschap # Loading module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes winbind_retry_with_normalised_username = no } # Loading module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } # Loaded module rlm_pap # Loading module "pap" from file /usr/local/etc/raddb/mods-enabled/pap pap { normalise = yes } # Loaded module rlm_passwd # Loading module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd passwd etc_passwd { filename = "/etc/passwd" format = "*User-Name:Crypt-Password:" delimiter = ":" ignore_nislike = no ignore_empty = yes allow_multiple_keys = no hash_size = 100 } # Loaded module rlm_preprocess # Loading module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess preprocess { huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" hints = "/usr/local/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_radutmp # Loading module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp radutmp { filename = "/usr/local/var/log/radius/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 384 caller_id = yes } # Loaded module rlm_realm # Loading module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm realm IPASS { format = "prefix" delimiter = "/" ignore_default = no ignore_null = no } # Loading module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Loading module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm realm bangpath { format = "prefix" delimiter = "!" ignore_default = no ignore_null = no } # Loading module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm realm realmpercent { format = "suffix" delimiter = "%" ignore_default = no ignore_null = no } # Loading module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm realm ntdomain { format = "prefix" delimiter = "\" ignore_default = no ignore_null = no } # Loaded module rlm_replicate # Loading module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate # Loaded module rlm_soh # Loading module "soh" from file /usr/local/etc/raddb/mods-enabled/soh soh { dhcp = yes } # Loading module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp radutmp sradutmp { filename = "/usr/local/var/log/radius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } # Loaded module rlm_totp # Loading module "totp" from file /usr/local/etc/raddb/mods-enabled/totp totp { time_step = 30 otp_length = 8 lookback_steps = 1 lookback_interval = 30 } # Loaded module rlm_unix # Loading module "unix" from file /usr/local/etc/raddb/mods-enabled/unix unix { radwtmp = "/usr/local/var/log/radius/radwtmp" } Creating attribute Unix-Group # Loaded module rlm_unpack # Loading module "unpack" from file /usr/local/etc/raddb/mods-enabled/unpack # Loaded module rlm_utf8 # Loading module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 instantiate { } # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/coa # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/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-enabled/detail.log # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap # Linked to sub-module rlm_eap_md5 # Linked to sub-module rlm_eap_gtc gtc { challenge = "Password: " auth_type = "PAP" } # Linked to sub-module rlm_eap_tls tls { tls = "tls-common" } tls-config tls-common { verify_depth = 0 ca_path = "/usr/local/etc/raddb/certs" pem_file_type = yes private_key_file = "/usr/local/etc/raddb/certs/server.pem" certificate_file = "/usr/local/etc/raddb/certs/server.pem" ca_file = "/usr/local/etc/raddb/certs/ca.pem" private_key_password = <<< secret >>> fragment_size = 1024 include_length = yes auto_chain = yes check_crl = no check_all_crl = no ca_path_reload_interval = 0 cipher_list = "DEFAULT" cipher_server_preference = no reject_unknown_intermediate_ca = no ecdh_curve = "" 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 = no override_cert_url = yes url = "http://127.0.0.1/ocsp/" use_nonce = yes timeout = 0 softfail = no } } # Linked to sub-module rlm_eap_ttls ttls { tls = "tls-common" default_eap_type = "md5" copy_request_to_tunnel = no use_tunneled_reply = no 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 = no proxy_tunneled_request_as_eap = yes virtual_server = "inner-tunnel" soh = no require_client_cert = no } tls: Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_mschapv2 mschapv2 { with_ntdomain_hack = no send_error = no } # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog # Instantiating module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap rlm_mschap (mschap): using internal authentication # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "totp" from file /usr/local/etc/raddb/mods-enabled/totp } # modules radiusd: #### Loading Virtual Servers #### server { # from file /usr/local/etc/raddb/radiusd.conf } # server server default { # from file /usr/local/etc/raddb/sites-enabled/default # Loading authenticate {...} Compiling Auth-Type PAP for attr Auth-Type Compiling Auth-Type CHAP for attr Auth-Type Compiling Auth-Type MS-CHAP for attr Auth-Type # Loading authorize {...} Ignoring "sql" (see raddb/mods-available/README.rst) Ignoring "ldap" (see raddb/mods-available/README.rst) Compiling Autz-Type New-TLS-Connection for attr Autz-Type # Loading preacct {...} # Loading accounting {...} # Loading post-proxy {...} # Loading post-auth {...} Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Compiling Post-Auth-Type Challenge for attr Post-Auth-Type Compiling Post-Auth-Type Client-Lost for attr Post-Auth-Type } # server default server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel # Loading authenticate {...} Compiling Auth-Type PAP for attr Auth-Type Compiling Auth-Type CHAP for attr Auth-Type Compiling Auth-Type MS-CHAP for attr Auth-Type # Loading authorize {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} # Skipping contents of 'if' as it is always 'false' -- /usr/local/etc/raddb/sites-enabled/inner-tunnel:366 Compiling Post-Auth-Type REJECT for attr Post-Auth-Type } # server inner-tunnel thread pool { start_servers = 5 max_servers = 32 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 0 cleanup_delay = 5 max_queue_size = 65536 auto_limit_acct = no } Thread spawned new child 1. Total threads in pool: 1 Thread spawned new child 2. Total threads in pool: 2 Thread spawned new child 3. Total threads in pool: 3 Thread 1 waiting to be assigned a request Thread spawned new child 4. Total threads in pool: 4 Thread 3 waiting to be assigned a request Thread 4 waiting to be assigned a request Thread spawned new child 5. Total threads in pool: 5 Thread pool initialized radiusd: #### Opening IP addresses and Ports #### Thread 2 waiting to be assigned a request Thread 5 waiting to be assigned a request listen { type = "auth+acct" virtual_server = "default" ipaddr = * port = 2083 proto = "tcp" tls { verify_depth = 0 ca_path = "/usr/local/etc/raddb/certs" pem_file_type = yes private_key_file = "/usr/local/etc/raddb/certs/server.pem" certificate_file = "/usr/local/etc/raddb/certs/server.pem" ca_file = "/usr/local/etc/raddb/certs/ca.pem" private_key_password = <<< secret >>> fragment_size = 8192 include_length = yes auto_chain = yes check_crl = no check_all_crl = no ca_path_reload_interval = 3600 cipher_list = "DEFAULT" cipher_server_preference = no require_client_cert = yes reject_unknown_intermediate_ca = no ecdh_curve = "prime256v1" tls_max_version = "1.3" tls_min_version = "1.2" cache { enable = no lifetime = 24 max_entries = 255 } verify { skip_if_ocsp_ok = no } ocsp { enable = no override_cert_url = no use_nonce = yes timeout = 0 softfail = no } } check_client_connections = yes limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } clients = "radsec" client 127.0.0.1 { ipaddr = * require_message_authenticator = no secret = <<< secret >>> proto = "tls" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } } listen { type = "auth" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipaddr = 127.0.0.1 port = 18120 } Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server default Listening on auth address * port 1812 bound to server default Listening on acct address * port 1813 bound to server default Listening on auth address :: port 1812 bound to server default Listening on acct address :: port 1813 bound to server default Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Listening on proxy address * port 45552 Listening on proxy address :: port 52860 Ready to process requests ... new connection request on TCP socket Listening on auth+acct from client (192.168.215.1, 19729) -> (*, 2083, virtual-server=default) Waking up in 0.4 seconds. (0) (TLS) RADIUS/TLS -Initiating new session (0) (TLS) RADIUS/TLS - Setting verify mode to require certificate from client (0) (TLS) RADIUS/TLS - Handshake state - before SSL initialization (0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization (0) (TLS) RADIUS/TLS - Handshake state - Server before SSL initialization (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello (0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write change cipher spec (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data (0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data (0) (TLS) RADIUS/TLS - In Handshake Phase Waking up in 0.4 seconds. (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client hello (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write server hello (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, EncryptedExtensions (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write encrypted extensions (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateRequest (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate request (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write certificate (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 write server certificate verify (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS write finished (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data (0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data (0) (TLS) RADIUS/TLS - In Handshake Phase Waking up in 0.4 seconds. (0) (TLS) RADIUS/TLS - Handshake state - Server TLSv1.3 early data (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate (0) (TLS) RADIUS/TLS - Creating attributes from client certificate (0) TLS-Client-Cert-Serial := "2aef75f0ea7f49c68b28781d7a6a2ff9" (0) TLS-Client-Cert-Expiration := "340208105559Z" (0) TLS-Client-Cert-Valid-Since := "240208104559Z" (0) TLS-Client-Cert-Subject := "/CN=BoilerPlate" (0) TLS-Client-Cert-Issuer := "/CN=BoilerPlate" (0) TLS-Client-Cert-Common-Name := "BoilerPlate" (0) TLS-Client-Cert-Subject-Alt-Name-Dns := "radius.BoilerPlate.net" (0) TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE" (0) TLS-Client-Cert-X509v3-Authority-Key-Identifier += "73:D2:45:9F:1A:5B:BB:04:31:0D:2B:52:A8:66:F9:72:EB:12:D1:54" (0) TLS-Client-Cert-X509v3-Subject-Key-Identifier += "73:D2:45:9F:1A:5B:BB:04:31:0D:2B:52:A8:66:F9:72:EB:12:D1:54" Certificate chain - 0 intermediate CA cert(s) untrusted To forbid these certificates see 'reject_unknown_intermediate_ca' (TLS) untrusted certificate with depth [0] subject name /CN=BoilerPlate (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read client certificate (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read certificate verify (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished (0) (TLS) RADIUS/TLS - Handshake state - Server SSLv3/TLS read finished (0) (TLS) RADIUS/TLS - Handshake state - SSL negotiation finished successfully (0) (TLS) RADIUS/TLS - Connection Established (0) TLS-Session-Cipher-Suite = "TLS_AES_256_GCM_SHA384" (0) TLS-Session-Version = "TLS 1.3" (0) (TLS) RADIUS/TLS - Application data. Threads: total/active/spare threads = 5/0/5 Waking up in 0.3 seconds. Thread 5 got semaphore Thread 5 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:19729 length 0 (0) Finished request Thread 5 waiting to be assigned a request Waking up in 4.5 seconds. (0) Cleaning up request packet ID 4294967295 with timestamp +7 due to cleanup_delay was reached Ready to process requests BR, Lineconnect
On Apr 12, 2024, at 6:29 AM, nabble@felix.world wrote:
I want to make some additional checks for RadSec connections.
After I’ve set `check_client_connections` to `yes`, the server is handling the connection over the auth type "Autz-Type New-TLS-Connection”. So far so good but after the connection has accepted, no further traffic is reaching the radius server.
I can see in packet captures that Access-Requests are send to the server and on the server netstat is also showing that packets are going to the socket which FreeRADIUS opens but only the queue is getting higher and never processed. After seeing this behaviour, of course also tested the behaviour with the default config. Just enabled tls, changed the `check_client_connections` and added a ip wildcard to the radsec clients.
Since I haven’t found any open GitHub issue or something on this list I assume either no one is using the functionality or there is something I’ve overlooked.
It should work, but most of my focus has been on v4 recently. I've pushed some more debug messages to the v3.2.x branch which may help track down what's going on. Can you try that? Also try running with "-Xx", which will give a bit more information about what's going on in the TLS state machine. Alan DeKok.
I've pushed some more debug messages to the v3.2.x branch which may help track down what's going on. Can you try that?
Sure. Since threading is needed for RadSec I was not able to start the server with -Xx and used -fxxx. But since I can’t find the messages which you’ve included I’m not sure if those two args are equal. Log: ``` Fri Apr 12 11:37:35 2024 : Debug: Server was built with: Fri Apr 12 11:37:35 2024 : Debug: accounting : yes Fri Apr 12 11:37:35 2024 : Debug: authentication : yes Fri Apr 12 11:37:35 2024 : Debug: ascend-binary-attributes : yes Fri Apr 12 11:37:35 2024 : Debug: coa : yes Fri Apr 12 11:37:35 2024 : Debug: recv-coa-from-home-server : no Fri Apr 12 11:37:35 2024 : Debug: control-socket : yes Fri Apr 12 11:37:35 2024 : Debug: detail : yes Fri Apr 12 11:37:35 2024 : Debug: dhcp : yes Fri Apr 12 11:37:35 2024 : Debug: dynamic-clients : yes Fri Apr 12 11:37:35 2024 : Debug: osfc2 : no Fri Apr 12 11:37:35 2024 : Debug: proxy : yes Fri Apr 12 11:37:35 2024 : Debug: regex-pcre : yes Fri Apr 12 11:37:35 2024 : Debug: regex-posix : no Fri Apr 12 11:37:35 2024 : Debug: regex-posix-extended : no Fri Apr 12 11:37:35 2024 : Debug: session-management : yes Fri Apr 12 11:37:35 2024 : Debug: stats : yes Fri Apr 12 11:37:35 2024 : Debug: systemd : no Fri Apr 12 11:37:35 2024 : Debug: tcp : yes Fri Apr 12 11:37:35 2024 : Debug: threads : yes Fri Apr 12 11:37:35 2024 : Debug: tls : yes Fri Apr 12 11:37:35 2024 : Debug: unlang : yes Fri Apr 12 11:37:35 2024 : Debug: vmps : yes Fri Apr 12 11:37:35 2024 : Debug: developer : no Fri Apr 12 11:37:35 2024 : Debug: Server core libs: Fri Apr 12 11:37:35 2024 : Debug: freeradius-server : 3.2.4 Fri Apr 12 11:37:35 2024 : Debug: talloc : 2.3.* Fri Apr 12 11:37:35 2024 : Debug: ssl : 3.0.0b dev Fri Apr 12 11:37:35 2024 : Debug: pcre : 8.39 2016-06-14 Fri Apr 12 11:37:35 2024 : Debug: Endianness: Fri Apr 12 11:37:35 2024 : Debug: little Fri Apr 12 11:37:35 2024 : Debug: Compilation flags: Fri Apr 12 11:37:35 2024 : Debug: cppflags : Fri Apr 12 11:37:35 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 -DPTHREAD_DEBUG -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Fri Apr 12 11:37:35 2024 : Debug: ldflags : Fri Apr 12 11:37:35 2024 : Debug: libs : -lcrypto -lssl -ltalloc -latomic -lpcre -lnsl -lresolv -ldl -lpthread Fri Apr 12 11:37:35 2024 : Debug: Fri Apr 12 11:37:35 2024 : Info: FreeRADIUS Version 3.2.4 Fri Apr 12 11:37:35 2024 : Info: Copyright (C) 1999-2023 The FreeRADIUS server project and contributors Fri Apr 12 11:37:35 2024 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Fri Apr 12 11:37:35 2024 : Info: PARTICULAR PURPOSE Fri Apr 12 11:37:35 2024 : Info: You may redistribute copies of FreeRADIUS under the terms of the Fri Apr 12 11:37:35 2024 : Info: GNU General Public License Fri Apr 12 11:37:35 2024 : Info: For more information about these matters, see the file named COPYRIGHT Fri Apr 12 11:37:35 2024 : Info: Starting - reading configuration files ... Fri Apr 12 11:37:35 2024 : Debug: including dictionary file /usr/local/share/freeradius/dictionary Fri Apr 12 11:37:35 2024 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.dhcp Fri Apr 12 11:37:35 2024 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.vqp Fri Apr 12 11:37:35 2024 : Debug: including dictionary file /usr/local/etc/raddb/dictionary Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/clients.conf Fri Apr 12 11:37:35 2024 : Debug: including files in directory /usr/local/etc/raddb/mods-enabled/ Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/chap Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/date Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/digest Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/eap Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/echo Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/exec Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expiration Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expr Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/files Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/linelog Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/logintime Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/mschap Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/pap Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/passwd Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/preprocess Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/radutmp Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/replicate Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/soh Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/totp Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unix Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unpack Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/utf8 Fri Apr 12 11:37:35 2024 : Debug: including files in directory /usr/local/etc/raddb/policy.d/ Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/abfab-tr Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/accounting Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/canonicalization Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/control Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/cui Fri Apr 12 11:37:35 2024 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Apr 12 11:37:35 2024 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Apr 12 11:37:35 2024 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Apr 12 11:37:35 2024 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/debug Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/dhcp Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/eap Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/filter Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/moonshot-targeted-ids Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/operator-name Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/policy.d/rfc7542 Fri Apr 12 11:37:35 2024 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel Fri Apr 12 11:37:35 2024 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/tls Fri Apr 12 11:37:35 2024 : Debug: main { Fri Apr 12 11:37:35 2024 : Debug: security { Fri Apr 12 11:37:35 2024 : Debug: allow_core_dumps = no Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[567]: The item 'max_attributes' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[584]: The item 'reject_delay' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[604]: The item 'status_server' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[614]: The item 'allow_vulnerable_openssl' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: name = "radiusd" Fri Apr 12 11:37:35 2024 : Debug: prefix = "/usr/local" Fri Apr 12 11:37:35 2024 : Debug: localstatedir = "/usr/local/var" Fri Apr 12 11:37:35 2024 : Debug: logdir = "/usr/local/var/log/radius" Fri Apr 12 11:37:35 2024 : Debug: run_dir = "/usr/local/var/run/radiusd" Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[138]: The item 'libdir' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[149]: The item 'pidfile' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[203]: The item 'max_request_time' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[222]: The item 'cleanup_delay' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[259]: The item 'hostname_lookups' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[413]: The item 'checkrad' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[633]: The item 'proxy_requests' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: main { Fri Apr 12 11:37:35 2024 : Debug: name = "radiusd" Fri Apr 12 11:37:35 2024 : Debug: prefix = "/usr/local" Fri Apr 12 11:37:35 2024 : Debug: localstatedir = "/usr/local/var" Fri Apr 12 11:37:35 2024 : Debug: sbindir = "/usr/local/sbin" Fri Apr 12 11:37:35 2024 : Debug: logdir = "/usr/local/var/log/radius" Fri Apr 12 11:37:35 2024 : Debug: run_dir = "/usr/local/var/run/radiusd" Fri Apr 12 11:37:35 2024 : Debug: libdir = "/usr/local/lib" Fri Apr 12 11:37:35 2024 : Debug: radacctdir = "/usr/local/var/log/radius/radacct" Fri Apr 12 11:37:35 2024 : Debug: hostname_lookups = no Fri Apr 12 11:37:35 2024 : Debug: max_request_time = 30 Fri Apr 12 11:37:35 2024 : Debug: proxy_dedup_window = 1 Fri Apr 12 11:37:35 2024 : Debug: cleanup_delay = 5 Fri Apr 12 11:37:35 2024 : Debug: max_requests = 16384 Fri Apr 12 11:37:35 2024 : Debug: postauth_client_lost = no Fri Apr 12 11:37:35 2024 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid" Fri Apr 12 11:37:35 2024 : Debug: checkrad = "/usr/local/sbin/checkrad" Fri Apr 12 11:37:35 2024 : Debug: debug_level = 0 Fri Apr 12 11:37:35 2024 : Debug: proxy_requests = yes Fri Apr 12 11:37:35 2024 : Debug: log { Fri Apr 12 11:37:35 2024 : Debug: stripped_names = no Fri Apr 12 11:37:35 2024 : Debug: auth = no Fri Apr 12 11:37:35 2024 : Debug: auth_badpass = no Fri Apr 12 11:37:35 2024 : Debug: auth_goodpass = no Fri Apr 12 11:37:35 2024 : Debug: colourise = yes Fri Apr 12 11:37:35 2024 : Debug: msg_denied = "You are already logged in - access denied" Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[309]: The item 'destination' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[326]: The item 'file' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[334]: The item 'syslog_facility' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: resources { Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: security { Fri Apr 12 11:37:35 2024 : Debug: max_attributes = 200 Fri Apr 12 11:37:35 2024 : Debug: reject_delay = 1.000000 Fri Apr 12 11:37:35 2024 : Debug: status_server = yes Fri Apr 12 11:37:35 2024 : Debug: allow_vulnerable_openssl = "no" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: radiusd: #### Loading Realms and Home Servers #### Fri Apr 12 11:37:35 2024 : Debug: proxy server { Fri Apr 12 11:37:35 2024 : Debug: retry_delay = 5 Fri Apr 12 11:37:35 2024 : Debug: retry_count = 3 Fri Apr 12 11:37:35 2024 : Debug: default_fallback = no Fri Apr 12 11:37:35 2024 : Debug: dead_time = 120 Fri Apr 12 11:37:35 2024 : Debug: wake_all_if_all_dead = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: home_server localhost { Fri Apr 12 11:37:35 2024 : Debug: nonblock = no Fri Apr 12 11:37:35 2024 : Debug: ipaddr = 127.0.0.1 Fri Apr 12 11:37:35 2024 : Debug: port = 1812 Fri Apr 12 11:37:35 2024 : Debug: type = "auth" Fri Apr 12 11:37:35 2024 : Debug: secret = "testing123" Fri Apr 12 11:37:35 2024 : Debug: response_window = 20.000000 Fri Apr 12 11:37:35 2024 : Debug: response_timeouts = 1 Fri Apr 12 11:37:35 2024 : Debug: max_outstanding = 65536 Fri Apr 12 11:37:35 2024 : Debug: zombie_period = 40 Fri Apr 12 11:37:35 2024 : Debug: status_check = "status-server" Fri Apr 12 11:37:35 2024 : Debug: ping_interval = 30 Fri Apr 12 11:37:35 2024 : Debug: check_interval = 30 Fri Apr 12 11:37:35 2024 : Debug: check_timeout = 4 Fri Apr 12 11:37:35 2024 : Debug: num_answers_to_alive = 3 Fri Apr 12 11:37:35 2024 : Debug: revive_interval = 120 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: max_requests = 0 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 0 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: coa { Fri Apr 12 11:37:35 2024 : Debug: irt = 2 Fri Apr 12 11:37:35 2024 : Debug: mrt = 16 Fri Apr 12 11:37:35 2024 : Debug: mrc = 5 Fri Apr 12 11:37:35 2024 : Debug: mrd = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: home_server tls { Fri Apr 12 11:37:35 2024 : Debug: nonblock = no Fri Apr 12 11:37:35 2024 : Debug: ipaddr = 127.0.0.1 Fri Apr 12 11:37:35 2024 : Debug: port = 2083 Fri Apr 12 11:37:35 2024 : Debug: type = "auth" Fri Apr 12 11:37:35 2024 : Debug: proto = "tcp" Fri Apr 12 11:37:35 2024 : Debug: secret = "radsec" Fri Apr 12 11:37:35 2024 : Debug: response_window = 30.000000 Fri Apr 12 11:37:35 2024 : Debug: response_timeouts = 1 Fri Apr 12 11:37:35 2024 : Debug: max_outstanding = 65536 Fri Apr 12 11:37:35 2024 : Debug: zombie_period = 40 Fri Apr 12 11:37:35 2024 : Debug: status_check = "none" Fri Apr 12 11:37:35 2024 : Debug: ping_interval = 30 Fri Apr 12 11:37:35 2024 : Debug: check_timeout = 4 Fri Apr 12 11:37:35 2024 : Debug: num_answers_to_alive = 3 Fri Apr 12 11:37:35 2024 : Debug: revive_interval = 300 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: max_requests = 0 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 0 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: coa { Fri Apr 12 11:37:35 2024 : Debug: irt = 2 Fri Apr 12 11:37:35 2024 : Debug: mrt = 16 Fri Apr 12 11:37:35 2024 : Debug: mrc = 5 Fri Apr 12 11:37:35 2024 : Debug: mrd = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: tls { Fri Apr 12 11:37:35 2024 : Debug: verify_depth = 0 Fri Apr 12 11:37:35 2024 : Debug: ca_path = "/usr/local/etc/raddb/certs" Fri Apr 12 11:37:35 2024 : Debug: pem_file_type = yes Fri Apr 12 11:37:35 2024 : Debug: private_key_file = "/usr/local/etc/raddb/certs/client.pem" Fri Apr 12 11:37:35 2024 : Debug: certificate_file = "/usr/local/etc/raddb/certs/client.pem" Fri Apr 12 11:37:35 2024 : Debug: ca_file = "/usr/local/etc/raddb/certs/ca.pem" Fri Apr 12 11:37:35 2024 : Debug: private_key_password = "whatever" Fri Apr 12 11:37:35 2024 : Debug: fragment_size = 8192 Fri Apr 12 11:37:35 2024 : Debug: include_length = yes Fri Apr 12 11:37:35 2024 : Debug: check_crl = no Fri Apr 12 11:37:35 2024 : Debug: cipher_list = "DEFAULT" Fri Apr 12 11:37:35 2024 : Debug: ca_path_reload_interval = 0 Fri Apr 12 11:37:35 2024 : Debug: ecdh_curve = "prime256v1" Fri Apr 12 11:37:35 2024 : Debug: tls_min_version = "1.2" Fri Apr 12 11:37:35 2024 : Warning: /usr/local/etc/raddb/sites-enabled/tls[720]: The item 'connect_timeout' is defined, but is unused by the configuration Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: connect_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: home_server_pool my_auth_failover { Fri Apr 12 11:37:35 2024 : Debug: type = fail-over Fri Apr 12 11:37:35 2024 : Debug: home_server = localhost Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: realm example.com { Fri Apr 12 11:37:35 2024 : Debug: auth_pool = my_auth_failover Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: realm LOCAL { Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: home_server_pool tls { Fri Apr 12 11:37:35 2024 : Debug: type = fail-over Fri Apr 12 11:37:35 2024 : Debug: home_server = tls Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: realm tls { Fri Apr 12 11:37:35 2024 : Debug: auth_pool = tls Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: radiusd: #### Loading Clients #### Fri Apr 12 11:37:35 2024 : Debug: client localhost { Fri Apr 12 11:37:35 2024 : Debug: ipaddr = 127.0.0.1 Fri Apr 12 11:37:35 2024 : Debug: require_message_authenticator = no Fri Apr 12 11:37:35 2024 : Debug: secret = "testing123" Fri Apr 12 11:37:35 2024 : Debug: nas_type = "other" Fri Apr 12 11:37:35 2024 : Debug: proto = "*" Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Fri Apr 12 11:37:35 2024 : Debug: client localhost_ipv6 { Fri Apr 12 11:37:35 2024 : Debug: ipv6addr = ::1 Fri Apr 12 11:37:35 2024 : Debug: require_message_authenticator = no Fri Apr 12 11:37:35 2024 : Debug: secret = "testing123" Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Fri Apr 12 11:37:35 2024 : Info: Debugger not attached Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = mschap Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = digest Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = eap Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = PAP Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = CHAP Fri Apr 12 11:37:35 2024 : Debug: # Creating Auth-Type = MS-CHAP Fri Apr 12 11:37:35 2024 : Debug: # Creating Autz-Type = New-TLS-Connection Fri Apr 12 11:37:35 2024 : Debug: radiusd: #### Instantiating modules #### Fri Apr 12 11:37:35 2024 : Debug: modules { Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_always, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_always Fri Apr 12 11:37:35 2024 : Debug: # Loading module "reject" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always reject { Fri Apr 12 11:37:35 2024 : Debug: rcode = "reject" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "fail" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always fail { Fri Apr 12 11:37:35 2024 : Debug: rcode = "fail" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "ok" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always ok { Fri Apr 12 11:37:35 2024 : Debug: rcode = "ok" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "handled" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always handled { Fri Apr 12 11:37:35 2024 : Debug: rcode = "handled" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always invalid { Fri Apr 12 11:37:35 2024 : Debug: rcode = "invalid" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always userlock { Fri Apr 12 11:37:35 2024 : Debug: rcode = "userlock" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always notfound { Fri Apr 12 11:37:35 2024 : Debug: rcode = "notfound" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "noop" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always noop { Fri Apr 12 11:37:35 2024 : Debug: rcode = "noop" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "updated" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: always updated { Fri Apr 12 11:37:35 2024 : Debug: rcode = "updated" Fri Apr 12 11:37:35 2024 : Debug: simulcount = 0 Fri Apr 12 11:37:35 2024 : Debug: mpp = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_attr_filter, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_attr_filter Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.post-proxy { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" Fri Apr 12 11:37:35 2024 : Debug: key = "%{Realm}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.pre-proxy { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" Fri Apr 12 11:37:35 2024 : Debug: key = "%{Realm}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.access_reject { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" Fri Apr 12 11:37:35 2024 : Debug: key = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.access_challenge { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" Fri Apr 12 11:37:35 2024 : Debug: key = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.accounting_response { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" Fri Apr 12 11:37:35 2024 : Debug: key = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "attr_filter.coa" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: attr_filter attr_filter.coa { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/coa" Fri Apr 12 11:37:35 2024 : Debug: key = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: relaxed = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_chap, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_chap Fri Apr 12 11:37:35 2024 : Debug: # Loading module "chap" from file /usr/local/etc/raddb/mods-enabled/chap Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_date, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_date Fri Apr 12 11:37:35 2024 : Debug: # Loading module "date" from file /usr/local/etc/raddb/mods-enabled/date Fri Apr 12 11:37:35 2024 : Debug: date { Fri Apr 12 11:37:35 2024 : Debug: format = "%b %e %Y %H:%M:%S %Z" Fri Apr 12 11:37:35 2024 : Debug: utc = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-enabled/date Fri Apr 12 11:37:35 2024 : Debug: date wispr2date { Fri Apr 12 11:37:35 2024 : Debug: format = "%Y-%m-%dT%H:%M:%S" Fri Apr 12 11:37:35 2024 : Debug: utc = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_detail, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_detail Fri Apr 12 11:37:35 2024 : Debug: # Loading module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Fri Apr 12 11:37:35 2024 : Debug: detail { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Fri Apr 12 11:37:35 2024 : Debug: header = "%t" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: locking = no Fri Apr 12 11:37:35 2024 : Debug: dates_as_integer = no Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: log_packet_header = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: detail auth_log { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Fri Apr 12 11:37:35 2024 : Debug: header = "%t" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: locking = no Fri Apr 12 11:37:35 2024 : Debug: dates_as_integer = no Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: log_packet_header = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: detail reply_log { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Fri Apr 12 11:37:35 2024 : Debug: header = "%t" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: locking = no Fri Apr 12 11:37:35 2024 : Debug: dates_as_integer = no Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: log_packet_header = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: detail pre_proxy_log { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Fri Apr 12 11:37:35 2024 : Debug: header = "%t" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: locking = no Fri Apr 12 11:37:35 2024 : Debug: dates_as_integer = no Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: log_packet_header = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: detail post_proxy_log { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Fri Apr 12 11:37:35 2024 : Debug: header = "%t" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: locking = no Fri Apr 12 11:37:35 2024 : Debug: dates_as_integer = no Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: log_packet_header = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_digest, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_digest Fri Apr 12 11:37:35 2024 : Debug: # Loading module "digest" from file /usr/local/etc/raddb/mods-enabled/digest Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_dynamic_clients Fri Apr 12 11:37:35 2024 : Debug: # Loading module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_eap, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_eap Fri Apr 12 11:37:35 2024 : Debug: # Loading module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Fri Apr 12 11:37:35 2024 : Debug: eap { Fri Apr 12 11:37:35 2024 : Debug: default_eap_type = "md5" Fri Apr 12 11:37:35 2024 : Debug: timer_expire = 60 Fri Apr 12 11:37:35 2024 : Debug: max_eap_type = 52 Fri Apr 12 11:37:35 2024 : Debug: ignore_unknown_eap_types = no Fri Apr 12 11:37:35 2024 : Debug: cisco_accounting_username_bug = no Fri Apr 12 11:37:35 2024 : Debug: max_sessions = 16384 Fri Apr 12 11:37:35 2024 : Debug: dedup_key = "" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_exec, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_exec Fri Apr 12 11:37:35 2024 : Debug: # Loading module "echo" from file /usr/local/etc/raddb/mods-enabled/echo Fri Apr 12 11:37:35 2024 : Debug: exec echo { Fri Apr 12 11:37:35 2024 : Debug: wait = yes Fri Apr 12 11:37:35 2024 : Debug: program = "/bin/echo %{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: input_pairs = "request" Fri Apr 12 11:37:35 2024 : Debug: output_pairs = "reply" Fri Apr 12 11:37:35 2024 : Debug: shell_escape = yes Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "exec" from file /usr/local/etc/raddb/mods-enabled/exec Fri Apr 12 11:37:35 2024 : Debug: exec { Fri Apr 12 11:37:35 2024 : Debug: wait = no Fri Apr 12 11:37:35 2024 : Debug: input_pairs = "request" Fri Apr 12 11:37:35 2024 : Debug: shell_escape = yes Fri Apr 12 11:37:35 2024 : Debug: timeout = 10 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_expiration, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_expiration Fri Apr 12 11:37:35 2024 : Debug: # Loading module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_expr, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_expr Fri Apr 12 11:37:35 2024 : Debug: # Loading module "expr" from file /usr/local/etc/raddb/mods-enabled/expr Fri Apr 12 11:37:35 2024 : Debug: expr { Fri Apr 12 11:37:35 2024 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_files, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_files Fri Apr 12 11:37:35 2024 : Debug: # Loading module "files" from file /usr/local/etc/raddb/mods-enabled/files Fri Apr 12 11:37:35 2024 : Debug: files { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/etc/raddb/mods-config/files/authorize" Fri Apr 12 11:37:35 2024 : Debug: acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" Fri Apr 12 11:37:35 2024 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_linelog, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_linelog Fri Apr 12 11:37:35 2024 : Debug: # Loading module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Fri Apr 12 11:37:35 2024 : Debug: linelog { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/linelog" Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: syslog_severity = "info" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: format = "This is a log message for %{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Fri Apr 12 11:37:35 2024 : Debug: linelog log_accounting { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/linelog-accounting" Fri Apr 12 11:37:35 2024 : Debug: escape_filenames = no Fri Apr 12 11:37:35 2024 : Debug: syslog_severity = "info" Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: format = "" Fri Apr 12 11:37:35 2024 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_logintime, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_logintime Fri Apr 12 11:37:35 2024 : Debug: # Loading module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Fri Apr 12 11:37:35 2024 : Debug: logintime { Fri Apr 12 11:37:35 2024 : Debug: minimum_timeout = 60 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_mschap, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_mschap Fri Apr 12 11:37:35 2024 : Debug: # Loading module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Fri Apr 12 11:37:35 2024 : Debug: mschap { Fri Apr 12 11:37:35 2024 : Debug: use_mppe = yes Fri Apr 12 11:37:35 2024 : Debug: require_encryption = no Fri Apr 12 11:37:35 2024 : Debug: require_strong = no Fri Apr 12 11:37:35 2024 : Debug: with_ntdomain_hack = yes Fri Apr 12 11:37:35 2024 : Debug: passchange { Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: allow_retry = yes Fri Apr 12 11:37:35 2024 : Debug: winbind_retry_with_normalised_username = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth Fri Apr 12 11:37:35 2024 : Debug: exec ntlm_auth { Fri Apr 12 11:37:35 2024 : Debug: wait = yes Fri Apr 12 11:37:35 2024 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Fri Apr 12 11:37:35 2024 : Debug: shell_escape = yes Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_pap, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_pap Fri Apr 12 11:37:35 2024 : Debug: # Loading module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Fri Apr 12 11:37:35 2024 : Debug: pap { Fri Apr 12 11:37:35 2024 : Debug: normalise = yes Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_passwd, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_passwd Fri Apr 12 11:37:35 2024 : Debug: # Loading module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Fri Apr 12 11:37:35 2024 : Debug: passwd etc_passwd { Fri Apr 12 11:37:35 2024 : Debug: filename = "/etc/passwd" Fri Apr 12 11:37:35 2024 : Debug: format = "*User-Name:Crypt-Password:" Fri Apr 12 11:37:35 2024 : Debug: delimiter = ":" Fri Apr 12 11:37:35 2024 : Debug: ignore_nislike = no Fri Apr 12 11:37:35 2024 : Debug: ignore_empty = yes Fri Apr 12 11:37:35 2024 : Debug: allow_multiple_keys = no Fri Apr 12 11:37:35 2024 : Debug: hash_size = 100 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_preprocess, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_preprocess Fri Apr 12 11:37:35 2024 : Debug: # Loading module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Fri Apr 12 11:37:35 2024 : Debug: preprocess { Fri Apr 12 11:37:35 2024 : Debug: huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" Fri Apr 12 11:37:35 2024 : Debug: hints = "/usr/local/etc/raddb/mods-config/preprocess/hints" Fri Apr 12 11:37:35 2024 : Debug: with_ascend_hack = no Fri Apr 12 11:37:35 2024 : Debug: ascend_channels_per_line = 23 Fri Apr 12 11:37:35 2024 : Debug: with_ntdomain_hack = no Fri Apr 12 11:37:35 2024 : Debug: with_specialix_jetstream_hack = no Fri Apr 12 11:37:35 2024 : Debug: with_cisco_vsa_hack = no Fri Apr 12 11:37:35 2024 : Debug: with_alvarion_vsa_hack = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_radutmp, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_radutmp Fri Apr 12 11:37:35 2024 : Debug: # Loading module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp Fri Apr 12 11:37:35 2024 : Debug: radutmp { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/radutmp" Fri Apr 12 11:37:35 2024 : Debug: username = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: case_sensitive = yes Fri Apr 12 11:37:35 2024 : Debug: check_with_nas = yes Fri Apr 12 11:37:35 2024 : Debug: permissions = 384 Fri Apr 12 11:37:35 2024 : Debug: caller_id = yes Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_realm, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_realm Fri Apr 12 11:37:35 2024 : Debug: # Loading module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: realm IPASS { Fri Apr 12 11:37:35 2024 : Debug: format = "prefix" Fri Apr 12 11:37:35 2024 : Debug: delimiter = "/" Fri Apr 12 11:37:35 2024 : Debug: ignore_default = no Fri Apr 12 11:37:35 2024 : Debug: ignore_null = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: realm suffix { Fri Apr 12 11:37:35 2024 : Debug: format = "suffix" Fri Apr 12 11:37:35 2024 : Debug: delimiter = "@" Fri Apr 12 11:37:35 2024 : Debug: ignore_default = no Fri Apr 12 11:37:35 2024 : Debug: ignore_null = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: realm bangpath { Fri Apr 12 11:37:35 2024 : Debug: format = "prefix" Fri Apr 12 11:37:35 2024 : Debug: delimiter = "!" Fri Apr 12 11:37:35 2024 : Debug: ignore_default = no Fri Apr 12 11:37:35 2024 : Debug: ignore_null = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: realm realmpercent { Fri Apr 12 11:37:35 2024 : Debug: format = "suffix" Fri Apr 12 11:37:35 2024 : Debug: delimiter = "%" Fri Apr 12 11:37:35 2024 : Debug: ignore_default = no Fri Apr 12 11:37:35 2024 : Debug: ignore_null = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: realm ntdomain { Fri Apr 12 11:37:35 2024 : Debug: format = "prefix" Fri Apr 12 11:37:35 2024 : Debug: delimiter = "\" Fri Apr 12 11:37:35 2024 : Debug: ignore_default = no Fri Apr 12 11:37:35 2024 : Debug: ignore_null = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_replicate, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_replicate Fri Apr 12 11:37:35 2024 : Debug: # Loading module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_soh, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_soh Fri Apr 12 11:37:35 2024 : Debug: # Loading module "soh" from file /usr/local/etc/raddb/mods-enabled/soh Fri Apr 12 11:37:35 2024 : Debug: soh { Fri Apr 12 11:37:35 2024 : Debug: dhcp = yes Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Loading module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp Fri Apr 12 11:37:35 2024 : Debug: radutmp sradutmp { Fri Apr 12 11:37:35 2024 : Debug: filename = "/usr/local/var/log/radius/sradutmp" Fri Apr 12 11:37:35 2024 : Debug: username = "%{User-Name}" Fri Apr 12 11:37:35 2024 : Debug: case_sensitive = yes Fri Apr 12 11:37:35 2024 : Debug: check_with_nas = yes Fri Apr 12 11:37:35 2024 : Debug: permissions = 420 Fri Apr 12 11:37:35 2024 : Debug: caller_id = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_totp, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_totp Fri Apr 12 11:37:35 2024 : Debug: # Loading module "totp" from file /usr/local/etc/raddb/mods-enabled/totp Fri Apr 12 11:37:35 2024 : Debug: totp { Fri Apr 12 11:37:35 2024 : Debug: time_step = 30 Fri Apr 12 11:37:35 2024 : Debug: otp_length = 8 Fri Apr 12 11:37:35 2024 : Debug: lookback_steps = 1 Fri Apr 12 11:37:35 2024 : Debug: lookback_interval = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_unix, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_unix Fri Apr 12 11:37:35 2024 : Debug: # Loading module "unix" from file /usr/local/etc/raddb/mods-enabled/unix Fri Apr 12 11:37:35 2024 : Debug: unix { Fri Apr 12 11:37:35 2024 : Debug: radwtmp = "/usr/local/var/log/radius/radwtmp" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Creating attribute Unix-Group Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_unpack, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_unpack Fri Apr 12 11:37:35 2024 : Debug: # Loading module "unpack" from file /usr/local/etc/raddb/mods-enabled/unpack Fri Apr 12 11:37:35 2024 : Debug: Loaded rlm_utf8, checking if it's valid Fri Apr 12 11:37:35 2024 : Debug: # Loaded module rlm_utf8 Fri Apr 12 11:37:35 2024 : Debug: # Loading module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 Fri Apr 12 11:37:35 2024 : Debug: instantiate { Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-enabled/attr_filter Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/coa Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_md5 Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_gtc Fri Apr 12 11:37:35 2024 : Debug: gtc { Fri Apr 12 11:37:35 2024 : Debug: challenge = "Password: " Fri Apr 12 11:37:35 2024 : Debug: auth_type = "PAP" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_tls Fri Apr 12 11:37:35 2024 : Debug: tls { Fri Apr 12 11:37:35 2024 : Debug: tls = "tls-common" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: tls-config tls-common { Fri Apr 12 11:37:35 2024 : Debug: verify_depth = 0 Fri Apr 12 11:37:35 2024 : Debug: ca_path = "/usr/local/etc/raddb/certs" Fri Apr 12 11:37:35 2024 : Debug: pem_file_type = yes Fri Apr 12 11:37:35 2024 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" Fri Apr 12 11:37:35 2024 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" Fri Apr 12 11:37:35 2024 : Debug: ca_file = "/usr/local/etc/raddb/certs/ca.pem" Fri Apr 12 11:37:35 2024 : Debug: private_key_password = "whatever" Fri Apr 12 11:37:35 2024 : Debug: fragment_size = 1024 Fri Apr 12 11:37:35 2024 : Debug: include_length = yes Fri Apr 12 11:37:35 2024 : Debug: auto_chain = yes Fri Apr 12 11:37:35 2024 : Debug: check_crl = no Fri Apr 12 11:37:35 2024 : Debug: check_all_crl = no Fri Apr 12 11:37:35 2024 : Debug: ca_path_reload_interval = 0 Fri Apr 12 11:37:35 2024 : Debug: cipher_list = "DEFAULT" Fri Apr 12 11:37:35 2024 : Debug: cipher_server_preference = no Fri Apr 12 11:37:35 2024 : Debug: reject_unknown_intermediate_ca = no Fri Apr 12 11:37:35 2024 : Debug: ecdh_curve = "" Fri Apr 12 11:37:35 2024 : Debug: tls_max_version = "1.2" Fri Apr 12 11:37:35 2024 : Debug: tls_min_version = "1.2" Fri Apr 12 11:37:35 2024 : Debug: cache { Fri Apr 12 11:37:35 2024 : Debug: enable = no Fri Apr 12 11:37:35 2024 : Debug: lifetime = 24 Fri Apr 12 11:37:35 2024 : Debug: max_entries = 255 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: verify { Fri Apr 12 11:37:35 2024 : Debug: skip_if_ocsp_ok = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: ocsp { Fri Apr 12 11:37:35 2024 : Debug: enable = no Fri Apr 12 11:37:35 2024 : Debug: override_cert_url = yes Fri Apr 12 11:37:35 2024 : Debug: url = "http://127.0.0.1/ocsp/" Fri Apr 12 11:37:35 2024 : Debug: use_nonce = yes Fri Apr 12 11:37:35 2024 : Debug: timeout = 0 Fri Apr 12 11:37:35 2024 : Debug: softfail = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_ttls Fri Apr 12 11:37:35 2024 : Debug: ttls { Fri Apr 12 11:37:35 2024 : Debug: tls = "tls-common" Fri Apr 12 11:37:35 2024 : Debug: default_eap_type = "md5" Fri Apr 12 11:37:35 2024 : Debug: copy_request_to_tunnel = no Fri Apr 12 11:37:35 2024 : Debug: use_tunneled_reply = no Fri Apr 12 11:37:35 2024 : Debug: virtual_server = "inner-tunnel" Fri Apr 12 11:37:35 2024 : Debug: include_length = yes Fri Apr 12 11:37:35 2024 : Debug: require_client_cert = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: tls: Using cached TLS configuration from previous invocation Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_peap Fri Apr 12 11:37:35 2024 : Debug: peap { Fri Apr 12 11:37:35 2024 : Debug: tls = "tls-common" Fri Apr 12 11:37:35 2024 : Debug: default_eap_type = "mschapv2" Fri Apr 12 11:37:35 2024 : Debug: copy_request_to_tunnel = no Fri Apr 12 11:37:35 2024 : Debug: use_tunneled_reply = no Fri Apr 12 11:37:35 2024 : Debug: proxy_tunneled_request_as_eap = yes Fri Apr 12 11:37:35 2024 : Debug: virtual_server = "inner-tunnel" Fri Apr 12 11:37:35 2024 : Debug: soh = no Fri Apr 12 11:37:35 2024 : Debug: require_client_cert = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: tls: Using cached TLS configuration from previous invocation Fri Apr 12 11:37:35 2024 : Debug: # Linked to sub-module rlm_eap_mschapv2 Fri Apr 12 11:37:35 2024 : Debug: mschapv2 { Fri Apr 12 11:37:35 2024 : Debug: with_ntdomain_hack = no Fri Apr 12 11:37:35 2024 : Debug: send_error = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Fri Apr 12 11:37:35 2024 : Debug: rlm_mschap (mschap): using internal authentication Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Fri Apr 12 11:37:35 2024 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups Fri Apr 12 11:37:35 2024 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Fri Apr 12 11:37:35 2024 : Debug: # Instantiating module "totp" from file /usr/local/etc/raddb/mods-enabled/totp Fri Apr 12 11:37:35 2024 : Debug: } # modules Fri Apr 12 11:37:35 2024 : Debug: radiusd: #### Loading Virtual Servers #### Fri Apr 12 11:37:35 2024 : Debug: server { # from file /usr/local/etc/raddb/radiusd.conf Fri Apr 12 11:37:35 2024 : Debug: } # server Fri Apr 12 11:37:35 2024 : Debug: server default { # from file /usr/local/etc/raddb/sites-enabled/default Fri Apr 12 11:37:35 2024 : Debug: # Loading authenticate {...} Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type PAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type CHAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type MS-CHAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: mschap Fri Apr 12 11:37:35 2024 : Debug: digest Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: # Loading authorize {...} Fri Apr 12 11:37:35 2024 : Debug: policy filter_username { Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name) { Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ / /) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@[^@]*@/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /\.\./) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /\.$/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@\./) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: preprocess Fri Apr 12 11:37:35 2024 : Debug: chap Fri Apr 12 11:37:35 2024 : Debug: mschap Fri Apr 12 11:37:35 2024 : Debug: digest Fri Apr 12 11:37:35 2024 : Debug: suffix Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: files Fri Apr 12 11:37:35 2024 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Fri Apr 12 11:37:35 2024 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Apr 12 11:37:35 2024 : Debug: expiration Fri Apr 12 11:37:35 2024 : Debug: logintime Fri Apr 12 11:37:35 2024 : Debug: pap Fri Apr 12 11:37:35 2024 : Debug: Compiling Autz-Type New-TLS-Connection for attr Autz-Type Fri Apr 12 11:37:35 2024 : Debug: # Loading preacct {...} Fri Apr 12 11:37:35 2024 : Debug: preprocess Fri Apr 12 11:37:35 2024 : Debug: policy acct_unique { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Tmp-String-9 := "ai:" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if ("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/ && "%{string:&Class}" =~ /^ai:([0-9a-f]{32})/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: else { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Tmp-String-9 !* ANY Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: suffix Fri Apr 12 11:37:35 2024 : Debug: files Fri Apr 12 11:37:35 2024 : Debug: # Loading accounting {...} Fri Apr 12 11:37:35 2024 : Debug: detail Fri Apr 12 11:37:35 2024 : Debug: unix Fri Apr 12 11:37:35 2024 : Debug: exec Fri Apr 12 11:37:35 2024 : Debug: attr_filter.accounting_response Fri Apr 12 11:37:35 2024 : Debug: # Loading post-proxy {...} Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: # Loading post-auth {...} Fri Apr 12 11:37:35 2024 : Debug: if (&session-state:User-Name && &reply:User-Name && &User-Name && &reply:User-Name == &User-Name) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &reply:User-Name !* ANY Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &reply:[*] += &session-state:[*] Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: exec Fri Apr 12 11:37:35 2024 : Debug: policy remove_reply_message_if_eap { Fri Apr 12 11:37:35 2024 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &reply:Reply-Message !* ANY Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: else { Fri Apr 12 11:37:35 2024 : Debug: noop Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Post-Auth-Type Challenge for attr Post-Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Post-Auth-Type Client-Lost for attr Post-Auth-Type Fri Apr 12 11:37:35 2024 : Debug: if (&EAP-Key-Name && &reply:EAP-Session-Id) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &reply:EAP-Key-Name := &reply:EAP-Session-Id Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } # server default Fri Apr 12 11:37:35 2024 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Fri Apr 12 11:37:35 2024 : Debug: # Loading authenticate {...} Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type PAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type CHAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: Compiling Auth-Type MS-CHAP for attr Auth-Type Fri Apr 12 11:37:35 2024 : Debug: mschap Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: # Loading authorize {...} Fri Apr 12 11:37:35 2024 : Debug: policy filter_username { Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name) { Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ / /) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@[^@]*@/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /\.\./) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /\.$/) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: if (&User-Name =~ /@\./) { Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: reject Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: chap Fri Apr 12 11:37:35 2024 : Debug: mschap Fri Apr 12 11:37:35 2024 : Debug: suffix Fri Apr 12 11:37:35 2024 : Debug: update { Fri Apr 12 11:37:35 2024 : Debug: &control:Proxy-To-Realm := LOCAL Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: files Fri Apr 12 11:37:35 2024 : Debug: expiration Fri Apr 12 11:37:35 2024 : Debug: logintime Fri Apr 12 11:37:35 2024 : Debug: pap Fri Apr 12 11:37:35 2024 : Debug: # Loading session {...} Fri Apr 12 11:37:35 2024 : Debug: radutmp Fri Apr 12 11:37:35 2024 : Debug: # Loading post-proxy {...} Fri Apr 12 11:37:35 2024 : Debug: eap Fri Apr 12 11:37:35 2024 : Debug: # Loading post-auth {...} Fri Apr 12 11:37:35 2024 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/etc/raddb/sites-enabled/inner-tunnel:366 Fri Apr 12 11:37:35 2024 : Debug: if (false) { Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Fri Apr 12 11:37:35 2024 : Debug: } # server inner-tunnel Fri Apr 12 11:37:35 2024 : Debug: thread pool { Fri Apr 12 11:37:35 2024 : Debug: start_servers = 5 Fri Apr 12 11:37:35 2024 : Debug: max_servers = 32 Fri Apr 12 11:37:35 2024 : Debug: min_spare_servers = 3 Fri Apr 12 11:37:35 2024 : Debug: max_spare_servers = 10 Fri Apr 12 11:37:35 2024 : Debug: max_requests_per_server = 0 Fri Apr 12 11:37:35 2024 : Debug: cleanup_delay = 5 Fri Apr 12 11:37:35 2024 : Debug: max_queue_size = 65536 Fri Apr 12 11:37:35 2024 : Debug: auto_limit_acct = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Thread spawned new child 1. Total threads in pool: 1 Fri Apr 12 11:37:35 2024 : Debug: Thread spawned new child 2. Total threads in pool: 2 Fri Apr 12 11:37:35 2024 : Debug: Thread 1 waiting to be assigned a request Fri Apr 12 11:37:35 2024 : Debug: Thread spawned new child 3. Total threads in pool: 3 Fri Apr 12 11:37:35 2024 : Debug: Thread spawned new child 4. Total threads in pool: 4 Fri Apr 12 11:37:35 2024 : Debug: Thread 2 waiting to be assigned a request Fri Apr 12 11:37:35 2024 : Debug: Thread 3 waiting to be assigned a request Fri Apr 12 11:37:35 2024 : Debug: Thread spawned new child 5. Total threads in pool: 5 Fri Apr 12 11:37:35 2024 : Debug: Thread 4 waiting to be assigned a request Fri Apr 12 11:37:35 2024 : Debug: Thread pool initialized Fri Apr 12 11:37:35 2024 : Debug: radiusd: #### Opening IP addresses and Ports #### Fri Apr 12 11:37:35 2024 : Debug: Thread 5 waiting to be assigned a request Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "auth+acct" Fri Apr 12 11:37:35 2024 : Debug: virtual_server = "default" Fri Apr 12 11:37:35 2024 : Debug: ipaddr = * Fri Apr 12 11:37:35 2024 : Debug: port = 2083 Fri Apr 12 11:37:35 2024 : Debug: proto = "tcp" Fri Apr 12 11:37:35 2024 : Debug: tls { Fri Apr 12 11:37:35 2024 : Debug: verify_depth = 0 Fri Apr 12 11:37:35 2024 : Debug: ca_path = "/usr/local/etc/raddb/certs" Fri Apr 12 11:37:35 2024 : Debug: pem_file_type = yes Fri Apr 12 11:37:35 2024 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" Fri Apr 12 11:37:35 2024 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" Fri Apr 12 11:37:35 2024 : Debug: ca_file = "/usr/local/etc/raddb/certs/ca.pem" Fri Apr 12 11:37:35 2024 : Debug: private_key_password = "whatever" Fri Apr 12 11:37:35 2024 : Debug: fragment_size = 8192 Fri Apr 12 11:37:35 2024 : Debug: include_length = yes Fri Apr 12 11:37:35 2024 : Debug: auto_chain = yes Fri Apr 12 11:37:35 2024 : Debug: check_crl = no Fri Apr 12 11:37:35 2024 : Debug: check_all_crl = no Fri Apr 12 11:37:35 2024 : Debug: ca_path_reload_interval = 3600 Fri Apr 12 11:37:35 2024 : Debug: cipher_list = "DEFAULT" Fri Apr 12 11:37:35 2024 : Debug: cipher_server_preference = no Fri Apr 12 11:37:35 2024 : Debug: require_client_cert = yes Fri Apr 12 11:37:35 2024 : Debug: reject_unknown_intermediate_ca = no Fri Apr 12 11:37:35 2024 : Debug: ecdh_curve = "prime256v1" Fri Apr 12 11:37:35 2024 : Debug: tls_max_version = "1.3" Fri Apr 12 11:37:35 2024 : Debug: tls_min_version = "1.2" Fri Apr 12 11:37:35 2024 : Debug: cache { Fri Apr 12 11:37:35 2024 : Debug: enable = no Fri Apr 12 11:37:35 2024 : Debug: lifetime = 24 Fri Apr 12 11:37:35 2024 : Debug: max_entries = 255 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: verify { Fri Apr 12 11:37:35 2024 : Debug: skip_if_ocsp_ok = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: ocsp { Fri Apr 12 11:37:35 2024 : Debug: enable = no Fri Apr 12 11:37:35 2024 : Debug: override_cert_url = no Fri Apr 12 11:37:35 2024 : Debug: use_nonce = yes Fri Apr 12 11:37:35 2024 : Debug: timeout = 0 Fri Apr 12 11:37:35 2024 : Debug: softfail = no Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: check_client_connections = yes Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: clients = "radsec" Fri Apr 12 11:37:35 2024 : Debug: client 127.0.0.1 { Fri Apr 12 11:37:35 2024 : Debug: ipaddr = * Fri Apr 12 11:37:35 2024 : Debug: require_message_authenticator = no Fri Apr 12 11:37:35 2024 : Debug: secret = "radsec" Fri Apr 12 11:37:35 2024 : Debug: proto = "tls" Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Adding client 0.0.0.0/0 (0.0.0.0) to prefix tree 0 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "auth" Fri Apr 12 11:37:35 2024 : Debug: ipaddr = * Fri Apr 12 11:37:35 2024 : Debug: port = 0 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "acct" Fri Apr 12 11:37:35 2024 : Debug: ipaddr = * Fri Apr 12 11:37:35 2024 : Debug: port = 0 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "auth" Fri Apr 12 11:37:35 2024 : Debug: ipv6addr = :: Fri Apr 12 11:37:35 2024 : Debug: port = 0 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "acct" Fri Apr 12 11:37:35 2024 : Debug: ipv6addr = :: Fri Apr 12 11:37:35 2024 : Debug: port = 0 Fri Apr 12 11:37:35 2024 : Debug: limit { Fri Apr 12 11:37:35 2024 : Debug: max_connections = 16 Fri Apr 12 11:37:35 2024 : Debug: lifetime = 0 Fri Apr 12 11:37:35 2024 : Debug: idle_timeout = 30 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: listen { Fri Apr 12 11:37:35 2024 : Debug: type = "auth" Fri Apr 12 11:37:35 2024 : Debug: ipaddr = 127.0.0.1 Fri Apr 12 11:37:35 2024 : Debug: port = 18120 Fri Apr 12 11:37:35 2024 : Debug: } Fri Apr 12 11:37:35 2024 : Debug: Listening on auth+acct proto tcp address * port 2083 (TLS) bound to server default Fri Apr 12 11:37:35 2024 : Debug: Listening on auth address * port 1812 bound to server default Fri Apr 12 11:37:35 2024 : Debug: Listening on acct address * port 1813 bound to server default Fri Apr 12 11:37:35 2024 : Debug: Listening on auth address :: port 1812 bound to server default Fri Apr 12 11:37:35 2024 : Debug: Listening on acct address :: port 1813 bound to server default Fri Apr 12 11:37:35 2024 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Fri Apr 12 11:37:35 2024 : Debug: Opened new proxy socket 'proxy address * port 54130' Fri Apr 12 11:37:35 2024 : Debug: Listening on proxy address * port 54130 Fri Apr 12 11:37:35 2024 : Debug: Opened new proxy socket 'proxy address :: port 43555' Fri Apr 12 11:37:35 2024 : Debug: Listening on proxy address :: port 43555 Fri Apr 12 11:37:35 2024 : Info: Ready to process requests Fri Apr 12 11:37:40 2024 : Debug: ... new connection request on TCP socket Fri Apr 12 11:37:40 2024 : Debug: Listening on auth+acct from client (192.168.215.1, 33537) -> (*, 2083, virtual-server=default) Fri Apr 12 11:37:40 2024 : Debug: Waking up in 0.5 seconds. Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS -Initiating new session Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Setting verify mode to require certificate from client Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Reading from socket 15 READ FROM SSL 293 00: 16 03 01 01 20 01 00 01 1c 03 03 75 3d 57 c6 3f 10: 52 14 34 62 0e b8 f0 4d 75 15 07 8b 40 31 d0 31 20: d3 19 c7 a9 10 15 9c 26 a5 98 c3 20 45 ce d9 43 30: af f9 f0 dc d8 da d2 18 50 1a c7 37 b2 d9 22 2b 40: a8 dd f1 fd ea f0 b3 52 8e d6 8d 36 00 3e 13 02 50: 13 03 13 01 c0 2c c0 30 00 9f cc a9 cc a8 cc aa 60: c0 2b c0 2f 00 9e c0 24 c0 28 00 6b c0 23 c0 27 70: 00 67 c0 0a c0 14 00 39 c0 09 c0 13 00 33 00 9d 80: 00 9c 00 3d 00 3c 00 35 00 2f 00 ff 01 00 00 95 90: 00 0b 00 04 03 00 01 02 00 0a 00 16 00 14 00 1d a0: 00 17 00 1e 00 19 00 18 01 00 01 01 01 02 01 03 b0: 01 04 00 23 00 00 00 16 00 00 00 17 00 00 00 0d c0: 00 2a 00 28 04 03 05 03 06 03 08 07 08 08 08 09 d0: 08 0a 08 0b 08 04 08 05 08 06 04 01 05 01 06 01 e0: 03 03 03 01 03 02 04 02 05 02 06 02 00 2b 00 05 f0: 04 03 04 03 03 00 2d 00 02 01 01 00 33 00 26 00 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - before SSL initialization (0) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Server before SSL initialization (0) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [PINIT] - Server before SSL initialization (0) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCH] - Server SSLv3/TLS read client hello (20) Fri Apr 12 11:37:40 2024 : Debug: (0) Server preferred ciphers (by priority) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [0] TLS_AES_256_GCM_SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [2] TLS_AES_128_GCM_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [13] ECDHE-RSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [14] DHE-RSA-AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [16] ECDHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [17] DHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [18] ECDHE-ECDSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [19] ECDHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [20] DHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [21] ECDHE-ECDSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [22] ECDHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [23] DHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [24] RSA-PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [25] DHE-PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [26] RSA-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [27] DHE-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [28] ECDHE-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [29] AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [30] PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [31] PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [32] RSA-PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [33] DHE-PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [34] AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [35] PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [36] AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [37] AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [38] ECDHE-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [39] ECDHE-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [40] SRP-RSA-AES-256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [41] SRP-AES-256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [42] RSA-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [43] DHE-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [44] RSA-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [45] DHE-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [46] AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [47] PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [48] PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [49] ECDHE-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [50] ECDHE-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [51] SRP-RSA-AES-128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [52] SRP-AES-128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [53] RSA-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [54] DHE-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [55] RSA-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [56] DHE-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [57] AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [58] PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [59] PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Client preferred ciphers (by priority) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [0] TLS_AES_256_GCM_SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [2] TLS_AES_128_GCM_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [13] ECDHE-RSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [14] DHE-RSA-AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [16] ECDHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [17] DHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [18] ECDHE-ECDSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [19] ECDHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [20] DHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [21] ECDHE-ECDSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [22] ECDHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [23] DHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [24] AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [25] AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [26] AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [27] AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [28] AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [29] AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWSH] - Server SSLv3/TLS write server hello (22) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 ChangeCipherSpec Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCCS] - Server SSLv3/TLS write change cipher spec (35) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TED] - Server TLSv1.3 early data (46) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - In Handshake Phase Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS- got 99 bytes of data Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Writing to socket 15 Fri Apr 12 11:37:40 2024 : Debug: Waking up in 0.5 seconds. Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Reading from socket 15 READ FROM SSL 332 00: 14 03 03 00 01 01 16 03 03 01 41 01 00 01 3d 03 10: 03 75 3d 57 c6 3f 52 14 34 62 0e b8 f0 4d 75 15 20: 07 8b 40 31 d0 31 d3 19 c7 a9 10 15 9c 26 a5 98 30: c3 20 45 ce d9 43 af f9 f0 dc d8 da d2 18 50 1a 40: c7 37 b2 d9 22 2b a8 dd f1 fd ea f0 b3 52 8e d6 50: 8d 36 00 3e 13 02 13 03 13 01 c0 2c c0 30 00 9f 60: cc a9 cc a8 cc aa c0 2b c0 2f 00 9e c0 24 c0 28 70: 00 6b c0 23 c0 27 00 67 c0 0a c0 14 00 39 c0 09 80: c0 13 00 33 00 9d 00 9c 00 3d 00 3c 00 35 00 2f 90: 00 ff 01 00 00 b6 00 0b 00 04 03 00 01 02 00 0a a0: 00 16 00 14 00 1d 00 17 00 1e 00 19 00 18 01 00 b0: 01 01 01 02 01 03 01 04 00 23 00 00 00 16 00 00 c0: 00 17 00 00 00 0d 00 2a 00 28 04 03 05 03 06 03 d0: 08 07 08 08 08 09 08 0a 08 0b 08 04 08 05 08 06 e0: 04 01 05 01 06 01 03 03 03 01 03 02 04 02 05 02 f0: 06 02 00 2b 00 05 04 03 04 03 03 00 2d 00 02 01 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TED] - Server TLSv1.3 early data (46) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, ClientHello Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCH] - Server SSLv3/TLS read client hello (20) Fri Apr 12 11:37:40 2024 : Debug: (0) Server preferred ciphers (by priority) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [0] TLS_AES_256_GCM_SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [2] TLS_AES_128_GCM_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [13] ECDHE-RSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [14] DHE-RSA-AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [16] ECDHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [17] DHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [18] ECDHE-ECDSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [19] ECDHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [20] DHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [21] ECDHE-ECDSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [22] ECDHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [23] DHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [24] RSA-PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [25] DHE-PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [26] RSA-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [27] DHE-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [28] ECDHE-PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [29] AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [30] PSK-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [31] PSK-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [32] RSA-PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [33] DHE-PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [34] AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [35] PSK-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [36] AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [37] AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [38] ECDHE-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [39] ECDHE-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [40] SRP-RSA-AES-256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [41] SRP-AES-256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [42] RSA-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [43] DHE-PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [44] RSA-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [45] DHE-PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [46] AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [47] PSK-AES256-CBC-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [48] PSK-AES256-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [49] ECDHE-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [50] ECDHE-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [51] SRP-RSA-AES-128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [52] SRP-AES-128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [53] RSA-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [54] DHE-PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [55] RSA-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [56] DHE-PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [57] AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [58] PSK-AES128-CBC-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [59] PSK-AES128-CBC-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Client preferred ciphers (by priority) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [0] TLS_AES_256_GCM_SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [2] TLS_AES_128_GCM_SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [13] ECDHE-RSA-AES256-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [14] DHE-RSA-AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [16] ECDHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [17] DHE-RSA-AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [18] ECDHE-ECDSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [19] ECDHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [20] DHE-RSA-AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [21] ECDHE-ECDSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [22] ECDHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [23] DHE-RSA-AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [24] AES256-GCM-SHA384 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [25] AES128-GCM-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [26] AES256-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [27] AES128-SHA256 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [28] AES256-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) [29] AES128-SHA Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, ServerHello Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWSH] - Server SSLv3/TLS write server hello (22) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, EncryptedExtensions Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWEE] - Server TLSv1.3 write encrypted extensions (37) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateRequest Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWCR] - Server SSLv3/TLS write certificate request (25) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Certificate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWSC] - Server SSLv3/TLS write certificate (23) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, CertificateVerify Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWSCV] - Server TLSv1.3 write server certificate verify (40) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - send TLS 1.3 Handshake, Finished Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TWFIN] - Server SSLv3/TLS write finished (36) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TED] - Server TLSv1.3 early data (46) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Server : Need to read more data: TLSv1.3 early data Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - In Handshake Phase Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS- got 3766 bytes of data Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Writing to socket 15 Fri Apr 12 11:37:40 2024 : Debug: Waking up in 0.5 seconds. Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Reading from socket 15 READ FROM SSL 2015 00: 17 03 03 05 72 13 de d6 3a d5 10 82 88 8b 91 e4 10: 37 8f fa c0 7c 25 dc d3 32 22 bd ca 7c 9e 73 29 20: 7f 52 f3 1d 97 18 d0 48 18 34 9a 8f c1 1f 71 88 30: d4 be a9 4b 6f b3 48 77 3c 1a ab 5c af c9 f1 2c 40: c4 1c 4b 1d 8a d3 8e e8 18 0a bc 2b 18 fc 3c 2a 50: 34 51 d3 dc 0d 8c 69 99 21 a8 92 f4 4f 46 f7 b0 60: b0 2a 58 6c 02 1d 2e 98 2f 69 09 4e d9 ac 4d 8f 70: 4e 7f 73 1f 9d 76 3d 1d ac ef f2 05 a0 c4 42 f6 80: d6 ae a4 12 95 4b 92 ab 81 e8 9d 3a d7 fc 92 ca 90: f7 01 0d 07 28 57 66 cc 43 81 ea 7a 4c 3a 6e 80 a0: ed 9f 22 d6 27 98 49 ce c4 34 0f aa b2 7f 0c 2c b0: 06 58 13 9f de bd df 3e 22 36 e6 20 c8 16 56 49 c0: 96 89 2e 26 83 22 23 ba 49 58 df 55 6d 8d 86 1a d0: 3d 31 97 5a fe de 47 da f4 62 97 9e b7 b0 5a 0c e0: 9e 4c a5 69 26 2f 8e 68 ff 18 a9 b4 26 4f f9 10 f0: 5c fb 0c e4 3a 63 74 66 cc 88 fc 4b d8 d2 85 3c Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TED] - Server TLSv1.3 early data (46) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Certificate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Creating attributes from client certificate Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Serial := "2aef75f0ea7f49c68b28781d7a6a2ff9" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Expiration := "340208105559Z" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Valid-Since := "240208104559Z" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Subject := "/CN=BoilerPlate" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Issuer := "/CN=BoilerPlate" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Common-Name := "BoilerPlate" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-Subject-Alt-Name-Dns := "radius.BoilerPlate.net" Fri Apr 12 11:37:40 2024 : Debug: (0) Skipping TLS-Client-Cert-X509v3-Key-Usage += 'Digital Signature, Key Encipherment, Certificate Sign'. Please check that both the attribute and value are defined in the dictionaries Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-X509v3-Basic-Constraints += "CA:FALSE" Fri Apr 12 11:37:40 2024 : Debug: (0) Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:radius.BoilerPlate.net'. Please check that both the attribute and value are defined in the dictionaries Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-X509v3-Authority-Key-Identifier += "73:D2:45:9F:1A:5B:BB:04:31:0D:2B:52:A8:66:F9:72:EB:12:D1:54" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Client-Cert-X509v3-Subject-Key-Identifier += "73:D2:45:9F:1A:5B:BB:04:31:0D:2B:52:A8:66:F9:72:EB:12:D1:54" Fri Apr 12 11:37:40 2024 : Warning: Certificate chain - 0 intermediate CA cert(s) untrusted Fri Apr 12 11:37:40 2024 : Warning: To forbid these certificates see 'reject_unknown_intermediate_ca' Fri Apr 12 11:37:40 2024 : Warning: (TLS) untrusted certificate with depth [0] subject name /CN=BoilerPlate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) chain-depth : 0 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) error : 0 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) common name : BoilerPlate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) subject : /CN=BoilerPlate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) issuer : /CN=BoilerPlate Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) verify return : 1 Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCC] - Server SSLv3/TLS read client certificate (27) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, CertificateVerify Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRCV] - Server SSLv3/TLS read certificate verify (29) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - recv TLS 1.3 Handshake, Finished Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [TRFIN] - Server SSLv3/TLS read finished (32) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Handshake state [SSLOK] - SSL negotiation finished successfully (1) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Connection Established Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Session-Cipher-Suite = "TLS_AES_256_GCM_SHA384" Fri Apr 12 11:37:40 2024 : Debug: (0) TLS-Session-Version = "TLS 1.3" Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) RADIUS/TLS - Application data. Fri Apr 12 11:37:40 2024 : Debug: Threads: total/active/spare threads = 5/0/5 Fri Apr 12 11:37:40 2024 : Debug: Waking up in 0.3 seconds. Fri Apr 12 11:37:40 2024 : Debug: Thread 5 got semaphore Fri Apr 12 11:37:40 2024 : Debug: Thread 5 handling request 0, (1 handled so far) Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Checking connection to see if it is authorized. Fri Apr 12 11:37:40 2024 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Fri Apr 12 11:37:40 2024 : Debug: (0) Autz-Type New-TLS-Connection { Fri Apr 12 11:37:40 2024 : Debug: (0) modsingle[authorize]: calling ok (rlm_always) Fri Apr 12 11:37:40 2024 : Debug: (0) modsingle[authorize]: returned from ok (rlm_always) Fri Apr 12 11:37:40 2024 : Debug: (0) [ok] = ok Fri Apr 12 11:37:40 2024 : Debug: (0) } # Autz-Type New-TLS-Connection = ok Fri Apr 12 11:37:40 2024 : Debug: (0) (TLS) Connection is authorized Fri Apr 12 11:37:40 2024 : Debug: (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:33537 length 0 Fri Apr 12 11:37:40 2024 : Debug: (0) Finished request Fri Apr 12 11:37:40 2024 : Debug: Thread 5 waiting to be assigned a request Fri Apr 12 11:37:40 2024 : Debug: Waking up in 0.1 seconds. Fri Apr 12 11:37:41 2024 : Debug: Waking up in 4.4 seconds. Fri Apr 12 11:37:45 2024 : Debug: (0) Cleaning up request packet ID 4294967295 with timestamp +5 due to cleanup_delay was reached Fri Apr 12 11:37:45 2024 : Info: Ready to process requests ``` Netstat output: ``` Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 0.0.0.0:2083 0.0.0.0:* LISTEN 99/radiusd tcp 468 0 a11e1a6f10a3:2083 192.168.215.1:33537 ESTABLISHED 99/radiusd udp 0 0 0.0.0.0:54130 0.0.0.0:* 99/radiusd udp 0 0 localhost:18120 0.0.0.0:* 99/radiusd udp 0 0 0.0.0.0:radius 0.0.0.0:* 99/radiusd udp 0 0 0.0.0.0:radius-acct 0.0.0.0:* 99/radiusd udp6 0 0 [::]:radius [::]:* 99/radiusd udp6 0 0 [::]:radius-acct [::]:* 99/radiusd ``` - Lineconnect
On Apr 12, 2024, at 8:05 AM, nabble@felix.world wrote:
I've pushed some more debug messages to the v3.2.x branch which may help track down what's going on. Can you try that?
Sure. Since threading is needed for RadSec I was not able to start the server with -Xx and used -fxxx. But since I can’t find the messages which you’ve included I’m not sure if those two args are equal.
That's fine. If the new messages aren't being printed, then that code isn't being run. Which explains why the server never reads from the socket. Please try this patch. If it works, I'll push ti to GitHub.
Hmm could you point me to the patch? There was no mail attachment and as said it’s not on GitHub yet and I don’t know where to look.
On 12. Apr 2024, at 14:56, Alan DeKok <aland@deployingradius.com> wrote:
On Apr 12, 2024, at 8:05 AM, nabble@felix.world wrote:
I've pushed some more debug messages to the v3.2.x branch which may help track down what's going on. Can you try that?
Sure. Since threading is needed for RadSec I was not able to start the server with -Xx and used -fxxx. But since I can’t find the messages which you’ve included I’m not sure if those two args are equal.
That's fine.
If the new messages aren't being printed, then that code isn't being run. Which explains why the server never reads from the socket.
Please try this patch. If it works, I'll push ti to GitHub.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
That worked! Now the requests are coming through. Thanks! One thing to mention is that every time, the radsec client connects, there is one new error. hread 4 got semaphore Thread 4 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) ERROR: Failed signing packet: ERROR: RADIUS packets must be assigned an Id (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:32993 length 20 (0) Finished request Thread 4 waiting to be assigned a request Waking up in 0.2 seconds. Waking up in 4.6 seconds. - Lineconnect
Thanks. I've pushed the patch, and another one-line fix which stops that error.
On Apr 12, 2024, at 11:36 AM, nabble@felix.world wrote:
That worked! Now the requests are coming through. Thanks!
One thing to mention is that every time, the radsec client connects, there is one new error.
hread 4 got semaphore Thread 4 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) ERROR: Failed signing packet: ERROR: RADIUS packets must be assigned an Id (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:32993 length 20 (0) Finished request Thread 4 waiting to be assigned a request Waking up in 0.2 seconds. Waking up in 4.6 seconds.
- Lineconnect
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi there, We’ve some productive instances which experience the same issue but only after a certain time. Therefore I’m currently not able to reproduce it reliably but it’s visible that the Recv-Q is getting bigger and bigger. root@radius-d6674b64-xt6x4:/# netstat -ap Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 9 0 0.0.0.0:2083 0.0.0.0:* LISTEN 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35878 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39682 CLOSE_WAIT 1/radiusd tcp 236288 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37974 ESTABLISHED 1/radiusd tcp 442 0 radius-d6674b64-xt:2083 10-244-25-182.tra:40226 CLOSE_WAIT 1/radiusd tcp 298 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39460 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33402 CLOSE_WAIT - tcp 6404 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33096 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51816 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39432 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59936 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58720 CLOSE_WAIT 1/radiusd tcp 199 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33400 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59178 CLOSE_WAIT - tcp 8023 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51882 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57698 CLOSE_WAIT 1/radiusd tcp 6765 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37272 CLOSE_WAIT 1/radiusd tcp 258034 0 radius-d6674b64-xt:2083 10-244-25-182.tra:55148 ESTABLISHED 1/radiusd tcp 247 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58998 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49494 CLOSE_WAIT 1/radiusd tcp 1 0 radius-d6674b64-x:38118 20.50.2.37:http CLOSE_WAIT 1/radiusd tcp 5736 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39550 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57830 CLOSE_WAIT - tcp 19335 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57654 CLOSE_WAIT 1/radiusd tcp 994 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35026 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:47572 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49282 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59172 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35852 CLOSE_WAIT 1/radiusd udp 0 0 localhost:18120 0.0.0.0:* 1/radiusd Active UNIX domain sockets (servers and established) Proto RefCnt Flags Type State I-Node PID/Program name Path unix 3 [ ] STREAM CONNECTED 498007517 1/radiusd unix 3 [ ] STREAM CONNECTED 498007516 1/radiusd I know it's cheeky to ask this without a reproducible test, but the last time there was an obvious error, so I wanted to ask if you could look at it? I fully understand if not. — Lineconnect
On 12. Apr 2024, at 18:05, Alan DeKok <aland@deployingradius.com> wrote:
Thanks. I've pushed the patch, and another one-line fix which stops that error.
On Apr 12, 2024, at 11:36 AM, nabble@felix.world wrote:
That worked! Now the requests are coming through. Thanks!
One thing to mention is that every time, the radsec client connects, there is one new error.
hread 4 got semaphore Thread 4 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) ERROR: Failed signing packet: ERROR: RADIUS packets must be assigned an Id (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:32993 length 20 (0) Finished request Thread 4 waiting to be assigned a request Waking up in 0.2 seconds. Waking up in 4.6 seconds.
- Lineconnect
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
I assume you have checked some obvious things: 1. Request Rate isn’t hugely spiky, but the average rate is completely within the capability of the server to respond. If it is there is not much you can do except ensure the backlog queues are big enough to handle it without the max latency getting > request timeout. 2. Response Rate = Request Rate. Obvious really if response rate is the same you likely haven’t got an immediate issue but perhaps time to start optimising things. In absence of (1) queues are the sign that you are starting to get close to the ‘hocky sticky’ in a throughput vs latency graph. 3. Bad Clients (many ignore the random geometric back-off so if you reject they come back immediately again and again). If that’s the case, it may be useful to cache rejects so you can reduce the ‘cost’ of those requests. Also look to see if the sending device can limit such request hammering at source rather than ‘causing’ issues. Now… My educated guess there is a database or similar that’s blocking threads sooner of later that ends up with the input side queuing data. Note that THROUGHPUT is almost totally dominated by LATENCY of a request. Assuming all resources have capacity spare (eg CPU, NIC, etc) then throughput is simply (1/latency per request)*threads. This starts to become non-linear quite quickly because you nearly always become contended on something like I/O kernel calls. Graphed this will look like a hockey stick (graph latency against request rate), first linear growth with tiny latency increases until you start hitting the limits. At this point a tiny increase in request/s causes a vast change in latency. With limits on queueing or timeouts this can end up with total meltdown where response rates actually drop and things don’t get better. From: Freeradius-Users <freeradius-users-bounces+alister.winfield=sky.uk@lists.freeradius.org> on behalf of nabble@felix.world <nabble@felix.world> Date: Wednesday, 18 December 2024 at 11:35 To: FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Subject: [EXTERNAL] Re: No auth requests through TLS tunnel if connection was checked Hi there, We’ve some productive instances which experience the same issue but only after a certain time. Therefore I’m currently not able to reproduce it reliably but it’s visible that the Recv-Q is getting bigger and bigger. root@radius-d6674b64-xt6x4:/# netstat -ap Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 9 0 0.0.0.0:2083 0.0.0.0:* LISTEN 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35878 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39682 CLOSE_WAIT 1/radiusd tcp 236288 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37974 ESTABLISHED 1/radiusd tcp 442 0 radius-d6674b64-xt:2083 10-244-25-182.tra:40226 CLOSE_WAIT 1/radiusd tcp 298 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39460 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33402 CLOSE_WAIT - tcp 6404 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33096 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51816 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39432 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59936 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58720 CLOSE_WAIT 1/radiusd tcp 199 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33400 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59178 CLOSE_WAIT - tcp 8023 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51882 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57698 CLOSE_WAIT 1/radiusd tcp 6765 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37272 CLOSE_WAIT 1/radiusd tcp 258034 0 radius-d6674b64-xt:2083 10-244-25-182.tra:55148 ESTABLISHED 1/radiusd tcp 247 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58998 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49494 CLOSE_WAIT 1/radiusd tcp 1 0 radius-d6674b64-x:38118 20.50.2.37:http CLOSE_WAIT 1/radiusd tcp 5736 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39550 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57830 CLOSE_WAIT - tcp 19335 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57654 CLOSE_WAIT 1/radiusd tcp 994 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35026 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:47572 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49282 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59172 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35852 CLOSE_WAIT 1/radiusd udp 0 0 localhost:18120 0.0.0.0:* 1/radiusd Active UNIX domain sockets (servers and established) Proto RefCnt Flags Type State I-Node PID/Program name Path unix 3 [ ] STREAM CONNECTED 498007517 1/radiusd unix 3 [ ] STREAM CONNECTED 498007516 1/radiusd I know it's cheeky to ask this without a reproducible test, but the last time there was an obvious error, so I wanted to ask if you could look at it? I fully understand if not. — Lineconnect
On 12. Apr 2024, at 18:05, Alan DeKok <aland@deployingradius.com> wrote:
Thanks. I've pushed the patch, and another one-line fix which stops that error.
On Apr 12, 2024, at 11:36 AM, nabble@felix.world wrote:
That worked! Now the requests are coming through. Thanks!
One thing to mention is that every time, the radsec client connects, there is one new error.
hread 4 got semaphore Thread 4 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) ERROR: Failed signing packet: ERROR: RADIUS packets must be assigned an Id (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:32993 length 20 (0) Finished request Thread 4 waiting to be assigned a request Waking up in 0.2 seconds. Waking up in 4.6 seconds.
- Lineconnect
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html -------------------------------------------------------------------- This email is from an external source. Please do not open attachments or click links from an unknown or suspicious origin. Phishing attempts can be reported by using the report message button in Outlook or sending them as an attachment to phishing@sky.uk. Thank you -------------------------------------------------------------------- Information in this email including any attachments may be privileged, confidential and is intended exclusively for the addressee. The views expressed may not be official policy, but the personal views of the originator. If you have received it in error, please notify the sender by return e-mail and delete it from your system. You should not reproduce, distribute, store, retransmit, use or disclose its contents to anyone. Please note we reserve the right to monitor all e-mail communication through our internal and external networks. SKY and the SKY marks are trademarks of Sky Limited and Sky International AG and are used under licence. Sky UK Limited (Registration No. 2906991), Sky-In-Home Service Limited (Registration No. 2067075), Sky Subscribers Services Limited (Registration No. 2340150) and Sky CP Limited (Registration No. 9513259) are direct or indirect subsidiaries of Sky Limited (Registration No. 2247735). All of the companies mentioned in this paragraph are incorporated in England and Wales and share the same registered office at Grant Way, Isleworth, Middlesex TW7 5QD
Thanks for your input. Yes I’ve checked it. The request rate is nearly zero ( 10 Authentications every 2 minutes ) and there is no database connection at all. The issue get’s resolved when we disable `check_client_connections` in the TLS server. We use `check_client_connections` to do some certificate revocations checks with the python module and I’ve also checked that this script is not blocking something and there is no open process which is blocking further processing. And there was an issue (where this thread was opened with) that the connection was accepted but the socket just don’t reads the data from it which is why I assumed that the issue got back with the changes for BLAST RADIUS. Also there is currently an open issue that the server segfaults with `check_client_connections` enabled https://github.com/FreeRADIUS/freeradius-server/issues/5480. I assume that not many out there use this functionality which is why no other reported it. The only difference now is that it’s not a general problem but happens after a while. — Lineconnect
On 18. Dec 2024, at 16:28, Winfield, Alister (Senior Solutions Architect) via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I assume you have checked some obvious things:
1. Request Rate isn’t hugely spiky, but the average rate is completely within the capability of the server to respond. If it is there is not much you can do except ensure the backlog queues are big enough to handle it without the max latency getting > request timeout. 2. Response Rate = Request Rate. Obvious really if response rate is the same you likely haven’t got an immediate issue but perhaps time to start optimising things. In absence of (1) queues are the sign that you are starting to get close to the ‘hocky sticky’ in a throughput vs latency graph. 3. Bad Clients (many ignore the random geometric back-off so if you reject they come back immediately again and again). If that’s the case, it may be useful to cache rejects so you can reduce the ‘cost’ of those requests. Also look to see if the sending device can limit such request hammering at source rather than ‘causing’ issues.
Now…
My educated guess there is a database or similar that’s blocking threads sooner of later that ends up with the input side queuing data.
Note that THROUGHPUT is almost totally dominated by LATENCY of a request.
Assuming all resources have capacity spare (eg CPU, NIC, etc) then throughput is simply (1/latency per request)*threads. This starts to become non-linear quite quickly because you nearly always become contended on something like I/O kernel calls. Graphed this will look like a hockey stick (graph latency against request rate), first linear growth with tiny latency increases until you start hitting the limits. At this point a tiny increase in request/s causes a vast change in latency. With limits on queueing or timeouts this can end up with total meltdown where response rates actually drop and things don’t get better.
From: Freeradius-Users <freeradius-users-bounces+alister.winfield=sky.uk@lists.freeradius.org> on behalf of nabble@felix.world <nabble@felix.world> Date: Wednesday, 18 December 2024 at 11:35 To: FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Subject: [EXTERNAL] Re: No auth requests through TLS tunnel if connection was checked Hi there,
We’ve some productive instances which experience the same issue but only after a certain time. Therefore I’m currently not able to reproduce it reliably but it’s visible that the Recv-Q is getting bigger and bigger.
root@radius-d6674b64-xt6x4:/# netstat -ap Active Internet connections (servers and established) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 9 0 0.0.0.0:2083 0.0.0.0:* LISTEN 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35878 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39682 CLOSE_WAIT 1/radiusd tcp 236288 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37974 ESTABLISHED 1/radiusd tcp 442 0 radius-d6674b64-xt:2083 10-244-25-182.tra:40226 CLOSE_WAIT 1/radiusd tcp 298 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39460 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33402 CLOSE_WAIT - tcp 6404 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33096 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51816 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39432 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59936 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58720 CLOSE_WAIT 1/radiusd tcp 199 0 radius-d6674b64-xt:2083 10-244-25-182.tra:33400 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59178 CLOSE_WAIT - tcp 8023 0 radius-d6674b64-xt:2083 10-244-25-182.tra:51882 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57698 CLOSE_WAIT 1/radiusd tcp 6765 0 radius-d6674b64-xt:2083 10-244-25-182.tra:37272 CLOSE_WAIT 1/radiusd tcp 258034 0 radius-d6674b64-xt:2083 10-244-25-182.tra:55148 ESTABLISHED 1/radiusd tcp 247 0 radius-d6674b64-xt:2083 10-244-25-182.tra:58998 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49494 CLOSE_WAIT 1/radiusd tcp 1 0 radius-d6674b64-x:38118 20.50.2.37:http CLOSE_WAIT 1/radiusd tcp 5736 0 radius-d6674b64-xt:2083 10-244-25-182.tra:39550 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57830 CLOSE_WAIT - tcp 19335 0 radius-d6674b64-xt:2083 10-244-25-182.tra:57654 CLOSE_WAIT 1/radiusd tcp 994 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35026 CLOSE_WAIT 1/radiusd tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:47572 CLOSE_WAIT 1/radiusd tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:49282 CLOSE_WAIT - tcp 326 0 radius-d6674b64-xt:2083 10-244-25-182.tra:59172 CLOSE_WAIT - tcp 85 0 radius-d6674b64-xt:2083 10-244-25-182.tra:35852 CLOSE_WAIT 1/radiusd udp 0 0 localhost:18120 0.0.0.0:* 1/radiusd Active UNIX domain sockets (servers and established) Proto RefCnt Flags Type State I-Node PID/Program name Path unix 3 [ ] STREAM CONNECTED 498007517 1/radiusd unix 3 [ ] STREAM CONNECTED 498007516 1/radiusd
I know it's cheeky to ask this without a reproducible test, but the last time there was an obvious error, so I wanted to ask if you could look at it? I fully understand if not.
— Lineconnect
On 12. Apr 2024, at 18:05, Alan DeKok <aland@deployingradius.com> wrote:
Thanks. I've pushed the patch, and another one-line fix which stops that error.
On Apr 12, 2024, at 11:36 AM, nabble@felix.world wrote:
That worked! Now the requests are coming through. Thanks!
One thing to mention is that every time, the radsec client connects, there is one new error.
hread 4 got semaphore Thread 4 handling request 0, (1 handled so far) (0) (TLS) Checking connection to see if it is authorized. (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (0) Autz-Type New-TLS-Connection { (0) [ok] = ok (0) } # Autz-Type New-TLS-Connection = ok (0) (TLS) Connection is authorized (0) ERROR: Failed signing packet: ERROR: RADIUS packets must be assigned an Id (0) Sent Access-Accept Id 4294967295 from 0.0.0.0:2083 to 192.168.215.1:32993 length 20 (0) Finished request Thread 4 waiting to be assigned a request Waking up in 0.2 seconds. Waking up in 4.6 seconds.
- Lineconnect
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html -------------------------------------------------------------------- This email is from an external source. Please do not open attachments or click links from an unknown or suspicious origin. Phishing attempts can be reported by using the report message button in Outlook or sending them as an attachment to phishing@sky.uk. Thank you -------------------------------------------------------------------- Information in this email including any attachments may be privileged, confidential and is intended exclusively for the addressee. The views expressed may not be official policy, but the personal views of the originator. If you have received it in error, please notify the sender by return e-mail and delete it from your system. You should not reproduce, distribute, store, retransmit, use or disclose its contents to anyone. Please note we reserve the right to monitor all e-mail communication through our internal and external networks. SKY and the SKY marks are trademarks of Sky Limited and Sky International AG and are used under licence.
Sky UK Limited (Registration No. 2906991), Sky-In-Home Service Limited (Registration No. 2067075), Sky Subscribers Services Limited (Registration No. 2340150) and Sky CP Limited (Registration No. 9513259) are direct or indirect subsidiaries of Sky Limited (Registration No. 2247735). All of the companies mentioned in this paragraph are incorporated in England and Wales and share the same registered office at Grant Way, Isleworth, Middlesex TW7 5QD - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Dec 19, 2024, at 3:14 AM, nabble@felix.world wrote:
The issue get’s resolved when we disable `check_client_connections` in the TLS server.
I've pushed changes to the v3.2.x branch which address this issue. Please download that and try it. Alan DeKok.
participants (3)
-
Alan DeKok -
nabble＠felix.world -
Winfield, Alister (Senior Solutions Architect)