May 2019 - Freeradius-Users - lists.freeradius.org

OFFER doesnot have any other option than message_type
by Chinnapaiyan, Nagamani 08 May '19

08 May '19

Hi, The dhcp offer message does not have any option other than message type. (see attached test.pcap) Even though, debug output shows it is included in the offer. git commit hash is latest one from master branch: f4c62999942bc76506cd9e9a22db85d5c837bfe9 # /sbin/radiusd -X Info : FreeRADIUS Version 4.0.0 Info : Copyright 1999-2019 The FreeRADIUS server project and contributors Info : There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info : PARTICULAR PURPOSE Info : You may redistribute copies of FreeRADIUS under the terms of the Info : GNU General Public License Info : For more information about these matters, see the file named COPYRIGHT Info : Starting - reading configuration files ... Debug : Including dictionary file "/etc/raddb/dictionary" Debug : including configuration file /etc/raddb/radiusd.conf Debug : including configuration file /etc/raddb/clients.conf Debug : Including files in directory "/etc/raddb/mods-enabled/" Debug : including configuration file /etc/raddb/mods-enabled/always Debug : including configuration file /etc/raddb/mods-enabled/attr_filter Debug : including configuration file /etc/raddb/mods-enabled/cache_eap Debug : including configuration file /etc/raddb/mods-enabled/chap Debug : including configuration file /etc/raddb/mods-enabled/client Debug : including configuration file /etc/raddb/mods-enabled/delay Debug : including configuration file /etc/raddb/mods-enabled/detail Debug : including configuration file /etc/raddb/mods-enabled/detail.log Debug : including configuration file /etc/raddb/mods-enabled/dhcpv4 Debug : including configuration file /etc/raddb/mods-enabled/digest Debug : including configuration file /etc/raddb/mods-enabled/echo Debug : including configuration file /etc/raddb/mods-enabled/escape Debug : including configuration file /etc/raddb/mods-enabled/exec Debug : including configuration file /etc/raddb/mods-enabled/expiration Debug : including configuration file /etc/raddb/mods-enabled/expr Debug : including configuration file /etc/raddb/mods-enabled/files Debug : including configuration file /etc/raddb/mods-enabled/linelog Debug : including configuration file /etc/raddb/mods-enabled/logintime Debug : including configuration file /etc/raddb/mods-enabled/mschap Debug : including configuration file /etc/raddb/mods-enabled/ntlm_auth Debug : including configuration file /etc/raddb/mods-enabled/pap Debug : including configuration file /etc/raddb/mods-enabled/passwd Debug : including configuration file /etc/raddb/mods-enabled/radius Debug : including configuration file /etc/raddb/mods-enabled/radutmp Debug : including configuration file /etc/raddb/mods-enabled/sradutmp Debug : including configuration file /etc/raddb/mods-enabled/stats Debug : including configuration file /etc/raddb/mods-enabled/unix Debug : including configuration file /etc/raddb/mods-enabled/unpack Debug : including configuration file /etc/raddb/mods-enabled/utf8 Debug : including configuration file /etc/raddb/mods-enabled/redis_ippool Debug : including configuration file /etc/raddb/mods-enabled/redis Debug : Including files in directory "/etc/raddb/policy.d/" Debug : including configuration file /etc/raddb/policy.d/abfab-tr Debug : including configuration file /etc/raddb/policy.d/accounting Debug : including configuration file /etc/raddb/policy.d/canonicalization Debug : including configuration file /etc/raddb/policy.d/control Debug : including configuration file /etc/raddb/policy.d/cui Debug : including configuration file /etc/raddb/policy.d/debug Debug : including configuration file /etc/raddb/policy.d/dhcp Debug : including configuration file /etc/raddb/policy.d/eap Debug : including configuration file /etc/raddb/policy.d/filter Debug : including configuration file /etc/raddb/policy.d/operator-name Debug : including configuration file /etc/raddb/policy.d/time Debug : including configuration file /etc/raddb/policy.d/vendor Debug : Including files in directory "/etc/raddb/sites-enabled/" Debug : including configuration file /etc/raddb/sites-enabled/dhcp Debug : Loading dictionaries for proto_dhcpv4 Info : Loaded module "proto_dhcpv4" Debug : Parsing security rules to bootstrap UID / GID / chroot / etc. Debug : main { Debug : security { Debug : allow_core_dumps = no Debug : allow_vulnerable_openssl = "no" Debug : openssl_fips_mode = no Debug : } Debug : name = radiusd Debug : name = "radiusd" Debug : prefix = "/usr" Debug : local_state_dir = "/usr/var" Debug : run_dir = "/var/run/radiusd" Debug : } Debug : Parsing main configuration. Debug : main { Debug : server dhcp { Debug : listen { Debug : type = DHCP-Discover Debug : Loading dictionaries for proto_dhcpv4_base Info : Loaded module "proto_dhcpv4_base" Debug : type = DHCP-Request Debug : type = DHCP-Inform Debug : type = DHCP-Release Debug : type = DHCP-Decline Debug : transport = udp Debug : Loading dictionaries for proto_dhcpv4_udp Info : Loaded module "proto_dhcpv4_udp" Debug : udp { Debug : ipaddr = 10.43.18.104 Debug : src_ipaddr = 10.43.18.104 Debug : port = 67 Debug : broadcast = no Debug : networks { Debug : } Debug : max_packet_size = 4096 Debug : max_attributes = 0 Debug : } Debug : limit { Debug : idle_timeout = 30.000000 Debug : nak_lifetime = 30.000000 Debug : max_connections = 1024 Debug : max_clients = 256 Debug : max_pending_packets = 256 Debug : priority { Debug : DHCP-Discover = normal Debug : DHCP-Request = normal Debug : DHCP-Decline = normal Debug : DHCP-Release = normal Debug : DHCP-Inform = normal Debug : DHCP-Lease-Query = low Debug : DHCP-Bulk-Lease-Query = low Debug : } Debug : } Debug : } Debug : } Debug : security { Debug : } Debug : sbin_dir = "/usr/sbin" Debug : logdir = "/var/log/radius" Debug : libdir = "/usr/lib64/freeradius" Debug : radacctdir = "/var/log/radius/radacct" Debug : reverse_lookups = no Debug : reverse_lookups = no Debug : hostname_lookups = yes Debug : hostname_lookups = yes Debug : max_request_time = 30 Debug : max_request_time = 30 Debug : pidfile = "/var/run/radiusd/radiusd.pid" Debug : debug_level = 0 Debug : log { Debug : colourise = yes Debug : } Debug : resources { Debug : } Debug : thread pool { Debug : num_networks = 1 Debug : num_networks = 1 Debug : num_workers = 4 Debug : num_workers = 4 Debug : } Debug : } Switching to configured log settings radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } client localhost_ipv6 { ipv6addr = ::1 require_message_authenticator = no secret = <<< secret >>> limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached trigger { ... } subsection not found, triggers will be disabled systemd watchdog is disabled #### Bootstrapping listeners #### #### Bootstrapping modules #### modules { Loaded module "rlm_always" always reject { rcode = "reject" simulcount = 0 mpp = no } always fail { rcode = "fail" simulcount = 0 mpp = no } always ok { rcode = "ok" simulcount = 0 mpp = no } always handled { rcode = "handled" simulcount = 0 mpp = no } always invalid { rcode = "invalid" simulcount = 0 mpp = no } always userlock { rcode = "userlock" simulcount = 0 mpp = no } always notfound { rcode = "notfound" simulcount = 0 mpp = no } always noop { rcode = "noop" simulcount = 0 mpp = no } always updated { rcode = "updated" simulcount = 0 mpp = no } Loading dictionaries for rlm_attr_filter Loaded module "rlm_attr_filter" attr_filter attr_filter.pre-proxy { filename = "/etc/raddb/mods-config/attr_filter/pre-proxy" relaxed = no } attr_filter attr_filter.post-proxy { filename = "/etc/raddb/mods-config/attr_filter/post-proxy" relaxed = no } attr_filter attr_filter.access_reject { filename = "/etc/raddb/mods-config/attr_filter/access_reject" relaxed = no } attr_filter attr_filter.access_challenge { filename = "/etc/raddb/mods-config/attr_filter/access_challenge" relaxed = no } attr_filter attr_filter.accounting_response { filename = "/etc/raddb/mods-config/attr_filter/accounting_response" relaxed = no } Loading dictionaries for rlm_cache Loaded module "rlm_cache" cache cache_eap { driver = "rlm_cache_rbtree" ttl = 15 max_entries = 0 epoch = 0 add_stats = no } Bootstrapping module "cache_eap" Loaded module "rlm_cache_rbtree" Loading dictionaries for rlm_chap Loaded module "rlm_chap" Bootstrapping module "chap" Loaded module "rlm_client" Bootstrapping module "client" Loaded module "rlm_delay" delay { relative = no force_reschedule = no } Bootstrapping module "delay" delay delay_reject { relative = yes force_reschedule = no } Bootstrapping module "delay_reject" Loading dictionaries for rlm_detail Loaded module "rlm_detail" detail { filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y-%m-%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } detail auth_log { filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y-%m-%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } detail reply_log { filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y-%m-%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } detail pre_proxy_log { filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y-%m-%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } detail post_proxy_log { filename = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y-%m-%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } Loading dictionaries for rlm_dhcpv4 Loaded module "rlm_dhcpv4" Loading dictionaries for rlm_digest Loaded module "rlm_digest" Bootstrapping module "digest" Loaded module "rlm_exec" exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = "request" output_pairs = "reply" shell_escape = yes } Bootstrapping module "echo" Loaded module "rlm_escape" escape { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" } Bootstrapping module "escape" exec { wait = yes input_pairs = "request" shell_escape = yes timeout = 10 } Bootstrapping module "exec" Loading dictionaries for rlm_expiration Loaded module "rlm_expiration" Loaded module "rlm_expr" Bootstrapping module "expr" Loading dictionaries for rlm_files Loaded module "rlm_files" files { filename = "/etc/raddb/mods-config/files/authorize" acctusersfile = "/etc/raddb/mods-config/files/accounting" preproxy_usersfile = "/etc/raddb/mods-config/files/pre-proxy" } Loaded module "rlm_linelog" linelog { destination = "file" delimiter = "\n" file { filename = "/var/log/radius/linelog" permissions = 384 escape_filenames = no } syslog { severity = "info" } unix { } tcp { server = localhost IPv4 address [127.0.0.1] port = 514 timeout = 2.000000 } udp { server = localhost IPv4 address [127.0.0.1] port = 514 timeout = 2.000000 } } linelog log_accounting { destination = "file" delimiter = "\n" file { filename = "/var/log/radius/linelog-accounting" permissions = 384 escape_filenames = no } syslog { severity = "info" } unix { } tcp { timeout = 1000.000000 } udp { timeout = 1000.000000 } } Loading dictionaries for rlm_logintime Loaded module "rlm_logintime" logintime { minimum_timeout = 60 } Loading dictionaries for rlm_mschap Loaded module "rlm_mschap" mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes winbind { retry_with_normalised_username = no } } Bootstrapping module "mschap" exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } Bootstrapping module "ntlm_auth" Loading dictionaries for rlm_pap Loaded module "rlm_pap" pap { normalise = yes } Bootstrapping module "pap" Loading dictionaries for rlm_passwd Loaded module "rlm_passwd" passwd etc_passwd { filename = "/etc/passwd" format = "*User-Name:Crypt-Password:" delimiter = ":" ignore_nislike = no ignore_empty = yes allow_multiple_keys = no hash_size = 100 } Loading dictionaries for rlm_radius Loaded module "rlm_radius" radius { transport = udp Loading dictionaries for rlm_radius_udp Loaded module "rlm_radius_udp" udp { ipaddr = 127.0.0.1 port = 1812 secret = "testing123" max_packet_size = 4096 } type = Access-Request type = Accounting-Request status_checks { type = Status-Server } max_connections = 32 max_attributes = 255 connection { connect_timeout = 5.000000 reconnect_delay = 5.000000 idle_timeout = 5.000000 zombie_period = 10.000000 } Access-Request { initial_retransmission_time = 2 maximum_retransmission_time = 16 maximum_retransmission_count = 2 maximum_retransmission_duration = 30 } Accounting-Request { initial_retransmission_time = 2 maximum_retransmission_time = 16 maximum_retransmission_count = 5 maximum_retransmission_duration = 30 } Status-Server { initial_retransmission_time = 2 maximum_retransmission_time = 16 maximum_retransmission_count = 5 maximum_retransmission_duration = 30 } } Bootstrapping module "radius" Loading dictionaries for rlm_radutmp Loaded module "rlm_radutmp" radutmp { filename = "/var/log/radius/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 384 caller_id = no } radutmp sradutmp { filename = "/var/log/radius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } Loading dictionaries for rlm_stats Loaded module "rlm_stats" stats { } Loading dictionaries for rlm_unix Loaded module "rlm_unix" unix { } Bootstrapping module "unix" Creating attribute Unix-Group Loading dictionaries for rlm_unpack Loaded module "rlm_unpack" Bootstrapping module "unpack" Loaded module "rlm_utf8" libfreeradius-redis: libhiredis version: 0.12.1 Loading dictionaries for rlm_redis_ippool Loaded module "rlm_redis_ippool" redis_ippool { copy_on_update = yes redis { server = "devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com" port = 6379 database = 0 max_nodes = 20 max_alt = 3 max_redirects = 2 } } libfreeradius-redis: libhiredis version: 0.12.1 Loaded module "rlm_redis" redis { server = "devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com" port = 6379 database = 0 max_nodes = 20 max_alt = 3 max_redirects = 2 } Bootstrapping module "redis" instantiate { } } # modules #### Instantiating listeners #### Compiling policies in server dhcp { ... } Compiling policies in - recv DHCP-Discover {...} Compiling policies in - recv DHCP-Request {...} Compiling policies in - recv DHCP-Release {...} Compiling policies in - recv DHCP-Inform {...} Compiling policies in - recv DHCP-Lease-Query {...} /etc/raddb/sites-enabled/dhcp[306]: recv DHCP-Decline { ... } section is unused #### Instantiating modules #### Instantiating module "attr_filter.access_challenge" Reading file /etc/raddb/mods-config/attr_filter/access_challenge Instantiating module "attr_filter.access_reject" Reading file /etc/raddb/mods-config/attr_filter/access_reject Instantiating module "attr_filter.accounting_response" Reading file /etc/raddb/mods-config/attr_filter/accounting_response Instantiating module "attr_filter.post-proxy" Reading file /etc/raddb/mods-config/attr_filter/post-proxy Instantiating module "attr_filter.pre-proxy" Reading file /etc/raddb/mods-config/attr_filter/pre-proxy Instantiating module "auth_log" rlm_detail (auth_log) - 'User-Password' suppressed, will not appear in detail output Instantiating module "cache_eap" Instantiating module "detail" Instantiating module "etc_passwd" Instantiating module "expiration" Instantiating module "fail" Instantiating module "files" Reading file /etc/raddb/mods-config/files/authorize Reading file /etc/raddb/mods-config/files/accounting Reading file /etc/raddb/mods-config/files/pre-proxy Instantiating module "handled" Instantiating module "invalid" Instantiating module "linelog" Instantiating module "log_accounting" Instantiating module "logintime" Instantiating module "mschap" mschap: using internal authentication Instantiating module "noop" Instantiating module "notfound" Instantiating module "ok" Instantiating module "post_proxy_log" Instantiating module "pre_proxy_log" Instantiating module "radius" Instantiating module "redis" rlm_redis (redis) [1] - Initialising connection pool pool { start = 4 min = 4 max = 4 max_pending = 0 spare = 1 uses = 0 lifetime = 86400 cleanup_interval = 300 idle_timeout = 600 connect_timeout = 3.000000 held_trigger_min = 0.000000 held_trigger_max = 0.500000 retry_delay = 30 spread = no } rlm_redis (redis) [1] - Ignoring "spare = 1", forcing to "spare = 0" rlm_redis (redis) [1] - Opening additional connection (0), 1 of 4 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 rlm_redis (redis) [1] - Opening additional connection (1), 1 of 3 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 rlm_redis (redis) [1] - Opening additional connection (2), 1 of 2 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 rlm_redis (redis) [1] - Opening additional connection (3), 1 of 1 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 rlm_redis (redis) [1] - Reserved connection (3) rlm_redis (redis) [1] - Released connection (3) rlm_redis (redis) - Cluster map consists of 1 key ranges rlm_redis (redis) - 0 - keys 0-16383 rlm_redis (redis) - master: 10.43.17.86:6379 rlm_redis (redis) - slave0: 10.43.16.148:6379 rlm_redis (redis) - slave1: 10.43.16.109:6379 rlm_redis (redis) [2] - Initialising connection pool pool { start = 4 min = 4 max = 4 max_pending = 0 spare = 1 uses = 0 lifetime = 86400 cleanup_interval = 300 idle_timeout = 600 connect_timeout = 3.000000 held_trigger_min = 0.000000 held_trigger_max = 0.500000 retry_delay = 30 spread = no } rlm_redis (redis) [2] - Ignoring "spare = 1", forcing to "spare = 0" rlm_redis (redis) [2] - Opening additional connection (0), 1 of 4 pending slots used rlm_redis (redis) - [2] Connecting to node 10.43.16.148:6379 rlm_redis (redis) [2] - Opening additional connection (1), 1 of 3 pending slots used rlm_redis (redis) - [2] Connecting to node 10.43.16.148:6379 rlm_redis (redis) [2] - Opening additional connection (2), 1 of 2 pending slots used rlm_redis (redis) - [2] Connecting to node 10.43.16.148:6379 rlm_redis (redis) [2] - Opening additional connection (3), 1 of 1 pending slots used rlm_redis (redis) - [2] Connecting to node 10.43.16.148:6379 rlm_redis (redis) [3] - Initialising connection pool pool { start = 4 min = 4 max = 4 max_pending = 0 spare = 1 uses = 0 lifetime = 86400 cleanup_interval = 300 idle_timeout = 600 connect_timeout = 3.000000 held_trigger_min = 0.000000 held_trigger_max = 0.500000 retry_delay = 30 spread = no } rlm_redis (redis) [3] - Ignoring "spare = 1", forcing to "spare = 0" rlm_redis (redis) [3] - Opening additional connection (0), 1 of 4 pending slots used rlm_redis (redis) - [3] Connecting to node 10.43.16.109:6379 rlm_redis (redis) [3] - Opening additional connection (1), 1 of 3 pending slots used rlm_redis (redis) - [3] Connecting to node 10.43.16.109:6379 rlm_redis (redis) [3] - Opening additional connection (2), 1 of 2 pending slots used rlm_redis (redis) - [3] Connecting to node 10.43.16.109:6379 rlm_redis (redis) [3] - Opening additional connection (3), 1 of 1 pending slots used rlm_redis (redis) - [3] Connecting to node 10.43.16.109:6379 Instantiating module "redis_ippool" rlm_redis (redis) [1] - Initialising connection pool pool { start = 0 min = 4 max = 4 max_pending = 0 spare = 1 uses = 0 lifetime = 0 cleanup_interval = 30 idle_timeout = 60 connect_timeout = 3.000000 held_trigger_min = 0.000000 held_trigger_max = 0.500000 retry_delay = 30 spread = no } rlm_redis (redis) [1] - Ignoring "spare = 1", forcing to "spare = 0" rlm_redis (redis) [1] - 0 of 0 connections in use. You may need to increase "spare" rlm_redis (redis) [1] - Opening additional connection (0), 1 of 4 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 rlm_redis (redis) [1] - Reserved connection (0) rlm_redis (redis) [1] - Released connection (0) rlm_redis (redis) [1] - Need 3 more connections to reach min connections (4) rlm_redis (redis) [1] - Opening additional connection (1), 1 of 3 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 Instantiating module "reject" Instantiating module "reply_log" Instantiating module "stats" Instantiating module "updated" Instantiating module "userlock" Instantiating module "cache_eap.rbtree" [1] radius - Connection initialising [1] radius - Connection initialised Scheduler created in single-threaded mode #### Opening listener interfaces #### Listening on dhcpv4 address proto_dhcpv4_udp server 10.43.18.104 port 67 bound to virtual server dhcp Waking up in 4.9 seconds. radius - Connection open - proto udp local 0.0.0.0 port 32817 remote 127.0.0.1 port 1812 radius - Allocated Status-Server ID 0 for status checks on connection proto udp local 0.0.0.0 port 32817 remote 127.0.0.1 port 1812 radius - Setting idle timeout to +5.000000 for connection proto udp local 0.0.0.0 port 32817 remote 127.0.0.1 port 1812 [1] radius - Connection established Waking up in 4.9 seconds. Waking up in 4.9 seconds. proto_dhcpv4_udp - Received DHCP-Discover XID 10000000 length 311 proto_dhcpv4_udp server 10.43.18.104 port 67 Resetting worker 30 cleanup timer to +0s (0) running request (0) Received DHCP-Discover XID 10000000 from 10.43.18.180:67 to 10.43.18.104:67 via eth1 (0) &DHCP-Opcode = Client-Message (0) &DHCP-Hardware-Type = Ethernet (0) &DHCP-Hardware-Address-Length = 6 (0) &DHCP-Hop-Count = 0 (0) &DHCP-Transaction-Id = 268435456 (0) &DHCP-Number-of-Seconds = 0 (0) &DHCP-Flags = 0 (0) &DHCP-Client-IP-Address = 0.0.0.0 (0) &DHCP-Your-IP-Address = 0.0.0.0 (0) &DHCP-Server-IP-Address = 0.0.0.0 (0) &DHCP-Gateway-IP-Address = 10.43.18.180 (0) &DHCP-Client-Hardware-Address = 00:a0:bc:00:00:0a (0) &DHCP-Message-Type = DHCP-Discover (0) &DHCP-Parameter-Request-List = DHCP-Subnet-Mask (0) &DHCP-Parameter-Request-List = DHCP-Broadcast-Address (0) &DHCP-Parameter-Request-List = DHCP-Time-Offset (0) &DHCP-Parameter-Request-List = DHCP-Router-Address (0) &DHCP-Parameter-Request-List = DHCP-Domain-Name (0) &DHCP-Parameter-Request-List = DHCP-Domain-Name-Server (0) &DHCP-Parameter-Request-List = DHCP-Hostname (0) &DHCP-DHCP-Maximum-Msg-Size = 1500 (0) &DHCP-Subscriber-Id = "10myidsimres(a)unassigned.viasat.com" (0) &DHCP-Relay-Remote-Id = 0x00a0bc00000a (0) &DHCP-Relay-Circuit-Id = 0x000000000064 (0) Running 'recv DHCP-Discover' from file /etc/raddb/sites-enabled/dhcp (0) recv DHCP-Discover { (0) update reply { (0) &DHCP-Message-Type = DHCP-Offer (0) } # update reply (noop) (0) update reply { (0) &DHCP-Subnet-Mask = 255.255.255.0 (0) &DHCP-Router-Address = 192.0.2.1 (0) &DHCP-DHCP-Server-Identifier = 10.43.18.104 (0) } # update reply (noop) (0) if ("0x%{hex:%{DHCP-Client-Hardware-Address}}" == "%{DHCP-Relay-Remote-Id}") { (0) EXPAND 0x%{hex:%{DHCP-Client-Hardware-Address}} (0) EXPAND %{DHCP-Client-Hardware-Address} (0) --> 00:a0:bc:00:00:0a (0) EXPAND %{hex:%{DHCP-Client-Hardware-Address}} (0) (%{hex:00:a0:bc:00:00:0a}) (0) --> 00a0bc00000a (0) --> 0x00a0bc00000a (0) EXPAND %{DHCP-Relay-Remote-Id} (0) --> 0x00a0bc00000a (0) if ("%{DHCP-Subscriber-Id}" =~ /^.*(res.via|signed).*$/) { (0) EXPAND %{DHCP-Subscriber-Id} (0) --> 10myidsimres(a)unassigned.viasat.com (0) update control { (0) &Pool-Name := "VSAT-UT" (0) } # update control (noop) (0) } # if ("%{DHCP-Subscriber-Id}" =~ /^.*(res.via|signed).*$/) (noop) (0) update reply { (0) Key "viasatut:option43" -> slot 12207 (0) Reserved connection (3) (0) [1] >>> Sending command(s) to 10.43.17.86:6379 (0) Executing command: GET (0) With arguments (0) [1] viasatut:option43 (0) [1] <<< Returned: success (0) Released connection (3) (0) EXPAND %{redis: GET viasatut:option43} (0) --> 010300a0bc0c0200060e0100145e0100020103110500440044070043004301000201030606c0a86400180700500050010102010306070016001701010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f000000082651687474703a2f2f616373696e7430312d6661742e6465762e6e617730312e636d742e7669617361742e696f3a393637352f6c6976652f4350454d616e616765722f435045732f67656e6572696354523639 (0) EXPAND %{bin:%{redis: GET viasatut:option43}} (0) (%{bin:010300a0bc0c0200060e0100145e0100020103110500440044070043004301000201030606c0a86400180700500050010102010306070016001701010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f000000082651687474703a2f2f616373696e7430312d6661742e6465762e6e617730312e636d742e7669617361742e696f3a393637352f6c6976652f4350454d616e616765722f435045732f67656e6572696354523639}) (0) --> 0x010300a0bc0c0200060e0100145e0100020103110500440044070043004301000201030606c0a86400180700500050010102010306070016001701010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f000000082651687474703a2f2f616373696e7430312d6661742e6465762e6e617730312e636d742e7669617361742e696f3a393637352f6c6976652f4350454d616e616765722f435045732f67656e6572696354523639 (0) &DHCP-IP-Address-Lease-Time = 900 (0) &DHCP-Domain-Name-Server = 72.173.31.41 (0) &DHCP-Domain-Name-Server = 72.173.31.42 (0) &DHCP-Vendor = 0x010300a0bc0c0200060e0100145e0100020103110500440044070043004301000201030606c0a86400180700500050010102010306070016001701010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f000000082651687474703a2f2f616373696e7430312d6661742e6465762e6e617730312e636d742e7669617361742e696f3a393637352f6c6976652f4350454d616e616765722f435045732f67656e6572696354523639 (0) } # update reply (noop) (0) } # if ("0x%{hex:%{DHCP-Client-Hardware-Address}}" == "%{DHCP-Relay-Remote-Id}") (noop) (0) redis_ippool - Allocating lease from pool "VSAT-UT", to "00:a0:bc:00:00:0a", expires in 900s (0) redis_ippool - Reserved connection (1) (0) redis_ippool - [1] >>> Sending command(s) to 10.43.17.86:6379 (0) redis_ippool - [1] <<< Returned: success (0) redis_ippool - Released connection (1) (0) redis_ippool - Need 2 more connections to reach min connections (4) (0) redis_ippool - Opening additional connection (2), 1 of 2 pending slots used rlm_redis (redis) - [1] Connecting to node 10.43.17.86:6379 (0) redis_ippool - &reply:DHCP-Your-IP-Address := 10.88.64.130 (0) redis_ippool - &reply:DHCP-IP-Address-Lease-Time := 824 (0) redis_ippool - IP address lease allocated (0) redis_ippool (updated) (0) ok (ok) (0) } # recv DHCP-Discover (updated) (0) Sending DHCP-Offer XID 10000000 from 10.43.18.104:67 to 10.43.18.180:67 via eth1 (0) &DHCP-Message-Type = DHCP-Offer (0) &DHCP-Subnet-Mask = 255.255.255.0 (0) &DHCP-Router-Address = 192.0.2.1 (0) &DHCP-DHCP-Server-Identifier = 10.43.18.104 (0) &DHCP-IP-Address-Lease-Time := 824 (0) &DHCP-Domain-Name-Server = 72.173.31.41 (0) &DHCP-Vendor = 0x010300a0bc0c0200060e0100145e0100020103110500440044070043004301000201030606c0a86400180700500050010102010306070016001701010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f000000082651687474703a2f2f616373696e7430312d6661742e6465762e6e617730312e636d742e7669617361742e696f3a393637352f6c6976652f4350454d616e616765722f435045732f67656e6572696354523639 (0) done request (0) finished request. Waking up in 0.8 seconds. Reply will be sent to giaddr. proto_dhcpv4_udp - cleaning up ID 1 Waking up in 0.8 seconds. radius - Idle timeout for connection proto udp local 0.0.0.0 port 32817 remote 127.0.0.1 port 1812 [1] radius - Closing connection (25) radius - Connection closed - proto udp local 0.0.0.0 port 32817 remote 127.0.0.1 port 1812 Ready to process requests Regards, Nagamani Chinnapaiyan

