Tue Feb 4 10:40:53 2020 : Debug: Server was built with: Tue Feb 4 10:40:53 2020 : Debug: accounting : yes Tue Feb 4 10:40:53 2020 : Debug: authentication : yes Tue Feb 4 10:40:53 2020 : Debug: ascend-binary-attributes : yes Tue Feb 4 10:40:53 2020 : Debug: coa : yes Tue Feb 4 10:40:53 2020 : Debug: control-socket : yes Tue Feb 4 10:40:53 2020 : Debug: detail : yes Tue Feb 4 10:40:53 2020 : Debug: dhcp : yes Tue Feb 4 10:40:53 2020 : Debug: dynamic-clients : yes Tue Feb 4 10:40:53 2020 : Debug: osfc2 : no Tue Feb 4 10:40:53 2020 : Debug: proxy : yes Tue Feb 4 10:40:53 2020 : Debug: regex-pcre : no Tue Feb 4 10:40:53 2020 : Debug: regex-posix : yes Tue Feb 4 10:40:53 2020 : Debug: regex-posix-extended : yes Tue Feb 4 10:40:53 2020 : Debug: session-management : yes Tue Feb 4 10:40:53 2020 : Debug: stats : yes Tue Feb 4 10:40:53 2020 : Debug: systemd : yes Tue Feb 4 10:40:53 2020 : Debug: tcp : yes Tue Feb 4 10:40:53 2020 : Debug: threads : yes Tue Feb 4 10:40:53 2020 : Debug: tls : yes Tue Feb 4 10:40:53 2020 : Debug: unlang : yes Tue Feb 4 10:40:53 2020 : Debug: vmps : yes Tue Feb 4 10:40:53 2020 : Debug: developer : no Tue Feb 4 10:40:53 2020 : Debug: Server core libs: Tue Feb 4 10:40:53 2020 : Debug: freeradius-server : 3.0.20 Tue Feb 4 10:40:53 2020 : Debug: talloc : 2.0.* Tue Feb 4 10:40:53 2020 : Debug: ssl : 1.0.2g release Tue Feb 4 10:40:53 2020 : Debug: Endianness: Tue Feb 4 10:40:53 2020 : Debug: little Tue Feb 4 10:40:53 2020 : Debug: Compilation flags: Tue Feb 4 10:40:53 2020 : Debug: cppflags : -Wdate-time -D_FORTIFY_SOURCE=2 Tue Feb 4 10:40:53 2020 : Debug: cflags : -I. -Isrc -include src/freeradius-devel/autoconf.h -include src/freeradius-devel/build.h -include src/freeradius-devel/features.h -include src/freeradius-devel/radpaths.h -fno-strict-aliasing -g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -O2 -Wall -std=c99 -D_GNU_SOURCE -D_REENTRANT -D_POSIX_PTHREAD_SEMANTICS -DOPENSSL_NO_KRB5 -DNDEBUG -DIS_MODULE=1 Tue Feb 4 10:40:53 2020 : Debug: ldflags : -Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now Tue Feb 4 10:40:53 2020 : Debug: libs : -lcrypto -lssl -ltalloc -latomic -lcap -lnsl -lresolv -ldl -lpthread -lreadline Tue Feb 4 10:40:53 2020 : Debug: Tue Feb 4 10:40:53 2020 : Info: FreeRADIUS Version 3.0.20 Tue Feb 4 10:40:53 2020 : Info: Copyright (C) 1999-2019 The FreeRADIUS server project and contributors Tue Feb 4 10:40:53 2020 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Feb 4 10:40:53 2020 : Info: PARTICULAR PURPOSE Tue Feb 4 10:40:53 2020 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Feb 4 10:40:53 2020 : Info: GNU General Public License Tue Feb 4 10:40:53 2020 : Info: For more information about these matters, see the file named COPYRIGHT Tue Feb 4 10:40:53 2020 : Info: Starting - reading configuration files ... Tue Feb 4 10:40:53 2020 : Debug: including dictionary file /usr/share/freeradius/dictionary Tue Feb 4 10:40:53 2020 : Debug: including dictionary file /usr/share/freeradius/dictionary.dhcp Tue Feb 4 10:40:53 2020 : Debug: including dictionary file /usr/share/freeradius/dictionary.vqp Tue Feb 4 10:40:53 2020 : Debug: including dictionary file /etc/freeradius/dictionary Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/radiusd.conf Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/proxy.conf Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/clients.conf Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/sql Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-config/sql/main/mysql/queries.conf Tue Feb 4 10:40:53 2020 : Debug: including files in directory /etc/freeradius/mods-enabled/ Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/echo Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/utf8 Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/replicate Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/ntlm_auth Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/pap Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/files Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/date Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/mschap Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/passwd Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/exec Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/sqlippool Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-config/sql/ippool/mysql/queries.conf Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/chap Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/preprocess Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/expr Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/expiration Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/unpack Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/dynamic_clients Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/linelog Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/soh Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/mods-enabled/logintime Tue Feb 4 10:40:53 2020 : Debug: including files in directory /etc/freeradius/policy.d/ Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/rfc7542 Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/moonshot-targeted-ids Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/debug Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/operator-name Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/dhcp Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/accounting Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/control Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/filter Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/canonicalization Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/eap Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/abfab-tr Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/policy.d/cui Tue Feb 4 10:40:53 2020 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Feb 4 10:40:53 2020 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Feb 4 10:40:53 2020 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Tue Feb 4 10:40:53 2020 : Debug: OPTIMIZING (no == yes) --> FALSE Tue Feb 4 10:40:53 2020 : Debug: including files in directory /etc/freeradius/sites-enabled/ Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Tue Feb 4 10:40:53 2020 : Debug: including configuration file /etc/freeradius/sites-enabled/default Tue Feb 4 10:40:53 2020 : Debug: main { Tue Feb 4 10:40:53 2020 : Debug: security { Tue Feb 4 10:40:53 2020 : Debug: user = "freerad" Tue Feb 4 10:40:53 2020 : Debug: group = "freerad" Tue Feb 4 10:40:53 2020 : Debug: allow_core_dumps = no Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[473]: The item 'max_attributes' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[491]: The item 'reject_delay' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[511]: The item 'status_server' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: name = "freeradius" Tue Feb 4 10:40:53 2020 : Debug: prefix = "/usr" Tue Feb 4 10:40:53 2020 : Debug: localstatedir = "/var" Tue Feb 4 10:40:53 2020 : Debug: logdir = "/var/log/freeradius" Tue Feb 4 10:40:53 2020 : Debug: run_dir = "/var/run/freeradius" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[85]: The item 'sysconfdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[90]: The item 'radacctdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[99]: The item 'certdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[100]: The item 'cadir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[138]: The item 'libdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[149]: The item 'pidfile' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[170]: The item 'correct_escapes' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[224]: The item 'max_request_time' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[243]: The item 'cleanup_delay' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[262]: The item 'max_requests' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[280]: The item 'hostname_lookups' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[383]: The item 'checkrad' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[532]: The item 'proxy_requests' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: main { Tue Feb 4 10:40:53 2020 : Debug: name = "freeradius" Tue Feb 4 10:40:53 2020 : Debug: prefix = "/usr" Tue Feb 4 10:40:53 2020 : Debug: localstatedir = "/var" Tue Feb 4 10:40:53 2020 : Debug: sbindir = "/usr/sbin" Tue Feb 4 10:40:53 2020 : Debug: logdir = "/var/log/freeradius" Tue Feb 4 10:40:53 2020 : Debug: run_dir = "/var/run/freeradius" Tue Feb 4 10:40:53 2020 : Debug: libdir = "/usr/lib/freeradius" Tue Feb 4 10:40:53 2020 : Debug: radacctdir = "/var/log/freeradius/radacct" Tue Feb 4 10:40:53 2020 : Debug: hostname_lookups = no Tue Feb 4 10:40:53 2020 : Debug: max_request_time = 15 Tue Feb 4 10:40:53 2020 : Debug: cleanup_delay = 10 Tue Feb 4 10:40:53 2020 : Debug: max_requests = 7680 Tue Feb 4 10:40:53 2020 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Tue Feb 4 10:40:53 2020 : Debug: checkrad = "/usr/sbin/checkrad" Tue Feb 4 10:40:53 2020 : Debug: debug_level = 0 Tue Feb 4 10:40:53 2020 : Debug: proxy_requests = no Tue Feb 4 10:40:53 2020 : Debug: log { Tue Feb 4 10:40:53 2020 : Debug: stripped_names = no Tue Feb 4 10:40:53 2020 : Debug: auth = yes Tue Feb 4 10:40:53 2020 : Debug: auth_badpass = yes Tue Feb 4 10:40:53 2020 : Debug: auth_goodpass = no Tue Feb 4 10:40:53 2020 : Debug: colourise = yes Tue Feb 4 10:40:53 2020 : Debug: msg_denied = "You are already logged in - access denied" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[298]: The item 'destination' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[315]: The item 'file' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[323]: The item 'syslog_facility' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: resources { Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: security { Tue Feb 4 10:40:53 2020 : Debug: max_attributes = 200 Tue Feb 4 10:40:53 2020 : Debug: reject_delay = 1.000000 Tue Feb 4 10:40:53 2020 : Debug: status_server = yes Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[85]: The item 'sysconfdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[97]: The item 'confdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[99]: The item 'certdir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[100]: The item 'cadir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[104]: The item 'db_dir' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/radiusd.conf[170]: The item 'correct_escapes' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Feb 4 10:40:53 2020 : Debug: proxy server { Tue Feb 4 10:40:53 2020 : Debug: retry_delay = 5 Tue Feb 4 10:40:53 2020 : Debug: retry_count = 3 Tue Feb 4 10:40:53 2020 : Debug: default_fallback = no Tue Feb 4 10:40:53 2020 : Debug: dead_time = 120 Tue Feb 4 10:40:53 2020 : Debug: wake_all_if_all_dead = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: home_server localhost { Tue Feb 4 10:40:53 2020 : Debug: ipaddr = 127.0.0.1 Tue Feb 4 10:40:53 2020 : Debug: port = 1812 Tue Feb 4 10:40:53 2020 : Debug: type = "auth" Tue Feb 4 10:40:53 2020 : Debug: secret = "testing123" Tue Feb 4 10:40:53 2020 : Debug: response_window = 20.000000 Tue Feb 4 10:40:53 2020 : Debug: response_timeouts = 1 Tue Feb 4 10:40:53 2020 : Debug: max_outstanding = 65536 Tue Feb 4 10:40:53 2020 : Debug: zombie_period = 40 Tue Feb 4 10:40:53 2020 : Debug: status_check = "status-server" Tue Feb 4 10:40:53 2020 : Debug: ping_interval = 30 Tue Feb 4 10:40:53 2020 : Debug: check_interval = 30 Tue Feb 4 10:40:53 2020 : Debug: check_timeout = 4 Tue Feb 4 10:40:53 2020 : Debug: num_answers_to_alive = 3 Tue Feb 4 10:40:53 2020 : Debug: revive_interval = 120 Tue Feb 4 10:40:53 2020 : Debug: limit { Tue Feb 4 10:40:53 2020 : Debug: max_connections = 16 Tue Feb 4 10:40:53 2020 : Debug: max_requests = 0 Tue Feb 4 10:40:53 2020 : Debug: lifetime = 0 Tue Feb 4 10:40:53 2020 : Debug: idle_timeout = 0 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: coa { Tue Feb 4 10:40:53 2020 : Debug: irt = 2 Tue Feb 4 10:40:53 2020 : Debug: mrt = 16 Tue Feb 4 10:40:53 2020 : Debug: mrc = 5 Tue Feb 4 10:40:53 2020 : Debug: mrd = 30 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Warning: Ignoring "response_window = 20.000000", forcing to "response_window = 15.000000" Tue Feb 4 10:40:53 2020 : Debug: home_server_pool my_auth_failover { Tue Feb 4 10:40:53 2020 : Debug: type = fail-over Tue Feb 4 10:40:53 2020 : Debug: home_server = localhost Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: realm example.com { Tue Feb 4 10:40:53 2020 : Debug: auth_pool = my_auth_failover Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: realm LOCAL { Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: radiusd: #### Loading Clients #### Tue Feb 4 10:40:53 2020 : Debug: client localhost { Tue Feb 4 10:40:53 2020 : Debug: ipaddr = 127.0.0.1 Tue Feb 4 10:40:53 2020 : Debug: require_message_authenticator = no Tue Feb 4 10:40:53 2020 : Debug: secret = "secret" Tue Feb 4 10:40:53 2020 : Debug: nas_type = "other" Tue Feb 4 10:40:53 2020 : Debug: proto = "*" Tue Feb 4 10:40:53 2020 : Debug: limit { Tue Feb 4 10:40:53 2020 : Debug: max_connections = 16 Tue Feb 4 10:40:53 2020 : Debug: lifetime = 0 Tue Feb 4 10:40:53 2020 : Debug: idle_timeout = 30 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Tue Feb 4 10:40:53 2020 : Debug: client localhost_ipv6 { Tue Feb 4 10:40:53 2020 : Debug: ipv6addr = ::1 Tue Feb 4 10:40:53 2020 : Debug: require_message_authenticator = no Tue Feb 4 10:40:53 2020 : Debug: secret = "testing123" Tue Feb 4 10:40:53 2020 : Debug: limit { Tue Feb 4 10:40:53 2020 : Debug: max_connections = 16 Tue Feb 4 10:40:53 2020 : Debug: lifetime = 0 Tue Feb 4 10:40:53 2020 : Debug: idle_timeout = 30 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Tue Feb 4 10:40:53 2020 : Info: Debugger not attached Tue Feb 4 10:40:53 2020 : Info: systemd watchdog is disabled Tue Feb 4 10:40:53 2020 : Debug: # Creating Auth-Type = mschap Tue Feb 4 10:40:53 2020 : Debug: # Creating Auth-Type = PAP Tue Feb 4 10:40:53 2020 : Debug: # Creating Auth-Type = CHAP Tue Feb 4 10:40:53 2020 : Debug: # Creating Auth-Type = MS-CHAP Tue Feb 4 10:40:53 2020 : Debug: radiusd: #### Instantiating modules #### Tue Feb 4 10:40:53 2020 : Debug: modules { Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_sql, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_sql Tue Feb 4 10:40:53 2020 : Debug: # Loading module "sql" from file /etc/freeradius/mods-enabled/sql Tue Feb 4 10:40:53 2020 : Debug: sql { Tue Feb 4 10:40:53 2020 : Debug: driver = "rlm_sql_mysql" Tue Feb 4 10:40:53 2020 : Debug: server = "mysql.mpc.com.br" Tue Feb 4 10:40:53 2020 : Debug: port = 3306 Tue Feb 4 10:40:53 2020 : Debug: login = "FREERADIUS" Tue Feb 4 10:40:53 2020 : Debug: password = "CfnpEuBJhvaPpjAd" Tue Feb 4 10:40:53 2020 : Debug: radius_db = "mpc_freeradius" Tue Feb 4 10:40:53 2020 : Debug: read_groups = yes Tue Feb 4 10:40:53 2020 : Debug: read_profiles = yes Tue Feb 4 10:40:53 2020 : Debug: read_clients = yes Tue Feb 4 10:40:53 2020 : Debug: delete_stale_sessions = yes Tue Feb 4 10:40:53 2020 : Debug: sql_user_name = "%{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: default_user_profile = "" Tue Feb 4 10:40:53 2020 : Debug: client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Tue Feb 4 10:40:53 2020 : Debug: authorize_check_query = "SELECT DISTINCT (R.id), R.username, R.attribute, R.value, R.op FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist M WHERE R.username = BINARY '%{SQL-User-Name}' AND M.usuario_login = BINARY '%{SQL-User-Name}' AND N.nasname = '%{Nas-IP-Address}' AND N.gw_id = (SELECT gateway_id FROM mpc_lw.maclist WHERE usuario_login = BINARY '%{SQL-User-Name}' AND plano_id NOT IN (6,8,9,793) AND gateway_id = ( SELECT gw_id FROM mpc_freeradius.nas WHERE nasname = '%{Nas-IP-Address}' ) ORDER BY ID) UNION ALL SELECT DISTINCT (R.id), R.username, R.attribute, R.value, R.op FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist M WHERE R.username = BINARY '%{SQL-User-Name}' AND M.usuario_login = BINARY '%{SQL-User-Name}' AND M.grupocliente = 'ALL-POPS'" Tue Feb 4 10:40:53 2020 : Debug: authorize_reply_query = "SELECT DISTINCT (R.id), R.username, R.attribute, R.value, R.op FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist M WHERE R.username = BINARY '%{SQL-User-Name}' AND M.usuario_login = BINARY '%{SQL-User-Name}' AND N.nasname = '%{Nas-IP-Address}' AND N.gw_id = (SELECT gateway_id FROM mpc_lw.maclist WHERE usuario_login = BINARY '%{SQL-User-Name}' AND plano_id NOT IN (6,8,9,793) AND gateway_id = ( SELECT gw_id FROM mpc_freeradius.nas WHERE nasname = '%{Nas-IP-Address}' ) ORDER BY ID) UNION ALL SELECT DISTINCT (R.id), R.username, R.attribute, R.value, R.op FROM mpc_freeradius.radcheck R, mpc_freeradius.nas N, mpc_lw.maclist M WHERE R.username = BINARY '%{SQL-User-Name}' AND M.usuario_login = BINARY '%{SQL-User-Name}' AND M.grupocliente = 'ALL-POPS'" Tue Feb 4 10:40:53 2020 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id" Tue Feb 4 10:40:53 2020 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id" Tue Feb 4 10:40:53 2020 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Tue Feb 4 10:40:53 2020 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL AND framedipaddress NOT REGEXP '^10\.'" Tue Feb 4 10:40:53 2020 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL AND framedipaddress NOT REGEXP '^10\.'" Tue Feb 4 10:40:53 2020 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Feb 4 10:40:53 2020 : Debug: auto_escape = no Tue Feb 4 10:40:53 2020 : Debug: accounting { Tue Feb 4 10:40:53 2020 : Debug: reference = "%{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}" Tue Feb 4 10:40:53 2020 : Debug: type { Tue Feb 4 10:40:53 2020 : Debug: accounting-on { Tue Feb 4 10:40:53 2020 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = '%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: accounting-off { Tue Feb 4 10:40:53 2020 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = '%{integer:Event-Timestamp}' - UNIX_TIMESTAMP(acctstarttime), acctterminatecause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= FROM_UNIXTIME(%{integer:Event-Timestamp})" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: start { Tue Feb 4 10:40:53 2020 : Debug: query = "INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, framedipv6address,framedipv6prefix, framedinterfaceid, delegatedipv6prefix) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port}:-%{NAS-Port-ID}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Framed-IPv6-Address}', '%{Framed-IPv6-Prefix}', '%{Framed-Interface-Id}', '%{Delegated-IPv6-Prefix}')" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-config/sql/main/mysql/queries.conf[432]: The item '-query' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: interim-update { Tue Feb 4 10:40:53 2020 : Debug: query = "UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctinterval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-config/sql/main/mysql/queries.conf[541]: The item '-query' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: stop { Tue Feb 4 10:40:53 2020 : Debug: query = "UPDATE radacct SET acctstoptime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-config/sql/main/mysql/queries.conf[633]: The item '-query' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: post-auth { Tue Feb 4 10:40:53 2020 : Debug: reference = ".query" Tue Feb 4 10:40:53 2020 : Debug: query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-enabled/sql[148]: The item 'authreply_table' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Feb 4 10:40:53 2020 : Debug: Creating attribute SQL-Group Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_always, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_always Tue Feb 4 10:40:53 2020 : Debug: # Loading module "reject" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always reject { Tue Feb 4 10:40:53 2020 : Debug: rcode = "reject" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "fail" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always fail { Tue Feb 4 10:40:53 2020 : Debug: rcode = "fail" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "ok" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always ok { Tue Feb 4 10:40:53 2020 : Debug: rcode = "ok" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "handled" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always handled { Tue Feb 4 10:40:53 2020 : Debug: rcode = "handled" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "invalid" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always invalid { Tue Feb 4 10:40:53 2020 : Debug: rcode = "invalid" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "userlock" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always userlock { Tue Feb 4 10:40:53 2020 : Debug: rcode = "userlock" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "notfound" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always notfound { Tue Feb 4 10:40:53 2020 : Debug: rcode = "notfound" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "noop" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always noop { Tue Feb 4 10:40:53 2020 : Debug: rcode = "noop" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "updated" from file /etc/freeradius/mods-enabled/always Tue Feb 4 10:40:53 2020 : Debug: always updated { Tue Feb 4 10:40:53 2020 : Debug: rcode = "updated" Tue Feb 4 10:40:53 2020 : Debug: simulcount = 0 Tue Feb 4 10:40:53 2020 : Debug: mpp = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_exec, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_exec Tue Feb 4 10:40:53 2020 : Debug: # Loading module "echo" from file /etc/freeradius/mods-enabled/echo Tue Feb 4 10:40:53 2020 : Debug: exec echo { Tue Feb 4 10:40:53 2020 : Debug: wait = yes Tue Feb 4 10:40:53 2020 : Debug: program = "/bin/echo %{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: input_pairs = "request" Tue Feb 4 10:40:53 2020 : Debug: output_pairs = "reply" Tue Feb 4 10:40:53 2020 : Debug: shell_escape = yes Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_utf8, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_utf8 Tue Feb 4 10:40:53 2020 : Debug: # Loading module "utf8" from file /etc/freeradius/mods-enabled/utf8 Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_replicate, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_replicate Tue Feb 4 10:40:53 2020 : Debug: # Loading module "replicate" from file /etc/freeradius/mods-enabled/replicate Tue Feb 4 10:40:53 2020 : Debug: # Loading module "ntlm_auth" from file /etc/freeradius/mods-enabled/ntlm_auth Tue Feb 4 10:40:53 2020 : Debug: exec ntlm_auth { Tue Feb 4 10:40:53 2020 : Debug: wait = yes Tue Feb 4 10:40:53 2020 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Tue Feb 4 10:40:53 2020 : Debug: shell_escape = yes Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_pap, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_pap Tue Feb 4 10:40:53 2020 : Debug: # Loading module "pap" from file /etc/freeradius/mods-enabled/pap Tue Feb 4 10:40:53 2020 : Debug: pap { Tue Feb 4 10:40:53 2020 : Debug: normalise = yes Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_realm, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_realm Tue Feb 4 10:40:53 2020 : Debug: # Loading module "IPASS" from file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: realm IPASS { Tue Feb 4 10:40:53 2020 : Debug: format = "prefix" Tue Feb 4 10:40:53 2020 : Debug: delimiter = "/" Tue Feb 4 10:40:53 2020 : Debug: ignore_default = no Tue Feb 4 10:40:53 2020 : Debug: ignore_null = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "suffix" from file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: realm suffix { Tue Feb 4 10:40:53 2020 : Debug: format = "suffix" Tue Feb 4 10:40:53 2020 : Debug: delimiter = "@" Tue Feb 4 10:40:53 2020 : Debug: ignore_default = no Tue Feb 4 10:40:53 2020 : Debug: ignore_null = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "bangpath" from file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: realm bangpath { Tue Feb 4 10:40:53 2020 : Debug: format = "prefix" Tue Feb 4 10:40:53 2020 : Debug: delimiter = "!" Tue Feb 4 10:40:53 2020 : Debug: ignore_default = no Tue Feb 4 10:40:53 2020 : Debug: ignore_null = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "realmpercent" from file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: realm realmpercent { Tue Feb 4 10:40:53 2020 : Debug: format = "suffix" Tue Feb 4 10:40:53 2020 : Debug: delimiter = "%" Tue Feb 4 10:40:53 2020 : Debug: ignore_default = no Tue Feb 4 10:40:53 2020 : Debug: ignore_null = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "ntdomain" from file /etc/freeradius/mods-enabled/realm Tue Feb 4 10:40:53 2020 : Debug: realm ntdomain { Tue Feb 4 10:40:53 2020 : Debug: format = "prefix" Tue Feb 4 10:40:53 2020 : Debug: delimiter = "\\" Tue Feb 4 10:40:53 2020 : Debug: ignore_default = no Tue Feb 4 10:40:53 2020 : Debug: ignore_null = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_files, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_files Tue Feb 4 10:40:53 2020 : Debug: # Loading module "files" from file /etc/freeradius/mods-enabled/files Tue Feb 4 10:40:53 2020 : Debug: files { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/files/authorize" Tue Feb 4 10:40:53 2020 : Debug: acctusersfile = "/etc/freeradius/mods-config/files/accounting" Tue Feb 4 10:40:53 2020 : Debug: preproxy_usersfile = "/etc/freeradius/mods-config/files/pre-proxy" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_attr_filter, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_attr_filter Tue Feb 4 10:40:53 2020 : Debug: # Loading module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: attr_filter attr_filter.post-proxy { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/post-proxy" Tue Feb 4 10:40:53 2020 : Debug: key = "%{Realm}" Tue Feb 4 10:40:53 2020 : Debug: relaxed = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: attr_filter attr_filter.pre-proxy { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/pre-proxy" Tue Feb 4 10:40:53 2020 : Debug: key = "%{Realm}" Tue Feb 4 10:40:53 2020 : Debug: relaxed = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: attr_filter attr_filter.access_reject { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/access_reject" Tue Feb 4 10:40:53 2020 : Debug: key = "%{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: relaxed = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: attr_filter attr_filter.access_challenge { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/access_challenge" Tue Feb 4 10:40:53 2020 : Debug: key = "%{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: relaxed = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter Tue Feb 4 10:40:53 2020 : Debug: attr_filter attr_filter.accounting_response { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/accounting_response" Tue Feb 4 10:40:53 2020 : Debug: key = "%{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: relaxed = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_date, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_date Tue Feb 4 10:40:53 2020 : Debug: # Loading module "date" from file /etc/freeradius/mods-enabled/date Tue Feb 4 10:40:53 2020 : Debug: date { Tue Feb 4 10:40:53 2020 : Debug: format = "%b %e %Y %H:%M:%S %Z" Tue Feb 4 10:40:53 2020 : Debug: utc = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "wispr2date" from file /etc/freeradius/mods-enabled/date Tue Feb 4 10:40:53 2020 : Debug: date wispr2date { Tue Feb 4 10:40:53 2020 : Debug: format = "%Y-%m-%dT%H:%M:%S" Tue Feb 4 10:40:53 2020 : Debug: utc = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_mschap, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_mschap Tue Feb 4 10:40:53 2020 : Debug: # Loading module "mschap" from file /etc/freeradius/mods-enabled/mschap Tue Feb 4 10:40:53 2020 : Debug: mschap { Tue Feb 4 10:40:53 2020 : Debug: use_mppe = yes Tue Feb 4 10:40:53 2020 : Debug: require_encryption = no Tue Feb 4 10:40:53 2020 : Debug: require_strong = no Tue Feb 4 10:40:53 2020 : Debug: with_ntdomain_hack = yes Tue Feb 4 10:40:53 2020 : Debug: passchange { Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: allow_retry = yes Tue Feb 4 10:40:53 2020 : Debug: winbind_retry_with_normalised_username = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_passwd, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_passwd Tue Feb 4 10:40:53 2020 : Debug: # Loading module "etc_passwd" from file /etc/freeradius/mods-enabled/passwd Tue Feb 4 10:40:53 2020 : Debug: passwd etc_passwd { Tue Feb 4 10:40:53 2020 : Debug: filename = "/etc/passwd" Tue Feb 4 10:40:53 2020 : Debug: format = "*User-Name:Crypt-Password:" Tue Feb 4 10:40:53 2020 : Debug: delimiter = ":" Tue Feb 4 10:40:53 2020 : Debug: ignore_nislike = no Tue Feb 4 10:40:53 2020 : Debug: ignore_empty = yes Tue Feb 4 10:40:53 2020 : Debug: allow_multiple_keys = no Tue Feb 4 10:40:53 2020 : Debug: hash_size = 100 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "exec" from file /etc/freeradius/mods-enabled/exec Tue Feb 4 10:40:53 2020 : Debug: exec { Tue Feb 4 10:40:53 2020 : Debug: wait = no Tue Feb 4 10:40:53 2020 : Debug: input_pairs = "request" Tue Feb 4 10:40:53 2020 : Debug: shell_escape = yes Tue Feb 4 10:40:53 2020 : Debug: timeout = 10 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_sqlippool, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_sqlippool Tue Feb 4 10:40:53 2020 : Debug: # Loading module "sqlippool" from file /etc/freeradius/mods-enabled/sqlippool Tue Feb 4 10:40:53 2020 : Debug: sqlippool { Tue Feb 4 10:40:53 2020 : Debug: sql_module_instance = "sql" Tue Feb 4 10:40:53 2020 : Debug: lease_duration = 3600 Tue Feb 4 10:40:53 2020 : Debug: pool_name = "Pool-Name" Tue Feb 4 10:40:53 2020 : Debug: default_pool = "main_pool" Tue Feb 4 10:40:53 2020 : Debug: attribute_name = "Framed-IP-Address" Tue Feb 4 10:40:53 2020 : Debug: allocate_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: allocate_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'" Tue Feb 4 10:40:53 2020 : Debug: allocate_clear_timeout = 1 Tue Feb 4 10:40:53 2020 : Debug: allocate_find = "SELECT framedipaddress FROM radippool WHERE pool_name = '%{control:Pool-Name}' AND (expiry_time < NOW() OR expiry_time IS NULL) ORDER BY (username <> '%{User-Name}'), (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE" Tue Feb 4 10:40:53 2020 : Debug: allocate_update = "UPDATE radippool SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress = '%I' AND expiry_time IS NULL" Tue Feb 4 10:40:53 2020 : Debug: allocate_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: pool_check = "SELECT id FROM radippool WHERE pool_name='%{control:Pool-Name}' LIMIT 1" Tue Feb 4 10:40:53 2020 : Debug: start_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: start_update = "UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{NAS-IP-Address}' AND pool_key = '%{Calling-Station-Id}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" Tue Feb 4 10:40:53 2020 : Debug: start_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: alive_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: alive_update = "UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}' AND pool_key = '%{Calling-Station-Id}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" Tue Feb 4 10:40:53 2020 : Debug: alive_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: stop_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: stop_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}' AND pool_key = '%{Calling-Station-Id}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" Tue Feb 4 10:40:53 2020 : Debug: stop_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: on_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: on_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'" Tue Feb 4 10:40:53 2020 : Debug: on_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: off_begin = "START TRANSACTION" Tue Feb 4 10:40:53 2020 : Debug: off_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{%{Nas-IP-Address}:-%{Nas-IPv6-Address}}'" Tue Feb 4 10:40:53 2020 : Debug: off_commit = "COMMIT" Tue Feb 4 10:40:53 2020 : Debug: messages { Tue Feb 4 10:40:53 2020 : Debug: exists = "Existing IP: %{reply:Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" Tue Feb 4 10:40:53 2020 : Debug: success = "Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" Tue Feb 4 10:40:53 2020 : Debug: clear = "Released IP Framed-IP-Address (did %{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name})" Tue Feb 4 10:40:53 2020 : Debug: failed = "IP Allocation FAILED from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" Tue Feb 4 10:40:53 2020 : Debug: nopool = "No Pool-Name defined (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_chap, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_chap Tue Feb 4 10:40:53 2020 : Debug: # Loading module "chap" from file /etc/freeradius/mods-enabled/chap Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_preprocess, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_preprocess Tue Feb 4 10:40:53 2020 : Debug: # Loading module "preprocess" from file /etc/freeradius/mods-enabled/preprocess Tue Feb 4 10:40:53 2020 : Debug: preprocess { Tue Feb 4 10:40:53 2020 : Debug: huntgroups = "/etc/freeradius/mods-config/preprocess/huntgroups" Tue Feb 4 10:40:53 2020 : Debug: hints = "/etc/freeradius/mods-config/preprocess/hints" Tue Feb 4 10:40:53 2020 : Debug: with_ascend_hack = no Tue Feb 4 10:40:53 2020 : Debug: ascend_channels_per_line = 23 Tue Feb 4 10:40:53 2020 : Debug: with_ntdomain_hack = no Tue Feb 4 10:40:53 2020 : Debug: with_specialix_jetstream_hack = no Tue Feb 4 10:40:53 2020 : Debug: with_cisco_vsa_hack = no Tue Feb 4 10:40:53 2020 : Debug: with_alvarion_vsa_hack = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_expr, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_expr Tue Feb 4 10:40:53 2020 : Debug: # Loading module "expr" from file /etc/freeradius/mods-enabled/expr Tue Feb 4 10:40:53 2020 : Debug: expr { Tue Feb 4 10:40:53 2020 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_expiration, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_expiration Tue Feb 4 10:40:53 2020 : Debug: # Loading module "expiration" from file /etc/freeradius/mods-enabled/expiration Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_unpack, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_unpack Tue Feb 4 10:40:53 2020 : Debug: # Loading module "unpack" from file /etc/freeradius/mods-enabled/unpack Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_dynamic_clients Tue Feb 4 10:40:53 2020 : Debug: # Loading module "dynamic_clients" from file /etc/freeradius/mods-enabled/dynamic_clients Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_linelog, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_linelog Tue Feb 4 10:40:53 2020 : Debug: # Loading module "linelog" from file /etc/freeradius/mods-enabled/linelog Tue Feb 4 10:40:53 2020 : Debug: linelog { Tue Feb 4 10:40:53 2020 : Debug: filename = "/var/log/freeradius/radius.log" Tue Feb 4 10:40:53 2020 : Debug: escape_filenames = no Tue Feb 4 10:40:53 2020 : Debug: syslog_severity = "info" Tue Feb 4 10:40:53 2020 : Debug: permissions = 384 Tue Feb 4 10:40:53 2020 : Debug: format = "This is a log message for %{User-Name}" Tue Feb 4 10:40:53 2020 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "log_accounting" from file /etc/freeradius/mods-enabled/linelog Tue Feb 4 10:40:53 2020 : Debug: linelog log_accounting { Tue Feb 4 10:40:53 2020 : Debug: filename = "/var/log/freeradius/radius.log" Tue Feb 4 10:40:53 2020 : Debug: escape_filenames = no Tue Feb 4 10:40:53 2020 : Debug: syslog_severity = "info" Tue Feb 4 10:40:53 2020 : Debug: permissions = 384 Tue Feb 4 10:40:53 2020 : Debug: format = "" Tue Feb 4 10:40:53 2020 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Loading module "log_post_auth" from file /etc/freeradius/mods-enabled/linelog Tue Feb 4 10:40:53 2020 : Debug: linelog log_post_auth { Tue Feb 4 10:40:53 2020 : Debug: filename = "/var/log/freeradius/radius.log" Tue Feb 4 10:40:53 2020 : Debug: escape_filenames = no Tue Feb 4 10:40:53 2020 : Debug: syslog_severity = "info" Tue Feb 4 10:40:53 2020 : Debug: permissions = 384 Tue Feb 4 10:40:53 2020 : Debug: reference = "%{reply:Packet-Type}" Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-enabled/linelog[176]: The item 'Access-Accept' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Warning: /etc/freeradius/mods-enabled/linelog[177]: The item 'Access-Reject' is defined, but is unused by the configuration Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_soh, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_soh Tue Feb 4 10:40:53 2020 : Debug: # Loading module "soh" from file /etc/freeradius/mods-enabled/soh Tue Feb 4 10:40:53 2020 : Debug: soh { Tue Feb 4 10:40:53 2020 : Debug: dhcp = yes Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: Loaded rlm_logintime, checking if it's valid Tue Feb 4 10:40:53 2020 : Debug: # Loaded module rlm_logintime Tue Feb 4 10:40:53 2020 : Debug: # Loading module "logintime" from file /etc/freeradius/mods-enabled/logintime Tue Feb 4 10:40:53 2020 : Debug: logintime { Tue Feb 4 10:40:53 2020 : Debug: minimum_timeout = 60 Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: instantiate { Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: # Instantiating module "sql" from file /etc/freeradius/mods-enabled/sql Tue Feb 4 10:40:53 2020 : Info: rlm_sql_mysql: libmysql version: 5.7.29 Tue Feb 4 10:40:53 2020 : Debug: mysql { Tue Feb 4 10:40:53 2020 : Debug: tls { Tue Feb 4 10:40:53 2020 : Debug: tls_required = no Tue Feb 4 10:40:53 2020 : Debug: check_cert = no Tue Feb 4 10:40:53 2020 : Debug: check_cert_cn = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Debug: warnings = "auto" Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Attempting to connect to database "mpc_freeradius" Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql): Initialising connection pool Tue Feb 4 10:40:53 2020 : Debug: pool { Tue Feb 4 10:40:53 2020 : Debug: start = 5 Tue Feb 4 10:40:53 2020 : Debug: min = 3 Tue Feb 4 10:40:53 2020 : Debug: max = 32 Tue Feb 4 10:40:53 2020 : Debug: spare = 10 Tue Feb 4 10:40:53 2020 : Debug: uses = 0 Tue Feb 4 10:40:53 2020 : Debug: lifetime = 60 Tue Feb 4 10:40:53 2020 : Debug: cleanup_interval = 30 Tue Feb 4 10:40:53 2020 : Debug: idle_timeout = 60 Tue Feb 4 10:40:53 2020 : Debug: retry_delay = 30 Tue Feb 4 10:40:53 2020 : Debug: spread = no Tue Feb 4 10:40:53 2020 : Debug: } Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Opening additional connection (0), 1 of 32 pending slots used Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Connected to database 'mpc_freeradius' on mysql.mpc.com.br via TCP/IP, server version 5.7.27-0ubuntu0.16.04.1-log, protocol version 10 Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Opening additional connection (1), 1 of 31 pending slots used Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Connected to database 'mpc_freeradius' on mysql.mpc.com.br via TCP/IP, server version 5.7.27-0ubuntu0.16.04.1-log, protocol version 10 Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Opening additional connection (2), 1 of 30 pending slots used Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Connected to database 'mpc_freeradius' on mysql.mpc.com.br via TCP/IP, server version 5.7.27-0ubuntu0.16.04.1-log, protocol version 10 Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Opening additional connection (3), 1 of 29 pending slots used Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Connected to database 'mpc_freeradius' on mysql.mpc.com.br via TCP/IP, server version 5.7.27-0ubuntu0.16.04.1-log, protocol version 10 Tue Feb 4 10:40:53 2020 : Info: rlm_sql (sql): Opening additional connection (4), 1 of 28 pending slots used Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Feb 4 10:40:53 2020 : Debug: rlm_sql_mysql: Connected to database 'mpc_freeradius' on mysql.mpc.com.br via TCP/IP, server version 5.7.27-0ubuntu0.16.04.1-log, protocol version 10 Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql): Processing generate_sql_clients Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql): Reserved connection (0) Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql): Executing select query: SELECT id, nasname, shortname, type, secret, server FROM nas Tue Feb 4 10:40:53 2020 : Debug: rlm_sql (sql): Adding client 127.0.0.1 (Local Host) to global clients list Tue Feb 4 10:40:53 2020 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Tue Feb 4 10:40:53 2020 : Error: Failed to add duplicate client Local Host Tue Feb 4 10:40:53 2020 : Warning: Failed to add client, possible duplicate? Bad talloc magic value - unknown value talloc abort: Bad talloc magic value - unknown value Aborted (core dumped)