escaping close brace inside "d string is not working

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