2 1

Always get: Expected Access-Accept got Access-Reject
by Alexandre Lessard 08 May '19

08 May '19

Hi, I'm new to Freeradius and I kind of fell bad to ask to the community about this basic issue. But here it is. I have just made a fresh Debian 9 install with with Freeradius 3.0.1 by doing those exact command: apt update apt upgrade apt install freeradius I also install Mysql because i plan to use it: apt install mysql-server After this, I've configure a test user in users by doing this: cd /etc/freeradius/3.0/ echo 'testing Cleartext-Password := "password"' | cat - users > temp && mv temp users That simply add the line testing Cleartext-Password := "password" to the top of users. Next, I simply run a radtest in debug mode: freeradius -X And open another terminal to do the radtest: radtest testing password localhost 0 testing123 The problem is that I always receive a Access-Reject. What am I doing wrong? I've read the instruction many times and i don't get it. Here is the debug output: root@Freeradius3Client:~# freeradius -X FreeRADIUS Version 3.0.12 Copyright (C) 1999-2016 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /usr/share/freeradius/dictionary including dictionary file /usr/share/freeradius/dictionary.dhcp including dictionary file /usr/share/freeradius/dictionary.vqp including dictionary file /etc/freeradius/3.0/dictionary including configuration file /etc/freeradius/3.0/radiusd.conf including configuration file /etc/freeradius/3.0/proxy.conf including configuration file /etc/freeradius/3.0/clients.conf including files in directory /etc/freeradius/3.0/mods-enabled/ including configuration file /etc/freeradius/3.0/mods-enabled/logintime including configuration file /etc/freeradius/3.0/mods-enabled/passwd including configuration file /etc/freeradius/3.0/mods-enabled/utf8 including configuration file /etc/freeradius/3.0/mods-enabled/detail.log including configuration file /etc/freeradius/3.0/mods-enabled/chap including configuration file /etc/freeradius/3.0/mods-enabled/eap including configuration file /etc/freeradius/3.0/mods-enabled/expr including configuration file /etc/freeradius/3.0/mods-enabled/digest including configuration file /etc/freeradius/3.0/mods-enabled/linelog including configuration file /etc/freeradius/3.0/mods-enabled/preprocess including configuration file /etc/freeradius/3.0/mods-enabled/detail including configuration file /etc/freeradius/3.0/mods-enabled/unix including configuration file /etc/freeradius/3.0/mods-enabled/files including configuration file /etc/freeradius/3.0/mods-enabled/sradutmp including configuration file /etc/freeradius/3.0/mods-enabled/soh including configuration file /etc/freeradius/3.0/mods-enabled/cache_eap including configuration file /etc/freeradius/3.0/mods-enabled/expiration including configuration file /etc/freeradius/3.0/mods-enabled/unpack including configuration file /etc/freeradius/3.0/mods-enabled/pap including configuration file /etc/freeradius/3.0/mods-enabled/exec including configuration file /etc/freeradius/3.0/mods-enabled/dynamic_clients including configuration file /etc/freeradius/3.0/mods-enabled/radutmp including configuration file /etc/freeradius/3.0/mods-enabled/realm including configuration file /etc/freeradius/3.0/mods-enabled/ntlm_auth including configuration file /etc/freeradius/3.0/mods-enabled/always including configuration file /etc/freeradius/3.0/mods-enabled/attr_filter including configuration file /etc/freeradius/3.0/mods-enabled/replicate including configuration file /etc/freeradius/3.0/mods-enabled/mschap including configuration file /etc/freeradius/3.0/mods-enabled/echo including files in directory /etc/freeradius/3.0/policy.d/ including configuration file /etc/freeradius/3.0/policy.d/filter including configuration file /etc/freeradius/3.0/policy.d/dhcp including configuration file /etc/freeradius/3.0/policy.d/abfab-tr including configuration file /etc/freeradius/3.0/policy.d/cui including configuration file /etc/freeradius/3.0/policy.d/debug including configuration file /etc/freeradius/3.0/policy.d/moonshot-targeted-ids including configuration file /etc/freeradius/3.0/policy.d/eap including configuration file /etc/freeradius/3.0/policy.d/canonicalization including configuration file /etc/freeradius/3.0/policy.d/control including configuration file /etc/freeradius/3.0/policy.d/accounting including configuration file /etc/freeradius/3.0/policy.d/operator-name including files in directory /etc/freeradius/3.0/sites-enabled/ including configuration file /etc/freeradius/3.0/sites-enabled/default including configuration file /etc/freeradius/3.0/sites-enabled/inner-tunnel main { security { user = "freerad" group = "freerad" allow_core_dumps = no } name = "freeradius" prefix = "/usr" localstatedir = "/var" logdir = "/var/log/freeradius" run_dir = "/var/run/freeradius" } main { name = "freeradius" prefix = "/usr" localstatedir = "/var" sbindir = "/usr/sbin" logdir = "/var/log/freeradius" run_dir = "/var/run/freeradius" libdir = "/usr/lib/freeradius" radacctdir = "/var/log/freeradius/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 5 max_requests = 16384 pidfile = "/var/run/freeradius/freeradius.pid" checkrad = "/usr/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 1.000000 status_server = yes } } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } home_server localhost { ipaddr = 127.0.0.1 port = 1812 type = "auth" secret = <<< secret >>> response_window = 20.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "status-server" ping_interval = 30 check_interval = 30 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 120 limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } home_server_pool my_auth_failover { type = fail-over home_server = localhost } realm example.com { auth_pool = my_auth_failover } realm LOCAL { } radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } client localhost_ipv6 { ipv6addr = ::1 require_message_authenticator = no secret = <<< secret >>> limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached # Creating Auth-Type = mschap # Creating Auth-Type = digest # Creating Auth-Type = eap # Creating Auth-Type = PAP # Creating Auth-Type = CHAP # Creating Auth-Type = MS-CHAP radiusd: #### Instantiating modules #### modules { # Loaded module rlm_logintime # Loading module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime logintime { minimum_timeout = 60 } # Loaded module rlm_passwd # Loading module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd passwd etc_passwd { filename = "/etc/passwd" format = "*User-Name:Crypt-Password:" delimiter = ":" ignore_nislike = no ignore_empty = yes allow_multiple_keys = no hash_size = 100 } # Loaded module rlm_utf8 # Loading module "utf8" from file /etc/freeradius/3.0/mods-enabled/utf8 # Loaded module rlm_detail # Loading module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log detail auth_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log detail reply_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log detail pre_proxy_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log detail post_proxy_log { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loaded module rlm_chap # Loading module "chap" from file /etc/freeradius/3.0/mods-enabled/chap # Loaded module rlm_eap # Loading module "eap" from file /etc/freeradius/3.0/mods-enabled/eap eap { default_eap_type = "md5" timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 16384 } # Loaded module rlm_expr # Loading module "expr" from file /etc/freeradius/3.0/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" } # Loaded module rlm_digest # Loading module "digest" from file /etc/freeradius/3.0/mods-enabled/digest # Loaded module rlm_linelog # Loading module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog linelog { filename = "/var/log/freeradius/linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{reply:Packet-Type}:-default}" } # Loading module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog linelog log_accounting { filename = "/var/log/freeradius/linelog-accounting" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loaded module rlm_preprocess # Loading module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess preprocess { huntgroups = "/etc/freeradius/3.0/mods-config/preprocess/huntgroups" hints = "/etc/freeradius/3.0/mods-config/preprocess/hints" with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } # Loading module "detail" from file /etc/freeradius/3.0/mods-enabled/detail detail { filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loaded module rlm_unix # Loading module "unix" from file /etc/freeradius/3.0/mods-enabled/unix unix { radwtmp = "/var/log/freeradius/radwtmp" } Creating attribute Unix-Group # Loaded module rlm_files # Loading module "files" from file /etc/freeradius/3.0/mods-enabled/files files { filename = "/etc/freeradius/3.0/mods-config/files/authorize" acctusersfile = "/etc/freeradius/3.0/mods-config/files/accounting" preproxy_usersfile = "/etc/freeradius/3.0/mods-config/files/pre-proxy" } # Loaded module rlm_radutmp # Loading module "sradutmp" from file /etc/freeradius/3.0/mods-enabled/sradutmp radutmp sradutmp { filename = "/var/log/freeradius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } # Loaded module rlm_soh # Loading module "soh" from file /etc/freeradius/3.0/mods-enabled/soh soh { dhcp = yes } # Loaded module rlm_cache # Loading module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap cache cache_eap { driver = "rlm_cache_rbtree" key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" ttl = 15 max_entries = 0 epoch = 0 add_stats = no } # Loaded module rlm_expiration # Loading module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration # Loaded module rlm_unpack # Loading module "unpack" from file /etc/freeradius/3.0/mods-enabled/unpack # Loaded module rlm_pap # Loading module "pap" from file /etc/freeradius/3.0/mods-enabled/pap pap { normalise = yes } # Loaded module rlm_exec # Loading module "exec" from file /etc/freeradius/3.0/mods-enabled/exec exec { wait = no input_pairs = "request" shell_escape = yes timeout = 10 } # Loaded module rlm_dynamic_clients # Loading module "dynamic_clients" from file /etc/freeradius/3.0/mods-enabled/dynamic_clients # Loading module "radutmp" from file /etc/freeradius/3.0/mods-enabled/radutmp radutmp { filename = "/var/log/freeradius/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 384 caller_id = yes } # Loaded module rlm_realm # Loading module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm realm IPASS { format = "prefix" delimiter = "/" ignore_default = no ignore_null = no } # Loading module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Loading module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm realm realmpercent { format = "suffix" delimiter = "%" ignore_default = no ignore_null = no } # Loading module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm realm ntdomain { format = "prefix" delimiter = "\\" ignore_default = no ignore_null = no } # Loading module "ntlm_auth" from file /etc/freeradius/3.0/mods-enabled/ntlm_auth exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } # Loaded module rlm_always # Loading module "reject" from file /etc/freeradius/3.0/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /etc/freeradius/3.0/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /etc/freeradius/3.0/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /etc/freeradius/3.0/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /etc/freeradius/3.0/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /etc/freeradius/3.0/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /etc/freeradius/3.0/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /etc/freeradius/3.0/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /etc/freeradius/3.0/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_attr_filter # Loading module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/etc/freeradius/3.0/mods-config/attr_filter/post-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/etc/freeradius/3.0/mods-config/attr_filter/pre-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_reject" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/etc/freeradius/3.0/mods-config/attr_filter/access_challenge" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/etc/freeradius/3.0/mods-config/attr_filter/accounting_response" key = "%{User-Name}" relaxed = no } # Loaded module rlm_replicate # Loading module "replicate" from file /etc/freeradius/3.0/mods-enabled/replicate # Loaded module rlm_mschap # Loading module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes } # Loading module "echo" from file /etc/freeradius/3.0/mods-enabled/echo exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = "request" output_pairs = "reply" shell_escape = yes } instantiate { } # Instantiating module "logintime" from file /etc/freeradius/3.0/mods-enabled/logintime # Instantiating module "etc_passwd" from file /etc/freeradius/3.0/mods-enabled/passwd rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no # Instantiating module "auth_log" from file /etc/freeradius/3.0/mods-enabled/detail.log rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output # Instantiating module "reply_log" from file /etc/freeradius/3.0/mods-enabled/detail.log # Instantiating module "pre_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log # Instantiating module "post_proxy_log" from file /etc/freeradius/3.0/mods-enabled/detail.log # Instantiating module "eap" from file /etc/freeradius/3.0/mods-enabled/eap # Linked to sub-module rlm_eap_md5 # Linked to sub-module rlm_eap_leap # Linked to sub-module rlm_eap_gtc gtc { challenge = "Password: " auth_type = "PAP" } # Linked to sub-module rlm_eap_tls tls { tls = "tls-common" } tls-config tls-common { verify_depth = 0 ca_path = "/etc/freeradius/3.0/certs" pem_file_type = yes private_key_file = "/etc/ssl/private/ssl-cert-snakeoil.key" certificate_file = "/etc/ssl/certs/ssl-cert-snakeoil.pem" ca_file = "/etc/ssl/certs/ca-certificates.crt" private_key_password = <<< secret >>> dh_file = "/etc/freeradius/3.0/certs/dh" fragment_size = 1024 include_length = yes auto_chain = yes check_crl = no check_all_crl = no cipher_list = "DEFAULT" ecdh_curve = "prime256v1" cache { enable = yes lifetime = 24 max_entries = 255 } verify { skip_if_ocsp_ok = no } ocsp { enable = no override_cert_url = yes url = "http://127.0.0.1/ocsp/" use_nonce = yes timeout = 0 softfail = no } } # Linked to sub-module rlm_eap_ttls ttls { tls = "tls-common" default_eap_type = "md5" copy_request_to_tunnel = no use_tunneled_reply = no virtual_server = "inner-tunnel" include_length = yes require_client_cert = no } tls: Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_peap peap { tls = "tls-common" default_eap_type = "mschapv2" copy_request_to_tunnel = no use_tunneled_reply = no proxy_tunneled_request_as_eap = yes virtual_server = "inner-tunnel" soh = no require_client_cert = no } tls: Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_mschapv2 mschapv2 { with_ntdomain_hack = no send_error = no } # Instantiating module "linelog" from file /etc/freeradius/3.0/mods-enabled/linelog # Instantiating module "log_accounting" from file /etc/freeradius/3.0/mods-enabled/linelog # Instantiating module "preprocess" from file /etc/freeradius/3.0/mods-enabled/preprocess reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/huntgroups reading pairlist file /etc/freeradius/3.0/mods-config/preprocess/hints # Instantiating module "detail" from file /etc/freeradius/3.0/mods-enabled/detail # Instantiating module "files" from file /etc/freeradius/3.0/mods-enabled/files reading pairlist file /etc/freeradius/3.0/mods-config/files/authorize reading pairlist file /etc/freeradius/3.0/mods-config/files/accounting reading pairlist file /etc/freeradius/3.0/mods-config/files/pre-proxy # Instantiating module "cache_eap" from file /etc/freeradius/3.0/mods-enabled/cache_eap rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked # Instantiating module "expiration" from file /etc/freeradius/3.0/mods-enabled/expiration # Instantiating module "pap" from file /etc/freeradius/3.0/mods-enabled/pap # Instantiating module "IPASS" from file /etc/freeradius/3.0/mods-enabled/realm # Instantiating module "suffix" from file /etc/freeradius/3.0/mods-enabled/realm # Instantiating module "realmpercent" from file /etc/freeradius/3.0/mods-enabled/realm # Instantiating module "ntdomain" from file /etc/freeradius/3.0/mods-enabled/realm # Instantiating module "reject" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "fail" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "ok" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "handled" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "invalid" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "userlock" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "notfound" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "noop" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "updated" from file /etc/freeradius/3.0/mods-enabled/always # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/3.0/mods-enabled/attr_filter reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/3.0/mods-enabled/attr_filter reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_reject [/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". [/etc/freeradius/3.0/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/3.0/mods-enabled/attr_filter reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/3.0/mods-enabled/attr_filter reading pairlist file /etc/freeradius/3.0/mods-config/attr_filter/accounting_response # Instantiating module "mschap" from file /etc/freeradius/3.0/mods-enabled/mschap rlm_mschap (mschap): using internal authentication } # modules radiusd: #### Loading Virtual Servers #### server { # from file /etc/freeradius/3.0/radiusd.conf } # server server default { # from file /etc/freeradius/3.0/sites-enabled/default # Loading authenticate {...} # Loading authorize {...} Ignoring "sql" (see raddb/mods-available/README.rst) Ignoring "ldap" (see raddb/mods-available/README.rst) # Loading preacct {...} # Loading accounting {...} # Loading post-proxy {...} # Loading post-auth {...} } # server default server inner-tunnel { # from file /etc/freeradius/3.0/sites-enabled/inner-tunnel # Loading authenticate {...} # Loading authorize {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} } # server inner-tunnel radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipaddr = * port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipv6addr = :: port = 0 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "auth" ipaddr = 127.0.0.1 port = 18120 } Listening on auth address * port 1812 bound to server default Listening on acct address * port 1813 bound to server default Listening on auth address :: port 1812 bound to server default Listening on acct address :: port 1813 bound to server default Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Listening on proxy address * port 43535 Listening on proxy address :: port 47361 Ready to process requests (0) Received Access-Request Id 170 from 127.0.0.1:43385 to 127.0.0.1:1812 length 77 (0) User-Name = "testing" (0) User-Password = "password" (0) NAS-IP-Address = 10.5.2.27 (0) NAS-Port = 0 (0) Message-Authenticator = 0x1d182275b1c589d878cfe545c0388727 (0) # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/default (0) authorize { (0) policy filter_username { (0) if (&User-Name) { (0) if (&User-Name) -> TRUE (0) if (&User-Name) { (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@[^@]*@/ ) { (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (0) if (&User-Name =~ /\.\./ ) { (0) if (&User-Name =~ /\.\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\.$/) { (0) if (&User-Name =~ /\.$/) -> FALSE (0) if (&User-Name =~ /(a)\./) { (0) if (&User-Name =~ /(a)\./) -> FALSE (0) } # if (&User-Name) = notfound (0) } # policy filter_username = notfound (0) [preprocess] = ok (0) [chap] = noop (0) [mschap] = noop (0) [digest] = noop (0) suffix: Checking for suffix after "@" (0) suffix: No '@' in User-Name = "testing", looking up realm NULL (0) suffix: No such realm "NULL" (0) [suffix] = noop (0) eap: No EAP-Message, not doing EAP (0) [eap] = noop (0) [files] = noop (0) [expiration] = noop (0) [logintime] = noop (0) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (0) pap: WARNING: Authentication will fail unless a "known good" password is available (0) [pap] = noop (0) } # authorize = ok (0) ERROR: No Auth-Type found: rejecting the user via Post-Auth-Type = Reject (0) Failed to authenticate the user (0) Using Post-Auth-Type Reject (0) # Executing group from file /etc/freeradius/3.0/sites-enabled/default (0) Post-Auth-Type REJECT { (0) attr_filter.access_reject: EXPAND %{User-Name} (0) attr_filter.access_reject: --> testing (0) attr_filter.access_reject: Matched entry DEFAULT at line 11 (0) [attr_filter.access_reject] = updated (0) [eap] = noop (0) policy remove_reply_message_if_eap { (0) if (&reply:EAP-Message && &reply:Reply-Message) { (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (0) else { (0) [noop] = noop (0) } # else = noop (0) } # policy remove_reply_message_if_eap = noop (0) } # Post-Auth-Type REJECT = updated (0) Delaying response for 1.000000 seconds Waking up in 0.3 seconds. Waking up in 0.6 seconds. (0) Sending delayed response (0) Sent Access-Reject Id 170 from 127.0.0.1:1812 to 127.0.0.1:43385 length 20 Waking up in 3.9 seconds. (0) Cleaning up request packet ID 170 with timestamp +2 Ready to process requests And the output of the radtest: root@Freeradius3Client:/etc/freeradius/3.0# radtest testing password localhost 0 testing123 Sent Access-Request Id 170 from 0.0.0.0:43385 to 127.0.0.1:1812 length 77 User-Name = "testing" User-Password = "password" NAS-IP-Address = 10.5.2.27 NAS-Port = 0 Message-Authenticator = 0x00 Cleartext-Password = "password" Received Access-Reject Id 170 from 127.0.0.1:1812 to 0.0.0.0:0 length 20 (0) -: Expected Access-Accept got Access-Reject Regards Alex -- Alexandre Lessard Administrateur réseau | Network administrator T 514.607.0117 # 123 E alex(a)targointernet.com

