- Freeradius-Users - lists.freeradius.org

Difference between proxying to real and virtual server in proxy-inner-tunnel
by Herwin Weststrate 05 Dec '18

05 Dec '18

Given the following setup: - Client using PEAP - Server configured to use proxy-inner-tunnel for PEAP - proxy_tunneled_request_as_eap disabled - proxy-inner-tunnel assigns a fixed value to Proxy-To-Realm - proxy.conf configured for this realm to proxy to localhost:18121 - a virtual server listening on this port, very basic configuration - users file has user bob enabled Using eapol_test to authenticate with user bob works fine. The debug log shows we get a request on 127.0.0.1:18121 with User-Name bob and some MS-CHAP-attributes. In the end we get an Access-Accept. Now, I tried to switch to a virtual server by removing ipaddr/port/secret from the home_server statement, and replacing it with a virtual_server option. I would expect this to behave the same, but instead of proxying the inner packet I get the outer packet in the virtual server and the authentication breaks because we don't have the inner EAP information. I've seen this behaviour in both 3.0.15 and the current v3.0.x (commit 8ef4848c34696caa0d61003470d321974049b794). The behaviour is not what I did expect, so I guess this is a bug. It's also a bug that is pretty to fix without breaking backwards compatibility. -- Herwin Weststrate

2 2

Re: Hex to Cleartext
by Chinnapaiyan, Nagamani 05 Dec '18

05 Dec '18

