Hello, everyone. I try to change the username attribute in the request by the result of sql select query: if ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}"
"0") { update request { User-Name = "%{sql_main:select phone from vbmacs where mac='%{User-Name}'}" } } else { reject }
This code is placed in authorize section after module preprocess. But in debug I see "update request = noop" after successful expanding of sql query result. Can you help me with this issue? root@debian:/etc/freeradius/sql/mysql# freeradius -XXX Wed Jun 29 19:01:07 2016 : Info: freeradius: FreeRADIUS Version 2.2.5, for host x86_64-pc-linux-gnu, built on Oct 28 2014 at 16:27:11 Wed Jun 29 19:01:07 2016 : Debug: Server was built with: Wed Jun 29 19:01:07 2016 : Debug: accounting Wed Jun 29 19:01:07 2016 : Debug: authentication Wed Jun 29 19:01:07 2016 : Debug: WITH_DHCP Wed Jun 29 19:01:07 2016 : Debug: WITH_VMPS Wed Jun 29 19:01:07 2016 : Debug: Server core libs: Wed Jun 29 19:01:07 2016 : Debug: ssl: OpenSSL 1.0.1e 11 Feb 2013 Wed Jun 29 19:01:07 2016 : Info: Copyright (C) 1999-2013 The FreeRADIUS server project and contributors. Wed Jun 29 19:01:07 2016 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Wed Jun 29 19:01:07 2016 : Info: PARTICULAR PURPOSE. Wed Jun 29 19:01:07 2016 : Info: You may redistribute copies of FreeRADIUS under the terms of the Wed Jun 29 19:01:07 2016 : Info: GNU General Public License. Wed Jun 29 19:01:07 2016 : Info: For more information about these matters, see the file named COPYRIGHT. Wed Jun 29 19:01:07 2016 : Info: Starting - reading configuration files ... Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/radiusd.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/proxy.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/clients.conf Wed Jun 29 19:01:07 2016 : Debug: including files in directory /etc/freeradius/modules/ Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/detail Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/rediswho Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/linelog Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/mac2ip Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/ippool Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/perl Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/echo Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/replicate Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/sql_log Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/realm Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/attr_filter Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/counter Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/detail.example.com Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/always Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/smsotp Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/wimax Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/pam Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/dhcp_sqlippool Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/soh Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/etc_group Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/detail.log Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/mac2vlan Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/cui Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/ldap Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/redis Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/dynamic_clients Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/digest Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/checkval Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/expiration Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/passwd Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/pap Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/policy Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/unix Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/preprocess Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/cache Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/chap Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/radutmp Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/logintime Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/otp Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/expr Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/radrelay Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/mschap Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/acct_unique Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/smbpasswd Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/sradutmp Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/opendirectory Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/exec Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/krb5 Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/inner-eap Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/modules/files Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/eap.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sql.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sql/mysql/mac-filter-sql.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/policy.conf Wed Jun 29 19:01:07 2016 : Debug: including files in directory /etc/freeradius/sites-enabled/ Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/default Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sql/mysql/mac-filter.conf Wed Jun 29 19:01:07 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Wed Jun 29 19:01:07 2016 : Debug: main { Wed Jun 29 19:01:07 2016 : Debug: user = "freerad" Wed Jun 29 19:01:07 2016 : Debug: group = "freerad" Wed Jun 29 19:01:07 2016 : Debug: allow_core_dumps = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: including dictionary file /etc/freeradius/dictionary Wed Jun 29 19:01:07 2016 : Debug: main { Wed Jun 29 19:01:07 2016 : Debug: name = "freeradius" Wed Jun 29 19:01:07 2016 : Debug: prefix = "/usr" Wed Jun 29 19:01:07 2016 : Debug: localstatedir = "/var" Wed Jun 29 19:01:07 2016 : Debug: sbindir = "/usr/sbin" Wed Jun 29 19:01:07 2016 : Debug: logdir = "/var/log/freeradius" Wed Jun 29 19:01:07 2016 : Debug: run_dir = "/var/run/freeradius" Wed Jun 29 19:01:07 2016 : Debug: libdir = "/usr/lib/freeradius" Wed Jun 29 19:01:07 2016 : Debug: radacctdir = "/var/log/freeradius/radacct" Wed Jun 29 19:01:07 2016 : Debug: hostname_lookups = no Wed Jun 29 19:01:07 2016 : Debug: max_request_time = 30 Wed Jun 29 19:01:07 2016 : Debug: cleanup_delay = 5 Wed Jun 29 19:01:07 2016 : Debug: max_requests = 1024 Wed Jun 29 19:01:07 2016 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Wed Jun 29 19:01:07 2016 : Debug: checkrad = "/usr/sbin/checkrad" Wed Jun 29 19:01:07 2016 : Debug: debug_level = 0 Wed Jun 29 19:01:07 2016 : Debug: proxy_requests = no Wed Jun 29 19:01:07 2016 : Debug: log { Wed Jun 29 19:01:07 2016 : Debug: stripped_names = no Wed Jun 29 19:01:07 2016 : Debug: auth = no Wed Jun 29 19:01:07 2016 : Debug: auth_badpass = no Wed Jun 29 19:01:07 2016 : Debug: auth_goodpass = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: security { Wed Jun 29 19:01:07 2016 : Debug: max_attributes = 200 Wed Jun 29 19:01:07 2016 : Debug: reject_delay = 0 Wed Jun 29 19:01:07 2016 : Debug: status_server = yes Wed Jun 29 19:01:07 2016 : Debug: allow_vulnerable_openssl = yes Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: radiusd: #### Loading Realms and Home Servers #### Wed Jun 29 19:01:07 2016 : Debug: proxy server { Wed Jun 29 19:01:07 2016 : Debug: retry_delay = 5 Wed Jun 29 19:01:07 2016 : Debug: retry_count = 3 Wed Jun 29 19:01:07 2016 : Debug: default_fallback = no Wed Jun 29 19:01:07 2016 : Debug: dead_time = 120 Wed Jun 29 19:01:07 2016 : Debug: wake_all_if_all_dead = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: home_server localhost { Wed Jun 29 19:01:07 2016 : Debug: ipaddr = 127.0.0.1 Wed Jun 29 19:01:07 2016 : Debug: port = 1812 Wed Jun 29 19:01:07 2016 : Debug: type = "auth" Wed Jun 29 19:01:07 2016 : Debug: secret = "testing123" Wed Jun 29 19:01:07 2016 : Debug: response_window = 20 Wed Jun 29 19:01:07 2016 : Debug: max_outstanding = 65536 Wed Jun 29 19:01:07 2016 : Debug: require_message_authenticator = yes Wed Jun 29 19:01:07 2016 : Debug: zombie_period = 40 Wed Jun 29 19:01:07 2016 : Debug: status_check = "status-server" Wed Jun 29 19:01:07 2016 : Debug: ping_interval = 30 Wed Jun 29 19:01:07 2016 : Debug: check_interval = 30 Wed Jun 29 19:01:07 2016 : Debug: num_answers_to_alive = 3 Wed Jun 29 19:01:07 2016 : Debug: num_pings_to_alive = 3 Wed Jun 29 19:01:07 2016 : Debug: revive_interval = 120 Wed Jun 29 19:01:07 2016 : Debug: status_check_timeout = 4 Wed Jun 29 19:01:07 2016 : Debug: coa { Wed Jun 29 19:01:07 2016 : Debug: irt = 2 Wed Jun 29 19:01:07 2016 : Debug: mrt = 16 Wed Jun 29 19:01:07 2016 : Debug: mrc = 5 Wed Jun 29 19:01:07 2016 : Debug: mrd = 30 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: home_server_pool my_auth_failover { Wed Jun 29 19:01:07 2016 : Debug: type = fail-over Wed Jun 29 19:01:07 2016 : Debug: home_server = localhost Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: realm example.com { Wed Jun 29 19:01:07 2016 : Debug: auth_pool = my_auth_failover Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: realm LOCAL { Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: radiusd: #### Loading Clients #### Wed Jun 29 19:01:07 2016 : Debug: client localhost { Wed Jun 29 19:01:07 2016 : Debug: ipaddr = 127.0.0.1 Wed Jun 29 19:01:07 2016 : Debug: require_message_authenticator = no Wed Jun 29 19:01:07 2016 : Debug: secret = "testing123" Wed Jun 29 19:01:07 2016 : Debug: nastype = "other" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: radiusd: #### Instantiating modules #### Wed Jun 29 19:01:07 2016 : Debug: instantiate { Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_exec, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_exec Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "exec" from file /etc/freeradius/modules/exec Wed Jun 29 19:01:07 2016 : Debug: exec { Wed Jun 29 19:01:07 2016 : Debug: wait = no Wed Jun 29 19:01:07 2016 : Debug: input_pairs = "request" Wed Jun 29 19:01:07 2016 : Debug: shell_escape = yes Wed Jun 29 19:01:07 2016 : Debug: timeout = 10 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_expr, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_expr Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "expr" from file /etc/freeradius/modules/expr Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_expiration, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_expiration Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "expiration" from file /etc/freeradius/modules/expiration Wed Jun 29 19:01:07 2016 : Debug: expiration { Wed Jun 29 19:01:07 2016 : Debug: reply-message = "Password Has Expired " Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_logintime, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_logintime Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "logintime" from file /etc/freeradius/modules/logintime Wed Jun 29 19:01:07 2016 : Debug: logintime { Wed Jun 29 19:01:07 2016 : Debug: reply-message = "You are calling outside your allowed timespan " Wed Jun 29 19:01:07 2016 : Debug: minimum-timeout = 60 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: radiusd: #### Loading Virtual Servers #### Wed Jun 29 19:01:07 2016 : Debug: server { # from file ▒▒▒? Wed Jun 29 19:01:07 2016 : Debug: modules { Wed Jun 29 19:01:07 2016 : Debug: Module: Creating Auth-Type = digest Wed Jun 29 19:01:07 2016 : Debug: Module: Creating Post-Auth-Type = REJECT Wed Jun 29 19:01:07 2016 : Debug: Module: Checking authenticate {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_pap, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_pap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "pap" from file /etc/freeradius/modules/pap Wed Jun 29 19:01:07 2016 : Debug: pap { Wed Jun 29 19:01:07 2016 : Debug: encryption_scheme = "auto" Wed Jun 29 19:01:07 2016 : Debug: auto_header = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_chap, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_chap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "chap" from file /etc/freeradius/modules/chap Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_mschap, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_mschap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "mschap" from file /etc/freeradius/modules/mschap Wed Jun 29 19:01:07 2016 : Debug: mschap { Wed Jun 29 19:01:07 2016 : Debug: use_mppe = yes Wed Jun 29 19:01:07 2016 : Debug: require_encryption = no Wed Jun 29 19:01:07 2016 : Debug: require_strong = no Wed Jun 29 19:01:07 2016 : Debug: with_ntdomain_hack = no Wed Jun 29 19:01:07 2016 : Debug: allow_retry = yes Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_digest, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_digest Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "digest" from file /etc/freeradius/modules/digest Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_unix, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_unix Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "unix" from file /etc/freeradius/modules/unix Wed Jun 29 19:01:07 2016 : Debug: unix { Wed Jun 29 19:01:07 2016 : Debug: radwtmp = "/var/log/freeradius/radwtmp" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_eap, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_eap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "eap" from file /etc/freeradius/eap.conf Wed Jun 29 19:01:07 2016 : Debug: eap { Wed Jun 29 19:01:07 2016 : Debug: default_eap_type = "md5" Wed Jun 29 19:01:07 2016 : Debug: timer_expire = 60 Wed Jun 29 19:01:07 2016 : Debug: ignore_unknown_eap_types = no Wed Jun 29 19:01:07 2016 : Debug: cisco_accounting_username_bug = no Wed Jun 29 19:01:07 2016 : Debug: max_sessions = 1024 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_md5 Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-md5 Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_leap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-leap Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_gtc Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-gtc Wed Jun 29 19:01:07 2016 : Debug: gtc { Wed Jun 29 19:01:07 2016 : Debug: challenge = "Password: " Wed Jun 29 19:01:07 2016 : Debug: auth_type = "PAP" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_tls Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-tls Wed Jun 29 19:01:07 2016 : Debug: tls { Wed Jun 29 19:01:07 2016 : Debug: rsa_key_exchange = no Wed Jun 29 19:01:07 2016 : Debug: dh_key_exchange = yes Wed Jun 29 19:01:07 2016 : Debug: rsa_key_length = 512 Wed Jun 29 19:01:07 2016 : Debug: dh_key_length = 512 Wed Jun 29 19:01:07 2016 : Debug: verify_depth = 0 Wed Jun 29 19:01:07 2016 : Debug: CA_path = "/etc/freeradius/certs" Wed Jun 29 19:01:07 2016 : Debug: pem_file_type = yes Wed Jun 29 19:01:07 2016 : Debug: private_key_file = "/etc/freeradius/certs/server.key" Wed Jun 29 19:01:07 2016 : Debug: certificate_file = "/etc/freeradius/certs/server.pem" Wed Jun 29 19:01:07 2016 : Debug: CA_file = "/etc/freeradius/certs/ca.pem" Wed Jun 29 19:01:07 2016 : Debug: private_key_password = "whatever" Wed Jun 29 19:01:07 2016 : Debug: dh_file = "/etc/freeradius/certs/dh" Wed Jun 29 19:01:07 2016 : Debug: random_file = "/dev/urandom" Wed Jun 29 19:01:07 2016 : Debug: fragment_size = 1024 Wed Jun 29 19:01:07 2016 : Debug: include_length = yes Wed Jun 29 19:01:07 2016 : Debug: check_crl = no Wed Jun 29 19:01:07 2016 : Debug: cipher_list = "DEFAULT" Wed Jun 29 19:01:07 2016 : Debug: make_cert_command = "/etc/freeradius/certs/bootstrap" Wed Jun 29 19:01:07 2016 : Debug: ecdh_curve = "prime256v1" Wed Jun 29 19:01:07 2016 : Debug: cache { Wed Jun 29 19:01:07 2016 : Debug: enable = no Wed Jun 29 19:01:07 2016 : Debug: lifetime = 24 Wed Jun 29 19:01:07 2016 : Debug: max_entries = 255 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: verify { Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: ocsp { Wed Jun 29 19:01:07 2016 : Debug: enable = no Wed Jun 29 19:01:07 2016 : Debug: override_cert_url = yes Wed Jun 29 19:01:07 2016 : Debug: url = "http://127.0.0.1/ocsp/" Wed Jun 29 19:01:07 2016 : Debug: use_nonce = yes Wed Jun 29 19:01:07 2016 : Debug: timeout = 0 Wed Jun 29 19:01:07 2016 : Debug: softfail = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_ttls Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-ttls Wed Jun 29 19:01:07 2016 : Debug: ttls { Wed Jun 29 19:01:07 2016 : Debug: default_eap_type = "md5" Wed Jun 29 19:01:07 2016 : Debug: copy_request_to_tunnel = no Wed Jun 29 19:01:07 2016 : Debug: use_tunneled_reply = no Wed Jun 29 19:01:07 2016 : Debug: virtual_server = "inner-tunnel" Wed Jun 29 19:01:07 2016 : Debug: include_length = yes Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_peap Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-peap Wed Jun 29 19:01:07 2016 : Debug: peap { Wed Jun 29 19:01:07 2016 : Debug: default_eap_type = "mschapv2" Wed Jun 29 19:01:07 2016 : Debug: copy_request_to_tunnel = no Wed Jun 29 19:01:07 2016 : Debug: use_tunneled_reply = no Wed Jun 29 19:01:07 2016 : Debug: proxy_tunneled_request_as_eap = yes Wed Jun 29 19:01:07 2016 : Debug: virtual_server = "inner-tunnel" Wed Jun 29 19:01:07 2016 : Debug: soh = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating eap-mschapv2 Wed Jun 29 19:01:07 2016 : Debug: mschapv2 { Wed Jun 29 19:01:07 2016 : Debug: with_ntdomain_hack = no Wed Jun 29 19:01:07 2016 : Debug: send_error = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Checking authorize {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_preprocess, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_preprocess Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "preprocess" from file /etc/freeradius/modules/preprocess Wed Jun 29 19:01:07 2016 : Debug: preprocess { Wed Jun 29 19:01:07 2016 : Debug: huntgroups = "/etc/freeradius/huntgroups" Wed Jun 29 19:01:07 2016 : Debug: hints = "/etc/freeradius/hints" Wed Jun 29 19:01:07 2016 : Debug: with_ascend_hack = no Wed Jun 29 19:01:07 2016 : Debug: ascend_channels_per_line = 23 Wed Jun 29 19:01:07 2016 : Debug: with_ntdomain_hack = no Wed Jun 29 19:01:07 2016 : Debug: with_specialix_jetstream_hack = no Wed Jun 29 19:01:07 2016 : Debug: with_cisco_vsa_hack = no Wed Jun 29 19:01:07 2016 : Debug: with_alvarion_vsa_hack = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/huntgroups Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/hints Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_always, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_always Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "reject" from file /etc/freeradius/modules/always Wed Jun 29 19:01:07 2016 : Debug: always reject { Wed Jun 29 19:01:07 2016 : Debug: rcode = "reject" Wed Jun 29 19:01:07 2016 : Debug: simulcount = 0 Wed Jun 29 19:01:07 2016 : Debug: mpp = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_realm, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_realm Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "suffix" from file /etc/freeradius/modules/realm Wed Jun 29 19:01:07 2016 : Debug: realm suffix { Wed Jun 29 19:01:07 2016 : Debug: format = "suffix" Wed Jun 29 19:01:07 2016 : Debug: delimiter = "@" Wed Jun 29 19:01:07 2016 : Debug: ignore_default = no Wed Jun 29 19:01:07 2016 : Debug: ignore_null = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_files, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_files Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "files" from file /etc/freeradius/modules/files Wed Jun 29 19:01:07 2016 : Debug: files { Wed Jun 29 19:01:07 2016 : Debug: usersfile = "/etc/freeradius/users" Wed Jun 29 19:01:07 2016 : Debug: acctusersfile = "/etc/freeradius/acct_users" Wed Jun 29 19:01:07 2016 : Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Wed Jun 29 19:01:07 2016 : Debug: compat = "no" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/users Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/acct_users Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/preproxy_users Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_sql, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_sql Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "sql_main" from file /etc/freeradius/sql.conf Wed Jun 29 19:01:07 2016 : Debug: sql sql_main { Wed Jun 29 19:01:07 2016 : Debug: driver = "rlm_sql_mysql" Wed Jun 29 19:01:07 2016 : Debug: server = "localhost" Wed Jun 29 19:01:07 2016 : Debug: port = "" Wed Jun 29 19:01:07 2016 : Debug: login = "radius" Wed Jun 29 19:01:07 2016 : Debug: password = "vEdf84JEXdPAuUHv" Wed Jun 29 19:01:07 2016 : Debug: radius_db = "radius-test" Wed Jun 29 19:01:07 2016 : Debug: read_groups = yes Wed Jun 29 19:01:07 2016 : Debug: sqltrace = no Wed Jun 29 19:01:07 2016 : Debug: sqltracefile = "/var/log/freeradius/sqltrace.sql" Wed Jun 29 19:01:07 2016 : Debug: readclients = yes Wed Jun 29 19:01:07 2016 : Debug: deletestalesessions = yes Wed Jun 29 19:01:07 2016 : Debug: num_sql_socks = 32 Wed Jun 29 19:01:07 2016 : Debug: lifetime = 0 Wed Jun 29 19:01:07 2016 : Debug: max_queries = 0 Wed Jun 29 19:01:07 2016 : Debug: sql_user_name = "%{User-Name}" Wed Jun 29 19:01:07 2016 : Debug: default_user_profile = "" Wed Jun 29 19:01:07 2016 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Wed Jun 29 19:01:07 2016 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: accounting_onoff_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = unix_timestamp('%S') - unix_timestamp(acctstarttime), acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = %{%{Acct-Delay-Time}:-0} WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= '%S'" Wed Jun 29 19:01:07 2016 : Debug: accounting_update_query = " UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_update_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{X-Ascend-Session-Svr-Key}')" Wed Jun 29 19:01:07 2016 : Debug: accounting_start_query = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')" Wed Jun 29 19:01:07 2016 : Debug: accounting_start_query_alt = " UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_stop_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_stop_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{%{Acct-Delay-Time}:-0}')" Wed Jun 29 19:01:07 2016 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Wed Jun 29 19:01:07 2016 : Debug: connect_failure_retry_delay = 60 Wed Jun 29 19:01:07 2016 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Wed Jun 29 19:01:07 2016 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Wed Jun 29 19:01:07 2016 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Wed Jun 29 19:01:07 2016 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: rlm_sql Creating new attribute sql_main-SQL-Group Wed Jun 29 19:01:07 2016 : Debug: rlm_sql: Registering sql_groupcmp for sql_main-SQL-Group Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect to radius@localhost:/radius-test Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #0 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #1 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #3 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #4 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #5 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #6 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #7 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #8 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #9 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #10 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #11 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #12 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #13 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #14 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #15 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #16 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #17 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #18 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #19 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #20 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #21 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #22 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #23 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #24 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #25 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #26 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #27 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #28 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #29 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #30 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): starting 31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Attempting to connect rlm_sql_mysql #31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_main): Connected new DB handle, #31 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Processing generate_sql_clients Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Reserving sql socket id: 31 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.4.17.2,shortname=wlc-omc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.4.17.2 (wlc-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.7.17.2,shortname=wlc-priut-2,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.7.17.2 (wlc-priut-2, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.10.17.2,shortname=wlc-1389,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.10.17.2 (wlc-1389, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.25.17.2,shortname=wlc-okc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.25.17.2 (wlc-okc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.25.17.5,shortname=wlc-okc-2,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.25.17.5 (wlc-okc-2, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.25.17.4,shortname=wlc-okc_rezerv,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.25.17.4 (wlc-okc_rezerv, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.201.133.2,shortname=wlc-alpika,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.201.133.2 (wlc-alpika, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=172.31.17.251,shortname=wlc-peak,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 172.31.17.251 (wlc-peak, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.20.101.251,shortname=asr-okc,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.20.101.251 (asr-okc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.20.101.252,shortname=asr-gk1389,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.20.101.252 (asr-gk1389, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.20.101.253,shortname=asr-omc,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.20.101.253 (asr-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.20.101.13,shortname=2951-1200,secret=hg39fJ93Onf1Y Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.20.101.13 (2951-1200, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Read entry nasname=10.25.17.1,shortname=wlc-okc-omc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Adding client 10.25.17.1 (wlc-okc-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_main): Released sql socket id: 31 Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_sqlcounter, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_sqlcounter Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "expire_on_login" from file /etc/freeradius/modules/sqlcounter_expire_on_login Wed Jun 29 19:01:07 2016 : Debug: sqlcounter expire_on_login { Wed Jun 29 19:01:07 2016 : Debug: counter-name = "Expire-After-Initial-Login" Wed Jun 29 19:01:07 2016 : Debug: check-name = "Expire-After" Wed Jun 29 19:01:07 2016 : Debug: reply-name = "Session-Timeout" Wed Jun 29 19:01:07 2016 : Debug: key = "User-Name" Wed Jun 29 19:01:07 2016 : Debug: sqlmod-inst = "sql" Wed Jun 29 19:01:07 2016 : Debug: query = "SELECT TIME_TO_SEC(TIMEDIFF(NOW(), acctstarttime)) FROM radacct WHERE UserName='%{User-Name}' ORDER BY acctstarttime LIMIT 1;" Wed Jun 29 19:01:07 2016 : Debug: reset = "never" Wed Jun 29 19:01:07 2016 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: rlm_sqlcounter: Check attribute Expire-After is number 12001 Wed Jun 29 19:01:07 2016 : Debug: rlm_sqlcounter: Current Time: 1467216067 [2016-06-29 19:01:07], Next reset 0 [2016-06-29 19:00:00] Wed Jun 29 19:01:07 2016 : Debug: rlm_sqlcounter: Current Time: 1467216067 [2016-06-29 19:01:07], Prev reset 0 [2016-06-29 19:00:00] Wed Jun 29 19:01:07 2016 : Debug: Module: Checking preacct {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_acct_unique Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "acct_unique" from file /etc/freeradius/modules/acct_unique Wed Jun 29 19:01:07 2016 : Debug: acct_unique { Wed Jun 29 19:01:07 2016 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Checking accounting {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_detail, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_detail Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "detail" from file /etc/freeradius/modules/detail Wed Jun 29 19:01:07 2016 : Debug: detail { Wed Jun 29 19:01:07 2016 : Debug: detailfile = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Wed Jun 29 19:01:07 2016 : Debug: header = "%t" Wed Jun 29 19:01:07 2016 : Debug: detailperm = 384 Wed Jun 29 19:01:07 2016 : Debug: dirperm = 493 Wed Jun 29 19:01:07 2016 : Debug: locking = no Wed Jun 29 19:01:07 2016 : Debug: log_packet_header = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "sql_mac-filter" from file /etc/freeradius/sql.conf Wed Jun 29 19:01:07 2016 : Debug: sql sql_mac-filter { Wed Jun 29 19:01:07 2016 : Debug: driver = "rlm_sql_mysql" Wed Jun 29 19:01:07 2016 : Debug: server = "localhost" Wed Jun 29 19:01:07 2016 : Debug: port = "" Wed Jun 29 19:01:07 2016 : Debug: login = "radius" Wed Jun 29 19:01:07 2016 : Debug: password = "vEdf84JEXdPAuUHv" Wed Jun 29 19:01:07 2016 : Debug: radius_db = "radius-test" Wed Jun 29 19:01:07 2016 : Debug: read_groups = yes Wed Jun 29 19:01:07 2016 : Debug: sqltrace = no Wed Jun 29 19:01:07 2016 : Debug: sqltracefile = "/var/log/freeradius/sqltrace.sql" Wed Jun 29 19:01:07 2016 : Debug: readclients = yes Wed Jun 29 19:01:07 2016 : Debug: deletestalesessions = yes Wed Jun 29 19:01:07 2016 : Debug: num_sql_socks = 32 Wed Jun 29 19:01:07 2016 : Debug: lifetime = 0 Wed Jun 29 19:01:07 2016 : Debug: max_queries = 0 Wed Jun 29 19:01:07 2016 : Debug: sql_user_name = "%{User-Name}" Wed Jun 29 19:01:07 2016 : Debug: default_user_profile = "" Wed Jun 29 19:01:07 2016 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Wed Jun 29 19:01:07 2016 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Wed Jun 29 19:01:07 2016 : Debug: accounting_onoff_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = unix_timestamp('%S') - unix_timestamp(acctstarttime), acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = %{%{Acct-Delay-Time}:-0} WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= '%S'" Wed Jun 29 19:01:07 2016 : Debug: accounting_update_query = " UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_update_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{X-Ascend-Session-Svr-Key}')" Wed Jun 29 19:01:07 2016 : Debug: accounting_start_query = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')" Wed Jun 29 19:01:07 2016 : Debug: accounting_start_query_alt = " UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_stop_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Wed Jun 29 19:01:07 2016 : Debug: accounting_stop_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{%{Acct-Delay-Time}:-0}')" Wed Jun 29 19:01:07 2016 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Wed Jun 29 19:01:07 2016 : Debug: connect_failure_retry_delay = 60 Wed Jun 29 19:01:07 2016 : Debug: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Wed Jun 29 19:01:07 2016 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Wed Jun 29 19:01:07 2016 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Wed Jun 29 19:01:07 2016 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: rlm_sql Creating new attribute sql_mac-filter-SQL-Group Wed Jun 29 19:01:07 2016 : Debug: rlm_sql: Registering sql_groupcmp for sql_mac-filter-SQL-Group Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect to radius@localhost:/radius-test Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #0 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #1 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #3 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #4 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #5 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #6 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #7 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #8 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #9 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #10 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #11 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #12 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #13 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #14 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #15 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #15 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #16 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #16 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #17 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #17 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #18 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #18 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #19 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #19 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #20 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #20 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #21 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #21 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #22 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #22 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #23 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #23 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #24 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #24 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #25 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #25 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #26 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #26 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #27 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #27 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #28 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #28 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #29 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #29 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #30 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #30 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): starting 31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Attempting to connect rlm_sql_mysql #31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql_mysql: Starting connect to MySQL server for #31 Wed Jun 29 19:01:07 2016 : Info: rlm_sql (sql_mac-filter): Connected new DB handle, #31 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Processing generate_sql_clients Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Reserving sql socket id: 31 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.4.17.2,shortname=wlc-omc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.4.17.2 (wlc-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.4.17.2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.7.17.2,shortname=wlc-priut-2,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.7.17.2 (wlc-priut-2, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.7.17.2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.10.17.2,shortname=wlc-1389,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.10.17.2 (wlc-1389, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.10.17.2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.25.17.2,shortname=wlc-okc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.25.17.2 (wlc-okc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.25.17.2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.25.17.5,shortname=wlc-okc-2,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.25.17.5 (wlc-okc-2, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.25.17.5 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.25.17.4,shortname=wlc-okc_rezerv,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.25.17.4 (wlc-okc_rezerv, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.25.17.4 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.201.133.2,shortname=wlc-alpika,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.201.133.2 (wlc-alpika, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.201.133.2 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=172.31.17.251,shortname=wlc-peak,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 172.31.17.251 (wlc-peak, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 172.31.17.251 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.20.101.251,shortname=asr-okc,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.20.101.251 (asr-okc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.20.101.251 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.20.101.252,shortname=asr-gk1389,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.20.101.252 (asr-gk1389, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.20.101.252 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.20.101.253,shortname=asr-omc,secret=keisgradyius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.20.101.253 (asr-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.20.101.253 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.20.101.13,shortname=2951-1200,secret=hg39fJ93Onf1Y Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.20.101.13 (2951-1200, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.20.101.13 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Read entry nasname=10.25.17.1,shortname=wlc-okc-omc,secret=wlcradius Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Adding client 10.25.17.1 (wlc-okc-omc, server=<none>) to clients list Wed Jun 29 19:01:07 2016 : Debug: WARNING: Ignoring duplicate client 10.25.17.1 Wed Jun 29 19:01:07 2016 : Debug: rlm_sql (sql_mac-filter): Released sql socket id: 31 Wed Jun 29 19:01:07 2016 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Wed Jun 29 19:01:07 2016 : Debug: Module: Linked to module rlm_attr_filter Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/modules/attr_filter Wed Jun 29 19:01:07 2016 : Debug: attr_filter attr_filter.accounting_response { Wed Jun 29 19:01:07 2016 : Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Wed Jun 29 19:01:07 2016 : Debug: key = "%{User-Name}" Wed Jun 29 19:01:07 2016 : Debug: relaxed = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/attrs.accounting_response Wed Jun 29 19:01:07 2016 : Debug: Module: Checking session {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking post-proxy {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking post-auth {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /etc/freeradius/modules/attr_filter Wed Jun 29 19:01:07 2016 : Debug: attr_filter attr_filter.access_reject { Wed Jun 29 19:01:07 2016 : Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Wed Jun 29 19:01:07 2016 : Debug: key = "%{User-Name}" Wed Jun 29 19:01:07 2016 : Debug: relaxed = no Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: reading pairlist file /etc/freeradius/attrs.access_reject Wed Jun 29 19:01:07 2016 : Debug: } # modules Wed Jun 29 19:01:07 2016 : Debug: } # server Wed Jun 29 19:01:07 2016 : Debug: server inner-tunnel { # from file /etc/freeradius/sites-enabled/inner-tunnel Wed Jun 29 19:01:07 2016 : Debug: modules { Wed Jun 29 19:01:07 2016 : Debug: Module: Checking authenticate {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking authorize {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking session {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking post-proxy {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: Module: Checking post-auth {...} for more modules to load Wed Jun 29 19:01:07 2016 : Debug: } # modules Wed Jun 29 19:01:07 2016 : Debug: } # server Wed Jun 29 19:01:07 2016 : Debug: radiusd: #### Opening IP addresses and Ports #### Wed Jun 29 19:01:07 2016 : Debug: listen { Wed Jun 29 19:01:07 2016 : Debug: type = "auth" Wed Jun 29 19:01:07 2016 : Debug: ipaddr = * Wed Jun 29 19:01:07 2016 : Debug: port = 0 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: listen { Wed Jun 29 19:01:07 2016 : Debug: type = "acct" Wed Jun 29 19:01:07 2016 : Debug: ipaddr = * Wed Jun 29 19:01:07 2016 : Debug: port = 0 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: listen { Wed Jun 29 19:01:07 2016 : Debug: type = "auth" Wed Jun 29 19:01:07 2016 : Debug: ipaddr = 127.0.0.1 Wed Jun 29 19:01:07 2016 : Debug: port = 18120 Wed Jun 29 19:01:07 2016 : Debug: } Wed Jun 29 19:01:07 2016 : Debug: Listening on authentication address * port 1812 Wed Jun 29 19:01:07 2016 : Debug: Listening on accounting address * port 1813 Wed Jun 29 19:01:07 2016 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Wed Jun 29 19:01:07 2016 : Info: Ready to process requests. rad_recv: Access-Request packet from host 10.25.17.2 port 32770, id=111, length=185 User-Name = "90:00:4e:3d:fe:a2" Called-Station-Id = "AP-Park-410:mf" Calling-Station-Id = "90-00-4e-3d-fe-a2" NAS-Port = 13 NAS-IP-Address = 10.25.17.2 NAS-Identifier = "wlc-okc-060-cth1" Airespace-Wlan-Id = 13 Service-Type = Call-Check Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "192" Acct-Session-Id = "5773f0dd/90:00:4e:3d:fe:a2/64164" Wed Jun 29 19:01:31 2016 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Wed Jun 29 19:01:31 2016 : Info: +group authorize { Wed Jun 29 19:01:31 2016 : Info: ++[preprocess] = ok Wed Jun 29 19:01:31 2016 : Info: ++? if ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}" > "0") Wed Jun 29 19:01:31 2016 : Info: sql_xlat Wed Jun 29 19:01:31 2016 : Info: expand: %{User-Name} -> 90:00:4e:3d:fe:a2 Wed Jun 29 19:01:31 2016 : Info: sql_set_user escaped user --> '90:00:4e:3d:fe:a2' Wed Jun 29 19:01:31 2016 : Info: expand: select count(id) from vbmacs where mac='%{User-Name}' -> select count(id) from vbmacs where mac='90:00:4e:3d:fe:a2' Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Reserving sql socket id: 30 Wed Jun 29 19:01:31 2016 : Info: sql_xlat finished Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Released sql socket id: 30 Wed Jun 29 19:01:31 2016 : Info: expand: %{sql_main:select count(id) from vbmacs where mac='%{User-Name}'} -> 1 Wed Jun 29 19:01:31 2016 : Info: ? Evaluating ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}" > "0") -> TRUE Wed Jun 29 19:01:31 2016 : Info: ++? if ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}" > "0") -> TRUE Wed Jun 29 19:01:31 2016 : Info: ++if ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}" > "0") { Wed Jun 29 19:01:31 2016 : Info: +++update request { Wed Jun 29 19:01:31 2016 : Info: sql_xlat Wed Jun 29 19:01:31 2016 : Info: expand: %{User-Name} -> 90:00:4e:3d:fe:a2 Wed Jun 29 19:01:31 2016 : Info: sql_set_user escaped user --> '90:00:4e:3d:fe:a2' Wed Jun 29 19:01:31 2016 : Info: expand: select phone from vbmacs where mac='%{User-Name}' -> select phone from vbmacs where mac='90:00:4e:3d:fe:a2' Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Reserving sql socket id: 29 Wed Jun 29 19:01:31 2016 : Info: sql_xlat finished Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Released sql socket id: 29 Wed Jun 29 19:01:31 2016 : Info: expand: %{sql_main:select phone from vbmacs where mac='%{User-Name}'} -> 79280000000 Wed Jun 29 19:01:31 2016 : Info: +++} # update request = noop Wed Jun 29 19:01:31 2016 : Info: ++} # if ("%{sql_main:select count(id) from vbmacs where mac='%{User-Name}'}" > "0") = noop Wed Jun 29 19:01:31 2016 : Info: ++ ... skipping else for request 0: Preceding "if" was taken Wed Jun 29 19:01:31 2016 : Info: ++[chap] = noop Wed Jun 29 19:01:31 2016 : Info: ++[mschap] = noop Wed Jun 29 19:01:31 2016 : Info: ++[digest] = noop Wed Jun 29 19:01:31 2016 : Info: [suffix] No '@' in User-Name = "90:00:4e:3d:fe:a2", looking up realm NULL Wed Jun 29 19:01:31 2016 : Info: [suffix] No such realm "NULL" Wed Jun 29 19:01:31 2016 : Info: ++[suffix] = noop Wed Jun 29 19:01:31 2016 : Info: [eap] No EAP-Message, not doing EAP Wed Jun 29 19:01:31 2016 : Info: ++[eap] = noop Wed Jun 29 19:01:31 2016 : Info: ++[files] = noop Wed Jun 29 19:01:31 2016 : Info: [sql_main] expand: %{User-Name} -> 90:00:4e:3d:fe:a2 Wed Jun 29 19:01:31 2016 : Info: [sql_main] sql_set_user escaped user --> '90:00:4e:3d:fe:a2' Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Reserving sql socket id: 28 Wed Jun 29 19:01:31 2016 : Info: [sql_main] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '90:00:4e:3d:fe:a2' ORDER BY id Wed Jun 29 19:01:31 2016 : Info: [sql_main] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '90:00:4e:3d:fe:a2' ORDER BY priority Wed Jun 29 19:01:31 2016 : Debug: rlm_sql (sql_main): Released sql socket id: 28 Wed Jun 29 19:01:31 2016 : Info: [sql_main] User 90:00:4e:3d:fe:a2 not found Wed Jun 29 19:01:31 2016 : Info: ++[sql_main] = notfound Wed Jun 29 19:01:31 2016 : Info: ++[expiration] = noop Wed Jun 29 19:01:31 2016 : Info: ++[logintime] = noop Wed Jun 29 19:01:31 2016 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Wed Jun 29 19:01:31 2016 : Info: ++[pap] = noop Wed Jun 29 19:01:31 2016 : Debug: rlm_sqlcounter: Entering module authorize code Wed Jun 29 19:01:31 2016 : Debug: rlm_sqlcounter: Could not find Check item value pair Wed Jun 29 19:01:31 2016 : Info: ++[expire_on_login] = noop Wed Jun 29 19:01:31 2016 : Info: +} # group authorize = ok Wed Jun 29 19:01:31 2016 : Info: ERROR: No authenticate method (Auth-Type) found for the request: Rejecting the user Wed Jun 29 19:01:31 2016 : Info: Failed to authenticate the user. Wed Jun 29 19:01:31 2016 : Info: Using Post-Auth-Type REJECT Wed Jun 29 19:01:31 2016 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Wed Jun 29 19:01:31 2016 : Info: +group REJECT { Wed Jun 29 19:01:31 2016 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 90:00:4e:3d:fe:a2 Wed Jun 29 19:01:31 2016 : Debug: attr_filter: Matched entry DEFAULT at line 11 Wed Jun 29 19:01:31 2016 : Info: ++[attr_filter.access_reject] = updated Wed Jun 29 19:01:31 2016 : Info: +} # group REJECT = updated Sending Access-Reject of id 111 to 10.25.17.2 port 32770 Wed Jun 29 19:01:31 2016 : Info: Finished request 0. Wed Jun 29 19:01:31 2016 : Debug: Going to the next request Wed Jun 29 19:01:31 2016 : Debug: Waking up in 4.9 seconds. Wed Jun 29 19:01:36 2016 : Info: Cleaning up request 0 ID 111 with timestamp +24 Wed Jun 29 19:01:36 2016 : Info: Ready to process requests. -- С уважением, Бирюк Степан Ведущий программист Компьютерного центра Сочинский институт РУДН