3 3

Extra column in radpostauth
by Sudheer S 07 May '19

07 May '19

Hello, It would be nice to have an extra column in the |radpostauth |table to store the reasons for Access-Reject. I came across this article, <https://www.dlineradio.co.uk/articles/logging-failure-reasons-in-freeradius/>. The article suggests adding a column to the radpostauth table. I also remembered, Alan DeKok mentioned in one of the earlier threads that using standard tables for custom things is not preferred. Would you consider the extra column in the radpostauth table an exception to the rule of thumb? Or would you recommend using a custom table for this purpose? - Sudheer S ||

2 3

Simple RADSEC configuration for both client and server
by Paul Pathiakis 07 May '19

07 May '19

Hi, Is there a simple configuration or HOWTO document on installing RADSEC capability? I'm new to FreeRADIUS. I'm on CentOS 7. I've gotten somewhat familiar with everything in /etc/raddb . Something is missing that would allow me to check if a client machine can talk to the RADIUS server on 2038/tcp. Is there a command on a client that I can send? What does a typical server configuration look like for the TLS module? Thank you! P.

2 1

RE: redis_ippool module doesnot process lease_time in ack
by Chinnapaiyan, Nagamani 07 May '19

07 May '19

Alan, > Huh? That doesn't make sense. > The lease_time configuration item is supposed to be a number. Like "86400". > If you're setting the lease time here, why use the redis_ippool module? I'm not sure that I understand. We want to use different lease time for different set of mac addresses. The sites-enabled/dhcp chooses that number based on some logic on MAC address. redis_ippool module uses that number. Arran, > Could you also provide the command that you used to create the pool and addresses in it. /usr/local/bin/rlm_redis_ippool_tool -a 10.88.64.2-10.88.67.254 devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com VSAT-UT I am using old git hash 5309825993e5c61a4b2551d9799ba41ff141478c on master branch. Regards, Nagamani Chinnapaiyan

