root@CAMKHLNCNF0FM5H:/home/zzjlr7# radiusd -xX Tue Jul 26 16:45:23 2022 : Debug: Server was built with: Tue Jul 26 16:45:23 2022 : Debug: accounting : yes Tue Jul 26 16:45:23 2022 : Debug: authentication : yes Tue Jul 26 16:45:23 2022 : Debug: ascend-binary-attributes : yes Tue Jul 26 16:45:23 2022 : Debug: coa : yes Tue Jul 26 16:45:23 2022 : Debug: recv-coa-from-home-server : yes Tue Jul 26 16:45:23 2022 : Debug: control-socket : yes Tue Jul 26 16:45:23 2022 : Debug: detail : yes Tue Jul 26 16:45:23 2022 : Debug: dhcp : yes Tue Jul 26 16:45:23 2022 : Debug: dynamic-clients : yes Tue Jul 26 16:45:23 2022 : Debug: osfc2 : no Tue Jul 26 16:45:23 2022 : Debug: proxy : yes Tue Jul 26 16:45:23 2022 : Debug: regex-pcre : yes Tue Jul 26 16:45:23 2022 : Debug: regex-posix : no Tue Jul 26 16:45:23 2022 : Debug: regex-posix-extended : no Tue Jul 26 16:45:23 2022 : Debug: session-management : yes Tue Jul 26 16:45:23 2022 : Debug: stats : yes Tue Jul 26 16:45:23 2022 : Debug: systemd : no Tue Jul 26 16:45:23 2022 : Debug: tcp : yes Tue Jul 26 16:45:23 2022 : Debug: threads : yes Tue Jul 26 16:45:23 2022 : Debug: tls : yes Tue Jul 26 16:45:23 2022 : Debug: unlang : yes Tue Jul 26 16:45:23 2022 : Debug: vmps : yes Tue Jul 26 16:45:23 2022 : Debug: developer : no Tue Jul 26 16:45:23 2022 : Debug: Server core libs: Tue Jul 26 16:45:23 2022 : Debug: freeradius-server : 3.2.0 Tue Jul 26 16:45:23 2022 : Debug: talloc : 2.1.* Tue Jul 26 16:45:23 2022 : Debug: ssl : 1.1.1 release Tue Jul 26 16:45:23 2022 : Debug: pcre : 8.39 2016-06-14 Tue Jul 26 16:45:23 2022 : Debug: Endianness: Tue Jul 26 16:45:23 2022 : Debug: little Tue Jul 26 16:45:23 2022 : Debug: Compilation flags: Tue Jul 26 16:45:23 2022 : Debug: cppflags : Tue Jul 26 16:45:23 2022 : Debug: cflags : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -Wno-date-time -g -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Tue Jul 26 16:45:23 2022 : Debug: ldflags : Tue Jul 26 16:45:23 2022 : Debug: libs : -lcrypto -lssl -ltalloc -latomic -lpcre -lnsl -lresolv -ldl -lpthread Tue Jul 26 16:45:23 2022 : Debug: Tue Jul 26 16:45:23 2022 : Info: FreeRADIUS Version 3.2.0 Tue Jul 26 16:45:23 2022 : Info: Copyright (C) 1999-2021 The FreeRADIUS server project and contributors Tue Jul 26 16:45:23 2022 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Jul 26 16:45:23 2022 : Info: PARTICULAR PURPOSE Tue Jul 26 16:45:23 2022 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Jul 26 16:45:23 2022 : Info: GNU General Public License Tue Jul 26 16:45:23 2022 : Info: For more information about these matters, see the file named COPYRIGHT Tue Jul 26 16:45:23 2022 : Info: Starting - reading configuration files ... Tue Jul 26 16:45:23 2022 : Debug: including dictionary file /usr/local/share/freeradius/dictionary Tue Jul 26 16:45:23 2022 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.dhcp Tue Jul 26 16:45:23 2022 : Debug: including dictionary file /usr/local/share/freeradius/dictionary.vqp Tue Jul 26 16:45:23 2022 : Debug: including dictionary file /usr/local/etc/raddb/dictionary Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/clients.conf Tue Jul 26 16:45:23 2022 : Debug: including files in directory /usr/local/etc/raddb/mods-enabled/ Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/linelog Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/replicate Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/logintime Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/pap Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/eap Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/date Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/echo Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/radutmp Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/files Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/chap Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/utf8 Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/digest Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expiration Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/mschap Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/detail Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/exec Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unix Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/preprocess Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/soh Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/totp Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/expr Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/passwd Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/mods-enabled/unpack Tue Jul 26 16:45:23 2022 : Debug: including files in directory /usr/local/etc/raddb/policy.d/ Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/operator-name Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/eap Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/accounting Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/dhcp Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/cui Tue Jul 26 16:45:23 2022 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Jul 26 16:45:23 2022 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Jul 26 16:45:23 2022 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Jul 26 16:45:23 2022 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/filter Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/moonshot-targeted-ids Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/control Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/debug Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/abfab-tr Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/rfc7542 Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/policy.d/canonicalization Tue Jul 26 16:45:23 2022 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 26 16:45:23 2022 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:45:23 2022 : Debug: main { Tue Jul 26 16:45:23 2022 : Debug: security { Tue Jul 26 16:45:23 2022 : Debug: allow_core_dumps = no Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[536]: The item 'max_attributes' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[553]: The item 'reject_delay' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[573]: The item 'status_server' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[583]: The item 'allow_vulnerable_openssl' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: name = "radiusd" Tue Jul 26 16:45:23 2022 : Debug: prefix = "/usr/local" Tue Jul 26 16:45:23 2022 : Debug: localstatedir = "/usr/local/var" Tue Jul 26 16:45:23 2022 : Debug: logdir = "/usr/local/var/log/radius" Tue Jul 26 16:45:23 2022 : Debug: run_dir = "/usr/local/var/run/radiusd" Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[138]: The item 'libdir' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[149]: The item 'pidfile' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[203]: The item 'max_request_time' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[222]: The item 'cleanup_delay' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[259]: The item 'hostname_lookups' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[392]: The item 'checkrad' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[602]: The item 'proxy_requests' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: main { Tue Jul 26 16:45:23 2022 : Debug: name = "radiusd" Tue Jul 26 16:45:23 2022 : Debug: prefix = "/usr/local" Tue Jul 26 16:45:23 2022 : Debug: localstatedir = "/usr/local/var" Tue Jul 26 16:45:23 2022 : Debug: sbindir = "/usr/local/sbin" Tue Jul 26 16:45:23 2022 : Debug: logdir = "/usr/local/var/log/radius" Tue Jul 26 16:45:23 2022 : Debug: run_dir = "/usr/local/var/run/radiusd" Tue Jul 26 16:45:23 2022 : Debug: libdir = "/usr/local/lib" Tue Jul 26 16:45:23 2022 : Debug: radacctdir = "/usr/local/var/log/radius/radacct" Tue Jul 26 16:45:23 2022 : Debug: hostname_lookups = no Tue Jul 26 16:45:23 2022 : Debug: max_request_time = 30 Tue Jul 26 16:45:23 2022 : Debug: cleanup_delay = 5 Tue Jul 26 16:45:23 2022 : Debug: max_requests = 16384 Tue Jul 26 16:45:23 2022 : Debug: postauth_client_lost = no Tue Jul 26 16:45:23 2022 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid" Tue Jul 26 16:45:23 2022 : Debug: checkrad = "/usr/local/sbin/checkrad" Tue Jul 26 16:45:23 2022 : Debug: debug_level = 0 Tue Jul 26 16:45:23 2022 : Debug: proxy_requests = yes Tue Jul 26 16:45:23 2022 : Debug: log { Tue Jul 26 16:45:23 2022 : Debug: stripped_names = no Tue Jul 26 16:45:23 2022 : Debug: auth = no Tue Jul 26 16:45:23 2022 : Debug: auth_badpass = no Tue Jul 26 16:45:23 2022 : Debug: auth_goodpass = no Tue Jul 26 16:45:23 2022 : Debug: colourise = yes Tue Jul 26 16:45:23 2022 : Debug: msg_denied = "You are already logged in - access denied" Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[288]: The item 'destination' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[305]: The item 'file' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[313]: The item 'syslog_facility' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: resources { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: security { Tue Jul 26 16:45:23 2022 : Debug: max_attributes = 200 Tue Jul 26 16:45:23 2022 : Debug: reject_delay = 1.000000 Tue Jul 26 16:45:23 2022 : Debug: status_server = yes Tue Jul 26 16:45:23 2022 : Debug: allow_vulnerable_openssl = "no" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Warning: /usr/local/etc/raddb/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Jul 26 16:45:23 2022 : Debug: proxy server { Tue Jul 26 16:45:23 2022 : Debug: retry_delay = 5 Tue Jul 26 16:45:23 2022 : Debug: retry_count = 3 Tue Jul 26 16:45:23 2022 : Debug: default_fallback = no Tue Jul 26 16:45:23 2022 : Debug: dead_time = 120 Tue Jul 26 16:45:23 2022 : Debug: wake_all_if_all_dead = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: home_server localhost { Tue Jul 26 16:45:23 2022 : Debug: ipaddr = 127.0.0.1 Tue Jul 26 16:45:23 2022 : Debug: port = 1812 Tue Jul 26 16:45:23 2022 : Debug: type = "auth" Tue Jul 26 16:45:23 2022 : Debug: secret = "testing123" Tue Jul 26 16:45:23 2022 : Debug: response_window = 20.000000 Tue Jul 26 16:45:23 2022 : Debug: response_timeouts = 1 Tue Jul 26 16:45:23 2022 : Debug: max_outstanding = 65536 Tue Jul 26 16:45:23 2022 : Debug: zombie_period = 40 Tue Jul 26 16:45:23 2022 : Debug: status_check = "status-server" Tue Jul 26 16:45:23 2022 : Debug: ping_interval = 30 Tue Jul 26 16:45:23 2022 : Debug: check_interval = 30 Tue Jul 26 16:45:23 2022 : Debug: check_timeout = 4 Tue Jul 26 16:45:23 2022 : Debug: num_answers_to_alive = 3 Tue Jul 26 16:45:23 2022 : Debug: revive_interval = 120 Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: max_requests = 0 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 0 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: coa { Tue Jul 26 16:45:23 2022 : Debug: irt = 2 Tue Jul 26 16:45:23 2022 : Debug: mrt = 16 Tue Jul 26 16:45:23 2022 : Debug: mrc = 5 Tue Jul 26 16:45:23 2022 : Debug: mrd = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: recv_coa { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: home_server_pool my_auth_failover { Tue Jul 26 16:45:23 2022 : Debug: type = fail-over Tue Jul 26 16:45:23 2022 : Debug: home_server = localhost Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: realm example.com { Tue Jul 26 16:45:23 2022 : Debug: auth_pool = my_auth_failover Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: realm LOCAL { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: radiusd: #### Loading Clients #### Tue Jul 26 16:45:23 2022 : Debug: client localhost { Tue Jul 26 16:45:23 2022 : Debug: ipaddr = 127.0.0.1 Tue Jul 26 16:45:23 2022 : Debug: require_message_authenticator = no Tue Jul 26 16:45:23 2022 : Debug: secret = "testing123" Tue Jul 26 16:45:23 2022 : Debug: nas_type = "other" Tue Jul 26 16:45:23 2022 : Debug: proto = "*" Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Tue Jul 26 16:45:23 2022 : Debug: client netgearRAX200 { Tue Jul 26 16:45:23 2022 : Debug: ipaddr = 192.168.1.1 Tue Jul 26 16:45:23 2022 : Debug: require_message_authenticator = no Tue Jul 26 16:45:23 2022 : Debug: secret = "radiuspass2022" Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Adding client 192.168.1.1/32 (192.168.1.1) to prefix tree 32 Tue Jul 26 16:45:23 2022 : Debug: client localhost_ipv6 { Tue Jul 26 16:45:23 2022 : Debug: ipv6addr = ::1 Tue Jul 26 16:45:23 2022 : Debug: require_message_authenticator = no Tue Jul 26 16:45:23 2022 : Debug: secret = "testing123" Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Tue Jul 26 16:45:23 2022 : Info: Debugger not attached Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = mschap Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = eap Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = PAP Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = CHAP Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = MS-CHAP Tue Jul 26 16:45:23 2022 : Debug: # Creating Auth-Type = digest Tue Jul 26 16:45:23 2022 : Debug: # Creating Autz-Type = New-TLS-Connection Tue Jul 26 16:45:23 2022 : Debug: radiusd: #### Instantiating modules #### Tue Jul 26 16:45:23 2022 : Debug: modules { Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_linelog, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_linelog Tue Jul 26 16:45:23 2022 : Debug: # Loading module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Jul 26 16:45:23 2022 : Debug: linelog { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/linelog" Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: syslog_severity = "info" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: format = "This is a log message for %{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Jul 26 16:45:23 2022 : Debug: linelog log_accounting { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/linelog-accounting" Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: syslog_severity = "info" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: format = "" Tue Jul 26 16:45:23 2022 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_replicate, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_replicate Tue Jul 26 16:45:23 2022 : Debug: # Loading module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_logintime, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_logintime Tue Jul 26 16:45:23 2022 : Debug: # Loading module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Tue Jul 26 16:45:23 2022 : Debug: logintime { Tue Jul 26 16:45:23 2022 : Debug: minimum_timeout = 60 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_pap, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_pap Tue Jul 26 16:45:23 2022 : Debug: # Loading module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Tue Jul 26 16:45:23 2022 : Debug: pap { Tue Jul 26 16:45:23 2022 : Debug: normalise = yes Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_detail, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_detail Tue Jul 26 16:45:23 2022 : Debug: # Loading module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: detail auth_log { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Tue Jul 26 16:45:23 2022 : Debug: header = "%t" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: locking = no Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: log_packet_header = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: detail reply_log { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Tue Jul 26 16:45:23 2022 : Debug: header = "%t" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: locking = no Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: log_packet_header = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: detail pre_proxy_log { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Tue Jul 26 16:45:23 2022 : Debug: header = "%t" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: locking = no Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: log_packet_header = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: detail post_proxy_log { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Tue Jul 26 16:45:23 2022 : Debug: header = "%t" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: locking = no Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: log_packet_header = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_eap, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_eap Tue Jul 26 16:45:23 2022 : Debug: # Loading module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Tue Jul 26 16:45:23 2022 : Debug: eap { Tue Jul 26 16:45:23 2022 : Debug: default_eap_type = "tls" Tue Jul 26 16:45:23 2022 : Debug: timer_expire = 60 Tue Jul 26 16:45:23 2022 : Debug: ignore_unknown_eap_types = no Tue Jul 26 16:45:23 2022 : Debug: cisco_accounting_username_bug = no Tue Jul 26 16:45:23 2022 : Debug: max_sessions = 16384 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_always, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_always Tue Jul 26 16:45:23 2022 : Debug: # Loading module "reject" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always reject { Tue Jul 26 16:45:23 2022 : Debug: rcode = "reject" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "fail" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always fail { Tue Jul 26 16:45:23 2022 : Debug: rcode = "fail" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "ok" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always ok { Tue Jul 26 16:45:23 2022 : Debug: rcode = "ok" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "handled" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always handled { Tue Jul 26 16:45:23 2022 : Debug: rcode = "handled" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always invalid { Tue Jul 26 16:45:23 2022 : Debug: rcode = "invalid" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always userlock { Tue Jul 26 16:45:23 2022 : Debug: rcode = "userlock" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always notfound { Tue Jul 26 16:45:23 2022 : Debug: rcode = "notfound" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "noop" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always noop { Tue Jul 26 16:45:23 2022 : Debug: rcode = "noop" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "updated" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: always updated { Tue Jul 26 16:45:23 2022 : Debug: rcode = "updated" Tue Jul 26 16:45:23 2022 : Debug: simulcount = 0 Tue Jul 26 16:45:23 2022 : Debug: mpp = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_date, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_date Tue Jul 26 16:45:23 2022 : Debug: # Loading module "date" from file /usr/local/etc/raddb/mods-enabled/date Tue Jul 26 16:45:23 2022 : Debug: date { Tue Jul 26 16:45:23 2022 : Debug: format = "%b %e %Y %H:%M:%S %Z" Tue Jul 26 16:45:23 2022 : Debug: utc = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "wispr2date" from file /usr/local/etc/raddb/mods-enabled/date Tue Jul 26 16:45:23 2022 : Debug: date wispr2date { Tue Jul 26 16:45:23 2022 : Debug: format = "%Y-%m-%dT%H:%M:%S" Tue Jul 26 16:45:23 2022 : Debug: utc = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_exec, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_exec Tue Jul 26 16:45:23 2022 : Debug: # Loading module "echo" from file /usr/local/etc/raddb/mods-enabled/echo Tue Jul 26 16:45:23 2022 : Debug: exec echo { Tue Jul 26 16:45:23 2022 : Debug: wait = yes Tue Jul 26 16:45:23 2022 : Debug: program = "/bin/echo %{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: input_pairs = "request" Tue Jul 26 16:45:23 2022 : Debug: output_pairs = "reply" Tue Jul 26 16:45:23 2022 : Debug: shell_escape = yes Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_radutmp, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_radutmp Tue Jul 26 16:45:23 2022 : Debug: # Loading module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp Tue Jul 26 16:45:23 2022 : Debug: radutmp { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radutmp" Tue Jul 26 16:45:23 2022 : Debug: username = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: case_sensitive = yes Tue Jul 26 16:45:23 2022 : Debug: check_with_nas = yes Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: caller_id = yes Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_files, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_files Tue Jul 26 16:45:23 2022 : Debug: # Loading module "files" from file /usr/local/etc/raddb/mods-enabled/files Tue Jul 26 16:45:23 2022 : Debug: files { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/files/authorize" Tue Jul 26 16:45:23 2022 : Debug: acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" Tue Jul 26 16:45:23 2022 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_chap, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_chap Tue Jul 26 16:45:23 2022 : Debug: # Loading module "chap" from file /usr/local/etc/raddb/mods-enabled/chap Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_utf8, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_utf8 Tue Jul 26 16:45:23 2022 : Debug: # Loading module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_digest, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_digest Tue Jul 26 16:45:23 2022 : Debug: # Loading module "digest" from file /usr/local/etc/raddb/mods-enabled/digest Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_expiration, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_expiration Tue Jul 26 16:45:23 2022 : Debug: # Loading module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Tue Jul 26 16:45:23 2022 : Debug: # Loading module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth Tue Jul 26 16:45:23 2022 : Debug: exec ntlm_auth { Tue Jul 26 16:45:23 2022 : Debug: wait = yes Tue Jul 26 16:45:23 2022 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Tue Jul 26 16:45:23 2022 : Debug: shell_escape = yes Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_mschap, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_mschap Tue Jul 26 16:45:23 2022 : Debug: # Loading module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Tue Jul 26 16:45:23 2022 : Debug: mschap { Tue Jul 26 16:45:23 2022 : Debug: use_mppe = yes Tue Jul 26 16:45:23 2022 : Debug: require_encryption = no Tue Jul 26 16:45:23 2022 : Debug: require_strong = no Tue Jul 26 16:45:23 2022 : Debug: with_ntdomain_hack = yes Tue Jul 26 16:45:23 2022 : Debug: passchange { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: allow_retry = yes Tue Jul 26 16:45:23 2022 : Debug: winbind_retry_with_normalised_username = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Tue Jul 26 16:45:23 2022 : Debug: detail { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Tue Jul 26 16:45:23 2022 : Debug: header = "%t" Tue Jul 26 16:45:23 2022 : Debug: permissions = 384 Tue Jul 26 16:45:23 2022 : Debug: locking = no Tue Jul 26 16:45:23 2022 : Debug: escape_filenames = no Tue Jul 26 16:45:23 2022 : Debug: log_packet_header = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp Tue Jul 26 16:45:23 2022 : Debug: radutmp sradutmp { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/var/log/radius/sradutmp" Tue Jul 26 16:45:23 2022 : Debug: username = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: case_sensitive = yes Tue Jul 26 16:45:23 2022 : Debug: check_with_nas = yes Tue Jul 26 16:45:23 2022 : Debug: permissions = 420 Tue Jul 26 16:45:23 2022 : Debug: caller_id = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "exec" from file /usr/local/etc/raddb/mods-enabled/exec Tue Jul 26 16:45:23 2022 : Debug: exec { Tue Jul 26 16:45:23 2022 : Debug: wait = no Tue Jul 26 16:45:23 2022 : Debug: input_pairs = "request" Tue Jul 26 16:45:23 2022 : Debug: shell_escape = yes Tue Jul 26 16:45:23 2022 : Debug: timeout = 10 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_unix, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_unix Tue Jul 26 16:45:23 2022 : Debug: # Loading module "unix" from file /usr/local/etc/raddb/mods-enabled/unix Tue Jul 26 16:45:23 2022 : Debug: unix { Tue Jul 26 16:45:23 2022 : Debug: radwtmp = "/usr/local/var/log/radius/radwtmp" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Creating attribute Unix-Group Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_preprocess, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_preprocess Tue Jul 26 16:45:23 2022 : Debug: # Loading module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Tue Jul 26 16:45:23 2022 : Debug: preprocess { Tue Jul 26 16:45:23 2022 : Debug: huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" Tue Jul 26 16:45:23 2022 : Debug: hints = "/usr/local/etc/raddb/mods-config/preprocess/hints" Tue Jul 26 16:45:23 2022 : Debug: with_ascend_hack = no Tue Jul 26 16:45:23 2022 : Debug: ascend_channels_per_line = 23 Tue Jul 26 16:45:23 2022 : Debug: with_ntdomain_hack = no Tue Jul 26 16:45:23 2022 : Debug: with_specialix_jetstream_hack = no Tue Jul 26 16:45:23 2022 : Debug: with_cisco_vsa_hack = no Tue Jul 26 16:45:23 2022 : Debug: with_alvarion_vsa_hack = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_soh, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_soh Tue Jul 26 16:45:23 2022 : Debug: # Loading module "soh" from file /usr/local/etc/raddb/mods-enabled/soh Tue Jul 26 16:45:23 2022 : Debug: soh { Tue Jul 26 16:45:23 2022 : Debug: dhcp = yes Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_dynamic_clients Tue Jul 26 16:45:23 2022 : Debug: # Loading module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_realm, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_realm Tue Jul 26 16:45:23 2022 : Debug: # Loading module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: realm IPASS { Tue Jul 26 16:45:23 2022 : Debug: format = "prefix" Tue Jul 26 16:45:23 2022 : Debug: delimiter = "/" Tue Jul 26 16:45:23 2022 : Debug: ignore_default = no Tue Jul 26 16:45:23 2022 : Debug: ignore_null = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: realm suffix { Tue Jul 26 16:45:23 2022 : Debug: format = "suffix" Tue Jul 26 16:45:23 2022 : Debug: delimiter = "@" Tue Jul 26 16:45:23 2022 : Debug: ignore_default = no Tue Jul 26 16:45:23 2022 : Debug: ignore_null = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: realm bangpath { Tue Jul 26 16:45:23 2022 : Debug: format = "prefix" Tue Jul 26 16:45:23 2022 : Debug: delimiter = "!" Tue Jul 26 16:45:23 2022 : Debug: ignore_default = no Tue Jul 26 16:45:23 2022 : Debug: ignore_null = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: realm realmpercent { Tue Jul 26 16:45:23 2022 : Debug: format = "suffix" Tue Jul 26 16:45:23 2022 : Debug: delimiter = "%" Tue Jul 26 16:45:23 2022 : Debug: ignore_default = no Tue Jul 26 16:45:23 2022 : Debug: ignore_null = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: realm ntdomain { Tue Jul 26 16:45:23 2022 : Debug: format = "prefix" Tue Jul 26 16:45:23 2022 : Debug: delimiter = "\\" Tue Jul 26 16:45:23 2022 : Debug: ignore_default = no Tue Jul 26 16:45:23 2022 : Debug: ignore_null = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_attr_filter, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_attr_filter Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.post-proxy { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" Tue Jul 26 16:45:23 2022 : Debug: key = "%{Realm}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.pre-proxy { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" Tue Jul 26 16:45:23 2022 : Debug: key = "%{Realm}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.access_reject { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" Tue Jul 26 16:45:23 2022 : Debug: key = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.access_challenge { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" Tue Jul 26 16:45:23 2022 : Debug: key = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.accounting_response { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" Tue Jul 26 16:45:23 2022 : Debug: key = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Loading module "attr_filter.coa" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: attr_filter attr_filter.coa { Tue Jul 26 16:45:23 2022 : Debug: filename = "/usr/local/etc/raddb/mods-config/attr_filter/coa" Tue Jul 26 16:45:23 2022 : Debug: key = "%{User-Name}" Tue Jul 26 16:45:23 2022 : Debug: relaxed = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_totp, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_totp Tue Jul 26 16:45:23 2022 : Debug: # Loading module "totp" from file /usr/local/etc/raddb/mods-enabled/totp Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_expr, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_expr Tue Jul 26 16:45:23 2022 : Debug: # Loading module "expr" from file /usr/local/etc/raddb/mods-enabled/expr Tue Jul 26 16:45:23 2022 : Debug: expr { Tue Jul 26 16:45:23 2022 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_passwd, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_passwd Tue Jul 26 16:45:23 2022 : Debug: # Loading module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Tue Jul 26 16:45:23 2022 : Debug: passwd etc_passwd { Tue Jul 26 16:45:23 2022 : Debug: filename = "/etc/passwd" Tue Jul 26 16:45:23 2022 : Debug: format = "*User-Name:Crypt-Password:" Tue Jul 26 16:45:23 2022 : Debug: delimiter = ":" Tue Jul 26 16:45:23 2022 : Debug: ignore_nislike = no Tue Jul 26 16:45:23 2022 : Debug: ignore_empty = yes Tue Jul 26 16:45:23 2022 : Debug: allow_multiple_keys = no Tue Jul 26 16:45:23 2022 : Debug: hash_size = 100 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Loaded rlm_unpack, checking if it's valid Tue Jul 26 16:45:23 2022 : Debug: # Loaded module rlm_unpack Tue Jul 26 16:45:23 2022 : Debug: # Loading module "unpack" from file /usr/local/etc/raddb/mods-enabled/unpack Tue Jul 26 16:45:23 2022 : Debug: instantiate { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_md5 Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_pwd Tue Jul 26 16:45:23 2022 : Debug: pwd { Tue Jul 26 16:45:23 2022 : Debug: group = 19 Tue Jul 26 16:45:23 2022 : Debug: fragment_size = 1020 Tue Jul 26 16:45:23 2022 : Debug: server_id = "theserver@example.com" Tue Jul 26 16:45:23 2022 : Debug: virtual_server = "inner-tunnel" Tue Jul 26 16:45:23 2022 : Debug: prep = 0 Tue Jul 26 16:45:23 2022 : Debug: unhex = 1 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_gtc Tue Jul 26 16:45:23 2022 : Debug: gtc { Tue Jul 26 16:45:23 2022 : Debug: challenge = "Password: " Tue Jul 26 16:45:23 2022 : Debug: auth_type = "PAP" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_tls Tue Jul 26 16:45:23 2022 : Debug: tls { Tue Jul 26 16:45:23 2022 : Debug: tls = "tls-common" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: tls-config tls-common { Tue Jul 26 16:45:23 2022 : Debug: verify_depth = 0 Tue Jul 26 16:45:23 2022 : Debug: ca_path = "/usr/local/etc/raddb/certs" Tue Jul 26 16:45:23 2022 : Debug: pem_file_type = yes Tue Jul 26 16:45:23 2022 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" Tue Jul 26 16:45:23 2022 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" Tue Jul 26 16:45:23 2022 : Debug: ca_file = "/usr/local/etc/raddb/certs/ca.pem" Tue Jul 26 16:45:23 2022 : Debug: private_key_password = "whatever" Tue Jul 26 16:45:23 2022 : Debug: fragment_size = 1024 Tue Jul 26 16:45:23 2022 : Debug: include_length = yes Tue Jul 26 16:45:23 2022 : Debug: auto_chain = yes Tue Jul 26 16:45:23 2022 : Debug: check_crl = no Tue Jul 26 16:45:23 2022 : Debug: check_all_crl = no Tue Jul 26 16:45:23 2022 : Debug: ca_path_reload_interval = 0 Tue Jul 26 16:45:23 2022 : Debug: cipher_list = "DEFAULT" Tue Jul 26 16:45:23 2022 : Debug: cipher_server_preference = no Tue Jul 26 16:45:23 2022 : Debug: reject_unknown_intermediate_ca = no Tue Jul 26 16:45:23 2022 : Debug: ecdh_curve = "" Tue Jul 26 16:45:23 2022 : Debug: tls_max_version = "1.2" Tue Jul 26 16:45:23 2022 : Debug: tls_min_version = "1.2" Tue Jul 26 16:45:23 2022 : Debug: cache { Tue Jul 26 16:45:23 2022 : Debug: enable = no Tue Jul 26 16:45:23 2022 : Debug: lifetime = 24 Tue Jul 26 16:45:23 2022 : Debug: max_entries = 255 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: verify { Tue Jul 26 16:45:23 2022 : Debug: skip_if_ocsp_ok = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: ocsp { Tue Jul 26 16:45:23 2022 : Debug: enable = no Tue Jul 26 16:45:23 2022 : Debug: override_cert_url = yes Tue Jul 26 16:45:23 2022 : Debug: url = "http://127.0.0.1/ocsp/" Tue Jul 26 16:45:23 2022 : Debug: use_nonce = yes Tue Jul 26 16:45:23 2022 : Debug: timeout = 0 Tue Jul 26 16:45:23 2022 : Debug: softfail = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_ttls Tue Jul 26 16:45:23 2022 : Debug: ttls { Tue Jul 26 16:45:23 2022 : Debug: tls = "tls-common" Tue Jul 26 16:45:23 2022 : Debug: default_eap_type = "md5" Tue Jul 26 16:45:23 2022 : Debug: copy_request_to_tunnel = no Tue Jul 26 16:45:23 2022 : Debug: use_tunneled_reply = no Tue Jul 26 16:45:23 2022 : Debug: virtual_server = "inner-tunnel" Tue Jul 26 16:45:23 2022 : Debug: include_length = yes Tue Jul 26 16:45:23 2022 : Debug: require_client_cert = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: tls: Using cached TLS configuration from previous invocation Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_peap Tue Jul 26 16:45:23 2022 : Debug: peap { Tue Jul 26 16:45:23 2022 : Debug: tls = "tls-common" Tue Jul 26 16:45:23 2022 : Debug: default_eap_type = "mschapv2" Tue Jul 26 16:45:23 2022 : Debug: copy_request_to_tunnel = no Tue Jul 26 16:45:23 2022 : Debug: use_tunneled_reply = no Tue Jul 26 16:45:23 2022 : Debug: proxy_tunneled_request_as_eap = yes Tue Jul 26 16:45:23 2022 : Debug: virtual_server = "inner-tunnel" Tue Jul 26 16:45:23 2022 : Debug: soh = no Tue Jul 26 16:45:23 2022 : Debug: require_client_cert = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: tls: Using cached TLS configuration from previous invocation Tue Jul 26 16:45:23 2022 : Debug: # Linked to sub-module rlm_eap_mschapv2 Tue Jul 26 16:45:23 2022 : Debug: mschapv2 { Tue Jul 26 16:45:23 2022 : Debug: with_ntdomain_hack = no Tue Jul 26 16:45:23 2022 : Debug: send_error = no Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap Tue Jul 26 16:45:23 2022 : Debug: rlm_mschap (mschap): using internal authentication Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "bangpath" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "attr_filter.coa" from file /usr/local/etc/raddb/mods-enabled/attr_filter Tue Jul 26 16:45:23 2022 : Debug: reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/coa Tue Jul 26 16:45:23 2022 : Debug: # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd Tue Jul 26 16:45:23 2022 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Tue Jul 26 16:45:23 2022 : Debug: } # modules Tue Jul 26 16:45:23 2022 : Debug: radiusd: #### Loading Virtual Servers #### Tue Jul 26 16:45:23 2022 : Debug: server { # from file /usr/local/etc/raddb/radiusd.conf Tue Jul 26 16:45:23 2022 : Debug: } # server Tue Jul 26 16:45:23 2022 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Jul 26 16:45:23 2022 : Debug: # Loading authenticate {...} Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type PAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type CHAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type MS-CHAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: mschap Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: # Loading authorize {...} Tue Jul 26 16:45:23 2022 : Debug: policy filter_username { Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name) { Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ / /) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@[^@]*@/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /\.\./) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /\.$/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@\./) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: chap Tue Jul 26 16:45:23 2022 : Debug: mschap Tue Jul 26 16:45:23 2022 : Debug: suffix Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &control:Proxy-To-Realm := LOCAL Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: files Tue Jul 26 16:45:23 2022 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Tue Jul 26 16:45:23 2022 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Tue Jul 26 16:45:23 2022 : Debug: expiration Tue Jul 26 16:45:23 2022 : Debug: logintime Tue Jul 26 16:45:23 2022 : Debug: pap Tue Jul 26 16:45:23 2022 : Debug: # Loading session {...} Tue Jul 26 16:45:23 2022 : Debug: radutmp Tue Jul 26 16:45:23 2022 : Debug: # Loading post-proxy {...} Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: # Loading post-auth {...} Tue Jul 26 16:45:23 2022 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/etc/raddb/sites-enabled/inner-tunnel:336 Tue Jul 26 16:45:23 2022 : Debug: if (false) { Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Tue Jul 26 16:45:23 2022 : Debug: } # server inner-tunnel Tue Jul 26 16:45:23 2022 : Debug: server default { # from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:45:23 2022 : Debug: # Loading authenticate {...} Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type PAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type CHAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Auth-Type MS-CHAP for attr Auth-Type Tue Jul 26 16:45:23 2022 : Debug: mschap Tue Jul 26 16:45:23 2022 : Debug: digest Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: # Loading authorize {...} Tue Jul 26 16:45:23 2022 : Debug: policy filter_username { Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name) { Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ / /) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains whitespace' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@[^@]*@/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Multiple @ in User-Name' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /\.\./) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: User-Name contains multiple ..s' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm does not have at least one dot separator' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /\.$/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm ends with a dot' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if (&User-Name =~ /@\./) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Module-Failure-Message += 'Rejected: Realm begins with a dot' Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: reject Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: preprocess Tue Jul 26 16:45:23 2022 : Debug: chap Tue Jul 26 16:45:23 2022 : Debug: mschap Tue Jul 26 16:45:23 2022 : Debug: digest Tue Jul 26 16:45:23 2022 : Debug: suffix Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: files Tue Jul 26 16:45:23 2022 : Debug: expiration Tue Jul 26 16:45:23 2022 : Debug: logintime Tue Jul 26 16:45:23 2022 : Debug: pap Tue Jul 26 16:45:23 2022 : Debug: Compiling Autz-Type New-TLS-Connection for attr Autz-Type Tue Jul 26 16:45:23 2022 : Debug: # Loading preacct {...} Tue Jul 26 16:45:23 2022 : Debug: preprocess Tue Jul 26 16:45:23 2022 : Debug: policy acct_unique { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Tmp-String-9 := "ai:" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: if ("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/ && "%{string:&Class}" =~ /^ai:([0-9a-f]{32})/) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: else { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &Tmp-String-9 !* ANY Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: suffix Tue Jul 26 16:45:23 2022 : Debug: files Tue Jul 26 16:45:23 2022 : Debug: # Loading accounting {...} Tue Jul 26 16:45:23 2022 : Debug: detail Tue Jul 26 16:45:23 2022 : Debug: unix Tue Jul 26 16:45:23 2022 : Debug: exec Tue Jul 26 16:45:23 2022 : Debug: attr_filter.accounting_response Tue Jul 26 16:45:23 2022 : Debug: # Loading post-proxy {...} Tue Jul 26 16:45:23 2022 : Debug: eap Tue Jul 26 16:45:23 2022 : Debug: # Loading post-auth {...} Tue Jul 26 16:45:23 2022 : Debug: if (&session-state:User-Name && &reply:User-Name && &User-Name && &reply:User-Name == &User-Name) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &reply:User-Name !* ANY Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &reply:[*] += &session-state:[*] Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: exec Tue Jul 26 16:45:23 2022 : Debug: policy remove_reply_message_if_eap { Tue Jul 26 16:45:23 2022 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &reply:Reply-Message !* ANY Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: else { Tue Jul 26 16:45:23 2022 : Debug: noop Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Compiling Post-Auth-Type REJECT for attr Post-Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Post-Auth-Type Challenge for attr Post-Auth-Type Tue Jul 26 16:45:23 2022 : Debug: Compiling Post-Auth-Type Client-Lost for attr Post-Auth-Type Tue Jul 26 16:45:23 2022 : Debug: if (&EAP-Key-Name && &reply:EAP-Session-Id) { Tue Jul 26 16:45:23 2022 : Debug: update { Tue Jul 26 16:45:23 2022 : Debug: &reply:EAP-Key-Name := &reply:EAP-Session-Id Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } # server default Tue Jul 26 16:45:23 2022 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Jul 26 16:45:23 2022 : Debug: listen { Tue Jul 26 16:45:23 2022 : Debug: type = "auth" Tue Jul 26 16:45:23 2022 : Debug: ipaddr = 127.0.0.1 Tue Jul 26 16:45:23 2022 : Debug: port = 18120 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: listen { Tue Jul 26 16:45:23 2022 : Debug: type = "auth" Tue Jul 26 16:45:23 2022 : Debug: ipaddr = * Tue Jul 26 16:45:23 2022 : Debug: port = 0 Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: listen { Tue Jul 26 16:45:23 2022 : Debug: type = "acct" Tue Jul 26 16:45:23 2022 : Debug: ipaddr = * Tue Jul 26 16:45:23 2022 : Debug: port = 0 Tue Jul 26 16:45:23 2022 : Debug: limit { Tue Jul 26 16:45:23 2022 : Debug: max_connections = 16 Tue Jul 26 16:45:23 2022 : Debug: lifetime = 0 Tue Jul 26 16:45:23 2022 : Debug: idle_timeout = 30 Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: } Tue Jul 26 16:45:23 2022 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Tue Jul 26 16:45:23 2022 : Debug: Listening on auth address * port 1812 bound to server default Tue Jul 26 16:45:23 2022 : Debug: Listening on acct address * port 1813 bound to server default Tue Jul 26 16:45:23 2022 : Debug: Opened new proxy socket 'proxy address * port 37575' Tue Jul 26 16:45:23 2022 : Debug: Listening on proxy address * port 37575 Tue Jul 26 16:45:23 2022 : Info: Ready to process requests Tue Jul 26 16:46:02 2022 : Debug: (0) Received Access-Request Id 136 from 192.168.1.1:46090 to 192.168.1.9:1812 length 209 Tue Jul 26 16:46:02 2022 : Debug: (0) User-Name = "user" Tue Jul 26 16:46:02 2022 : Debug: (0) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:02 2022 : Debug: (0) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:02 2022 : Debug: (0) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:02 2022 : Debug: (0) Service-Type = Framed-User Tue Jul 26 16:46:02 2022 : Debug: (0) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:02 2022 : Debug: (0) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:02 2022 : Debug: (0) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:02 2022 : Debug: (0) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:02 2022 : Debug: (0) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:02 2022 : Debug: (0) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:02 2022 : Debug: (0) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:02 2022 : Debug: (0) Framed-MTU = 1400 Tue Jul 26 16:46:02 2022 : Debug: (0) EAP-Message = 0x022a00090175736572 Tue Jul 26 16:46:02 2022 : Debug: (0) Message-Authenticator = 0x5e0a6ab12eea0efa0acb6e6806498531 Tue Jul 26 16:46:02 2022 : Debug: (0) session-state: No State attribute Tue Jul 26 16:46:02 2022 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (0) authorize { Tue Jul 26 16:46:02 2022 : Debug: (0) policy filter_username { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name) -> TRUE Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ / /) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:02 2022 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:02 2022 : Debug: (0) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (0) } # if (&User-Name) = notfound Tue Jul 26 16:46:02 2022 : Debug: (0) } # policy filter_username = notfound Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (0) [preprocess] = ok Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (0) [chap] = noop Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (0) [mschap] = noop Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (0) [digest] = noop Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (0) suffix: Checking for suffix after "@" Tue Jul 26 16:46:02 2022 : Debug: (0) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:02 2022 : Debug: (0) suffix: No such realm "NULL" Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (0) [suffix] = noop Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 42 length 9 Tue Jul 26 16:46:02 2022 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (0) [eap] = ok Tue Jul 26 16:46:02 2022 : Debug: (0) } # authorize = ok Tue Jul 26 16:46:02 2022 : Debug: (0) Found Auth-Type = eap Tue Jul 26 16:46:02 2022 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (0) authenticate { Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (0) eap: Peer sent packet with method EAP Identity (1) Tue Jul 26 16:46:02 2022 : Debug: (0) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:02 2022 : Debug: (0) eap_tls: (TLS) Initiating new session Tue Jul 26 16:46:02 2022 : Debug: (0) eap_tls: (TLS) Setting verify mode to require certificate from client Tue Jul 26 16:46:02 2022 : Debug: (0) eap_tls: [eaptls start] = request Tue Jul 26 16:46:02 2022 : Debug: (0) eap: Sending EAP Request (code 1) ID 43 length 6 Tue Jul 26 16:46:02 2022 : Debug: (0) eap: EAP session adding &reply:State = 0x3b798b7d3b528623 Tue Jul 26 16:46:02 2022 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (0) [eap] = handled Tue Jul 26 16:46:02 2022 : Debug: (0) } # authenticate = handled Tue Jul 26 16:46:02 2022 : Debug: (0) Using Post-Auth-Type Challenge Tue Jul 26 16:46:02 2022 : Debug: (0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (0) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:02 2022 : Debug: (0) session-state: Saving cached attributes Tue Jul 26 16:46:02 2022 : Debug: (0) Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (0) Sent Access-Challenge Id 136 from 192.168.1.9:1812 to 192.168.1.1:46090 length 64 Tue Jul 26 16:46:02 2022 : Debug: (0) EAP-Message = 0x012b00060d20 Tue Jul 26 16:46:02 2022 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:02 2022 : Debug: (0) State = 0x3b798b7d3b528623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (0) Finished request Tue Jul 26 16:46:02 2022 : Debug: Waking up in 4.9 seconds. Tue Jul 26 16:46:02 2022 : Debug: (1) Received Access-Request Id 137 from 192.168.1.1:46090 to 192.168.1.9:1812 length 355 Tue Jul 26 16:46:02 2022 : Debug: (1) User-Name = "user" Tue Jul 26 16:46:02 2022 : Debug: (1) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:02 2022 : Debug: (1) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:02 2022 : Debug: (1) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:02 2022 : Debug: (1) Service-Type = Framed-User Tue Jul 26 16:46:02 2022 : Debug: (1) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:02 2022 : Debug: (1) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:02 2022 : Debug: (1) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:02 2022 : Debug: (1) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:02 2022 : Debug: (1) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:02 2022 : Debug: (1) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:02 2022 : Debug: (1) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:02 2022 : Debug: (1) Framed-MTU = 1400 Tue Jul 26 16:46:02 2022 : Debug: (1) EAP-Message = 0x022b00890d00160301007e0100007a03033ae6662d6fb9698898217fee903c48edfdb437a4448496aef3ce58dfc98e2ac800001ec02bc02fc02cc030cca9cca8c009c013c00ac014009c009d002f0035000a0100003300170000ff01000100000a00080006001d00170018000b00020100000d00140012040308040401050308050501080606010201 Tue Jul 26 16:46:02 2022 : Debug: (1) State = 0x3b798b7d3b528623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (1) Message-Authenticator = 0x355244d657788e084fc7ee2dd969d057 Tue Jul 26 16:46:02 2022 : Debug: (1) Restoring &session-state Tue Jul 26 16:46:02 2022 : Debug: (1) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (1) authorize { Tue Jul 26 16:46:02 2022 : Debug: (1) policy filter_username { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name) -> TRUE Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ / /) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:02 2022 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:02 2022 : Debug: (1) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (1) } # if (&User-Name) = notfound Tue Jul 26 16:46:02 2022 : Debug: (1) } # policy filter_username = notfound Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (1) [preprocess] = ok Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (1) [chap] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (1) [mschap] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (1) [digest] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (1) suffix: Checking for suffix after "@" Tue Jul 26 16:46:02 2022 : Debug: (1) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:02 2022 : Debug: (1) suffix: No such realm "NULL" Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (1) [suffix] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 43 length 137 Tue Jul 26 16:46:02 2022 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (1) [eap] = updated Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (1) [files] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (1) [expiration] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (1) [logintime] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (1) [pap] = noop Tue Jul 26 16:46:02 2022 : Debug: (1) } # authorize = updated Tue Jul 26 16:46:02 2022 : Debug: (1) Found Auth-Type = eap Tue Jul 26 16:46:02 2022 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (1) authenticate { Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Expiring EAP session with state 0x3b798b7d3b528623 Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Finished EAP session with state 0x3b798b7d3b528623 Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Previous EAP request found for state 0x3b798b7d3b528623, released from the list Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) EAP Got final fragment (131 bytes) Tue Jul 26 16:46:02 2022 : WARNING: (1) eap_tls: (TLS) EAP Total received record fragments (131 bytes), does not equal expected expected data length (0 bytes) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) EAP Verification says ok Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) EAP Done initial handshake Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [PINIT] - before SSL initialization (0) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [PINIT] - Server before SSL initialization (0) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [PINIT] - Server before SSL initialization (0) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) recv TLS 1.3 Handshake, ClientHello Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TRCH] - Server SSLv3/TLS read client hello (20) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: Server preferred ciphers (by priority) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [0] TLS_AES_256_GCM_SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [2] TLS_AES_128_GCM_SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [13] ECDHE-RSA-AES256-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [14] DHE-RSA-AES256-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [16] ECDHE-RSA-AES128-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [17] DHE-RSA-AES128-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [18] ECDHE-ECDSA-AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [19] ECDHE-RSA-AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [20] DHE-RSA-AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [21] ECDHE-ECDSA-AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [22] ECDHE-RSA-AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [23] DHE-RSA-AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [24] RSA-PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [25] DHE-PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [26] RSA-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [27] DHE-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [28] ECDHE-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [29] AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [30] PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [31] PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [32] RSA-PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [33] DHE-PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [34] AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [35] PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [36] AES256-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [37] AES128-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [38] ECDHE-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [39] ECDHE-PSK-AES256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [40] SRP-RSA-AES-256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [41] SRP-AES-256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [42] RSA-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [43] DHE-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [44] RSA-PSK-AES256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [45] DHE-PSK-AES256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [46] AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [47] PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [48] PSK-AES256-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [49] ECDHE-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [50] ECDHE-PSK-AES128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [51] SRP-RSA-AES-128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [52] SRP-AES-128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [53] RSA-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [54] DHE-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [55] RSA-PSK-AES128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [56] DHE-PSK-AES128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [57] AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [58] PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [59] PSK-AES128-CBC-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: Client preferred ciphers (by priority) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [0] ECDHE-ECDSA-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [1] ECDHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [2] ECDHE-ECDSA-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [3] ECDHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [4] ECDHE-ECDSA-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [5] ECDHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [6] ECDHE-ECDSA-AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [7] ECDHE-RSA-AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [8] ECDHE-ECDSA-AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [9] ECDHE-RSA-AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [10] AES128-GCM-SHA256 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [11] AES256-GCM-SHA384 Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [12] AES128-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) [13] AES256-SHA Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) send TLS 1.2 Handshake, ServerHello Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TWSH] - Server SSLv3/TLS write server hello (22) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) send TLS 1.2 Handshake, Certificate Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TWSC] - Server SSLv3/TLS write certificate (23) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) send TLS 1.2 Handshake, ServerKeyExchange Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TWSKE] - Server SSLv3/TLS write key exchange (24) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) send TLS 1.2 Handshake, CertificateRequest Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TWCR] - Server SSLv3/TLS write certificate request (25) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) send TLS 1.2 Handshake, ServerHelloDone Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Handshake state [TWSD] - Server SSLv3/TLS write server done (26) Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) Server : Need to read more data: SSLv3/TLS write server done Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) In Handshake Phase Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: (TLS) got 2907 bytes of data Tue Jul 26 16:46:02 2022 : Debug: (1) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:02 2022 : Debug: (1) eap: Sending EAP Request (code 1) ID 44 length 1004 Tue Jul 26 16:46:02 2022 : Debug: (1) eap: EAP session adding &reply:State = 0x3b798b7d3a558623 Tue Jul 26 16:46:02 2022 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (1) [eap] = handled Tue Jul 26 16:46:02 2022 : Debug: (1) } # authenticate = handled Tue Jul 26 16:46:02 2022 : Debug: (1) Using Post-Auth-Type Challenge Tue Jul 26 16:46:02 2022 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (1) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:02 2022 : Debug: (1) session-state: Saving cached attributes Tue Jul 26 16:46:02 2022 : Debug: (1) Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (1) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (1) Sent Access-Challenge Id 137 from 192.168.1.9:1812 to 192.168.1.1:46090 length 1068 Tue Jul 26 16:46:02 2022 : Debug: (1) EAP-Message = 0x012c03ec0dc000000b5b160303003d020000390303ce3cd4d49f5b35b9d1d9ba05abfbcb6f7c61b3a100ec43ea7e009cc0589d6f6000c02f000011ff01000100000b0004030001020017000016030309030b0008ff0008fc0003f8308203f4308202dca003020102020101300d06092a864886f70d01010b0500308193310b3009060355040613024652310f300d06035504080c065261646975733112301006035504070c09536f6d65776865726531153013060355040a0c0c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e6f72673126302406035504030c1d4578616d706c6520436572746966696361746520417574686f72697479301e170d3232303732303031303732375a170d3232303931383031303732375a307c310b3009060355040613024652310f300d06035504080c0652616469757331153013060355040a0c0c4578616d706c6520496e632e3123302106035504030c1a4578616d70 Tue Jul 26 16:46:02 2022 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:02 2022 : Debug: (1) State = 0x3b798b7d3a558623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (1) Finished request Tue Jul 26 16:46:02 2022 : Debug: Waking up in 4.9 seconds. Tue Jul 26 16:46:02 2022 : Debug: (2) Received Access-Request Id 138 from 192.168.1.1:46090 to 192.168.1.9:1812 length 224 Tue Jul 26 16:46:02 2022 : Debug: (2) User-Name = "user" Tue Jul 26 16:46:02 2022 : Debug: (2) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:02 2022 : Debug: (2) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:02 2022 : Debug: (2) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:02 2022 : Debug: (2) Service-Type = Framed-User Tue Jul 26 16:46:02 2022 : Debug: (2) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:02 2022 : Debug: (2) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:02 2022 : Debug: (2) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:02 2022 : Debug: (2) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:02 2022 : Debug: (2) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:02 2022 : Debug: (2) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:02 2022 : Debug: (2) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:02 2022 : Debug: (2) Framed-MTU = 1400 Tue Jul 26 16:46:02 2022 : Debug: (2) EAP-Message = 0x022c00060d00 Tue Jul 26 16:46:02 2022 : Debug: (2) State = 0x3b798b7d3a558623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (2) Message-Authenticator = 0xf6fd6f32529b4761edb959fc9b4cbbfd Tue Jul 26 16:46:02 2022 : Debug: (2) Restoring &session-state Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (2) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (2) authorize { Tue Jul 26 16:46:02 2022 : Debug: (2) policy filter_username { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name) -> TRUE Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ / /) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:02 2022 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:02 2022 : Debug: (2) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (2) } # if (&User-Name) = notfound Tue Jul 26 16:46:02 2022 : Debug: (2) } # policy filter_username = notfound Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (2) [preprocess] = ok Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (2) [chap] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (2) [mschap] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (2) [digest] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (2) suffix: Checking for suffix after "@" Tue Jul 26 16:46:02 2022 : Debug: (2) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:02 2022 : Debug: (2) suffix: No such realm "NULL" Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (2) [suffix] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 44 length 6 Tue Jul 26 16:46:02 2022 : Debug: (2) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (2) [eap] = updated Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (2) [files] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (2) [expiration] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (2) [logintime] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (2) [pap] = noop Tue Jul 26 16:46:02 2022 : Debug: (2) } # authorize = updated Tue Jul 26 16:46:02 2022 : Debug: (2) Found Auth-Type = eap Tue Jul 26 16:46:02 2022 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (2) authenticate { Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Expiring EAP session with state 0x3b798b7d3a558623 Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Finished EAP session with state 0x3b798b7d3a558623 Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Previous EAP request found for state 0x3b798b7d3a558623, released from the list Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:02 2022 : Debug: (2) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:02 2022 : Debug: (2) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:02 2022 : Debug: (2) eap_tls: (TLS) Peer ACKed our handshake fragment Tue Jul 26 16:46:02 2022 : Debug: (2) eap_tls: (TLS) EAP Verification says request Tue Jul 26 16:46:02 2022 : Debug: (2) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:02 2022 : Debug: (2) eap: Sending EAP Request (code 1) ID 45 length 1004 Tue Jul 26 16:46:02 2022 : Debug: (2) eap: EAP session adding &reply:State = 0x3b798b7d39548623 Tue Jul 26 16:46:02 2022 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (2) [eap] = handled Tue Jul 26 16:46:02 2022 : Debug: (2) } # authenticate = handled Tue Jul 26 16:46:02 2022 : Debug: (2) Using Post-Auth-Type Challenge Tue Jul 26 16:46:02 2022 : Debug: (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (2) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:02 2022 : Debug: (2) session-state: Saving cached attributes Tue Jul 26 16:46:02 2022 : Debug: (2) Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (2) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (2) Sent Access-Challenge Id 138 from 192.168.1.9:1812 to 192.168.1.1:46090 length 1068 Tue Jul 26 16:46:02 2022 : Debug: (2) EAP-Message = 0x012d03ec0dc000000b5b14d99d4ab6a487455d7897a393bf6c0208fc10802a4f2c5e0d3f7bd0b5c572b4d90ec5ca452fe2c7bb310cdf60b6b04a604b96a6e7e77d1bd91b682a2eb154dbef37ee3b41322481409db0b44660e8f529fad64eaab3f2f76af72ed2f5f1e56a6d3949d1b116940004fe308204fa308203e2a00302010202141f0bb74ab5a65d151582c41942ef11e81d04900c300d06092a864886f70d01010b0500308193310b3009060355040613024652310f300d06035504080c065261646975733112301006035504070c09536f6d65776865726531153013060355040a0c0c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e6f72673126302406035504030c1d4578616d706c6520436572746966696361746520417574686f72697479301e170d3232303732303031303732365a170d3232303931383031303732365a308193310b3009060355040613024652310f300d06035504080c06 Tue Jul 26 16:46:02 2022 : Debug: (2) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:02 2022 : Debug: (2) State = 0x3b798b7d39548623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (2) Finished request Tue Jul 26 16:46:02 2022 : Debug: Waking up in 4.9 seconds. Tue Jul 26 16:46:02 2022 : Debug: (3) Received Access-Request Id 139 from 192.168.1.1:46090 to 192.168.1.9:1812 length 224 Tue Jul 26 16:46:02 2022 : Debug: (3) User-Name = "user" Tue Jul 26 16:46:02 2022 : Debug: (3) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:02 2022 : Debug: (3) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:02 2022 : Debug: (3) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:02 2022 : Debug: (3) Service-Type = Framed-User Tue Jul 26 16:46:02 2022 : Debug: (3) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:02 2022 : Debug: (3) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:02 2022 : Debug: (3) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:02 2022 : Debug: (3) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:02 2022 : Debug: (3) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:02 2022 : Debug: (3) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:02 2022 : Debug: (3) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:02 2022 : Debug: (3) Framed-MTU = 1400 Tue Jul 26 16:46:02 2022 : Debug: (3) EAP-Message = 0x022d00060d00 Tue Jul 26 16:46:02 2022 : Debug: (3) State = 0x3b798b7d39548623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (3) Message-Authenticator = 0x73ca17877aece3f675623ce38b2da9ff Tue Jul 26 16:46:02 2022 : Debug: (3) Restoring &session-state Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (3) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (3) authorize { Tue Jul 26 16:46:02 2022 : Debug: (3) policy filter_username { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name) -> TRUE Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ / /) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:02 2022 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:02 2022 : Debug: (3) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (3) } # if (&User-Name) = notfound Tue Jul 26 16:46:02 2022 : Debug: (3) } # policy filter_username = notfound Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (3) [preprocess] = ok Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (3) [chap] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (3) [mschap] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (3) [digest] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (3) suffix: Checking for suffix after "@" Tue Jul 26 16:46:02 2022 : Debug: (3) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:02 2022 : Debug: (3) suffix: No such realm "NULL" Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (3) [suffix] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Peer sent EAP Response (code 2) ID 45 length 6 Tue Jul 26 16:46:02 2022 : Debug: (3) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (3) [eap] = updated Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (3) [files] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (3) [expiration] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (3) [logintime] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (3) [pap] = noop Tue Jul 26 16:46:02 2022 : Debug: (3) } # authorize = updated Tue Jul 26 16:46:02 2022 : Debug: (3) Found Auth-Type = eap Tue Jul 26 16:46:02 2022 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (3) authenticate { Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Expiring EAP session with state 0x3b798b7d39548623 Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Finished EAP session with state 0x3b798b7d39548623 Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Previous EAP request found for state 0x3b798b7d39548623, released from the list Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:02 2022 : Debug: (3) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:02 2022 : Debug: (3) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:02 2022 : Debug: (3) eap_tls: (TLS) Peer ACKed our handshake fragment Tue Jul 26 16:46:02 2022 : Debug: (3) eap_tls: (TLS) EAP Verification says request Tue Jul 26 16:46:02 2022 : Debug: (3) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:02 2022 : Debug: (3) eap: Sending EAP Request (code 1) ID 46 length 929 Tue Jul 26 16:46:02 2022 : Debug: (3) eap: EAP session adding &reply:State = 0x3b798b7d38578623 Tue Jul 26 16:46:02 2022 : Debug: (3) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (3) [eap] = handled Tue Jul 26 16:46:02 2022 : Debug: (3) } # authenticate = handled Tue Jul 26 16:46:02 2022 : Debug: (3) Using Post-Auth-Type Challenge Tue Jul 26 16:46:02 2022 : Debug: (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (3) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:02 2022 : Debug: (3) session-state: Saving cached attributes Tue Jul 26 16:46:02 2022 : Debug: (3) Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (3) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (3) Sent Access-Challenge Id 139 from 192.168.1.9:1812 to 192.168.1.1:46090 length 993 Tue Jul 26 16:46:02 2022 : Debug: (3) EAP-Message = 0x012e03a10d8000000b5b72746966696361746520417574686f7269747982141f0bb74ab5a65d151582c41942ef11e81d04900c300f0603551d130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b0500038201010065ff74d789b24f3fee1d0081f51e19c4b0b5615136c90ad765fe0d83265a10f28bf5afde23864c12f19f1ebb4ceb509937b0620d52a664ed0d1327a7b146b6c1d56d016042f4bbb34e329d981d32720cdc0919e1c568fb1bbdbcac4a114d48bd643fe8c7c15bc2e2acd3d33a9cc17831e6ebbaa37aff1ca35c2cbaf520eadae7f277acbc8343fe263a8c35fb782c315c71045e1b6780123206f398af036396118743ece71358d324d600319929f291745eb7952a0a6f1cb0f94cbbadcb653e4c4cb9f820c527107f6198b4c958fbce6ff4423bad244942c26dba656ae56cfe458232bcff95b0ed Tue Jul 26 16:46:02 2022 : Debug: (3) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:02 2022 : Debug: (3) State = 0x3b798b7d38578623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (3) Finished request Tue Jul 26 16:46:02 2022 : Debug: Waking up in 4.9 seconds. Tue Jul 26 16:46:02 2022 : Debug: (4) Received Access-Request Id 140 from 192.168.1.1:46090 to 192.168.1.9:1812 length 231 Tue Jul 26 16:46:02 2022 : Debug: (4) User-Name = "user" Tue Jul 26 16:46:02 2022 : Debug: (4) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:02 2022 : Debug: (4) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:02 2022 : Debug: (4) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:02 2022 : Debug: (4) Service-Type = Framed-User Tue Jul 26 16:46:02 2022 : Debug: (4) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:02 2022 : Debug: (4) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:02 2022 : Debug: (4) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:02 2022 : Debug: (4) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:02 2022 : Debug: (4) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:02 2022 : Debug: (4) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:02 2022 : Debug: (4) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:02 2022 : Debug: (4) Framed-MTU = 1400 Tue Jul 26 16:46:02 2022 : Debug: (4) EAP-Message = 0x022e000d0d0015030300020250 Tue Jul 26 16:46:02 2022 : Debug: (4) State = 0x3b798b7d38578623cca12dbe0bcc468f Tue Jul 26 16:46:02 2022 : Debug: (4) Message-Authenticator = 0xe4d87eff5eb54e091e8dc09a5a4947a6 Tue Jul 26 16:46:02 2022 : Debug: (4) Restoring &session-state Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:02 2022 : Debug: (4) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:02 2022 : Debug: (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (4) authorize { Tue Jul 26 16:46:02 2022 : Debug: (4) policy filter_username { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name) -> TRUE Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ / /) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:02 2022 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) } # if (&User-Name) = notfound Tue Jul 26 16:46:02 2022 : Debug: (4) } # policy filter_username = notfound Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:02 2022 : Debug: (4) [preprocess] = ok Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:02 2022 : Debug: (4) [chap] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:02 2022 : Debug: (4) [mschap] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:02 2022 : Debug: (4) [digest] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (4) suffix: Checking for suffix after "@" Tue Jul 26 16:46:02 2022 : Debug: (4) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:02 2022 : Debug: (4) suffix: No such realm "NULL" Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:02 2022 : Debug: (4) [suffix] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Peer sent EAP Response (code 2) ID 46 length 13 Tue Jul 26 16:46:02 2022 : Debug: (4) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) [eap] = updated Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:02 2022 : Debug: (4) [files] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:02 2022 : Debug: (4) [expiration] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:02 2022 : Debug: (4) [logintime] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:02 2022 : Debug: (4) [pap] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) } # authorize = updated Tue Jul 26 16:46:02 2022 : Debug: (4) Found Auth-Type = eap Tue Jul 26 16:46:02 2022 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (4) authenticate { Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Expiring EAP session with state 0x3b798b7d38578623 Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Finished EAP session with state 0x3b798b7d38578623 Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Previous EAP request found for state 0x3b798b7d38578623, released from the list Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) EAP Verification says ok Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) EAP Done initial handshake Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) recv TLS 1.2 Alert, fatal internal_error Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) The client is informing us that there is a failure inside the TLS protocol exchange. Tue Jul 26 16:46:02 2022 : ERROR: (4) eap_tls: (TLS) Alert read:fatal:internal error Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) Server : Need to read more data: error Tue Jul 26 16:46:02 2022 : ERROR: (4) eap_tls: (TLS) Failed reading from OpenSSL: ../ssl/record/rec_layer_s3.c[1528]:error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) In Handshake Phase Tue Jul 26 16:46:02 2022 : Debug: (4) eap_tls: (TLS) Application data. Tue Jul 26 16:46:02 2022 : ERROR: (4) eap_tls: (TLS) Cannot continue, as the peer is misbehaving. Tue Jul 26 16:46:02 2022 : ERROR: (4) eap_tls: [eaptls process] = fail Tue Jul 26 16:46:02 2022 : ERROR: (4) eap: Failed continuing EAP TLS (13) session. EAP sub-module failed Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Sending EAP Failure (code 4) ID 46 length 4 Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Failed in EAP select Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) [eap] = invalid Tue Jul 26 16:46:02 2022 : Debug: (4) } # authenticate = invalid Tue Jul 26 16:46:02 2022 : Debug: (4) Failed to authenticate the user Tue Jul 26 16:46:02 2022 : Debug: (4) Using Post-Auth-Type Reject Tue Jul 26 16:46:02 2022 : Debug: (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:02 2022 : Debug: (4) Post-Auth-Type REJECT { Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) Tue Jul 26 16:46:02 2022 : Debug: %{User-Name} Tue Jul 26 16:46:02 2022 : Debug: Parsed xlat tree: Tue Jul 26 16:46:02 2022 : Debug: attribute --> User-Name Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: EXPAND %{User-Name} Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: --> user Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: Matched entry DEFAULT at line 11 Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: EAP-Message = 0x042e0004 allowed by EAP-Message =* 0x Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Tue Jul 26 16:46:02 2022 : Debug: (4) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) Tue Jul 26 16:46:02 2022 : Debug: (4) [attr_filter.access_reject] = updated Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: calling eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) eap: Reply already contained an EAP-Message, not inserting EAP-Failure Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: returned from eap (rlm_eap) Tue Jul 26 16:46:02 2022 : Debug: (4) [eap] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) policy remove_reply_message_if_eap { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&reply:EAP-Message && &reply:Reply-Message) { Tue Jul 26 16:46:02 2022 : Debug: (4) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Tue Jul 26 16:46:02 2022 : Debug: (4) else { Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: calling noop (rlm_always) Tue Jul 26 16:46:02 2022 : Debug: (4) modsingle[post-auth]: returned from noop (rlm_always) Tue Jul 26 16:46:02 2022 : Debug: (4) [noop] = noop Tue Jul 26 16:46:02 2022 : Debug: (4) } # else = noop Tue Jul 26 16:46:02 2022 : Debug: (4) } # policy remove_reply_message_if_eap = noop Tue Jul 26 16:46:02 2022 : Debug: (4) } # Post-Auth-Type REJECT = updated Tue Jul 26 16:46:02 2022 : Debug: (4) Delaying response for 1.000000 seconds Tue Jul 26 16:46:02 2022 : Debug: Waking up in 0.3 seconds. Tue Jul 26 16:46:02 2022 : Debug: Waking up in 0.6 seconds. Tue Jul 26 16:46:03 2022 : Debug: (4) Sending delayed response Tue Jul 26 16:46:03 2022 : Debug: (4) Sent Access-Reject Id 140 from 192.168.1.9:1812 to 192.168.1.1:46090 length 44 Tue Jul 26 16:46:03 2022 : Debug: (4) EAP-Message = 0x042e0004 Tue Jul 26 16:46:03 2022 : Debug: (4) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:03 2022 : Debug: Waking up in 3.9 seconds. Tue Jul 26 16:46:06 2022 : Debug: (5) Received Access-Request Id 141 from 192.168.1.1:46090 to 192.168.1.9:1812 length 209 Tue Jul 26 16:46:06 2022 : Debug: (5) User-Name = "user" Tue Jul 26 16:46:06 2022 : Debug: (5) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:06 2022 : Debug: (5) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:06 2022 : Debug: (5) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:06 2022 : Debug: (5) Service-Type = Framed-User Tue Jul 26 16:46:06 2022 : Debug: (5) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:06 2022 : Debug: (5) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:06 2022 : Debug: (5) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:06 2022 : Debug: (5) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:06 2022 : Debug: (5) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:06 2022 : Debug: (5) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:06 2022 : Debug: (5) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:06 2022 : Debug: (5) Framed-MTU = 1400 Tue Jul 26 16:46:06 2022 : Debug: (5) EAP-Message = 0x02ec00090175736572 Tue Jul 26 16:46:06 2022 : Debug: (5) Message-Authenticator = 0x1e85e2bb21377bd9c3b2bfc2218667ec Tue Jul 26 16:46:06 2022 : Debug: (5) session-state: No State attribute Tue Jul 26 16:46:06 2022 : Debug: (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (5) authorize { Tue Jul 26 16:46:06 2022 : Debug: (5) policy filter_username { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name) -> TRUE Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ / /) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:06 2022 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:06 2022 : Debug: (5) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (5) } # if (&User-Name) = notfound Tue Jul 26 16:46:06 2022 : Debug: (5) } # policy filter_username = notfound Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (5) [preprocess] = ok Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (5) [chap] = noop Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (5) [mschap] = noop Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (5) [digest] = noop Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (5) suffix: Checking for suffix after "@" Tue Jul 26 16:46:06 2022 : Debug: (5) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:06 2022 : Debug: (5) suffix: No such realm "NULL" Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (5) [suffix] = noop Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (5) eap: Peer sent EAP Response (code 2) ID 236 length 9 Tue Jul 26 16:46:06 2022 : Debug: (5) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (5) [eap] = ok Tue Jul 26 16:46:06 2022 : Debug: (5) } # authorize = ok Tue Jul 26 16:46:06 2022 : Debug: (5) Found Auth-Type = eap Tue Jul 26 16:46:06 2022 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (5) authenticate { Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (5) eap: Peer sent packet with method EAP Identity (1) Tue Jul 26 16:46:06 2022 : Debug: (5) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:06 2022 : Debug: (5) eap_tls: (TLS) Initiating new session Tue Jul 26 16:46:06 2022 : Debug: (5) eap_tls: (TLS) Setting verify mode to require certificate from client Tue Jul 26 16:46:06 2022 : Debug: (5) eap_tls: [eaptls start] = request Tue Jul 26 16:46:06 2022 : Debug: (5) eap: Sending EAP Request (code 1) ID 237 length 6 Tue Jul 26 16:46:06 2022 : Debug: (5) eap: EAP session adding &reply:State = 0x1546e62e15abeb2a Tue Jul 26 16:46:06 2022 : Debug: (5) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (5) [eap] = handled Tue Jul 26 16:46:06 2022 : Debug: (5) } # authenticate = handled Tue Jul 26 16:46:06 2022 : Debug: (5) Using Post-Auth-Type Challenge Tue Jul 26 16:46:06 2022 : Debug: (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (5) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:06 2022 : Debug: (5) session-state: Saving cached attributes Tue Jul 26 16:46:06 2022 : Debug: (5) Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (5) Sent Access-Challenge Id 141 from 192.168.1.9:1812 to 192.168.1.1:46090 length 64 Tue Jul 26 16:46:06 2022 : Debug: (5) EAP-Message = 0x01ed00060d20 Tue Jul 26 16:46:06 2022 : Debug: (5) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:06 2022 : Debug: (5) State = 0x1546e62e15abeb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (5) Finished request Tue Jul 26 16:46:06 2022 : Debug: Waking up in 1.0 seconds. Tue Jul 26 16:46:06 2022 : Debug: (6) Received Access-Request Id 142 from 192.168.1.1:46090 to 192.168.1.9:1812 length 355 Tue Jul 26 16:46:06 2022 : Debug: (6) User-Name = "user" Tue Jul 26 16:46:06 2022 : Debug: (6) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:06 2022 : Debug: (6) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:06 2022 : Debug: (6) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:06 2022 : Debug: (6) Service-Type = Framed-User Tue Jul 26 16:46:06 2022 : Debug: (6) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:06 2022 : Debug: (6) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:06 2022 : Debug: (6) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:06 2022 : Debug: (6) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:06 2022 : Debug: (6) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:06 2022 : Debug: (6) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:06 2022 : Debug: (6) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:06 2022 : Debug: (6) Framed-MTU = 1400 Tue Jul 26 16:46:06 2022 : Debug: (6) EAP-Message = 0x02ed00890d00160301007e0100007a0303cfe40a9e39acedc3ec07aab89a14299e6a14797ec0c5e32cfb5a9c5c1ce1845600001ec02bc02fc02cc030cca9cca8c009c013c00ac014009c009d002f0035000a0100003300170000ff01000100000a00080006001d00170018000b00020100000d00140012040308040401050308050501080606010201 Tue Jul 26 16:46:06 2022 : Debug: (6) State = 0x1546e62e15abeb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (6) Message-Authenticator = 0xcb657ee8aa6e95a1319e6dc46e118f6e Tue Jul 26 16:46:06 2022 : Debug: (6) Restoring &session-state Tue Jul 26 16:46:06 2022 : Debug: (6) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (6) authorize { Tue Jul 26 16:46:06 2022 : Debug: (6) policy filter_username { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name) -> TRUE Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ / /) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:06 2022 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:06 2022 : Debug: (6) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (6) } # if (&User-Name) = notfound Tue Jul 26 16:46:06 2022 : Debug: (6) } # policy filter_username = notfound Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (6) [preprocess] = ok Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (6) [chap] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (6) [mschap] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (6) [digest] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (6) suffix: Checking for suffix after "@" Tue Jul 26 16:46:06 2022 : Debug: (6) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:06 2022 : Debug: (6) suffix: No such realm "NULL" Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (6) [suffix] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Peer sent EAP Response (code 2) ID 237 length 137 Tue Jul 26 16:46:06 2022 : Debug: (6) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (6) [eap] = updated Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (6) [files] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (6) [expiration] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (6) [logintime] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (6) [pap] = noop Tue Jul 26 16:46:06 2022 : Debug: (6) } # authorize = updated Tue Jul 26 16:46:06 2022 : Debug: (6) Found Auth-Type = eap Tue Jul 26 16:46:06 2022 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (6) authenticate { Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Expiring EAP session with state 0x1546e62e15abeb2a Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Finished EAP session with state 0x1546e62e15abeb2a Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Previous EAP request found for state 0x1546e62e15abeb2a, released from the list Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) EAP Got final fragment (131 bytes) Tue Jul 26 16:46:06 2022 : WARNING: (6) eap_tls: (TLS) EAP Total received record fragments (131 bytes), does not equal expected expected data length (0 bytes) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) EAP Verification says ok Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) EAP Done initial handshake Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [PINIT] - before SSL initialization (0) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [PINIT] - Server before SSL initialization (0) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [PINIT] - Server before SSL initialization (0) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) recv TLS 1.3 Handshake, ClientHello Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TRCH] - Server SSLv3/TLS read client hello (20) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: Server preferred ciphers (by priority) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [0] TLS_AES_256_GCM_SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [1] TLS_CHACHA20_POLY1305_SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [2] TLS_AES_128_GCM_SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [3] ECDHE-ECDSA-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [4] ECDHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [5] DHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [6] ECDHE-ECDSA-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [7] ECDHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [8] DHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [9] ECDHE-ECDSA-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [10] ECDHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [11] DHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [12] ECDHE-ECDSA-AES256-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [13] ECDHE-RSA-AES256-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [14] DHE-RSA-AES256-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [15] ECDHE-ECDSA-AES128-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [16] ECDHE-RSA-AES128-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [17] DHE-RSA-AES128-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [18] ECDHE-ECDSA-AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [19] ECDHE-RSA-AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [20] DHE-RSA-AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [21] ECDHE-ECDSA-AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [22] ECDHE-RSA-AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [23] DHE-RSA-AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [24] RSA-PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [25] DHE-PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [26] RSA-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [27] DHE-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [28] ECDHE-PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [29] AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [30] PSK-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [31] PSK-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [32] RSA-PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [33] DHE-PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [34] AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [35] PSK-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [36] AES256-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [37] AES128-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [38] ECDHE-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [39] ECDHE-PSK-AES256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [40] SRP-RSA-AES-256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [41] SRP-AES-256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [42] RSA-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [43] DHE-PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [44] RSA-PSK-AES256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [45] DHE-PSK-AES256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [46] AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [47] PSK-AES256-CBC-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [48] PSK-AES256-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [49] ECDHE-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [50] ECDHE-PSK-AES128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [51] SRP-RSA-AES-128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [52] SRP-AES-128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [53] RSA-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [54] DHE-PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [55] RSA-PSK-AES128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [56] DHE-PSK-AES128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [57] AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [58] PSK-AES128-CBC-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [59] PSK-AES128-CBC-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: Client preferred ciphers (by priority) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [0] ECDHE-ECDSA-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [1] ECDHE-RSA-AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [2] ECDHE-ECDSA-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [3] ECDHE-RSA-AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [4] ECDHE-ECDSA-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [5] ECDHE-RSA-CHACHA20-POLY1305 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [6] ECDHE-ECDSA-AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [7] ECDHE-RSA-AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [8] ECDHE-ECDSA-AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [9] ECDHE-RSA-AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [10] AES128-GCM-SHA256 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [11] AES256-GCM-SHA384 Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [12] AES128-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) [13] AES256-SHA Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) send TLS 1.2 Handshake, ServerHello Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TWSH] - Server SSLv3/TLS write server hello (22) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) send TLS 1.2 Handshake, Certificate Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TWSC] - Server SSLv3/TLS write certificate (23) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) send TLS 1.2 Handshake, ServerKeyExchange Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TWSKE] - Server SSLv3/TLS write key exchange (24) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) send TLS 1.2 Handshake, CertificateRequest Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TWCR] - Server SSLv3/TLS write certificate request (25) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) send TLS 1.2 Handshake, ServerHelloDone Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Handshake state [TWSD] - Server SSLv3/TLS write server done (26) Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) Server : Need to read more data: SSLv3/TLS write server done Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) In Handshake Phase Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: (TLS) got 2907 bytes of data Tue Jul 26 16:46:06 2022 : Debug: (6) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:06 2022 : Debug: (6) eap: Sending EAP Request (code 1) ID 238 length 1004 Tue Jul 26 16:46:06 2022 : Debug: (6) eap: EAP session adding &reply:State = 0x1546e62e14a8eb2a Tue Jul 26 16:46:06 2022 : Debug: (6) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (6) [eap] = handled Tue Jul 26 16:46:06 2022 : Debug: (6) } # authenticate = handled Tue Jul 26 16:46:06 2022 : Debug: (6) Using Post-Auth-Type Challenge Tue Jul 26 16:46:06 2022 : Debug: (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (6) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:06 2022 : Debug: (6) session-state: Saving cached attributes Tue Jul 26 16:46:06 2022 : Debug: (6) Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (6) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (6) Sent Access-Challenge Id 142 from 192.168.1.9:1812 to 192.168.1.1:46090 length 1068 Tue Jul 26 16:46:06 2022 : Debug: (6) EAP-Message = 0x01ee03ec0dc000000b5b160303003d02000039030382bc3c2769556693e4652b3d8d0f6fe223a139c2deae4dabbf34f5436553d6d900c02f000011ff01000100000b0004030001020017000016030309030b0008ff0008fc0003f8308203f4308202dca003020102020101300d06092a864886f70d01010b0500308193310b3009060355040613024652310f300d06035504080c065261646975733112301006035504070c09536f6d65776865726531153013060355040a0c0c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e6f72673126302406035504030c1d4578616d706c6520436572746966696361746520417574686f72697479301e170d3232303732303031303732375a170d3232303931383031303732375a307c310b3009060355040613024652310f300d06035504080c0652616469757331153013060355040a0c0c4578616d706c6520496e632e3123302106035504030c1a4578616d70 Tue Jul 26 16:46:06 2022 : Debug: (6) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:06 2022 : Debug: (6) State = 0x1546e62e14a8eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (6) Finished request Tue Jul 26 16:46:06 2022 : Debug: Waking up in 1.0 seconds. Tue Jul 26 16:46:06 2022 : Debug: (7) Received Access-Request Id 143 from 192.168.1.1:46090 to 192.168.1.9:1812 length 224 Tue Jul 26 16:46:06 2022 : Debug: (7) User-Name = "user" Tue Jul 26 16:46:06 2022 : Debug: (7) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:06 2022 : Debug: (7) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:06 2022 : Debug: (7) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:06 2022 : Debug: (7) Service-Type = Framed-User Tue Jul 26 16:46:06 2022 : Debug: (7) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:06 2022 : Debug: (7) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:06 2022 : Debug: (7) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:06 2022 : Debug: (7) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:06 2022 : Debug: (7) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:06 2022 : Debug: (7) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:06 2022 : Debug: (7) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:06 2022 : Debug: (7) Framed-MTU = 1400 Tue Jul 26 16:46:06 2022 : Debug: (7) EAP-Message = 0x02ee00060d00 Tue Jul 26 16:46:06 2022 : Debug: (7) State = 0x1546e62e14a8eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (7) Message-Authenticator = 0xd3d9cf31bf6747411f8749a7bfebe2b5 Tue Jul 26 16:46:06 2022 : Debug: (7) Restoring &session-state Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (7) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (7) authorize { Tue Jul 26 16:46:06 2022 : Debug: (7) policy filter_username { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name) -> TRUE Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ / /) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:06 2022 : Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:06 2022 : Debug: (7) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (7) } # if (&User-Name) = notfound Tue Jul 26 16:46:06 2022 : Debug: (7) } # policy filter_username = notfound Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (7) [preprocess] = ok Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (7) [chap] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (7) [mschap] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (7) [digest] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (7) suffix: Checking for suffix after "@" Tue Jul 26 16:46:06 2022 : Debug: (7) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:06 2022 : Debug: (7) suffix: No such realm "NULL" Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (7) [suffix] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Peer sent EAP Response (code 2) ID 238 length 6 Tue Jul 26 16:46:06 2022 : Debug: (7) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (7) [eap] = updated Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (7) [files] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (7) [expiration] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (7) [logintime] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (7) [pap] = noop Tue Jul 26 16:46:06 2022 : Debug: (7) } # authorize = updated Tue Jul 26 16:46:06 2022 : Debug: (7) Found Auth-Type = eap Tue Jul 26 16:46:06 2022 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (7) authenticate { Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Expiring EAP session with state 0x1546e62e14a8eb2a Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Finished EAP session with state 0x1546e62e14a8eb2a Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Previous EAP request found for state 0x1546e62e14a8eb2a, released from the list Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:06 2022 : Debug: (7) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:06 2022 : Debug: (7) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:06 2022 : Debug: (7) eap_tls: (TLS) Peer ACKed our handshake fragment Tue Jul 26 16:46:06 2022 : Debug: (7) eap_tls: (TLS) EAP Verification says request Tue Jul 26 16:46:06 2022 : Debug: (7) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:06 2022 : Debug: (7) eap: Sending EAP Request (code 1) ID 239 length 1004 Tue Jul 26 16:46:06 2022 : Debug: (7) eap: EAP session adding &reply:State = 0x1546e62e17a9eb2a Tue Jul 26 16:46:06 2022 : Debug: (7) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (7) [eap] = handled Tue Jul 26 16:46:06 2022 : Debug: (7) } # authenticate = handled Tue Jul 26 16:46:06 2022 : Debug: (7) Using Post-Auth-Type Challenge Tue Jul 26 16:46:06 2022 : Debug: (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (7) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:06 2022 : Debug: (7) session-state: Saving cached attributes Tue Jul 26 16:46:06 2022 : Debug: (7) Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (7) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (7) Sent Access-Challenge Id 143 from 192.168.1.9:1812 to 192.168.1.1:46090 length 1068 Tue Jul 26 16:46:06 2022 : Debug: (7) EAP-Message = 0x01ef03ec0dc000000b5b14d99d4ab6a487455d7897a393bf6c0208fc10802a4f2c5e0d3f7bd0b5c572b4d90ec5ca452fe2c7bb310cdf60b6b04a604b96a6e7e77d1bd91b682a2eb154dbef37ee3b41322481409db0b44660e8f529fad64eaab3f2f76af72ed2f5f1e56a6d3949d1b116940004fe308204fa308203e2a00302010202141f0bb74ab5a65d151582c41942ef11e81d04900c300d06092a864886f70d01010b0500308193310b3009060355040613024652310f300d06035504080c065261646975733112301006035504070c09536f6d65776865726531153013060355040a0c0c4578616d706c6520496e632e3120301e06092a864886f70d010901161161646d696e406578616d706c652e6f72673126302406035504030c1d4578616d706c6520436572746966696361746520417574686f72697479301e170d3232303732303031303732365a170d3232303931383031303732365a308193310b3009060355040613024652310f300d06035504080c06 Tue Jul 26 16:46:06 2022 : Debug: (7) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:06 2022 : Debug: (7) State = 0x1546e62e17a9eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (7) Finished request Tue Jul 26 16:46:06 2022 : Debug: Waking up in 1.0 seconds. Tue Jul 26 16:46:06 2022 : Debug: (8) Received Access-Request Id 144 from 192.168.1.1:46090 to 192.168.1.9:1812 length 224 Tue Jul 26 16:46:06 2022 : Debug: (8) User-Name = "user" Tue Jul 26 16:46:06 2022 : Debug: (8) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:06 2022 : Debug: (8) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:06 2022 : Debug: (8) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:06 2022 : Debug: (8) Service-Type = Framed-User Tue Jul 26 16:46:06 2022 : Debug: (8) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:06 2022 : Debug: (8) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:06 2022 : Debug: (8) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:06 2022 : Debug: (8) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:06 2022 : Debug: (8) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:06 2022 : Debug: (8) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:06 2022 : Debug: (8) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:06 2022 : Debug: (8) Framed-MTU = 1400 Tue Jul 26 16:46:06 2022 : Debug: (8) EAP-Message = 0x02ef00060d00 Tue Jul 26 16:46:06 2022 : Debug: (8) State = 0x1546e62e17a9eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (8) Message-Authenticator = 0x91924fcee303868d2b36f7b0be713404 Tue Jul 26 16:46:06 2022 : Debug: (8) Restoring &session-state Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (8) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (8) authorize { Tue Jul 26 16:46:06 2022 : Debug: (8) policy filter_username { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name) -> TRUE Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ / /) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:06 2022 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:06 2022 : Debug: (8) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (8) } # if (&User-Name) = notfound Tue Jul 26 16:46:06 2022 : Debug: (8) } # policy filter_username = notfound Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (8) [preprocess] = ok Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (8) [chap] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (8) [mschap] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (8) [digest] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (8) suffix: Checking for suffix after "@" Tue Jul 26 16:46:06 2022 : Debug: (8) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:06 2022 : Debug: (8) suffix: No such realm "NULL" Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (8) [suffix] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Peer sent EAP Response (code 2) ID 239 length 6 Tue Jul 26 16:46:06 2022 : Debug: (8) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (8) [eap] = updated Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (8) [files] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (8) [expiration] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (8) [logintime] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (8) [pap] = noop Tue Jul 26 16:46:06 2022 : Debug: (8) } # authorize = updated Tue Jul 26 16:46:06 2022 : Debug: (8) Found Auth-Type = eap Tue Jul 26 16:46:06 2022 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (8) authenticate { Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Expiring EAP session with state 0x1546e62e17a9eb2a Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Finished EAP session with state 0x1546e62e17a9eb2a Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Previous EAP request found for state 0x1546e62e17a9eb2a, released from the list Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:06 2022 : Debug: (8) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:06 2022 : Debug: (8) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:06 2022 : Debug: (8) eap_tls: (TLS) Peer ACKed our handshake fragment Tue Jul 26 16:46:06 2022 : Debug: (8) eap_tls: (TLS) EAP Verification says request Tue Jul 26 16:46:06 2022 : Debug: (8) eap_tls: [eaptls process] = handled Tue Jul 26 16:46:06 2022 : Debug: (8) eap: Sending EAP Request (code 1) ID 240 length 929 Tue Jul 26 16:46:06 2022 : Debug: (8) eap: EAP session adding &reply:State = 0x1546e62e16b6eb2a Tue Jul 26 16:46:06 2022 : Debug: (8) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (8) [eap] = handled Tue Jul 26 16:46:06 2022 : Debug: (8) } # authenticate = handled Tue Jul 26 16:46:06 2022 : Debug: (8) Using Post-Auth-Type Challenge Tue Jul 26 16:46:06 2022 : Debug: (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (8) Challenge { ... } # empty sub-section is ignored Tue Jul 26 16:46:06 2022 : Debug: (8) session-state: Saving cached attributes Tue Jul 26 16:46:06 2022 : Debug: (8) Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (8) TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (8) Sent Access-Challenge Id 144 from 192.168.1.9:1812 to 192.168.1.1:46090 length 993 Tue Jul 26 16:46:06 2022 : Debug: (8) EAP-Message = 0x01f003a10d8000000b5b72746966696361746520417574686f7269747982141f0bb74ab5a65d151582c41942ef11e81d04900c300f0603551d130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b0500038201010065ff74d789b24f3fee1d0081f51e19c4b0b5615136c90ad765fe0d83265a10f28bf5afde23864c12f19f1ebb4ceb509937b0620d52a664ed0d1327a7b146b6c1d56d016042f4bbb34e329d981d32720cdc0919e1c568fb1bbdbcac4a114d48bd643fe8c7c15bc2e2acd3d33a9cc17831e6ebbaa37aff1ca35c2cbaf520eadae7f277acbc8343fe263a8c35fb782c315c71045e1b6780123206f398af036396118743ece71358d324d600319929f291745eb7952a0a6f1cb0f94cbbadcb653e4c4cb9f820c527107f6198b4c958fbce6ff4423bad244942c26dba656ae56cfe458232bcff95b0ed Tue Jul 26 16:46:06 2022 : Debug: (8) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:06 2022 : Debug: (8) State = 0x1546e62e16b6eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (8) Finished request Tue Jul 26 16:46:06 2022 : Debug: Waking up in 1.0 seconds. Tue Jul 26 16:46:06 2022 : Debug: (9) Received Access-Request Id 145 from 192.168.1.1:46090 to 192.168.1.9:1812 length 231 Tue Jul 26 16:46:06 2022 : Debug: (9) User-Name = "user" Tue Jul 26 16:46:06 2022 : Debug: (9) NAS-IP-Address = 127.0.0.1 Tue Jul 26 16:46:06 2022 : Debug: (9) Called-Station-Id = "10-0C-6B-E1-13-55:NETGEAR27-5G-1" Tue Jul 26 16:46:06 2022 : Debug: (9) NAS-Port-Type = Wireless-802.11 Tue Jul 26 16:46:06 2022 : Debug: (9) Service-Type = Framed-User Tue Jul 26 16:46:06 2022 : Debug: (9) Calling-Station-Id = "DE-0D-98-97-FE-E6" Tue Jul 26 16:46:06 2022 : Debug: (9) Connect-Info = "CONNECT 0Mbps 802.11a" Tue Jul 26 16:46:06 2022 : Debug: (9) Acct-Session-Id = "B362C6F2258265D7" Tue Jul 26 16:46:06 2022 : Debug: (9) Acct-Multi-Session-Id = "BEFCEFC35A3B2A51" Tue Jul 26 16:46:06 2022 : Debug: (9) WLAN-Pairwise-Cipher = 1027076 Tue Jul 26 16:46:06 2022 : Debug: (9) WLAN-Group-Cipher = 1027074 Tue Jul 26 16:46:06 2022 : Debug: (9) WLAN-AKM-Suite = 1027073 Tue Jul 26 16:46:06 2022 : Debug: (9) Framed-MTU = 1400 Tue Jul 26 16:46:06 2022 : Debug: (9) EAP-Message = 0x02f0000d0d0015030300020250 Tue Jul 26 16:46:06 2022 : Debug: (9) State = 0x1546e62e16b6eb2ad5a43bed66bdc205 Tue Jul 26 16:46:06 2022 : Debug: (9) Message-Authenticator = 0xb0046be3d1259373fddf4c261729b5a8 Tue Jul 26 16:46:06 2022 : Debug: (9) Restoring &session-state Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:Framed-MTU = 994 Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) recv TLS 1.3 Handshake, ClientHello" Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHello" Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, Certificate" Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerKeyExchange" Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, CertificateRequest" Tue Jul 26 16:46:06 2022 : Debug: (9) &session-state:TLS-Session-Information = "(TLS) send TLS 1.2 Handshake, ServerHelloDone" Tue Jul 26 16:46:06 2022 : Debug: (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (9) authorize { Tue Jul 26 16:46:06 2022 : Debug: (9) policy filter_username { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name) -> TRUE Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ / /) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ / /) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /@[^@]*@/ ) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /\.\./ ) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /\.\./ ) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Tue Jul 26 16:46:06 2022 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /\.$/) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /\.$/) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /@\./) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&User-Name =~ /@\./) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) } # if (&User-Name) = notfound Tue Jul 26 16:46:06 2022 : Debug: (9) } # policy filter_username = notfound Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from preprocess (rlm_preprocess) Tue Jul 26 16:46:06 2022 : Debug: (9) [preprocess] = ok Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from chap (rlm_chap) Tue Jul 26 16:46:06 2022 : Debug: (9) [chap] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from mschap (rlm_mschap) Tue Jul 26 16:46:06 2022 : Debug: (9) [mschap] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from digest (rlm_digest) Tue Jul 26 16:46:06 2022 : Debug: (9) [digest] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (9) suffix: Checking for suffix after "@" Tue Jul 26 16:46:06 2022 : Debug: (9) suffix: No '@' in User-Name = "user", looking up realm NULL Tue Jul 26 16:46:06 2022 : Debug: (9) suffix: No such realm "NULL" Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from suffix (rlm_realm) Tue Jul 26 16:46:06 2022 : Debug: (9) [suffix] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Peer sent EAP Response (code 2) ID 240 length 13 Tue Jul 26 16:46:06 2022 : Debug: (9) eap: No EAP Start, assuming it's an on-going EAP conversation Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) [eap] = updated Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from files (rlm_files) Tue Jul 26 16:46:06 2022 : Debug: (9) [files] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from expiration (rlm_expiration) Tue Jul 26 16:46:06 2022 : Debug: (9) [expiration] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from logintime (rlm_logintime) Tue Jul 26 16:46:06 2022 : Debug: (9) [logintime] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: calling pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authorize]: returned from pap (rlm_pap) Tue Jul 26 16:46:06 2022 : Debug: (9) [pap] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) } # authorize = updated Tue Jul 26 16:46:06 2022 : Debug: (9) Found Auth-Type = eap Tue Jul 26 16:46:06 2022 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (9) authenticate { Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authenticate]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Expiring EAP session with state 0x1546e62e16b6eb2a Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Finished EAP session with state 0x1546e62e16b6eb2a Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Previous EAP request found for state 0x1546e62e16b6eb2a, released from the list Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Peer sent packet with method EAP TLS (13) Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Calling submodule eap_tls to process data Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) EAP Continuing ... Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) EAP Peer sent flags --- Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) EAP Verification says ok Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) EAP Done initial handshake Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) recv TLS 1.2 Alert, fatal internal_error Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) The client is informing us that there is a failure inside the TLS protocol exchange. Tue Jul 26 16:46:06 2022 : ERROR: (9) eap_tls: (TLS) Alert read:fatal:internal error Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) Server : Need to read more data: error Tue Jul 26 16:46:06 2022 : ERROR: (9) eap_tls: (TLS) Failed reading from OpenSSL: ../ssl/record/rec_layer_s3.c[1528]:error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) In Handshake Phase Tue Jul 26 16:46:06 2022 : Debug: (9) eap_tls: (TLS) Application data. Tue Jul 26 16:46:06 2022 : ERROR: (9) eap_tls: (TLS) Cannot continue, as the peer is misbehaving. Tue Jul 26 16:46:06 2022 : ERROR: (9) eap_tls: [eaptls process] = fail Tue Jul 26 16:46:06 2022 : ERROR: (9) eap: Failed continuing EAP TLS (13) session. EAP sub-module failed Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Sending EAP Failure (code 4) ID 240 length 4 Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Failed in EAP select Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[authenticate]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) [eap] = invalid Tue Jul 26 16:46:06 2022 : Debug: (9) } # authenticate = invalid Tue Jul 26 16:46:06 2022 : Debug: (9) Failed to authenticate the user Tue Jul 26 16:46:06 2022 : Debug: (9) Using Post-Auth-Type Reject Tue Jul 26 16:46:06 2022 : Debug: (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Jul 26 16:46:06 2022 : Debug: (9) Post-Auth-Type REJECT { Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) Tue Jul 26 16:46:06 2022 : Debug: %{User-Name} Tue Jul 26 16:46:06 2022 : Debug: Parsed xlat tree: Tue Jul 26 16:46:06 2022 : Debug: attribute --> User-Name Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: EXPAND %{User-Name} Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: --> user Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: Matched entry DEFAULT at line 11 Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: EAP-Message = 0x04f00004 allowed by EAP-Message =* 0x Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Tue Jul 26 16:46:06 2022 : Debug: (9) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) Tue Jul 26 16:46:06 2022 : Debug: (9) [attr_filter.access_reject] = updated Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: calling eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) eap: Reply already contained an EAP-Message, not inserting EAP-Failure Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: returned from eap (rlm_eap) Tue Jul 26 16:46:06 2022 : Debug: (9) [eap] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) policy remove_reply_message_if_eap { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&reply:EAP-Message && &reply:Reply-Message) { Tue Jul 26 16:46:06 2022 : Debug: (9) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Tue Jul 26 16:46:06 2022 : Debug: (9) else { Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: calling noop (rlm_always) Tue Jul 26 16:46:06 2022 : Debug: (9) modsingle[post-auth]: returned from noop (rlm_always) Tue Jul 26 16:46:06 2022 : Debug: (9) [noop] = noop Tue Jul 26 16:46:06 2022 : Debug: (9) } # else = noop Tue Jul 26 16:46:06 2022 : Debug: (9) } # policy remove_reply_message_if_eap = noop Tue Jul 26 16:46:06 2022 : Debug: (9) } # Post-Auth-Type REJECT = updated Tue Jul 26 16:46:06 2022 : Debug: (9) Delaying response for 1.000000 seconds Tue Jul 26 16:46:06 2022 : Debug: Waking up in 0.3 seconds. Tue Jul 26 16:46:06 2022 : Debug: Waking up in 0.6 seconds. Tue Jul 26 16:46:07 2022 : Debug: (9) Sending delayed response Tue Jul 26 16:46:07 2022 : Debug: (9) Sent Access-Reject Id 145 from 192.168.1.9:1812 to 192.168.1.1:46090 length 44 Tue Jul 26 16:46:07 2022 : Debug: (9) EAP-Message = 0x04f00004 Tue Jul 26 16:46:07 2022 : Debug: (9) Message-Authenticator = 0x00000000000000000000000000000000 Tue Jul 26 16:46:07 2022 : Debug: (0) Cleaning up request packet ID 136 with timestamp +39 due to cleanup_delay was reached Tue Jul 26 16:46:07 2022 : Debug: (1) Cleaning up request packet ID 137 with timestamp +39 due to cleanup_delay was reached Tue Jul 26 16:46:07 2022 : Debug: (2) Cleaning up request packet ID 138 with timestamp +39 due to cleanup_delay was reached Tue Jul 26 16:46:07 2022 : Debug: (3) Cleaning up request packet ID 139 with timestamp +39 due to cleanup_delay was reached Tue Jul 26 16:46:07 2022 : Debug: (4) Cleaning up request packet ID 140 with timestamp +39 due to cleanup_delay was reached Tue Jul 26 16:46:07 2022 : Debug: Waking up in 3.8 seconds. Tue Jul 26 16:46:11 2022 : Debug: (5) Cleaning up request packet ID 141 with timestamp +43 due to cleanup_delay was reached Tue Jul 26 16:46:11 2022 : Debug: (6) Cleaning up request packet ID 142 with timestamp +43 due to cleanup_delay was reached Tue Jul 26 16:46:11 2022 : Debug: (7) Cleaning up request packet ID 143 with timestamp +43 due to cleanup_delay was reached Tue Jul 26 16:46:11 2022 : Debug: (8) Cleaning up request packet ID 144 with timestamp +43 due to cleanup_delay was reached Tue Jul 26 16:46:11 2022 : Debug: (9) Cleaning up request packet ID 145 with timestamp +43 due to cleanup_delay was reached Tue Jul 26 16:46:11 2022 : Info: Ready to process requests