update request noop
saturn
saturn at rudn-sochi.ru
Thu Jun 30 07:54:36 CEST 2016
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 at 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 at 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 at 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.
--
С уважением,
Бирюк Степан
Ведущий программист Компьютерного центра
Сочинский институт РУДН
More information about the Freeradius-Users
mailing list