1 0

disconnect same user both whatever
by 佛来佛网 06 May '19

06 May '19

Hi Guys, sorry , I am not good at English. I have configured strongswan + freeradius working well. now I want user （ for example“test”）disconnect the same user when he connect whatever . I write this : ################################### authorize { update disconnect{ &User-Name = "%{User-Name}" } if(User-Name){ if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ } } filter_username ... ... } ###################################### some times it works and some times not works this is works good log ####################################### Sun May 5 09:45:45 2019 : Debug: (134) Received Access-Request Id 168 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163 Sun May 5 09:45:45 2019 : Debug: (134) User-Name = "test" Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port-Type = Virtual Sun May 5 09:45:45 2019 : Debug: (134) Service-Type = Framed-User Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port = 236 Sun May 5 09:45:45 2019 : Debug: (134) NAS-Port-Id = "IKEv2-EAP" Sun May 5 09:45:45 2019 : Debug: (134) NAS-IP-Address = 192.168.100.11 Sun May 5 09:45:45 2019 : Debug: (134) Called-Station-Id = "192.168.100.11[4500]" Sun May 5 09:45:45 2019 : Debug: (134) Calling-Station-Id = "153.119.175.39[56047]" Sun May 5 09:45:45 2019 : Debug: (134) Acct-Session-Id = "1557059862-236" Sun May 5 09:45:45 2019 : Debug: (134) EAP-Message = 0x020000090174657374 Sun May 5 09:45:45 2019 : Debug: (134) NAS-Identifier = "strongSwan" Sun May 5 09:45:45 2019 : Debug: (134) Message-Authenticator = 0x3111389892946d1452bab86037789b9e Sun May 5 09:45:45 2019 : Debug: (134) session-state: No State attribute Sun May 5 09:45:45 2019 : Debug: (134) # Executing section authorize from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (134) authorize { Sun May 5 09:45:45 2019 : Debug: (134) update disconnect { Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (134) --> test Sun May 5 09:45:45 2019 : Debug: (134) &User-Name = test Sun May 5 09:45:45 2019 : Debug: (134) } # update disconnect = noop Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name){ Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name) -> TRUE Sun May 5 09:45:45 2019 : Debug: (134) if (User-Name) { Sun May 5 09:45:45 2019 : Debug: (134) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ Sun May 5 09:45:45 2019 : Debug: %{User-Name} Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (134) --> test Sun May 5 09:45:45 2019 : Debug: (134) SQL-User-Name set to 'test' Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (53) Sun May 5 09:45:45 2019 : Debug: (134) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 Sun May 5 09:45:45 2019 : Debug: (134) SQL query returned no results Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (53) Sun May 5 09:45:45 2019 : Info: Need 2 more connections to reach 10 spares Sun May 5 09:45:45 2019 : Info: rlm_sql (sql): Opening additional connection (60), 1 of 24 pending slots used Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10 Sun May 5 09:45:45 2019 : Debug: (134) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null} Sun May 5 09:45:45 2019 : Debug: (134) --> Sun May 5 09:45:45 2019 : Debug: (134) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) } # if (User-Name) = noop Sun May 5 09:45:45 2019 : Debug: (134) policy filter_username { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) -> TRUE Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ / /) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ / /) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@[^@]*@/ ) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.\./ ) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.\./ ) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:45:45 2019 : Debug: (134) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.$/) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /\.$/) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /(a)\./) { Sun May 5 09:45:45 2019 : Debug: (134) if (&User-Name =~ /(a)\./) -> FALSE Sun May 5 09:45:45 2019 : Debug: (134) } # if (&User-Name) = noop Sun May 5 09:45:45 2019 : Debug: (134) } # policy filter_username = noop Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling preprocess (rlm_preprocess) Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sun May 5 09:45:45 2019 : Debug: (134) [preprocess] = ok Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling chap (rlm_chap) Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from chap (rlm_chap) Sun May 5 09:45:45 2019 : Debug: (134) [chap] = noop Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling mschap (rlm_mschap) Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from mschap (rlm_mschap) Sun May 5 09:45:45 2019 : Debug: (134) [mschap] = noop Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling digest (rlm_digest) Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from digest (rlm_digest) Sun May 5 09:45:45 2019 : Debug: (134) [digest] = noop Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling suffix (rlm_realm) Sun May 5 09:45:45 2019 : Debug: (134) suffix: Checking for suffix after "@" Sun May 5 09:45:45 2019 : Debug: (134) suffix: No '@' in User-Name = "test", looking up realm NULL Sun May 5 09:45:45 2019 : Debug: (134) suffix: No such realm "NULL" Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from suffix (rlm_realm) Sun May 5 09:45:45 2019 : Debug: (134) [suffix] = noop Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: calling eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (134) eap: Peer sent EAP Response (code 2) ID 0 length 9 Sun May 5 09:45:45 2019 : Debug: (134) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authorize]: returned from eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (134) [eap] = ok Sun May 5 09:45:45 2019 : Debug: (134) } # authorize = ok Sun May 5 09:45:45 2019 : Debug: (134) Found Auth-Type = eap Sun May 5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (134) authenticate { Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authenticate]: calling eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (134) eap: Peer sent packet with method EAP Identity (1) Sun May 5 09:45:45 2019 : Debug: (134) eap: Calling submodule eap_md5 to process data Sun May 5 09:45:45 2019 : Debug: (134) eap_md5: Issuing MD5 Challenge Sun May 5 09:45:45 2019 : Debug: (134) eap: Sending EAP Request (code 1) ID 1 length 22 Sun May 5 09:45:45 2019 : Debug: (134) eap: EAP session adding &reply:State = 0x3288c5703289c17c Sun May 5 09:45:45 2019 : Debug: (134) modsingle[authenticate]: returned from eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (134) [eap] = handled Sun May 5 09:45:45 2019 : Debug: (134) } # authenticate = handled Sun May 5 09:45:45 2019 : Debug: (134) Using Post-Auth-Type Challenge Sun May 5 09:45:45 2019 : Debug: (134) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (134) Challenge { ... } # empty sub-section is ignored Sun May 5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache Sun May 5 09:45:45 2019 : Debug: (134) Empty pre-proxy section in virtual server "default". Using default return values. Sun May 5 09:45:45 2019 : Debug: (134) proxy: Trying to allocate ID (0/2) Sun May 5 09:45:45 2019 : Debug: (134) proxy: request is now in proxy hash Sun May 5 09:45:45 2019 : Debug: (134) proxy: allocating destination 192.168.100.11 port 3799 - Id 62 Sun May 5 09:45:45 2019 : Debug: (134) session-state: Nothing to cache Sun May 5 09:45:45 2019 : Debug: (134) Sent Disconnect-Request Id 62 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26 Sun May 5 09:45:45 2019 : Debug: (134) User-Name = "test" Sun May 5 09:45:45 2019 : Debug: (134) Sent Access-Challenge Id 168 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0 Sun May 5 09:45:45 2019 : Debug: (134) EAP-Message = 0x010100160410d93a974e96d012a501eb4786e0dd3e77 Sun May 5 09:45:45 2019 : Debug: (134) Message-Authenticator = 0x00000000000000000000000000000000 Sun May 5 09:45:45 2019 : Debug: (134) State = 0x3288c5703289c17c78ded5beb28006bf Sun May 5 09:45:45 2019 : Debug: (134) Finished request Sun May 5 09:45:45 2019 : Debug: Waking up in 2.5 seconds. Sun May 5 09:45:45 2019 : Debug: (134) Clearing existing &reply: attributes Sun May 5 09:45:45 2019 : Debug: (134) Received Disconnect-NAK Id 62 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20 Sun May 5 09:45:45 2019 : Debug: (134) Empty post-proxy section in virtual server "default". Using default return values. Sun May 5 09:45:45 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867 Sun May 5 09:45:45 2019 : Debug: Waking up in 4.9 seconds. Sun May 5 09:45:45 2019 : Debug: (135) Received Access-Request Id 169 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194 Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test" Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port-Type = Virtual Sun May 5 09:45:45 2019 : Debug: (135) Service-Type = Framed-User Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port = 236 Sun May 5 09:45:45 2019 : Debug: (135) NAS-Port-Id = "IKEv2-EAP" Sun May 5 09:45:45 2019 : Debug: (135) NAS-IP-Address = 192.168.100.11 Sun May 5 09:45:45 2019 : Debug: (135) Called-Station-Id = "192.168.100.11[4500]" Sun May 5 09:45:45 2019 : Debug: (135) Calling-Station-Id = "153.119.175.39[56047]" Sun May 5 09:45:45 2019 : Debug: (135) Acct-Session-Id = "1557059862-236" Sun May 5 09:45:45 2019 : Debug: (135) EAP-Message = 0x020100160410ce217178fb4d579d68d54a027effd329 Sun May 5 09:45:45 2019 : Debug: (135) NAS-Identifier = "strongSwan" Sun May 5 09:45:45 2019 : Debug: (135) State = 0x3288c5703289c17c78ded5beb28006bf Sun May 5 09:45:45 2019 : Debug: (135) Message-Authenticator = 0x59fec2cedd5cf0d2f07cb53382317673 Sun May 5 09:45:45 2019 : Debug: (135) session-state: No cached attributes Sun May 5 09:45:45 2019 : Debug: (135) # Executing section authorize from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (135) authorize { Sun May 5 09:45:45 2019 : Debug: (135) update disconnect { Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (135) --> test Sun May 5 09:45:45 2019 : Debug: (135) &User-Name = test Sun May 5 09:45:45 2019 : Debug: (135) } # update disconnect = noop Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name){ Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name) -> TRUE Sun May 5 09:45:45 2019 : Debug: (135) if (User-Name) { Sun May 5 09:45:45 2019 : Debug: (135) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ Sun May 5 09:45:45 2019 : Debug: %{User-Name} Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (135) --> test Sun May 5 09:45:45 2019 : Debug: (135) SQL-User-Name set to 'test' Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (55) Sun May 5 09:45:45 2019 : Debug: (135) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null Sun May 5 09:45:45 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 Sun May 5 09:45:45 2019 : Debug: (135) SQL query returned no results Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (55) Sun May 5 09:45:45 2019 : Debug: (135) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null} Sun May 5 09:45:45 2019 : Debug: (135) --> Sun May 5 09:45:45 2019 : Debug: (135) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) } # if (User-Name) = noop Sun May 5 09:45:45 2019 : Debug: (135) policy filter_username { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) -> TRUE Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ / /) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ / /) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@[^@]*@/ ) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.\./ ) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.\./ ) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:45:45 2019 : Debug: (135) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.$/) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /\.$/) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /(a)\./) { Sun May 5 09:45:45 2019 : Debug: (135) if (&User-Name =~ /(a)\./) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) } # if (&User-Name) = noop Sun May 5 09:45:45 2019 : Debug: (135) } # policy filter_username = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling preprocess (rlm_preprocess) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sun May 5 09:45:45 2019 : Debug: (135) [preprocess] = ok Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling chap (rlm_chap) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from chap (rlm_chap) Sun May 5 09:45:45 2019 : Debug: (135) [chap] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling mschap (rlm_mschap) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from mschap (rlm_mschap) Sun May 5 09:45:45 2019 : Debug: (135) [mschap] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling digest (rlm_digest) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from digest (rlm_digest) Sun May 5 09:45:45 2019 : Debug: (135) [digest] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling suffix (rlm_realm) Sun May 5 09:45:45 2019 : Debug: (135) suffix: Checking for suffix after "@" Sun May 5 09:45:45 2019 : Debug: (135) suffix: No '@' in User-Name = "test", looking up realm NULL Sun May 5 09:45:45 2019 : Debug: (135) suffix: No such realm "NULL" Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from suffix (rlm_realm) Sun May 5 09:45:45 2019 : Debug: (135) [suffix] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (135) eap: Peer sent EAP Response (code 2) ID 1 length 22 Sun May 5 09:45:45 2019 : Debug: (135) eap: No EAP Start, assuming it's an on-going EAP conversation Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (135) [eap] = updated Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling files (rlm_files) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from files (rlm_files) Sun May 5 09:45:45 2019 : Debug: (135) [files] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling sql (rlm_sql) Sun May 5 09:45:45 2019 : Debug: %{User-Name} Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (135) sql: --> test Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test' Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (52) Sun May 5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: User found in radcheck table Sun May 5 09:45:45 2019 : Debug: (135) sql: Conditional check items matched, merging assignment check items Sun May 5 09:45:45 2019 : Debug: (135) sql: Cleartext-Password := "991999" Sun May 5 09:45:45 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = ' Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Sun May 5 09:45:45 2019 : Debug: (135) sql: User found in radreply table, merging reply items Sun May 5 09:45:45 2019 : Debug: (135) sql: Framed-IP-Address := 192.168.100.201 Sun May 5 09:45:45 2019 : Debug: (135) sql: ... falling-through to group processing Sun May 5 09:45:45 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:45:45 2019 : Debug: literal --> ' ORDER BY priority Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun May 5 09:45:45 2019 : Debug: (135) sql: --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Sun May 5 09:45:45 2019 : Debug: (135) sql: User not found in any groups Sun May 5 09:45:45 2019 : Debug: (135) sql: ... falling-through to profile processing Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (52) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from sql (rlm_sql) Sun May 5 09:45:45 2019 : Debug: (135) [sql] = ok Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling expiration (rlm_expiration) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from expiration (rlm_expiration) Sun May 5 09:45:45 2019 : Debug: (135) [expiration] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling logintime (rlm_logintime) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from logintime (rlm_logintime) Sun May 5 09:45:45 2019 : Debug: (135) [logintime] = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: calling pap (rlm_pap) Sun May 5 09:45:45 2019 : WARNING: (135) pap: Auth-Type already set. Not setting to PAP Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authorize]: returned from pap (rlm_pap) Sun May 5 09:45:45 2019 : Debug: (135) [pap] = noop Sun May 5 09:45:45 2019 : Debug: (135) } # authorize = updated Sun May 5 09:45:45 2019 : Debug: (135) Found Auth-Type = eap Sun May 5 09:45:45 2019 : Debug: (135) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (135) authenticate { Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authenticate]: calling eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (135) eap: Expiring EAP session with state 0x59e200a159e304fe Sun May 5 09:45:45 2019 : Debug: (135) eap: Finished EAP session with state 0x3288c5703289c17c Sun May 5 09:45:45 2019 : Debug: (135) eap: Previous EAP request found for state 0x3288c5703289c17c, released from the list Sun May 5 09:45:45 2019 : Debug: (135) eap: Peer sent packet with method EAP MD5 (4) Sun May 5 09:45:45 2019 : Debug: (135) eap: Calling submodule eap_md5 to process data Sun May 5 09:45:45 2019 : Debug: (135) eap: Sending EAP Success (code 3) ID 1 length 4 Sun May 5 09:45:45 2019 : Debug: (135) eap: Freeing handler Sun May 5 09:45:45 2019 : Debug: (135) modsingle[authenticate]: returned from eap (rlm_eap) Sun May 5 09:45:45 2019 : Debug: (135) [eap] = ok Sun May 5 09:45:45 2019 : Debug: (135) } # authenticate = ok Sun May 5 09:45:45 2019 : Debug: (135) # Executing section post-auth from file /etc/raddb/sites-enabled/default Sun May 5 09:45:45 2019 : Debug: (135) post-auth { Sun May 5 09:45:45 2019 : Debug: (135) update { Sun May 5 09:45:45 2019 : Debug: (135) No attributes updated Sun May 5 09:45:45 2019 : Debug: (135) } # update = noop Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling sql (rlm_sql) Sun May 5 09:45:45 2019 : Debug: .query Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: literal --> .query Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND .query Sun May 5 09:45:45 2019 : Debug: (135) sql: --> .query Sun May 5 09:45:45 2019 : Debug: (135) sql: Using query template 'query' Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Reserved connection (56) Sun May 5 09:45:45 2019 : Debug: %{User-Name} Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: attribute --> User-Name Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND %{User-Name} Sun May 5 09:45:45 2019 : Debug: (135) sql: --> test Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL-User-Name set to 'test' Sun May 5 09:45:45 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sun May 5 09:45:45 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:45 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Sun May 5 09:45:45 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:45:45 2019 : Debug: literal --> ', ' Sun May 5 09:45:45 2019 : Debug: XLAT-IF { Sun May 5 09:45:45 2019 : Debug: attribute --> User-Password Sun May 5 09:45:45 2019 : Debug: } Sun May 5 09:45:45 2019 : Debug: XLAT-ELSE { Sun May 5 09:45:45 2019 : Debug: attribute --> CHAP-Password Sun May 5 09:45:45 2019 : Debug: } Sun May 5 09:45:45 2019 : Debug: literal --> ', ' Sun May 5 09:45:45 2019 : Debug: attribute --> Packet-Type Sun May 5 09:45:45 2019 : Debug: literal --> ', ' Sun May 5 09:45:45 2019 : Debug: percent --> S Sun May 5 09:45:45 2019 : Debug: literal --> ') Sun May 5 09:45:45 2019 : Debug: (135) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sun May 5 09:45:45 2019 : Debug: (135) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383') Sun May 5 09:45:45 2019 : Debug: (135) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:45:45.841383') Sun May 5 09:45:45 2019 : Debug: (135) sql: SQL query returned: success Sun May 5 09:45:45 2019 : Debug: (135) sql: 1 record(s) updated Sun May 5 09:45:45 2019 : Debug: rlm_sql (sql): Released connection (56) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from sql (rlm_sql) Sun May 5 09:45:45 2019 : Debug: (135) [sql] = ok Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling exec (rlm_exec) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from exec (rlm_exec) Sun May 5 09:45:45 2019 : Debug: (135) [exec] = noop Sun May 5 09:45:45 2019 : Debug: (135) policy remove_reply_message_if_eap { Sun May 5 09:45:45 2019 : Debug: (135) if (&reply:EAP-Message && &reply:Reply-Message) { Sun May 5 09:45:45 2019 : Debug: (135) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Sun May 5 09:45:45 2019 : Debug: (135) else { Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: calling noop (rlm_always) Sun May 5 09:45:45 2019 : Debug: (135) modsingle[post-auth]: returned from noop (rlm_always) Sun May 5 09:45:45 2019 : Debug: (135) [noop] = noop Sun May 5 09:45:45 2019 : Debug: (135) } # else = noop Sun May 5 09:45:45 2019 : Debug: (135) } # policy remove_reply_message_if_eap = noop Sun May 5 09:45:45 2019 : Debug: (135) } # post-auth = ok Sun May 5 09:45:45 2019 : Debug: (135) Empty pre-proxy section in virtual server "default". Using default return values. Sun May 5 09:45:45 2019 : Debug: (135) proxy: Trying to allocate ID (0/2) Sun May 5 09:45:45 2019 : Debug: (135) proxy: request is now in proxy hash Sun May 5 09:45:45 2019 : Debug: (135) proxy: allocating destination 192.168.100.11 port 3799 - Id 21 Sun May 5 09:45:45 2019 : Debug: (135) session-state: Nothing to cache Sun May 5 09:45:45 2019 : Debug: (135) Sent Disconnect-Request Id 21 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26 Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test" Sun May 5 09:45:45 2019 : Debug: (135) Sent Access-Accept Id 169 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0 Sun May 5 09:45:45 2019 : Debug: (135) Framed-IP-Address = 192.168.100.201 Sun May 5 09:45:45 2019 : Debug: (135) EAP-Message = 0x03010004 Sun May 5 09:45:45 2019 : Debug: (135) Message-Authenticator = 0x00000000000000000000000000000000 Sun May 5 09:45:45 2019 : Debug: (135) User-Name = "test" Sun May 5 09:45:45 2019 : Debug: (135) Finished request Sun May 5 09:45:45 2019 : Debug: Waking up in 2.2 seconds. Sun May 5 09:45:45 2019 : Debug: (135) Clearing existing &reply: attributes Sun May 5 09:45:45 2019 : Debug: (135) Received Disconnect-NAK Id 21 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20 Sun May 5 09:45:45 2019 : Debug: (135) Empty post-proxy section in virtual server "default". Using default return values. Sun May 5 09:45:45 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867 Sun May 5 09:45:45 2019 : Debug: Waking up in 4.8 seconds. Sun May 5 09:45:46 2019 : Debug: (136) Received Accounting-Request Id 170 from 192.168.100.11:37595 to 192.168.100.12:1813 length 146 Sun May 5 09:45:46 2019 : Debug: (136) Acct-Status-Type = Start Sun May 5 09:45:46 2019 : Debug: (136) Acct-Session-Id = "1557059862-236" Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port-Type = Virtual Sun May 5 09:45:46 2019 : Debug: (136) Service-Type = Framed-User Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port = 236 Sun May 5 09:45:46 2019 : Debug: (136) NAS-Port-Id = "IKEv2-EAP" Sun May 5 09:45:46 2019 : Debug: (136) NAS-IP-Address = 192.168.100.11 Sun May 5 09:45:46 2019 : Debug: (136) Called-Station-Id = "192.168.100.11[4500]" Sun May 5 09:45:46 2019 : Debug: (136) Calling-Station-Id = "153.119.175.39[56047]" Sun May 5 09:45:46 2019 : Debug: (136) User-Name = "test" Sun May 5 09:45:46 2019 : Debug: (136) Framed-IP-Address = 192.168.100.201 Sun May 5 09:45:46 2019 : Debug: (136) NAS-Identifier = "strongSwan" Sun May 5 09:45:46 2019 : Debug: (136) # Executing section preacct from file /etc/raddb/sites-enabled/default Sun May 5 09:45:46 2019 : Debug: (136) preacct { Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling preprocess (rlm_preprocess) Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from preprocess (rlm_preprocess) Sun May 5 09:45:46 2019 : Debug: (136) [preprocess] = ok Sun May 5 09:45:46 2019 : Debug: (136) policy acct_unique { Sun May 5 09:45:46 2019 : Debug: (136) update request { Sun May 5 09:45:46 2019 : Debug: (136) &Tmp-String-9 := "ai:" Sun May 5 09:45:46 2019 : Debug: (136) } # update request = noop Sun May 5 09:45:46 2019 : Debug: (136) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Sun May 5 09:45:46 2019 : Debug: (136) EXPAND %{hex:&Class} Sun May 5 09:45:46 2019 : Debug: (136) --> Sun May 5 09:45:46 2019 : Debug: (136) EXPAND ^%{hex:&Tmp-String-9} Sun May 5 09:45:46 2019 : Debug: (136) --> ^61693a Sun May 5 09:45:46 2019 : Debug: (136) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Sun May 5 09:45:46 2019 : Debug: (136) else { Sun May 5 09:45:46 2019 : Debug: (136) update request { Sun May 5 09:45:46 2019 : Debug: (136) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Sun May 5 09:45:46 2019 : Debug: (136) --> e233fff2cfee67c8e0763a9ba11758cb Sun May 5 09:45:46 2019 : Debug: (136) &Acct-Unique-Session-Id := e233fff2cfee67c8e0763a9ba11758cb Sun May 5 09:45:46 2019 : Debug: (136) } # update request = noop Sun May 5 09:45:46 2019 : Debug: (136) } # else = noop Sun May 5 09:45:46 2019 : Debug: (136) } # policy acct_unique = noop Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling suffix (rlm_realm) Sun May 5 09:45:46 2019 : Debug: (136) suffix: Checking for suffix after "@" Sun May 5 09:45:46 2019 : Debug: (136) suffix: No '@' in User-Name = "test", looking up realm NULL Sun May 5 09:45:46 2019 : Debug: (136) suffix: No such realm "NULL" Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from suffix (rlm_realm) Sun May 5 09:45:46 2019 : Debug: (136) [suffix] = noop Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: calling files (rlm_files) Sun May 5 09:45:46 2019 : Debug: (136) modsingle[preacct]: returned from files (rlm_files) Sun May 5 09:45:46 2019 : Debug: (136) [files] = noop Sun May 5 09:45:46 2019 : Debug: (136) } # preacct = ok Sun May 5 09:45:46 2019 : Debug: (136) # Executing section accounting from file /etc/raddb/sites-enabled/default Sun May 5 09:45:46 2019 : Debug: (136) accounting { Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling detail (rlm_detail) Sun May 5 09:45:46 2019 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: literal --> /var/log/radius/radacct/ Sun May 5 09:45:46 2019 : Debug: XLAT-IF { Sun May 5 09:45:46 2019 : Debug: attribute --> Packet-Src-IP-Address Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: XLAT-ELSE { Sun May 5 09:45:46 2019 : Debug: attribute --> Packet-Src-IPv6-Address Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: literal --> /detail- Sun May 5 09:45:46 2019 : Debug: percent --> Y Sun May 5 09:45:46 2019 : Debug: percent --> m Sun May 5 09:45:46 2019 : Debug: percent --> d Sun May 5 09:45:46 2019 : Debug: (136) detail: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Sun May 5 09:45:46 2019 : Debug: (136) detail: --> /var/log/radius/radacct/192.168.100.11/detail-20190505 Sun May 5 09:45:46 2019 : Debug: (136) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/192.168.100.11/detail-20190505 Sun May 5 09:45:46 2019 : Debug: %t Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: percent --> t Sun May 5 09:45:46 2019 : Debug: (136) detail: EXPAND %t Sun May 5 09:45:46 2019 : Debug: (136) detail: --> Sun May 5 09:45:46 2019 Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from detail (rlm_detail) Sun May 5 09:45:46 2019 : Debug: (136) [detail] = ok Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling unix (rlm_unix) Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from unix (rlm_unix) Sun May 5 09:45:46 2019 : Debug: (136) [unix] = ok Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling sql (rlm_sql) Sun May 5 09:45:46 2019 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: xlat --> tolower Sun May 5 09:45:46 2019 : Debug: { Sun May 5 09:45:46 2019 : Debug: literal --> type. Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Status-Type Sun May 5 09:45:46 2019 : Debug: literal --> .query Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Sun May 5 09:45:46 2019 : Debug: (136) sql: --> type.start.query Sun May 5 09:45:46 2019 : Debug: (136) sql: Using query template 'query' Sun May 5 09:45:46 2019 : Debug: rlm_sql (sql): Reserved connection (54) Sun May 5 09:45:46 2019 : Debug: %{User-Name} Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: attribute --> User-Name Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND %{User-Name} Sun May 5 09:45:46 2019 : Debug: (136) sql: --> test Sun May 5 09:45:46 2019 : Debug: (136) sql: SQL-User-Name set to 'test' Sun May 5 09:45:46 2019 : Debug: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: literal --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES (' Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Session-Id Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Unique-Session-Id Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Realm Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-IP-Address Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: XLAT-IF { Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port-Id Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: XLAT-ELSE { Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> NAS-Port-Type Sun May 5 09:45:46 2019 : Debug: literal --> ', FROM_UNIXTIME( Sun May 5 09:45:46 2019 : Debug: xlat --> integer Sun May 5 09:45:46 2019 : Debug: { Sun May 5 09:45:46 2019 : Debug: literal --> Event-Timestamp Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: literal --> ), FROM_UNIXTIME( Sun May 5 09:45:46 2019 : Debug: xlat --> integer Sun May 5 09:45:46 2019 : Debug: { Sun May 5 09:45:46 2019 : Debug: literal --> Event-Timestamp Sun May 5 09:45:46 2019 : Debug: } Sun May 5 09:45:46 2019 : Debug: literal --> ), NULL, '0', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Acct-Authentic Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Connect-Info Sun May 5 09:45:46 2019 : Debug: literal --> ', '', '0', '0', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Called-Station-Id Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Calling-Station-Id Sun May 5 09:45:46 2019 : Debug: literal --> ', '', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Service-Type Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Framed-Protocol Sun May 5 09:45:46 2019 : Debug: literal --> ', ' Sun May 5 09:45:46 2019 : Debug: attribute --> Framed-IP-Address Sun May 5 09:45:46 2019 : Debug: literal --> ') Sun May 5 09:45:46 2019 : Debug: (136) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') Sun May 5 09:45:46 2019 : Debug: (136) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201') Sun May 5 09:45:46 2019 : Debug: (136) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets,calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('1557059862-236', 'e233fff2cfee67c8e0763a9ba11758cb', 'test', '', '192.168.100.11', 'IKEv2-EAP', 'Virtual', FROM_UNIXTIME(1557063946), FROM_UNIXTIME(1557063946), NULL, '0', '', '', '', '0', '0', '192.168.100.11=5B4500=5D', '153.119.175.39=5B56047=5D', '', 'Framed-User', '', '192.168.100.201') Sun May 5 09:45:46 2019 : Debug: (136) sql: SQL query returned: success Sun May 5 09:45:46 2019 : Debug: (136) sql: 1 record(s) updated Sun May 5 09:45:46 2019 : Debug: rlm_sql (sql): Released connection (54) Sun May 5 09:45:46 2019 : Info: Need 1 more connections to reach 10 spares Sun May 5 09:45:46 2019 : Info: rlm_sql (sql): Opening additional connection (61), 1 of 23 pending slots used Sun May 5 09:45:46 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sun May 5 09:45:46 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10 Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from sql (rlm_sql) Sun May 5 09:45:46 2019 : Debug: (136) [sql] = ok Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling exec (rlm_exec) Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from exec (rlm_exec) Sun May 5 09:45:46 2019 : Debug: (136) [exec] = noop Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Sun May 5 09:45:46 2019 : Debug: %{User-Name} Sun May 5 09:45:46 2019 : Debug: Parsed xlat tree: Sun May 5 09:45:46 2019 : Debug: attribute --> User-Name Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: EXPAND %{User-Name} Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: --> test Sun May 5 09:45:46 2019 : Debug: (136) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Sun May 5 09:45:46 2019 : Debug: (136) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Sun May 5 09:45:46 2019 : Debug: (136) [attr_filter.accounting_response] = updated Sun May 5 09:45:46 2019 : Debug: (136) } # accounting = updated Sun May 5 09:45:46 2019 : Debug: (136) Sent Accounting-Response Id 170 from 192.168.100.12:1813 to 192.168.100.11:37595 length 0 Sun May 5 09:45:46 2019 : Debug: (136) Finished request Sun May 5 09:45:46 2019 : Debug: (136) Cleaning up request packet ID 170 with timestamp +1868 Sun May 5 09:45:46 2019 : Debug: Waking up in 4.7 seconds. Sun May 5 09:45:50 2019 : Debug: (134) Cleaning up request packet ID 168 with timestamp +1867 Sun May 5 09:45:50 2019 : Debug: (135) Cleaning up request packet ID 169 with timestamp +1867 Sun May 5 09:45:50 2019 : Info: Ready to process requests ######################################### this is not works log ##################################################### Sun May 5 09:46:32 2019 : Debug: (138) Received Access-Request Id 172 from 192.168.100.11:59413 to 192.168.100.12:1812 length 163 Sun May 5 09:46:32 2019 : Debug: (138) User-Name = "test" Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port-Type = Virtual Sun May 5 09:46:32 2019 : Debug: (138) Service-Type = Framed-User Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port = 238 Sun May 5 09:46:32 2019 : Debug: (138) NAS-Port-Id = "IKEv2-EAP" Sun May 5 09:46:32 2019 : Debug: (138) NAS-IP-Address = 192.168.100.11 Sun May 5 09:46:32 2019 : Debug: (138) Called-Station-Id = "192.168.100.11[4500]" Sun May 5 09:46:32 2019 : Debug: (138) Calling-Station-Id = "153.119.175.39[56451]" Sun May 5 09:46:32 2019 : Debug: (138) Acct-Session-Id = "1557059862-238" Sun May 5 09:46:32 2019 : Debug: (138) EAP-Message = 0x020000090174657374 Sun May 5 09:46:32 2019 : Debug: (138) NAS-Identifier = "strongSwan" Sun May 5 09:46:32 2019 : Debug: (138) Message-Authenticator = 0xe29b962bf25ae5af41cb931202c00c6e Sun May 5 09:46:32 2019 : Debug: (138) session-state: No State attribute Sun May 5 09:46:32 2019 : Debug: (138) # Executing section authorize from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (138) authorize { Sun May 5 09:46:32 2019 : Debug: (138) update disconnect { Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (138) --> test Sun May 5 09:46:32 2019 : Debug: (138) &User-Name = test Sun May 5 09:46:32 2019 : Debug: (138) } # update disconnect = noop Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name){ Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name) -> TRUE Sun May 5 09:46:32 2019 : Debug: (138) if (User-Name) { Sun May 5 09:46:32 2019 : Debug: (138) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ Sun May 5 09:46:32 2019 : Debug: %{User-Name} Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (138) --> test Sun May 5 09:46:32 2019 : Debug: (138) SQL-User-Name set to 'test' Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (60) Sun May 5 09:46:32 2019 : Debug: (138) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 Sun May 5 09:46:32 2019 : Debug: (138) SQL query returned no results Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (60) Sun May 5 09:46:32 2019 : Info: Need 2 more connections to reach 10 spares Sun May 5 09:46:32 2019 : Info: rlm_sql (sql): Opening additional connection (63), 1 of 24 pending slots used Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Starting connect to MySQL server Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Connected to database 'radius' on 192.168.100.13 via TCP/IP, server version 5.5.60-MariaDB, protocol version 10 Sun May 5 09:46:32 2019 : Debug: (138) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null} Sun May 5 09:46:32 2019 : Debug: (138) --> Sun May 5 09:46:32 2019 : Debug: (138) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) } # if (User-Name) = noop Sun May 5 09:46:32 2019 : Debug: (138) policy filter_username { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) -> TRUE Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ / /) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ / /) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@[^@]*@/ ) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.\./ ) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.\./ ) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:46:32 2019 : Debug: (138) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.$/) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /\.$/) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /(a)\./) { Sun May 5 09:46:32 2019 : Debug: (138) if (&User-Name =~ /(a)\./) -> FALSE Sun May 5 09:46:32 2019 : Debug: (138) } # if (&User-Name) = noop Sun May 5 09:46:32 2019 : Debug: (138) } # policy filter_username = noop Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling preprocess (rlm_preprocess) Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sun May 5 09:46:32 2019 : Debug: (138) [preprocess] = ok Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling chap (rlm_chap) Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from chap (rlm_chap) Sun May 5 09:46:32 2019 : Debug: (138) [chap] = noop Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling mschap (rlm_mschap) Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from mschap (rlm_mschap) Sun May 5 09:46:32 2019 : Debug: (138) [mschap] = noop Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling digest (rlm_digest) Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from digest (rlm_digest) Sun May 5 09:46:32 2019 : Debug: (138) [digest] = noop Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling suffix (rlm_realm) Sun May 5 09:46:32 2019 : Debug: (138) suffix: Checking for suffix after "@" Sun May 5 09:46:32 2019 : Debug: (138) suffix: No '@' in User-Name = "test", looking up realm NULL Sun May 5 09:46:32 2019 : Debug: (138) suffix: No such realm "NULL" Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from suffix (rlm_realm) Sun May 5 09:46:32 2019 : Debug: (138) [suffix] = noop Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: calling eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (138) eap: Peer sent EAP Response (code 2) ID 0 length 9 Sun May 5 09:46:32 2019 : Debug: (138) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authorize]: returned from eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (138) [eap] = ok Sun May 5 09:46:32 2019 : Debug: (138) } # authorize = ok Sun May 5 09:46:32 2019 : Debug: (138) Found Auth-Type = eap Sun May 5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (138) authenticate { Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authenticate]: calling eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (138) eap: Peer sent packet with method EAP Identity (1) Sun May 5 09:46:32 2019 : Debug: (138) eap: Calling submodule eap_md5 to process data Sun May 5 09:46:32 2019 : Debug: (138) eap_md5: Issuing MD5 Challenge Sun May 5 09:46:32 2019 : Debug: (138) eap: Sending EAP Request (code 1) ID 1 length 22 Sun May 5 09:46:32 2019 : Debug: (138) eap: EAP session adding &reply:State = 0x6048d1426049d56d Sun May 5 09:46:32 2019 : Debug: (138) modsingle[authenticate]: returned from eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (138) [eap] = handled Sun May 5 09:46:32 2019 : Debug: (138) } # authenticate = handled Sun May 5 09:46:32 2019 : Debug: (138) Using Post-Auth-Type Challenge Sun May 5 09:46:32 2019 : Debug: (138) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (138) Challenge { ... } # empty sub-section is ignored Sun May 5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache Sun May 5 09:46:32 2019 : Debug: (138) Empty pre-proxy section in virtual server "default". Using default return values. Sun May 5 09:46:32 2019 : Debug: (138) proxy: Trying to allocate ID (0/2) Sun May 5 09:46:32 2019 : Debug: (138) proxy: request is now in proxy hash Sun May 5 09:46:32 2019 : Debug: (138) proxy: allocating destination 192.168.100.11 port 3799 - Id 57 Sun May 5 09:46:32 2019 : Debug: (138) session-state: Nothing to cache Sun May 5 09:46:32 2019 : Debug: (138) Sent Disconnect-Request Id 57 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26 Sun May 5 09:46:32 2019 : Debug: (138) User-Name = "test" Sun May 5 09:46:32 2019 : Debug: (138) Sent Access-Challenge Id 172 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0 Sun May 5 09:46:32 2019 : Debug: (138) EAP-Message = 0x0101001604106d1b45d49f879829562d2c46943013e8 Sun May 5 09:46:32 2019 : Debug: (138) Message-Authenticator = 0x00000000000000000000000000000000 Sun May 5 09:46:32 2019 : Debug: (138) State = 0x6048d1426049d56d1e82e3d0d58b93c7 Sun May 5 09:46:32 2019 : Debug: (138) Finished request Sun May 5 09:46:32 2019 : Debug: Waking up in 2.5 seconds. Sun May 5 09:46:32 2019 : Debug: (138) Clearing existing &reply: attributes Sun May 5 09:46:32 2019 : Debug: (138) Received Disconnect-NAK Id 57 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20 Sun May 5 09:46:32 2019 : Debug: (138) Empty post-proxy section in virtual server "default". Using default return values. Sun May 5 09:46:32 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914 Sun May 5 09:46:32 2019 : Debug: Waking up in 4.9 seconds. Sun May 5 09:46:32 2019 : Debug: (139) Received Access-Request Id 173 from 192.168.100.11:59413 to 192.168.100.12:1812 length 194 Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test" Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port-Type = Virtual Sun May 5 09:46:32 2019 : Debug: (139) Service-Type = Framed-User Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port = 238 Sun May 5 09:46:32 2019 : Debug: (139) NAS-Port-Id = "IKEv2-EAP" Sun May 5 09:46:32 2019 : Debug: (139) NAS-IP-Address = 192.168.100.11 Sun May 5 09:46:32 2019 : Debug: (139) Called-Station-Id = "192.168.100.11[4500]" Sun May 5 09:46:32 2019 : Debug: (139) Calling-Station-Id = "153.119.175.39[56451]" Sun May 5 09:46:32 2019 : Debug: (139) Acct-Session-Id = "1557059862-238" Sun May 5 09:46:32 2019 : Debug: (139) EAP-Message = 0x0201001604101a5615717d21560f482951e9124181b2 Sun May 5 09:46:32 2019 : Debug: (139) NAS-Identifier = "strongSwan" Sun May 5 09:46:32 2019 : Debug: (139) State = 0x6048d1426049d56d1e82e3d0d58b93c7 Sun May 5 09:46:32 2019 : Debug: (139) Message-Authenticator = 0x1002eed55d62afee39fbe2fcd41869de Sun May 5 09:46:32 2019 : Debug: (139) session-state: No cached attributes Sun May 5 09:46:32 2019 : Debug: (139) # Executing section authorize from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (139) authorize { Sun May 5 09:46:32 2019 : Debug: (139) update disconnect { Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (139) --> test Sun May 5 09:46:32 2019 : Debug: (139) &User-Name = test Sun May 5 09:46:32 2019 : Debug: (139) } # update disconnect = noop Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name){ Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name) -> TRUE Sun May 5 09:46:32 2019 : Debug: (139) if (User-Name) { Sun May 5 09:46:32 2019 : Debug: (139) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ Sun May 5 09:46:32 2019 : Debug: %{User-Name} Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (139) --> test Sun May 5 09:46:32 2019 : Debug: (139) SQL-User-Name set to 'test' Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (55) Sun May 5 09:46:32 2019 : Debug: (139) Executing select query: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='test' and AcctStopTime is null Sun May 5 09:46:32 2019 : Debug: rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0 Sun May 5 09:46:32 2019 : Debug: (139) SQL query returned no results Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (55) Sun May 5 09:46:32 2019 : Debug: (139) EXPAND %{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null} Sun May 5 09:46:32 2019 : Debug: (139) --> Sun May 5 09:46:32 2019 : Debug: (139) if ("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}") -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) } # if (User-Name) = noop Sun May 5 09:46:32 2019 : Debug: (139) policy filter_username { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) -> TRUE Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ / /) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ / /) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@[^@]*@/ ) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.\./ ) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.\./ ) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Sun May 5 09:46:32 2019 : Debug: (139) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.$/) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /\.$/) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /(a)\./) { Sun May 5 09:46:32 2019 : Debug: (139) if (&User-Name =~ /(a)\./) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) } # if (&User-Name) = noop Sun May 5 09:46:32 2019 : Debug: (139) } # policy filter_username = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling preprocess (rlm_preprocess) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from preprocess (rlm_preprocess) Sun May 5 09:46:32 2019 : Debug: (139) [preprocess] = ok Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling chap (rlm_chap) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from chap (rlm_chap) Sun May 5 09:46:32 2019 : Debug: (139) [chap] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling mschap (rlm_mschap) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from mschap (rlm_mschap) Sun May 5 09:46:32 2019 : Debug: (139) [mschap] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling digest (rlm_digest) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from digest (rlm_digest) Sun May 5 09:46:32 2019 : Debug: (139) [digest] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling suffix (rlm_realm) Sun May 5 09:46:32 2019 : Debug: (139) suffix: Checking for suffix after "@" Sun May 5 09:46:32 2019 : Debug: (139) suffix: No '@' in User-Name = "test", looking up realm NULL Sun May 5 09:46:32 2019 : Debug: (139) suffix: No such realm "NULL" Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from suffix (rlm_realm) Sun May 5 09:46:32 2019 : Debug: (139) [suffix] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (139) eap: Peer sent EAP Response (code 2) ID 1 length 22 Sun May 5 09:46:32 2019 : Debug: (139) eap: No EAP Start, assuming it's an on-going EAP conversation Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (139) [eap] = updated Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling files (rlm_files) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from files (rlm_files) Sun May 5 09:46:32 2019 : Debug: (139) [files] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling sql (rlm_sql) Sun May 5 09:46:32 2019 : Debug: %{User-Name} Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (139) sql: --> test Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test' Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (52) Sun May 5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: User found in radcheck table Sun May 5 09:46:32 2019 : Debug: (139) sql: Conditional check items matched, merging assignment check items Sun May 5 09:46:32 2019 : Debug: (139) sql: Cleartext-Password := "991999" Sun May 5 09:46:32 2019 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = ' Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Sun May 5 09:46:32 2019 : Debug: (139) sql: User found in radreply table, merging reply items Sun May 5 09:46:32 2019 : Debug: (139) sql: Framed-IP-Address := 192.168.100.201 Sun May 5 09:46:32 2019 : Debug: (139) sql: ... falling-through to group processing Sun May 5 09:46:32 2019 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:46:32 2019 : Debug: literal --> ' ORDER BY priority Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Sun May 5 09:46:32 2019 : Debug: (139) sql: --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Sun May 5 09:46:32 2019 : Debug: (139) sql: User not found in any groups Sun May 5 09:46:32 2019 : Debug: (139) sql: ... falling-through to profile processing Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (52) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from sql (rlm_sql) Sun May 5 09:46:32 2019 : Debug: (139) [sql] = ok Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling expiration (rlm_expiration) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from expiration (rlm_expiration) Sun May 5 09:46:32 2019 : Debug: (139) [expiration] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling logintime (rlm_logintime) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from logintime (rlm_logintime) Sun May 5 09:46:32 2019 : Debug: (139) [logintime] = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: calling pap (rlm_pap) Sun May 5 09:46:32 2019 : WARNING: (139) pap: Auth-Type already set. Not setting to PAP Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authorize]: returned from pap (rlm_pap) Sun May 5 09:46:32 2019 : Debug: (139) [pap] = noop Sun May 5 09:46:32 2019 : Debug: (139) } # authorize = updated Sun May 5 09:46:32 2019 : Debug: (139) Found Auth-Type = eap Sun May 5 09:46:32 2019 : Debug: (139) # Executing group from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (139) authenticate { Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authenticate]: calling eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x59e200a159e304fe Sun May 5 09:46:32 2019 : Debug: (139) eap: Expiring EAP session with state 0x6048d1426049d56d Sun May 5 09:46:32 2019 : Debug: (139) eap: Finished EAP session with state 0x6048d1426049d56d Sun May 5 09:46:32 2019 : Debug: (139) eap: Previous EAP request found for state 0x6048d1426049d56d, released from the list Sun May 5 09:46:32 2019 : Debug: (139) eap: Peer sent packet with method EAP MD5 (4) Sun May 5 09:46:32 2019 : Debug: (139) eap: Calling submodule eap_md5 to process data Sun May 5 09:46:32 2019 : Debug: (139) eap: Sending EAP Success (code 3) ID 1 length 4 Sun May 5 09:46:32 2019 : Debug: (139) eap: Freeing handler Sun May 5 09:46:32 2019 : Debug: (139) modsingle[authenticate]: returned from eap (rlm_eap) Sun May 5 09:46:32 2019 : Debug: (139) [eap] = ok Sun May 5 09:46:32 2019 : Debug: (139) } # authenticate = ok Sun May 5 09:46:32 2019 : Debug: (139) # Executing section post-auth from file /etc/raddb/sites-enabled/default Sun May 5 09:46:32 2019 : Debug: (139) post-auth { Sun May 5 09:46:32 2019 : Debug: (139) update { Sun May 5 09:46:32 2019 : Debug: (139) No attributes updated Sun May 5 09:46:32 2019 : Debug: (139) } # update = noop Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling sql (rlm_sql) Sun May 5 09:46:32 2019 : Debug: .query Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: literal --> .query Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND .query Sun May 5 09:46:32 2019 : Debug: (139) sql: --> .query Sun May 5 09:46:32 2019 : Debug: (139) sql: Using query template 'query' Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Reserved connection (56) Sun May 5 09:46:32 2019 : Debug: %{User-Name} Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: attribute --> User-Name Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND %{User-Name} Sun May 5 09:46:32 2019 : Debug: (139) sql: --> test Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL-User-Name set to 'test' Sun May 5 09:46:32 2019 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sun May 5 09:46:32 2019 : Debug: Parsed xlat tree: Sun May 5 09:46:32 2019 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Sun May 5 09:46:32 2019 : Debug: attribute --> SQL-User-Name Sun May 5 09:46:32 2019 : Debug: literal --> ', ' Sun May 5 09:46:32 2019 : Debug: XLAT-IF { Sun May 5 09:46:32 2019 : Debug: attribute --> User-Password Sun May 5 09:46:32 2019 : Debug: } Sun May 5 09:46:32 2019 : Debug: XLAT-ELSE { Sun May 5 09:46:32 2019 : Debug: attribute --> CHAP-Password Sun May 5 09:46:32 2019 : Debug: } Sun May 5 09:46:32 2019 : Debug: literal --> ', ' Sun May 5 09:46:32 2019 : Debug: attribute --> Packet-Type Sun May 5 09:46:32 2019 : Debug: literal --> ', ' Sun May 5 09:46:32 2019 : Debug: percent --> S Sun May 5 09:46:32 2019 : Debug: literal --> ') Sun May 5 09:46:32 2019 : Debug: (139) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Sun May 5 09:46:32 2019 : Debug: (139) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711') Sun May 5 09:46:32 2019 : Debug: (139) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', '', 'Access-Accept', '2019-05-05 09:46:32.465711') Sun May 5 09:46:32 2019 : Debug: (139) sql: SQL query returned: success Sun May 5 09:46:32 2019 : Debug: (139) sql: 1 record(s) updated Sun May 5 09:46:32 2019 : Debug: rlm_sql (sql): Released connection (56) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from sql (rlm_sql) Sun May 5 09:46:32 2019 : Debug: (139) [sql] = ok Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling exec (rlm_exec) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from exec (rlm_exec) Sun May 5 09:46:32 2019 : Debug: (139) [exec] = noop Sun May 5 09:46:32 2019 : Debug: (139) policy remove_reply_message_if_eap { Sun May 5 09:46:32 2019 : Debug: (139) if (&reply:EAP-Message && &reply:Reply-Message) { Sun May 5 09:46:32 2019 : Debug: (139) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Sun May 5 09:46:32 2019 : Debug: (139) else { Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: calling noop (rlm_always) Sun May 5 09:46:32 2019 : Debug: (139) modsingle[post-auth]: returned from noop (rlm_always) Sun May 5 09:46:32 2019 : Debug: (139) [noop] = noop Sun May 5 09:46:32 2019 : Debug: (139) } # else = noop Sun May 5 09:46:32 2019 : Debug: (139) } # policy remove_reply_message_if_eap = noop Sun May 5 09:46:32 2019 : Debug: (139) } # post-auth = ok Sun May 5 09:46:32 2019 : Debug: (139) Empty pre-proxy section in virtual server "default". Using default return values. Sun May 5 09:46:32 2019 : Debug: (139) proxy: Trying to allocate ID (0/2) Sun May 5 09:46:32 2019 : Debug: (139) proxy: request is now in proxy hash Sun May 5 09:46:32 2019 : Debug: (139) proxy: allocating destination 192.168.100.11 port 3799 - Id 104 Sun May 5 09:46:32 2019 : Debug: (139) session-state: Nothing to cache Sun May 5 09:46:32 2019 : Debug: (139) Sent Disconnect-Request Id 104 from 0.0.0.0:60459 to 192.168.100.11:3799 length 26 Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test" Sun May 5 09:46:32 2019 : Debug: (139) Sent Access-Accept Id 173 from 192.168.100.12:1812 to 192.168.100.11:59413 length 0 Sun May 5 09:46:32 2019 : Debug: (139) Framed-IP-Address = 192.168.100.201 Sun May 5 09:46:32 2019 : Debug: (139) EAP-Message = 0x03010004 Sun May 5 09:46:32 2019 : Debug: (139) Message-Authenticator = 0x00000000000000000000000000000000 Sun May 5 09:46:32 2019 : Debug: (139) User-Name = "test" Sun May 5 09:46:32 2019 : Debug: (139) Finished request Sun May 5 09:46:32 2019 : Debug: Waking up in 2.1 seconds. Sun May 5 09:46:32 2019 : Debug: (139) Clearing existing &reply: attributes Sun May 5 09:46:32 2019 : Debug: (139) Received Disconnect-ACK Id 104 from 192.168.100.11:3799 to 192.168.100.12:60459 length 20 Sun May 5 09:46:32 2019 : Debug: (139) Empty post-proxy section in virtual server "default". Using default return values. Sun May 5 09:46:32 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914 Sun May 5 09:46:32 2019 : Debug: Waking up in 4.8 seconds. Sun May 5 09:46:37 2019 : Debug: (138) Cleaning up request packet ID 172 with timestamp +1914 Sun May 5 09:46:37 2019 : Debug: Waking up in 0.1 seconds. Sun May 5 09:46:37 2019 : Debug: (139) Cleaning up request packet ID 173 with timestamp +1914 Sun May 5 09:46:37 2019 : Info: Ready to process requests ################################################## I think when server does this： ################################## update disconnect{ &User-Name = "%{User-Name}" } if(User-Name){ if("%{sql: UPDATE radacct set AcctStopTime=ADDDATE(AcctStartTime,INTERVAL AcctSessionTime SECOND), AcctTerminateCause='Clear-Stale Session' WHERE UserName='%{User-Name}' and AcctStopTime is null}"){ } } #################################### it shoud wait for the Disconnect-ACK or Disconnect-NAK and then do the next ################## filter_username ... ... ################## how can I write ? or how to write a delay time befor “filter_username”? or is there other idea to do this (disconnect same user both strongswan and freeradius whatever ) ? Thanks very much!