This “0x%{redis:…}” doesnot work for me. Lines in config file: if(updated && "0x%{redis: GET %{control:Pool-Name}:option}") { update reply { &DHCP-Vendor = "0x%{redis: GET %{control:Pool-Name}:option}" } } It parses the if condition correctly.. but the assignment part somehow it doesnot process it correctly. Debug output: Wed Dec 5 04:44:41 2018 : Info : FreeRADIUS Version 4.0.0 Wed Dec 5 04:44:41 2018 : Info : Copyright 1999-2018 The FreeRADIUS server project and contributors Wed Dec 5 04:44:41 2018 : Info : There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Wed Dec 5 04:44:41 2018 : Info : PARTICULAR PURPOSE Wed Dec 5 04:44:41 2018 : Info : You may redistribute copies of FreeRADIUS under the terms of the Wed Dec 5 04:44:41 2018 : Info : GNU General Public License Wed Dec 5 04:44:41 2018 : Info : For more information about these matters, see the file named COPYRIGHT Wed Dec 5 04:44:41 2018 : Info : Starting - reading configuration files ... Wed Dec 5 04:44:41 2018 : Debug : Including dictionary file "/usr/local/share/freeradius/dictionary" Wed Dec 5 04:44:41 2018 : Debug : Including dictionary file "/usr/local/etc/raddb/dictionary" Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/radiusd.conf Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/clients.conf Wed Dec 5 04:44:41 2018 : Debug : Including files in directory "/usr/local/etc/raddb/mods-enabled/" Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/always Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/cache_eap Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/chap Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/client Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/detail Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/detail.log Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/digest Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/dhcpv4 Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/eap_inner Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/echo Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/escape Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/exec Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/expiration Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/expr Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/files Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/linelog Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/logintime Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/mschap Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/pam Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/pap Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/passwd Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/radius Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/radutmp Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/soh Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/stats Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/unix Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/unpack Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/utf8 Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/mac2ip Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/redis_ippool Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/mods-enabled/redis Wed Dec 5 04:44:41 2018 : Debug : Including files in directory "/usr/local/etc/raddb/policy.d/" Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/abfab-tr Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/accounting Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/canonicalization Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/control Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/cui Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/debug Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/dhcp Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/eap Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/filter Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/operator-name Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/time Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/policy.d/vendor Wed Dec 5 04:44:41 2018 : Debug : Including files in directory "/usr/local/etc/raddb/sites-enabled/" Wed Dec 5 04:44:41 2018 : Debug : including configuration file /usr/local/etc/raddb/sites-enabled/dhcp Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary proto_dhcpv4 Wed Dec 5 04:44:41 2018 : Info : Loaded module "proto_dhcpv4" Wed Dec 5 04:44:41 2018 : Debug : Parsing security rules to bootstrap UID / GID / chroot / etc. Wed Dec 5 04:44:41 2018 : Debug : main { Wed Dec 5 04:44:41 2018 : Debug : security { Wed Dec 5 04:44:41 2018 : Debug : allow_core_dumps = no Wed Dec 5 04:44:41 2018 : Debug : allow_vulnerable_openssl = "no" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : name = radiusd Wed Dec 5 04:44:41 2018 : Debug : name = "radiusd" Wed Dec 5 04:44:41 2018 : Debug : prefix = "/usr/local" Wed Dec 5 04:44:41 2018 : Debug : local_state_dir = "/usr/local/var" Wed Dec 5 04:44:41 2018 : Debug : run_dir = "/usr/local/var/run/radiusd" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Parsing main configuration. Wed Dec 5 04:44:41 2018 : Debug : main { Wed Dec 5 04:44:41 2018 : Debug : server dhcp { Wed Dec 5 04:44:41 2018 : Debug : namespace = "dhcpv4" Wed Dec 5 04:44:41 2018 : Debug : listen { Wed Dec 5 04:44:41 2018 : Debug : type = DHCP-Discover Wed Dec 5 04:44:41 2018 : Info : Loaded module "proto_dhcpv4_base" Wed Dec 5 04:44:41 2018 : Debug : type = DHCP-Request Wed Dec 5 04:44:41 2018 : Debug : type = DHCP-Inform Wed Dec 5 04:44:41 2018 : Debug : type = DHCP-Release Wed Dec 5 04:44:41 2018 : Debug : type = DHCP-Decline Wed Dec 5 04:44:41 2018 : Debug : transport = udp Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary proto_dhcpv4_udp Wed Dec 5 04:44:41 2018 : Info : Loaded module "proto_dhcpv4_udp" Wed Dec 5 04:44:41 2018 : Debug : udp { Wed Dec 5 04:44:41 2018 : Debug : ipaddr = 10.43.18.92 Wed Dec 5 04:44:41 2018 : Debug : port = 67 Wed Dec 5 04:44:41 2018 : Debug : broadcast = no Wed Dec 5 04:44:41 2018 : Debug : networks { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : max_packet_size = 4096 Wed Dec 5 04:44:41 2018 : Debug : max_attributes = 0 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : limit { Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 30.000000 Wed Dec 5 04:44:41 2018 : Debug : nak_lifetime = 30.000000 Wed Dec 5 04:44:41 2018 : Debug : max_connections = 1024 Wed Dec 5 04:44:41 2018 : Debug : max_clients = 256 Wed Dec 5 04:44:41 2018 : Debug : max_pending_packets = 256 Wed Dec 5 04:44:41 2018 : Debug : priority { Wed Dec 5 04:44:41 2018 : Debug : DHCP-Discover = normal Wed Dec 5 04:44:41 2018 : Debug : DHCP-Request = normal Wed Dec 5 04:44:41 2018 : Debug : DHCP-Decline = normal Wed Dec 5 04:44:41 2018 : Debug : DHCP-Release = normal Wed Dec 5 04:44:41 2018 : Debug : DHCP-Inform = normal Wed Dec 5 04:44:41 2018 : Debug : DHCP-Lease-Query = low Wed Dec 5 04:44:41 2018 : Debug : DHCP-Bulk-Lease-Query = low Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : security { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : sbin_dir = "/usr/local/sbin" Wed Dec 5 04:44:41 2018 : Debug : logdir = "/usr/local/var/log/radius" Wed Dec 5 04:44:41 2018 : Debug : libdir = "/usr/local/lib" Wed Dec 5 04:44:41 2018 : Debug : radacctdir = "/usr/local/var/log/radius/radacct" Wed Dec 5 04:44:41 2018 : Debug : reverse_lookups = no Wed Dec 5 04:44:41 2018 : Debug : reverse_lookups = no Wed Dec 5 04:44:41 2018 : Debug : hostname_lookups = yes Wed Dec 5 04:44:41 2018 : Debug : hostname_lookups = yes Wed Dec 5 04:44:41 2018 : Debug : max_request_time = 30 Wed Dec 5 04:44:41 2018 : Debug : max_request_time = 30 Wed Dec 5 04:44:41 2018 : Debug : pidfile = "/usr/local/var/run/radiusd/radiusd.pid" Wed Dec 5 04:44:41 2018 : Debug : debug_level = 0 Wed Dec 5 04:44:41 2018 : Debug : log { Wed Dec 5 04:44:41 2018 : Debug : colourise = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : resources { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : thread pool { Wed Dec 5 04:44:41 2018 : Debug : num_networks = 1 Wed Dec 5 04:44:41 2018 : Debug : num_networks = 1 Wed Dec 5 04:44:41 2018 : Debug : num_workers = 4 Wed Dec 5 04:44:41 2018 : Debug : num_workers = 4 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Switching to configured log settings Wed Dec 5 04:44:41 2018 : Debug : radiusd: #### Loading Clients #### Wed Dec 5 04:44:41 2018 : Debug : client localhost { Wed Dec 5 04:44:41 2018 : Debug : ipaddr = 127.0.0.1 Wed Dec 5 04:44:41 2018 : Debug : require_message_authenticator = no Wed Dec 5 04:44:41 2018 : Debug : secret = <<< secret >>> Wed Dec 5 04:44:41 2018 : Debug : proto = "*" Wed Dec 5 04:44:41 2018 : Debug : limit { Wed Dec 5 04:44:41 2018 : Debug : max_connections = 16 Wed Dec 5 04:44:41 2018 : Debug : lifetime = 0 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : client localhost_ipv6 { Wed Dec 5 04:44:41 2018 : Debug : ipv6addr = ::1 Wed Dec 5 04:44:41 2018 : Debug : require_message_authenticator = no Wed Dec 5 04:44:41 2018 : Debug : secret = <<< secret >>> Wed Dec 5 04:44:41 2018 : Debug : limit { Wed Dec 5 04:44:41 2018 : Debug : max_connections = 16 Wed Dec 5 04:44:41 2018 : Debug : lifetime = 0 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : client private-network-1 { Wed Dec 5 04:44:41 2018 : Debug : ipaddr = 10.43.18.0/24 Wed Dec 5 04:44:41 2018 : Debug : require_message_authenticator = no Wed Dec 5 04:44:41 2018 : Debug : secret = <<< secret >>> Wed Dec 5 04:44:41 2018 : Debug : limit { Wed Dec 5 04:44:41 2018 : Debug : max_connections = 16 Wed Dec 5 04:44:41 2018 : Debug : lifetime = 0 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Debugger not attached Wed Dec 5 04:44:41 2018 : Debug : #### Bootstrapping listeners #### Wed Dec 5 04:44:41 2018 : Debug : #### Bootstrapping modules #### Wed Dec 5 04:44:41 2018 : Debug : modules { Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_always" Wed Dec 5 04:44:41 2018 : Debug : always reject { Wed Dec 5 04:44:41 2018 : Debug : rcode = "reject" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always fail { Wed Dec 5 04:44:41 2018 : Debug : rcode = "fail" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always ok { Wed Dec 5 04:44:41 2018 : Debug : rcode = "ok" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always handled { Wed Dec 5 04:44:41 2018 : Debug : rcode = "handled" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always invalid { Wed Dec 5 04:44:41 2018 : Debug : rcode = "invalid" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always userlock { Wed Dec 5 04:44:41 2018 : Debug : rcode = "userlock" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always notfound { Wed Dec 5 04:44:41 2018 : Debug : rcode = "notfound" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always noop { Wed Dec 5 04:44:41 2018 : Debug : rcode = "noop" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : always updated { Wed Dec 5 04:44:41 2018 : Debug : rcode = "updated" Wed Dec 5 04:44:41 2018 : Debug : simulcount = 0 Wed Dec 5 04:44:41 2018 : Debug : mpp = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_attr_filter Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_attr_filter" Wed Dec 5 04:44:41 2018 : Debug : attr_filter attr_filter.pre-proxy { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" Wed Dec 5 04:44:41 2018 : Debug : relaxed = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : attr_filter attr_filter.post-proxy { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" Wed Dec 5 04:44:41 2018 : Debug : relaxed = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : attr_filter attr_filter.access_reject { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" Wed Dec 5 04:44:41 2018 : Debug : relaxed = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : attr_filter attr_filter.access_challenge { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" Wed Dec 5 04:44:41 2018 : Debug : relaxed = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : attr_filter attr_filter.accounting_response { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" Wed Dec 5 04:44:41 2018 : Debug : relaxed = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_cache Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_cache" Wed Dec 5 04:44:41 2018 : Debug : cache cache_eap { Wed Dec 5 04:44:41 2018 : Debug : driver = "rlm_cache_rbtree" Wed Dec 5 04:44:41 2018 : Debug : ttl = 15 Wed Dec 5 04:44:41 2018 : Debug : max_entries = 0 Wed Dec 5 04:44:41 2018 : Debug : epoch = 0 Wed Dec 5 04:44:41 2018 : Debug : add_stats = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_chap Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_chap" Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_client" Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_detail Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_detail" Wed Dec 5 04:44:41 2018 : Debug : detail { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-S rc-IPv6-Address}}/detail-%Y-%m-%d" Wed Dec 5 04:44:41 2018 : Debug : header = "%t" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : locking = no Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : log_packet_header = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : detail auth_log { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-S rc-IPv6-Address}}/auth-detail-%Y-%m-%d" Wed Dec 5 04:44:41 2018 : Debug : header = "%t" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : locking = no Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : log_packet_header = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : detail reply_log { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-S rc-IPv6-Address}}/reply-detail-%Y-%m-%d" Wed Dec 5 04:44:41 2018 : Debug : header = "%t" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : locking = no Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : log_packet_header = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : detail pre_proxy_log { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-S rc-IPv6-Address}}/pre-proxy-detail-%Y-%m-%d" Wed Dec 5 04:44:41 2018 : Debug : header = "%t" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : locking = no Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : log_packet_header = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : detail post_proxy_log { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-S rc-IPv6-Address}}/post-proxy-detail-%Y-%m-%d" Wed Dec 5 04:44:41 2018 : Debug : header = "%t" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : locking = no Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : log_packet_header = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_digest Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_digest" Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_dhcpv4" Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_eap Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_eap" Wed Dec 5 04:44:41 2018 : Debug : eap inner-eap { Wed Dec 5 04:44:41 2018 : Debug : default_eap_type = mschapv2 Wed Dec 5 04:44:41 2018 : Debug : type = md5 Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_eap_md5 Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_eap_md5" Wed Dec 5 04:44:41 2018 : Debug : type = gtc Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_eap_gtc Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_eap_gtc" Wed Dec 5 04:44:41 2018 : Debug : gtc { Wed Dec 5 04:44:41 2018 : Debug : challenge = "Password: " Wed Dec 5 04:44:41 2018 : Debug : auth_type = PAP Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : type = mschapv2 Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_eap_mschapv2 Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_eap_mschapv2" Wed Dec 5 04:44:41 2018 : Debug : mschapv2 { Wed Dec 5 04:44:41 2018 : Debug : with_ntdomain_hack = no Wed Dec 5 04:44:41 2018 : Debug : auth_type = mschap Wed Dec 5 04:44:41 2018 : Debug : send_error = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : type = tls Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_eap_tls Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_eap_tls" Wed Dec 5 04:44:41 2018 : Debug : tls { Wed Dec 5 04:44:41 2018 : Debug : tls = "tls-peer" Wed Dec 5 04:44:41 2018 : Debug : require_client_cert = yes Wed Dec 5 04:44:41 2018 : Debug : include_length = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : ignore_unknown_eap_types = no Wed Dec 5 04:44:41 2018 : Debug : cisco_accounting_username_bug = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_exec" Wed Dec 5 04:44:41 2018 : Debug : exec echo { Wed Dec 5 04:44:41 2018 : Debug : wait = yes Wed Dec 5 04:44:41 2018 : Debug : program = "/bin/echo %{User-Name}" Wed Dec 5 04:44:41 2018 : Debug : input_pairs = "request" Wed Dec 5 04:44:41 2018 : Debug : output_pairs = "reply" Wed Dec 5 04:44:41 2018 : Debug : shell_escape = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_escape" Wed Dec 5 04:44:41 2018 : Debug : escape { Wed Dec 5 04:44:41 2018 : Debug : safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.- _: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : exec { Wed Dec 5 04:44:41 2018 : Debug : wait = no Wed Dec 5 04:44:41 2018 : Debug : input_pairs = "request" Wed Dec 5 04:44:41 2018 : Debug : shell_escape = yes Wed Dec 5 04:44:41 2018 : Debug : timeout = 10 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_expiration Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_expiration" Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_expr" Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_files Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_files" Wed Dec 5 04:44:41 2018 : Debug : files { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/files/authorize" Wed Dec 5 04:44:41 2018 : Debug : acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" Wed Dec 5 04:44:41 2018 : Debug : preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_linelog" Wed Dec 5 04:44:41 2018 : Debug : linelog { Wed Dec 5 04:44:41 2018 : Debug : destination = "file" Wed Dec 5 04:44:41 2018 : Debug : delimiter = " " Wed Dec 5 04:44:41 2018 : Debug : file { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/linelog" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : syslog { Wed Dec 5 04:44:41 2018 : Debug : severity = "info" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : unix { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : tcp { Wed Dec 5 04:44:41 2018 : Debug : port = 514 Wed Dec 5 04:44:41 2018 : Debug : timeout = 2.000000 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : udp { Wed Dec 5 04:44:41 2018 : Debug : port = 514 Wed Dec 5 04:44:41 2018 : Debug : timeout = 2.000000 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : linelog log_accounting { Wed Dec 5 04:44:41 2018 : Debug : destination = "file" Wed Dec 5 04:44:41 2018 : Debug : delimiter = " " Wed Dec 5 04:44:41 2018 : Debug : file { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/linelog-accounting" Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : escape_filenames = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : syslog { Wed Dec 5 04:44:41 2018 : Debug : severity = "info" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : unix { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : tcp { Wed Dec 5 04:44:41 2018 : Debug : timeout = 1000.000000 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : udp { Wed Dec 5 04:44:41 2018 : Debug : timeout = 1000.000000 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_logintime Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_logintime" Wed Dec 5 04:44:41 2018 : Debug : logintime { Wed Dec 5 04:44:41 2018 : Debug : minimum_timeout = 60 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_mschap" Wed Dec 5 04:44:41 2018 : Debug : mschap { Wed Dec 5 04:44:41 2018 : Debug : use_mppe = yes Wed Dec 5 04:44:41 2018 : Debug : require_encryption = no Wed Dec 5 04:44:41 2018 : Debug : require_strong = no Wed Dec 5 04:44:41 2018 : Debug : with_ntdomain_hack = yes Wed Dec 5 04:44:41 2018 : Debug : passchange { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : allow_retry = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : exec ntlm_auth { Wed Dec 5 04:44:41 2018 : Debug : wait = yes Wed Dec 5 04:44:41 2018 : Debug : program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap :User-Name} --password=%{User-Password}" Wed Dec 5 04:44:41 2018 : Debug : shell_escape = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_pam Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_pam" Wed Dec 5 04:44:41 2018 : Debug : pam { Wed Dec 5 04:44:41 2018 : Debug : pam_auth = "radiusd" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_pap Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_pap" Wed Dec 5 04:44:41 2018 : Debug : pap { Wed Dec 5 04:44:41 2018 : Debug : normalise = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_passwd Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_passwd" Wed Dec 5 04:44:41 2018 : Debug : passwd etc_passwd { Wed Dec 5 04:44:41 2018 : Debug : filename = "/etc/passwd" Wed Dec 5 04:44:41 2018 : Debug : format = "*User-Name:Crypt-Password:" Wed Dec 5 04:44:41 2018 : Debug : delimiter = ":" Wed Dec 5 04:44:41 2018 : Debug : ignore_nislike = no Wed Dec 5 04:44:41 2018 : Debug : ignore_empty = yes Wed Dec 5 04:44:41 2018 : Debug : allow_multiple_keys = no Wed Dec 5 04:44:41 2018 : Debug : hash_size = 100 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_radius Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_radius" Wed Dec 5 04:44:41 2018 : Debug : radius { Wed Dec 5 04:44:41 2018 : Debug : transport = udp Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_radius_udp Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_radius_udp" Wed Dec 5 04:44:41 2018 : Debug : udp { Wed Dec 5 04:44:41 2018 : Debug : ipaddr = 127.0.0.1 Wed Dec 5 04:44:41 2018 : Debug : port = 1812 Wed Dec 5 04:44:41 2018 : Debug : secret = "testing123" Wed Dec 5 04:44:41 2018 : Debug : max_packet_size = 4096 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : type = Access-Request Wed Dec 5 04:44:41 2018 : Debug : type = Accounting-Request Wed Dec 5 04:44:41 2018 : Debug : status_checks { Wed Dec 5 04:44:41 2018 : Debug : type = Status-Server Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : max_connections = 32 Wed Dec 5 04:44:41 2018 : Debug : max_attributes = 255 Wed Dec 5 04:44:41 2018 : Debug : connection { Wed Dec 5 04:44:41 2018 : Debug : connect_timeout = 5.000000 Wed Dec 5 04:44:41 2018 : Debug : reconnect_delay = 5.000000 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 5.000000 Wed Dec 5 04:44:41 2018 : Debug : zombie_period = 10.000000 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Access-Request { Wed Dec 5 04:44:41 2018 : Debug : initial_retransmission_time = 2 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_time = 16 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_count = 2 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_duration = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Accounting-Request { Wed Dec 5 04:44:41 2018 : Debug : initial_retransmission_time = 2 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_time = 16 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_count = 5 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_duration = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Status-Server { Wed Dec 5 04:44:41 2018 : Debug : initial_retransmission_time = 2 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_time = 16 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_count = 5 Wed Dec 5 04:44:41 2018 : Debug : maximum_retransmission_duration = 30 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_radutmp Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_radutmp" Wed Dec 5 04:44:41 2018 : Debug : radutmp { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/radutmp" Wed Dec 5 04:44:41 2018 : Debug : username = "%{User-Name}" Wed Dec 5 04:44:41 2018 : Debug : case_sensitive = yes Wed Dec 5 04:44:41 2018 : Debug : check_with_nas = yes Wed Dec 5 04:44:41 2018 : Debug : permissions = 384 Wed Dec 5 04:44:41 2018 : Debug : caller_id = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_soh Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_soh" Wed Dec 5 04:44:41 2018 : Debug : soh { Wed Dec 5 04:44:41 2018 : Debug : dhcp = yes Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : radutmp sradutmp { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/var/log/radius/sradutmp" Wed Dec 5 04:44:41 2018 : Debug : username = "%{User-Name}" Wed Dec 5 04:44:41 2018 : Debug : case_sensitive = yes Wed Dec 5 04:44:41 2018 : Debug : check_with_nas = yes Wed Dec 5 04:44:41 2018 : Debug : permissions = 420 Wed Dec 5 04:44:41 2018 : Debug : caller_id = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_stats Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_stats" Wed Dec 5 04:44:41 2018 : Debug : stats { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_unix Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_unix" Wed Dec 5 04:44:41 2018 : Debug : unix { Wed Dec 5 04:44:41 2018 : Debug : radwtmp = "/usr/local/var/log/radius/radwtmp" Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Creating attribute Unix-Group Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_unpack Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_unpack" Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_utf8" Wed Dec 5 04:44:41 2018 : Debug : passwd mac2ip { Wed Dec 5 04:44:41 2018 : Debug : filename = "/usr/local/etc/raddb/mods-config/passwd/mac2ip" Wed Dec 5 04:44:41 2018 : Debug : format = "*DHCP-Client-Hardware-Address:=DHCP-Your-IP-Address" Wed Dec 5 04:44:41 2018 : Debug : delimiter = "," Wed Dec 5 04:44:41 2018 : Debug : ignore_nislike = yes Wed Dec 5 04:44:41 2018 : Debug : ignore_empty = yes Wed Dec 5 04:44:41 2018 : Debug : allow_multiple_keys = no Wed Dec 5 04:44:41 2018 : Debug : hash_size = 100 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : libfreeradius-redis: libhiredis version: 0.12.1 Wed Dec 5 04:44:41 2018 : Debug : Loading dictionary rlm_redis_ippool Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_redis_ippool" Wed Dec 5 04:44:41 2018 : Debug : redis_ippool { Wed Dec 5 04:44:41 2018 : Debug : copy_on_update = yes Wed Dec 5 04:44:41 2018 : Debug : redis { Wed Dec 5 04:44:41 2018 : Debug : server = "10.43.16.224" Wed Dec 5 04:44:41 2018 : Debug : port = 6379 Wed Dec 5 04:44:41 2018 : Debug : database = 0 Wed Dec 5 04:44:41 2018 : Debug : max_nodes = 20 Wed Dec 5 04:44:41 2018 : Debug : max_alt = 3 Wed Dec 5 04:44:41 2018 : Debug : max_redirects = 2 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Info : libfreeradius-redis: libhiredis version: 0.12.1 Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_redis" Wed Dec 5 04:44:41 2018 : Debug : redis { Wed Dec 5 04:44:41 2018 : Debug : server = "10.43.16.224" Wed Dec 5 04:44:41 2018 : Debug : port = 6379 Wed Dec 5 04:44:41 2018 : Debug : database = 0 Wed Dec 5 04:44:41 2018 : Debug : max_nodes = 20 Wed Dec 5 04:44:41 2018 : Debug : max_alt = 3 Wed Dec 5 04:44:41 2018 : Debug : max_redirects = 2 Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : instantiate { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } # modules Wed Dec 5 04:44:41 2018 : Debug : #### Instantiating listeners #### Wed Dec 5 04:44:41 2018 : Debug : Compiling policies in server dhcp { ... } Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Discover {...} Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Request {...} Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Decline {...} Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Inform {...} Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Release {...} Wed Dec 5 04:44:41 2018 : Debug : compiling - recv DHCP-Lease-Query {...} Wed Dec 5 04:44:41 2018 : Debug : #### Instantiating modules #### Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "attr_filter.access_challenge" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "attr_filter.access_reject" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/attr_filter/access_reject Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "attr_filter.accounting_response" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "attr_filter.post-proxy" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "attr_filter.pre-proxy" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "auth_log" Wed Dec 5 04:44:41 2018 : Debug : rlm_detail (auth_log) - 'User-Password' suppressed, will not appear in detail output Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "cache_eap" Wed Dec 5 04:44:41 2018 : Info : Loaded module "rlm_cache_rbtree" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "detail" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "etc_passwd" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "expiration" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "fail" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "files" Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/files/authorize Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/files/accounting Wed Dec 5 04:44:41 2018 : Debug : Reading file /usr/local/etc/raddb/mods-config/files/pre-proxy Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "handled" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "inner-eap" Wed Dec 5 04:44:41 2018 : Debug : tls-config tls-peer { Wed Dec 5 04:44:41 2018 : Debug : auto_chain = yes Wed Dec 5 04:44:41 2018 : Debug : chain { Wed Dec 5 04:44:41 2018 : Debug : format = pem Wed Dec 5 04:44:41 2018 : Debug : certificate_file = "/usr/local/etc/raddb/certs/rsa/server.pem" Wed Dec 5 04:44:41 2018 : Debug : private_key_password = <<< secret >>> Wed Dec 5 04:44:41 2018 : Debug : private_key_file = "/usr/local/etc/raddb/certs/rsa/server.key" Wed Dec 5 04:44:41 2018 : Debug : ca_file = "/usr/local/etc/raddb/certs/rsa/ca.pem" Wed Dec 5 04:44:41 2018 : Debug : verify_mode = hard Wed Dec 5 04:44:41 2018 : Debug : include_root_ca = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : verify_depth = 0 Wed Dec 5 04:44:41 2018 : Debug : ca_path = "/usr/local/etc/raddb/certs" Wed Dec 5 04:44:41 2018 : Debug : ca_file = "/usr/local/etc/raddb/certs/rsa/ca.pem" Wed Dec 5 04:44:41 2018 : Debug : dh_file = "/usr/local/etc/raddb/certs/dh" Wed Dec 5 04:44:41 2018 : Debug : fragment_size = 16384 Wed Dec 5 04:44:41 2018 : Debug : check_crl = no Wed Dec 5 04:44:41 2018 : Debug : cipher_server_preference = yes Wed Dec 5 04:44:41 2018 : Debug : allow_renegotiation = no Wed Dec 5 04:44:41 2018 : Debug : ecdh_curve = "prime256v1" Wed Dec 5 04:44:41 2018 : Debug : tls_min_version = 1.000000 Wed Dec 5 04:44:41 2018 : Debug : cache { Wed Dec 5 04:44:41 2018 : Debug : lifetime = 86400 Wed Dec 5 04:44:41 2018 : Debug : verify = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : verify { Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : ocsp { Wed Dec 5 04:44:41 2018 : Debug : enable = no Wed Dec 5 04:44:41 2018 : Debug : override_cert_url = no Wed Dec 5 04:44:41 2018 : Debug : use_nonce = yes Wed Dec 5 04:44:41 2018 : Debug : timeout = 0 Wed Dec 5 04:44:41 2018 : Debug : softfail = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : staple { Wed Dec 5 04:44:41 2018 : Debug : enable = no Wed Dec 5 04:44:41 2018 : Debug : override_cert_url = no Wed Dec 5 04:44:41 2018 : Debug : use_nonce = yes Wed Dec 5 04:44:41 2018 : Debug : timeout = 0 Wed Dec 5 04:44:41 2018 : Debug : softfail = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "invalid" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "linelog" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "log_accounting" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "logintime" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "mac2ip" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "mschap" Wed Dec 5 04:44:41 2018 : Debug : mschap: using internal authentication Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "noop" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "notfound" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "ok" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "pam" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "post_proxy_log" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "pre_proxy_log" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "radius" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "redis" Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Initialising connection pool Wed Dec 5 04:44:41 2018 : Debug : pool { Wed Dec 5 04:44:41 2018 : Debug : start = 4 Wed Dec 5 04:44:41 2018 : Debug : min = 1 Wed Dec 5 04:44:41 2018 : Debug : max = 4 Wed Dec 5 04:44:41 2018 : Debug : max_pending = 0 Wed Dec 5 04:44:41 2018 : Debug : spare = 1 Wed Dec 5 04:44:41 2018 : Debug : uses = 0 Wed Dec 5 04:44:41 2018 : Debug : lifetime = 86400 Wed Dec 5 04:44:41 2018 : Debug : cleanup_interval = 300 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 600 Wed Dec 5 04:44:41 2018 : Debug : connect_timeout = 3.000000 Wed Dec 5 04:44:41 2018 : Debug : held_trigger_min = 0.000000 Wed Dec 5 04:44:41 2018 : Debug : held_trigger_max = 0.500000 Wed Dec 5 04:44:41 2018 : Debug : retry_delay = 30 Wed Dec 5 04:44:41 2018 : Debug : spread = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (0), 1 of 4 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (1), 1 of 3 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (2), 1 of 2 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (3), 1 of 1 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Reserved connection (3) Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis): Bootstrap server "10.43.16.224" returned: ERR This instance has cluster support disabled Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Released connection (3) Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "redis_ippool" Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Initialising connection pool Wed Dec 5 04:44:41 2018 : Debug : pool { Wed Dec 5 04:44:41 2018 : Debug : start = 0 Wed Dec 5 04:44:41 2018 : Debug : min = 4 Wed Dec 5 04:44:41 2018 : Debug : max = 4 Wed Dec 5 04:44:41 2018 : Debug : max_pending = 0 Wed Dec 5 04:44:41 2018 : Debug : spare = 1 Wed Dec 5 04:44:41 2018 : Debug : uses = 0 Wed Dec 5 04:44:41 2018 : Debug : lifetime = 0 Wed Dec 5 04:44:41 2018 : Debug : cleanup_interval = 30 Wed Dec 5 04:44:41 2018 : Debug : idle_timeout = 60 Wed Dec 5 04:44:41 2018 : Debug : connect_timeout = 3.000000 Wed Dec 5 04:44:41 2018 : Debug : held_trigger_min = 0.000000 Wed Dec 5 04:44:41 2018 : Debug : held_trigger_max = 0.500000 Wed Dec 5 04:44:41 2018 : Debug : retry_delay = 30 Wed Dec 5 04:44:41 2018 : Debug : spread = no Wed Dec 5 04:44:41 2018 : Debug : } Wed Dec 5 04:44:41 2018 : Warn : rlm_redis (redis) [1] - Ignoring "spare = 1", forcing to "spare = 0" Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - 0 of 0 connections in use. You may need to increase "spare" Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (0), 1 of 4 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Reserved connection (0) Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Released connection (0) Wed Dec 5 04:44:41 2018 : Info : rlm_redis (redis) [1] - Need 3 more connections to reach min connections (4) Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1] - Opening additional connection (1), 1 of 3 pending slots used Wed Dec 5 04:44:41 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "reject" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "reply_log" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "stats" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "updated" Wed Dec 5 04:44:41 2018 : Debug : Instantiating module "userlock" Wed Dec 5 04:44:41 2018 : Debug : [1] radius - Connection initialising Wed Dec 5 04:44:41 2018 : Debug : [1] radius - Connection initialised Wed Dec 5 04:44:41 2018 : Debug : Scheduler created in single-threaded mode Wed Dec 5 04:44:41 2018 : Debug : #### Opening listener interfaces #### Wed Dec 5 04:44:41 2018 : Debug : Listening on dhcpv4 address proto_dhcpv4_udp server 10.43.18.92 port 67 bound to virtual s erver dhcp Wed Dec 5 04:44:41 2018 : Debug : Waking up in 4.9 seconds. Wed Dec 5 04:44:41 2018 : Debug : radius - Connection open - proto udp local 0.0.0.0 port 41575 remote 127.0.0.1 port 1812 Wed Dec 5 04:44:41 2018 : Debug : radius - Allocated Status-Server ID 0 for status checks on connection proto udp local 0.0. 0.0 port 41575 remote 127.0.0.1 port 1812 Wed Dec 5 04:44:41 2018 : Debug : radius - Setting idle timeout to +5.000000 for connection proto udp local 0.0.0.0 port 415 75 remote 127.0.0.1 port 1812 Wed Dec 5 04:44:41 2018 : Debug : [1] radius - Connection established Wed Dec 5 04:44:41 2018 : Debug : Waking up in 4.9 seconds. Wed Dec 5 04:44:41 2018 : Debug : Waking up in 4.9 seconds. Wed Dec 5 04:44:46 2018 : Debug : radius - Idle timeout for connection proto udp local 0.0.0.0 port 41575 remote 127.0.0.1 p ort 1812 Wed Dec 5 04:44:46 2018 : Debug : [1] radius - Closing connection (18) Wed Dec 5 04:44:46 2018 : Debug : radius - Connection closed - proto udp local 0.0.0.0 port 41575 remote 127.0.0.1 port 1812 Wed Dec 5 04:44:46 2018 : Info : Ready to process requests Wed Dec 5 04:44:49 2018 : Debug : proto_dhcpv4_udp - Received DHCP-Discover XID 00000000 length 259 proto_dhcpv4_udp server 10.43.18.92 port 67 Wed Dec 5 04:44:49 2018 : Debug : Network received packet size 259 Wed Dec 5 04:44:49 2018 : Debug : Resetting worker 30 cleanup timer to +0s Wed Dec 5 04:44:49 2018 : Debug : (0) running request (0) Wed Dec 5 04:44:49 2018 : Debug : Received DHCP-Discover XID 00000000 from 127.0.0.1:67 to 10.43.18.92:67 via lo (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Opcode = Client-Message (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hardware-Type = Ethernet (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hardware-Address-Length = 6 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hop-Count = 1 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Transaction-Id = 0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Number-of-Seconds = 0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Flags = 0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-IP-Address = 127.0.0.1 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Your-IP-Address = 0.0.0.0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Server-IP-Address = 0.0.0.0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Gateway-IP-Address = 127.0.0.1 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-Hardware-Address = 00:a1:bc:00:10:01 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Message-Type = DHCP-Discover (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-Identifier = 0x0100a1bc000001 (0) Wed Dec 5 04:44:49 2018 : Debug : Running 'recv DHCP-Discover' from file /usr/local/etc/raddb/sites-enabled/dhcp (0) Wed Dec 5 04:44:49 2018 : Debug : recv DHCP-Discover { (0) Wed Dec 5 04:44:49 2018 : Debug : update reply { (0) Wed Dec 5 04:44:49 2018 : Debug : DHCP-Message-Type = DHCP-Offer (0) Wed Dec 5 04:44:49 2018 : Debug : } # update reply (noop) (0) Wed Dec 5 04:44:49 2018 : Debug : update reply { (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Subnet-Mask = 255.255.255.0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Router-Address = 10.43.18.92 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-IP-Address-Lease-Time = 900 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 (0) Wed Dec 5 04:44:49 2018 : Debug : } # update reply (noop) (0) Wed Dec 5 04:44:49 2018 : Debug : update control { (0) Wed Dec 5 04:44:49 2018 : Debug : &Pool-Name := "local" (0) Wed Dec 5 04:44:49 2018 : Debug : } # update control (noop) (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Allocating lease from pool "local", to "00:a1:bc:00:10:01", expires in 900s (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Reserved connection (1) (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - [1] >>> Sending command(s) to 10.43.16.224:6379 (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - [1] <<< Returned: success (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Released connection (1) (0) Wed Dec 5 04:44:49 2018 : Info : redis_ippool - Need 2 more connections to reach min connections (4) (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Opening additional connection (2), 1 of 2 pending slots used Wed Dec 5 04:44:49 2018 : Debug : rlm_redis (redis) [1]: Connecting node to 10.43.16.224:6379 (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - &reply:DHCP-Your-IP-Address := 192.168.24.0 (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - &reply:DHCP-IP-Address-Lease-Time := 663 (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - IP address lease allocated (0) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool (updated) (0) Wed Dec 5 04:44:49 2018 : Debug : ok (ok) (0) Wed Dec 5 04:44:49 2018 : Debug : } # recv DHCP-Discover (updated) (0) Wed Dec 5 04:44:49 2018 : Debug : Sent DHCP-Offer XID 00000000 from 10.43.18.92:67 to 127.0.0.1:67 via lo (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Message-Type = DHCP-Offer (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Subnet-Mask = 255.255.255.0 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Router-Address = 10.43.18.92 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-IP-Address-Lease-Time := 663 (0) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 Wed Dec 5 04:44:49 2018 : Debug : (0) done request Wed Dec 5 04:44:49 2018 : Debug : (0) finished request. Wed Dec 5 04:44:49 2018 : Info : Ready to process requests Wed Dec 5 04:44:49 2018 : Debug : Reply will be unicast to CIADDR from original packet. Wed Dec 5 04:44:49 2018 : Debug : proto_dhcpv4_udp - cleaning up ID 1 Wed Dec 5 04:44:49 2018 : Info : Ready to process requests Wed Dec 5 04:44:49 2018 : Debug : proto_dhcpv4_udp - Received DHCP-Request XID 00000000 length 265 proto_dhcpv4_udp server 1 0.43.18.92 port 67 Wed Dec 5 04:44:49 2018 : Debug : Network received packet size 265 Wed Dec 5 04:44:49 2018 : Debug : Resetting worker 30 cleanup timer to +0s Wed Dec 5 04:44:49 2018 : Debug : (1) running request (1) Wed Dec 5 04:44:49 2018 : Debug : Received DHCP-Request XID 00000000 from 127.0.0.1:67 to 10.43.18.92:67 via lo (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Opcode = Client-Message (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hardware-Type = Ethernet (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hardware-Address-Length = 6 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Hop-Count = 1 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Transaction-Id = 0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Number-of-Seconds = 0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Flags = 0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-IP-Address = 127.0.0.1 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Your-IP-Address = 0.0.0.0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Server-IP-Address = 0.0.0.0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Gateway-IP-Address = 127.0.0.1 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-Hardware-Address = 00:a1:bc:00:10:01 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Requested-IP-Address = 192.168.24.0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Message-Type = DHCP-Request (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Client-Identifier = 0x0100a1bc000001 (1) Wed Dec 5 04:44:49 2018 : Debug : Running 'recv DHCP-Request' from file /usr/local/etc/raddb/sites-enabled/dhcp (1) Wed Dec 5 04:44:49 2018 : Debug : recv DHCP-Request { (1) Wed Dec 5 04:44:49 2018 : Debug : update reply { (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Message-Type = DHCP-Ack (1) Wed Dec 5 04:44:49 2018 : Debug : } # update reply (noop) (1) Wed Dec 5 04:44:49 2018 : Debug : update reply { (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Subnet-Mask = 255.255.255.0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Router-Address = 10.43.18.92 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-IP-Address-Lease-Time = 900 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 (1) Wed Dec 5 04:44:49 2018 : Debug : } # update reply (noop) (1) Wed Dec 5 04:44:49 2018 : Debug : update control { (1) Wed Dec 5 04:44:49 2018 : Debug : &Pool-Name := "local" (1) Wed Dec 5 04:44:49 2018 : Debug : } # update control (noop) (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Allocating lease from pool "local", to "00:a1:bc:00:10:01", expires in 900s (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Reserved connection (2) (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - [1] >>> Sending command(s) to 10.43.16.224:6379 (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - [1] <<< Returned: success (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - Released connection (2) (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - &reply:DHCP-Your-IP-Address := 192.168.24.0 (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - &reply:DHCP-IP-Address-Lease-Time := 663 (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool - IP address lease allocated (1) Wed Dec 5 04:44:49 2018 : Debug : redis_ippool (updated) (1) Wed Dec 5 04:44:49 2018 : Debug : if (updated && "0x%{redis: GET %{control:Pool-Name}:option}") { (1) Wed Dec 5 04:44:49 2018 : Debug : EXPAND 0x%{redis: GET %{control:Pool-Name}:option} (1) Wed Dec 5 04:44:49 2018 : Debug : Reserved connection (3) (1) Wed Dec 5 04:44:49 2018 : Debug : [1] >>> Sending command(s) to 10.43.16.224:6379 (1) Wed Dec 5 04:44:49 2018 : Debug : Executing command: GET (1) Wed Dec 5 04:44:49 2018 : Debug : With arguments (1) Wed Dec 5 04:44:49 2018 : Debug : [1] local:option (1) Wed Dec 5 04:44:49 2018 : Debug : [1] <<< Returned: success (1) Wed Dec 5 04:44:49 2018 : Debug : Released connection (3) (1) Wed Dec 5 04:44:49 2018 : Debug : --> 0x010300a0bc0209555400000000000007030e555400000000000003070307001604115554 5f332e372e332e372e32322e62696e05040a4fff0f0c0200010e010014530100020103110500440044070043004301000201030606c0a8640018070050005 001010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f00000008330c55543200000000000000 29083b0e55543200000000000307030600003c115554325f332e372e332e362e302e62696e3d040a4fff06 (1) Wed Dec 5 04:44:49 2018 : Debug : update reply { (1) Wed Dec 5 04:44:49 2018 : Debug : EXPAND %{control:Pool-Name} (1) Wed Dec 5 04:44:49 2018 : Debug : --> local (1) Wed Dec 5 04:44:49 2018 : Debug : Reserved connection (3) (1) Wed Dec 5 04:44:49 2018 : Debug : [1] >>> Sending command(s) to 10.43.16.224:6379 (1) Wed Dec 5 04:44:49 2018 : Debug : Executing command: GET (1) Wed Dec 5 04:44:49 2018 : Debug : With arguments (1) Wed Dec 5 04:44:49 2018 : Debug : [1] local:option (1) Wed Dec 5 04:44:49 2018 : Debug : [1] <<< Returned: success (1) Wed Dec 5 04:44:49 2018 : Debug : Released connection (3) (1) Wed Dec 5 04:44:49 2018 : Debug : EXPAND %{redis: GET %{control:Pool-Name}:option} (1) Wed Dec 5 04:44:49 2018 : Debug : (%{redis: GET local:option}) (1) Wed Dec 5 04:44:49 2018 : Debug : --> 010300a0bc0209555400000000000007030e5554000000000000030703070016041155545 f332e372e332e372e32322e62696e05040a4fff0f0c0200010e010014530100020103110500440044070043004301000201030606c0a86400180700500050 01010201060a000000080101020106ac1000000c0101020106c0a80000100101020106a9fe00001001010201067f00000008330c555432000000000000002 9083b0e55543200000000000307030600003c115554325f332e372e332e362e302e62696e3d040a4fff06 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Vendor = 0x30783031303330306130626330323039353535343030303030303030303030 30303730333065353535343030303030303030303030303033303730333037303031363034313135353534356633333265333732653333326533373265333 23332326536323639366530353034306134666666306630633032303030313065303130303134353330313030303230313033313130353030343430303434 30373030343330303433303130303032303130333036303663306138363430303138303730303530303035303031303130323031303630613030303030303 03830313031303230313036616331303030303030633031303130323031303663306138303030303130303130313032303130366139666530303030313030 31303130323031303637663030303030303038333330633535353433323030303030303030303030303030323930383362306535353534333230303030303 03030303030333037303330363030303033633131353535343332356633333265333732653333326533363265333032653632363936653364303430613466 66663036 (1) Wed Dec 5 04:44:49 2018 : Debug : } # update reply (noop) (1) Wed Dec 5 04:44:49 2018 : Debug : } # if (updated && "0x%{redis: GET %{control:Pool-Name}:option}") (noop) (1) Wed Dec 5 04:44:49 2018 : Debug : ok (ok) (1) Wed Dec 5 04:44:49 2018 : Debug : } # recv DHCP-Request (updated) (1) Wed Dec 5 04:44:49 2018 : Debug : Sent DHCP-Ack XID 00000000 from 10.43.18.92:67 to 127.0.0.1:67 via lo (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Message-Type = DHCP-Ack (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Subnet-Mask = 255.255.255.0 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Router-Address = 10.43.18.92 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-IP-Address-Lease-Time := 663 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-DHCP-Server-Identifier = 10.43.18.92 (1) Wed Dec 5 04:44:49 2018 : Debug : &DHCP-Vendor = 0x307830313033303061306263303230393535353430303030303030303030303030 37303330653535353430303030303030303030303030333037303330373030313630343131353535343566333332653337326533333265333732653332333 23265363236393665303530343061346666663066306330323030303130653031303031343533303130303032303130333131303530303434303034343037 30303433303034333031303030323031303330363036633061383634303031383037303035303030353030313031303230313036306130303030303030383 03130313032303130366163313030303030306330313031303230313036633061383030303031303031303130323031303661396665303030303130303130 31303230313036376630303030303030383333306335353534333230303030303030303030303030303239303833623065353535343332303030303030303 03030303330373033303630303030336331313535353433323566333332653337326533333265333632653330326536323639366533643034306134666666 3036 Wed Dec 5 04:44:49 2018 : Debug : (1) done request Regards, Nagamani Chinnapaiyan

2 1

Authentication either username or mac address
by Mohammad Mahefooz 04 Dec '18

04 Dec '18

I have searched about this, but couldn't find proper answer. If it has been already answered kindly share the link. Would like to authenticate users either with username or specified mac address. Generally we can authenticate users either when using only username or only mac address (using mac authentication). But let's say we want to give users the option of either using username or mac address to login, but count data and session time on username basis, how to achieve this in freeradius? - Mohammad

2 5

Closing Accounting Sessions at the end of Month
by Ali Arslan 03 Dec '18

03 Dec '18

Hi all,I am using freeradius 3.0.12 with mysql.I want to close all open accounting sessions at the end of month to be able calculate monthly usages. Should i use radzap, or another better option? When i tried radzap as: radzap -N nas-ip radiusServer-ip secret i get: Sent Accounting-Request Id 4 from 0.0.0.0:39563 to radiusServer-ip:1813 length 38 #(3 trials)(0) No reply from server for ID 4 socket 3 What am i doing wrong? Thanks.

2 2

Re: LDAP Post-Auth with computer names using eap-tls certs
by Kevin Virk 03 Dec '18

03 Dec '18

>Has it been working with FreeRADIUS? Or with a command-line tool? It has been working with Freeradius. >That's likely an AD extension to the LDAP standard. It might not work with other LDAP servers. Ahh yess that makes sense thank you very much. >The issue here is that FreeRADIUS is intended to work with *multiple* different LDAP servers. Adding specific magic just for AD isn't always simple. I believe that is what is going on here. I will just revert back to the stage where it was working! Thank you so much Alan as always you have been a great help

1 0

Test connection TO UDP PORT 1813
by Bassem Mettichi 03 Dec '18

03 Dec '18

Hello, iam using nc tool to test connection to port 1813 of my freeradius server and iam getting this error on freeradius debug mode: /usr/bin/nc -vnzu freeradiusIP 1813 Receive - Invalid data from NASIP: Expected at least 4 bytes of header data, got 1 bytes any one have an idea how to send 4 bytes of header data with nc tool? Thanks Bassem

2 1

Get Daily Usage: Repeat Question
by Imdad Hasan 02 Dec '18

02 Dec '18

Dear All, I am going to repeat my question because i not got the reply of my question which i asked before 3.5 Months ago. If any have the solution or idea then please reply. *Question: How can i make daily usage report with freeradius.* I got a idea earlier from the *freeradius user list, *But that fails on one problem. *Problem:* Say for example: if any user "XYZ" have a one accounting session with the acct-start-time = "2018-08-16 05:00:00" and acct-stop-time = " 2018-08-19 11:16:46". Ok. Means only one accounting session 3 days. So, in this example how can i calculate OR get the "2018-08-17" OR "2018-08-18" s' data usage of that "XYZ" user? Warm regards Imdadali Kadiwala

3 3

[4.0.x] Status-Server with FreeRADIUS-Stats4 shows no output
by Milan Nikolic 02 Dec '18

02 Dec '18

I understand status works differently now, but I can not find example, test or any information about how can one now query Status-Server. I send packet with TLV attribute and `FreeRADIUS-Stats4-Type` is set to `Global` but I get nothing in debug output: ``` Sun Dec 2 01:09:32 2018 : Debug : (1) proto_radius decode packet Code: Status-Server Id: 50 Length: 52 Vector: 7cab2806a1a0e3a98ed3c550382ee5ef 1a 0e 00002c50 (11344) 0f 08 01 06 00 00 00 01 50 12 1f 47 67 ef 79 c8 e0 e6 8c 49 aa d5 06 bc 57 b6 Sun Dec 2 01:09:32 2018 : Debug : Resetting worker 30 cleanup timer to +0s Sun Dec 2 01:09:32 2018 : Debug : (1) running request Sun Dec 2 01:09:32 2018 : Debug : (1) Received Status-Server ID 50 Sun Dec 2 01:09:32 2018 : Debug : (1) FreeRADIUS-Stats4-Type = Global Sun Dec 2 01:09:32 2018 : Debug : (1) Message-Authenticator = 0x1f4767ef79c8e0e68c49aad506bc57b6 Sun Dec 2 01:09:32 2018 : Debug : (1) Running 'recv Status-Server' from file /etc/raddb/sites-enabled/status Sun Dec 2 01:09:32 2018 : Debug : (1) recv Status-Server { Sun Dec 2 01:09:32 2018 : Debug : (1) ok (ok) Sun Dec 2 01:09:32 2018 : Debug : (1) } # recv Status-Server (ok) Sun Dec 2 01:09:32 2018 : Debug : (1) Sent code 2 Id 50 from 192.168.0.31:18121 to 192.168.0.10:42101 via ens33 length 0 Sun Dec 2 01:09:32 2018 : Debug : (1) done request Sun Dec 2 01:09:32 2018 : Debug : (1) proto_radius encode packet Code: Access-Accept Id: 50 Length: 20 Vector: 0a2f9c14653b3dccaf9503e94c0d3b7f Sun Dec 2 01:09:32 2018 : Debug : (1) finished request. Sun Dec 2 01:09:32 2018 : Debug : freeing request ``` I tried many combinations, and also added `stats` to many send and recv sections, is that needed now? Can someone please give me some pointers, I tried looking at source at some places but it is too complicated for me to follow. Thanks

2 3

Migration -> FR3 + CiscoAPs + Multiple SSID+ EAP-TLS +Multiple Certs
by Ted Hyde (RSI) 30 Nov '18

30 Nov '18

> Sure. What you're looking for then, is more this: > > authorize { > ... > eap > ... > } > > authenticate { > ... > eap > ... > } > > post-auth { > ... > if (MAC_LIMITED-SSID && EAP-CERT-01) > { > look up MAC > if !known MAC reject > if blocked MAC reject > } > ... > } > > > Which is pretty simple. That assumes that both client certs are issued by the same CA. Yes, the CA is under my control, (self signed) so no expected challenge there. > Alan DeKok. > That said, how does the pseudo code get translated into unlang? I think I understand a partial of %{request:Cisco-AVPair[0]} would provide the SSID (based upon looking at the freeradius -X trace where it scrolls by first) but I am unsure about testing for the [certificate name?]. (I got the above from 'man unlang'; hopefully an appropriate reference.) I expect "real" data is now necessary to continue forward? Thanks, Ted.

2 1

FreeRadius 3.0.17 - TLS issue
by Thorsten Fritsch 30 Nov '18

30 Nov '18

Dear All, we're running FR 3.0.17 and currently have some trouble with Windows 10 Clients which since just recently no longer can connect to the PEAP/MS-CHAPv2-based eduroam network. According to the radius debug log the FR server sends an Access Accept to the NAS (Cisco WLC) but it then terminates with the information: ERROR: eap_peap: TLS Alert write:fatal:protocol version 53282519) Tue Nov 27 16:07:35 2018: Debug: Sent Access-Accept Id 251 from 131.152.21.100:1812 to 10.33.6.2:54247 length 0 (53282519) Tue Nov 27 16:07:35 2018: Debug: Tunnel-Type = VLAN (53282519) Tue Nov 27 16:07:35 2018: Debug: Tunnel-Medium-Type = IEEE-802 (53282519) Tue Nov 27 16:07:35 2018: Debug: Tunnel-Private-Group-Id = "822" (53282519) Tue Nov 27 16:07:35 2018: Debug: User-Name := "marcel.sumsander(a)unibas.ch" (53282519) Tue Nov 27 16:07:35 2018: Debug: Chargeable-User-Identity := 0x36353637356537306236383335323162656233383262323062616538613935393935303934323763 (53282519) Tue Nov 27 16:07:35 2018: Debug: MS-MPPE-Recv-Key = 0xde555d4feda0c69ee0c251195d63e1d0f81618a8781522cbe398610d7df41745 (53282519) Tue Nov 27 16:07:35 2018: Debug: MS-MPPE-Send-Key = 0xb3a46cb36458a0dda59935105ffc8bfd38e4141952800b3bb9f989192ada38b0 (53282519) Tue Nov 27 16:07:35 2018: Debug: EAP-Message = 0x030c0004 (53282519) Tue Nov 27 16:07:35 2018: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (53282519) Tue Nov 27 16:07:35 2018: Debug: Finished request (53282373) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 241 with timestamp +2433639 (53282375) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 242 with timestamp +2433639 (53282376) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 243 with timestamp +2433639 (53282378) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 244 with timestamp +2433639 (53282379) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 245 with timestamp +2433639 (53282380) Tue Nov 27 16:07:38 2018: Debug: Cleaning up request packet ID 246 with timestamp +2433639 (53282493) Tue Nov 27 16:07:39 2018: Debug: Cleaning up request packet ID 247 with timestamp +2433640 (53282497) Tue Nov 27 16:07:39 2018: Debug: Cleaning up request packet ID 248 with timestamp +2433640 (53282502) Tue Nov 27 16:07:39 2018: Debug: Cleaning up request packet ID 249 with timestamp +2433640 (53282509) Tue Nov 27 16:07:40 2018: Debug: Cleaning up request packet ID 250 with timestamp +2433640 (53282519) Tue Nov 27 16:07:40 2018: Debug: Cleaning up request packet ID 251 with timestamp +2433641 (53283340) Tue Nov 27 16:07:46 2018: ERROR: eap_peap: TLS Alert write:fatal:protocol version It looks like a TLS mismtach but not sure. Any experiences with this ? Which TLS versions are supported by FR 3.0.17 ? Thanks and BR, Thorsten

4 8