2 1

Freeradius does not Executing section "authorize from file /etc/freeradius/sites-enabled/default"
by myxmail1919＠yahoo.com 06 May '19

06 May '19

Hi everyone,,maybe someone can help me ? have a mysql query in /etc/freeradius/sites-enabled/default (authorize section )before authorizeing a user it checks for some attributes in mysql it works fine when i run freeradius and test it with some users !but it does not Executing section "authorize from file /etc/freeradius/sites-enabled/default" when i start freeradius under heavy load ! Start radius and test with some users : # Executing section authorize from file /etc/freeradius/sites-enabled/default +group authorize { ++[preprocess] = ok rlm_sql (sql): Released sql socket id: 29 expand: %{sql:SELECT ************************************** } ->? Evaluating ("%{sql:SELECT ************************************** }" > 1 ) -> FALSE++? if ("%{sql:SELECT ************************************** " > 1 ) -> FALSE++else else {+++[ok] = ok+++update control { +++} # update control = noop++} # else else = ok

3 4

How can i reset user quota after user consumed completely
by Abdul Riyaz 06 May '19

06 May '19

Hi, I have a user called "user" with Cleartext-Password:- 123456. I installed freeradius in UBuntu 18.04 in docker container. Now, I connected freeradius to Mikrotik Nas. Everythings works fine. user has attributes: Mikrotik-Rate-Limit :- 1000k/1000k Mikrotik-Total-Limit :- 200000000 (~2GB) Expiration: 1559678897 (June 5th 2019) The user has already consumed 2GB of data within 2 days. Data exhausted and user is unable to login. How can i reset the "user" with same quota manually. When package is changed, i want user to start using new data. I don;t wanna mess with radacct table. Can anyone advise how can i achieve this? TO say Simply, change package after data is consumed. user should login this time. My question might be so silly but please help me with this. Many Thanks Abdul Riyaz

2 1

RE: redis_ippool module doesnot process lease_time in ack
by Chinnapaiyan, Nagamani 04 May '19

04 May '19

redis_ippool module: redis_ippool { # # Note all configuration items at this level (above the redis block) # are polymorphic, meaning xlats, attribute references, literal values # and execs may be specified. # # For example pool_name could be pool_name = 'my_test_pool' if only a # single pool were being used. # # Name of the pool to allocate leases from. # pool_name = &control:Pool-Name # # How long a lease is reserved for after making an offer to the DHCP client # if no value is provided, the value from lease_time is used for initial # allocations. No value should be provided for PPP/VPNs, this is mainly for # the DORA flow in DHCP. # offer_time = 120 # # How long a lease is allocated for # lease_time = &reply:DHCP-IP-Address-Lease-Time # # The device identifier, usually the Mac-Address but could be a combination # of attributes, a user-name or a certificate serial number (if the number # of sessions were limited to one per user/serial). # device = &DHCP-Client-Hardware-Address # # The IP address being renewed or released # requested_address = "%{%{DHCP-Requested-IP-Address}:-%{DHCP-Client-IP-Address}}" # # List and attribute where the allocated address is written to. # allocated_address_attr = &reply:DHCP-Your-IP-Address # # List and attribute where the Pool-Range ID (if set) is written to. # # The idea of the Pool-Range is that it provides a key into other datastores # or caches, which store the additional options associated with the range an # IP address belongs to. # # There may be multiple ranges of IP address contained within any given pool, # which is why this is provided in addition to the pool name. # range_attr = &reply:Pool-Range # # If set - the list and attribute to write the remaining lease time to. # This can be populated on alloc, or renew, if an IP address was available # for the alloc. # expiry_attr = &reply:DHCP-IP-Address-Lease-Time # # If true - Copy the value of ip_address to the attribute specified by # reply_attr when performing an update/renew. This is needed for DHCP where # we need to send back DHCP-Your-IP-Address in ACKs. # copy_on_update = yes # # Redis connection settings - Identical to all other Redis based modules. # redis { server = devstack08-db-eval1-0001-001.oovb0g.0001.usw2.cache.amazonaws.com pool { start = 0 min = ${thread[pool].num_workers} max = ${thread[pool].num_workers} spare = 1 uses = 0 lifetime = 0 retry_delay = 30 idle_timeout = 60 } } } dhcp server: recv DHCP-Request { ... update reply { &DHCP-IP-Address-Lease-Time = 3600 &DHCP-Domain-Name-Server = 72.173.31.41 ... } Regards, Nagamani Chinnapaiyan

3 2

Fwd: Re: SQL query as fallback to auth script?
by Wladyslaw Jankowski 04 May '19

04 May '19

On 03.05.19 18:35, Alan DeKok wrote: >> On May 3, 2019, at 10:40 AM, Wladyslaw Jankowski <wladekj(a)interia.pl> >> wrote: >> >> Learn how to format your messages. When you make it difficult for us >> to help you, we're inclined to avoid helping you. Please accept my apologies for my last message's formatting. What was written in plain ASCII became somehow re-formatted to HTML, and a lot of newlines were scrambled. Using different client now. >> This is the idea: script should always reject - doing its thing >> behind the scenes - and allow for SQL fallback. >> >> That makes no sense whatsoever. If the script always rejects, then >> you always need a work-around for that reject. >> >> Why not just have the script do it's thing, and have it return an >> "ok" code? The idea is for the script to ping the auth server (proprietary solution) for given user's NT hash, and store it in a local database for a short period of time. Script should always "Reject" and there is where I was hoping for an ability for an SQL fallback. This way the script would temporarily insert NT hash into the local database, and FreeRADIUS would query the database entry moments later. This would introduce a short delay but should work - would the fallback be possible. > I can't "Accept" RADIUS auth with this script as it can't calculate > MSCHAP challanges and no cleartext password will be provided to it > (can't use PAP). > Yes, FreeRADIUS does authentication. Your script doesn't. That's the > way it should work./ From my understanding of MSCHAP RFC documents - access to the NT hash is required to calculate/validate the challenge and/or Authenticator field. The idea was for the RADIUS server not to have full access to the whole database but to fire up a script that would grab one given hash, store it in a local database, and allow FreeRADIUS to use "sql" authorization method to validate the MSCHAP challenge based on the NT hash. > Perhaps you could set a password? > > Or, set "Auth-Type := Accept" if you want the user to always be accepted. I can't blindly accept any given password without validation. The least insecure way I've figured out was to be able to grab one given hash and work with that. That's why the script was supposed to always "Reject" (or is there like a half-way-Reject allowing for fallback?). > The problem here is that you're asking how to fix the "solution" you > came up with. That's bad practice. Instead, you should be describing > your requirements. We can then offer you advice as to how to meet > those requirements. My requirements were basically that I would like to be able to authorize users with EAP-MSCHAPv2 / EAP-TTLS without having direct access to the db with NT passwords. With PAP it is possible to pass %{User-Password} to the script but no such field is present in MSCHAPv2 packets. The fallback-idea was to blindly grab the (one given) hash from the proprietary solution and allow FreeRADIUS to validate credentials based on it. Short after it was supposed to be deleted from local store. > So what are you trying to do? What *problem* are you trying to solve? > And don't answer "run the script and SQL". That isn't relevant. What > are the users trying to do? What answers do you want the RADIUS server > to return? And why? Initial problem: with fancy-artsy authorization methods - the password is not being sent in clear text like it was with PAP - so there is no way to pass username and password to the script. Desired behavior: RADIUS server should Accept or Reject the request based on given credentials. I was hoping here to do this in such way that FreeRADIUS wouldn't have to have access to the full database but I guess that I'll have to go this path if it's the only viable option(?) Thanks WJ

1 0