FreeRadius Authorizing and Authenticating Anyone if One User Logs in
Lennon Mazonde
lmmazonde at gmail.com
Thu Mar 27 20:42:30 CET 2014
Hi Everyone,
Newbie here. I am running freeradius administered via daloradius with
coovachilli for my captive portal. My problem is that if one user logs
in (via the captive portal), freeradius is granting access to any user.
In other words, anyone who logs in after the first user doesn't get
redirected to the captive portal, they simply gain (free) access. If any
one user logs out of the session, again all the other users are logged
out. I've looked at the freeradius debug output, but i can't see
anything out of the ordinary, perhaps i'm not looking in the right
places? Please help me :-(
Output from freeradius -XXX:
Thu Mar 27 21:33:31 2014 : Info: FreeRADIUS Version 2.1.10, for host
x86_64-pc-l inux-gnu, built on Feb 24 2014 at 15:16:50
Thu Mar 27 21:33:31 2014 : Info: Copyright (C) 1999-2009 The FreeRADIUS
server p roject and contributors.
Thu Mar 27 21:33:31 2014 : Info: There is NO warranty; not even for
MERCHANTABIL ITY or FITNESS FOR A
Thu Mar 27 21:33:31 2014 : Info: PARTICULAR PURPOSE.
Thu Mar 27 21:33:31 2014 : Info: You may redistribute copies of
FreeRADIUS under the terms of the
Thu Mar 27 21:33:31 2014 : Info: GNU General Public License v2.
Thu Mar 27 21:33:31 2014 : Info: Starting - reading configuration files ...
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/r adiusd.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/p roxy.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/c lients.conf
Thu Mar 27 21:33:31 2014 : Debug: including files in directory
/etc/freeradius/m odules/
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/exec
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/mac2ip
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/cui
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/detail.log
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/digest
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/files
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/counter
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/checkval
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/attr_filter
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/passwd
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/acct_unique
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/krb5
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/sradutmp
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/chap
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/mschap
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/preprocess
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/ldap
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/ippool
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/opendirectory
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/inner-eap
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/logintime
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/mac2vlan
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/smsotp
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/sql_log
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/attr_rewrite
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/otp
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/wimax
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/linelog
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/pam
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/echo
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/pap
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/dynamic_clients
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/etc_group
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/policy
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/expiration
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/smbpasswd
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/perl
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/detail
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/realm
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/sqlcounter_expire_on_login
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/always
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/expr
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/unix
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/detail.example.com
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/ntlm_auth
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/m odules/radutmp
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/e ap.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/s ql.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/s ql/mysql/dialup.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/s ql/mysql/counter.conf
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/p olicy.conf
Thu Mar 27 21:33:31 2014 : Debug: including files in directory
/etc/freeradius/s ites-enabled/
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/s ites-enabled/inner-tunnel
Thu Mar 27 21:33:31 2014 : Debug: including configuration file
/etc/freeradius/s ites-enabled/default
Thu Mar 27 21:33:31 2014 : Debug: main {
Thu Mar 27 21:33:31 2014 : Debug: user = "freerad"
Thu Mar 27 21:33:31 2014 : Debug: group = "freerad"
Thu Mar 27 21:33:31 2014 : Debug: allow_core_dumps = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: including dictionary file
/etc/freeradius/dict ionary
Thu Mar 27 21:33:31 2014 : Debug: main {
Thu Mar 27 21:33:31 2014 : Debug: prefix = "/usr"
Thu Mar 27 21:33:31 2014 : Debug: localstatedir = "/var"
Thu Mar 27 21:33:31 2014 : Debug: logdir = "/var/log/freeradius"
Thu Mar 27 21:33:31 2014 : Debug: libdir = "/usr/lib/freeradius"
Thu Mar 27 21:33:31 2014 : Debug: radacctdir =
"/var/log/freeradius/radacc t"
Thu Mar 27 21:33:31 2014 : Debug: hostname_lookups = no
Thu Mar 27 21:33:31 2014 : Debug: max_request_time = 30
Thu Mar 27 21:33:31 2014 : Debug: cleanup_delay = 5
Thu Mar 27 21:33:31 2014 : Debug: max_requests = 1024
Thu Mar 27 21:33:31 2014 : Debug: pidfile =
"/var/run/freeradius/freeradiu s.pid"
Thu Mar 27 21:33:31 2014 : Debug: checkrad = "/usr/sbin/checkrad"
Thu Mar 27 21:33:31 2014 : Debug: debug_level = 0
Thu Mar 27 21:33:31 2014 : Debug: proxy_requests = yes
Thu Mar 27 21:33:31 2014 : Debug: log {
Thu Mar 27 21:33:31 2014 : Debug: stripped_names = no
Thu Mar 27 21:33:31 2014 : Debug: auth = no
Thu Mar 27 21:33:31 2014 : Debug: auth_badpass = no
Thu Mar 27 21:33:31 2014 : Debug: auth_goodpass = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: security {
Thu Mar 27 21:33:31 2014 : Debug: max_attributes = 200
Thu Mar 27 21:33:31 2014 : Debug: reject_delay = 1
Thu Mar 27 21:33:31 2014 : Debug: status_server = yes
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Thu Mar 27 21:33:31 2014 : Debug: proxy server {
Thu Mar 27 21:33:31 2014 : Debug: retry_delay = 5
Thu Mar 27 21:33:31 2014 : Debug: retry_count = 3
Thu Mar 27 21:33:31 2014 : Debug: default_fallback = no
Thu Mar 27 21:33:31 2014 : Debug: dead_time = 120
Thu Mar 27 21:33:31 2014 : Debug: wake_all_if_all_dead = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: home_server localhost {
Thu Mar 27 21:33:31 2014 : Debug: ipaddr = 127.0.0.1
Thu Mar 27 21:33:31 2014 : Debug: port = 1812
Thu Mar 27 21:33:31 2014 : Debug: type = "auth"
Thu Mar 27 21:33:31 2014 : Debug: secret = "testing123"
Thu Mar 27 21:33:31 2014 : Debug: response_window = 20
Thu Mar 27 21:33:31 2014 : Debug: max_outstanding = 65536
Thu Mar 27 21:33:31 2014 : Debug: require_message_authenticator = yes
Thu Mar 27 21:33:31 2014 : Debug: zombie_period = 40
Thu Mar 27 21:33:31 2014 : Debug: status_check = "status-server"
Thu Mar 27 21:33:31 2014 : Debug: ping_interval = 30
Thu Mar 27 21:33:31 2014 : Debug: check_interval = 30
Thu Mar 27 21:33:31 2014 : Debug: num_answers_to_alive = 3
Thu Mar 27 21:33:31 2014 : Debug: num_pings_to_alive = 3
Thu Mar 27 21:33:31 2014 : Debug: revive_interval = 120
Thu Mar 27 21:33:31 2014 : Debug: status_check_timeout = 4
Thu Mar 27 21:33:31 2014 : Debug: irt = 2
Thu Mar 27 21:33:31 2014 : Debug: mrt = 16
Thu Mar 27 21:33:31 2014 : Debug: mrc = 5
Thu Mar 27 21:33:31 2014 : Debug: mrd = 30
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: home_server_pool my_auth_failover {
Thu Mar 27 21:33:31 2014 : Debug: type = fail-over
Thu Mar 27 21:33:31 2014 : Debug: home_server = localhost
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: realm example.com {
Thu Mar 27 21:33:31 2014 : Debug: auth_pool = my_auth_failover
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: realm LOCAL {
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: radiusd: #### Loading Clients ####
Thu Mar 27 21:33:31 2014 : Debug: client localhost {
Thu Mar 27 21:33:31 2014 : Debug: ipaddr = 127.0.0.1
Thu Mar 27 21:33:31 2014 : Debug: require_message_authenticator = no
Thu Mar 27 21:33:31 2014 : Debug: secret = "testing123"
Thu Mar 27 21:33:31 2014 : Debug: nastype = "other"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: radiusd: #### Instantiating modules ####
Thu Mar 27 21:33:31 2014 : Debug: instantiate {
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_exec, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_exec
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "exec"
from file /etc/freeradius/modules/exec
Thu Mar 27 21:33:31 2014 : Debug: exec {
Thu Mar 27 21:33:31 2014 : Debug: wait = no
Thu Mar 27 21:33:31 2014 : Debug: input_pairs = "request"
Thu Mar 27 21:33:31 2014 : Debug: shell_escape = yes
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_expr, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_expr
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "expr"
from file /etc/freeradius/modules/expr
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_expiration, checking
if it's v alid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_expiration
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"expiration" fro m file /etc/freeradius/modules/expiration
Thu Mar 27 21:33:31 2014 : Debug: expiration {
Thu Mar 27 21:33:31 2014 : Debug: reply-message = "Password Has
Expired "
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_logintime, checking if
it's va lid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_logintime
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"logintime" from file /etc/freeradius/modules/logintime
Thu Mar 27 21:33:31 2014 : Debug: logintime {
Thu Mar 27 21:33:31 2014 : Debug: reply-message = "You are calling
outside your allowed timespan "
Thu Mar 27 21:33:31 2014 : Debug: minimum-timeout = 60
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_sqlcounter, checking
if it's v alid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_sqlcounter
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"chillispot_max_ bytes" from file /etc/freeradius/sql/mysql/counter.conf
Thu Mar 27 21:33:31 2014 : Debug: sqlcounter chillispot_max_bytes {
Thu Mar 27 21:33:31 2014 : Debug: counter-name =
"ChilliSpot-Max-Total-Oct ets"
Thu Mar 27 21:33:31 2014 : Debug: check-name =
"ChilliSpot-Max-Total-Octet s"
Thu Mar 27 21:33:31 2014 : Debug: reply-name =
"ChilliSpot-Max-Total-Octet s"
Thu Mar 27 21:33:31 2014 : Debug: key = "User-Name"
Thu Mar 27 21:33:31 2014 : Debug: sqlmod-inst = "sql"
Thu Mar 27 21:33:31 2014 : Debug: query = "SELECT
SUM(AcctInputOctets) + S UM(AcctOutputOctets) FROM radacct WHERE
UserName='%{%k'"
Thu Mar 27 21:33:31 2014 : Debug: reset = "never"
Thu Mar 27 21:33:31 2014 : Debug: safe-characters =
"@abcdefghijklmnopqrst uvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Reply attribute
ChilliSpot-Max -Total-Octets is number 954138627
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Counter attribute
ChilliSpot-M ax-Total-Octets is number 954138627
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Check attribute
ChilliSpot-Max -Total-Octets is number 954138627
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Current Time:
1395948811 [2014 -03-27 21:33:31], Next reset 0 [2014-03-27 21:00:00]
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Current Time:
1395948811 [2014 -03-27 21:33:31], Prev reset 0 [2014-03-27 21:00:00]
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"noresetcounter" from file /etc/freeradius/sql/mysql/counter.conf
Thu Mar 27 21:33:31 2014 : Debug: sqlcounter noresetcounter {
Thu Mar 27 21:33:31 2014 : Debug: counter-name =
"Max-All-Session-Time"
Thu Mar 27 21:33:31 2014 : Debug: check-name = "Max-All-Session"
Thu Mar 27 21:33:31 2014 : Debug: key = "User-Name"
Thu Mar 27 21:33:31 2014 : Debug: sqlmod-inst = "sql"
Thu Mar 27 21:33:31 2014 : Debug: query = "SELECT
IFNULL(SUM(AcctSessionTi me),0) FROM radacct WHERE UserName='%{%k}'"
Thu Mar 27 21:33:31 2014 : Debug: reset = "never"
Thu Mar 27 21:33:31 2014 : Debug: safe-characters =
"@abcdefghijklmnopqrst uvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Reply attribute set to
Session -Timeout.
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Counter attribute
Max-All-Sess ion-Time is number 11273
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Check attribute
Max-All-Sessio n is number 11274
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Current Time:
1395948811 [2014 -03-27 21:33:31], Next reset 0 [2014-03-27 21:00:00]
Thu Mar 27 21:33:31 2014 : Debug: rlm_sqlcounter: Current Time:
1395948811 [2014 -03-27 21:33:31], Prev reset 0 [2014-03-27 21:00:00]
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: radiusd: #### Loading Virtual Servers ####
Thu Mar 27 21:33:31 2014 : Debug: server inner-tunnel { # from file
/etc/freerad ius/sites-enabled/inner-tunnel
Thu Mar 27 21:33:31 2014 : Debug: modules {
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking authenticate {...}
for more modules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_pap, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_pap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "pap"
from file /etc/freeradius/modules/pap
Thu Mar 27 21:33:31 2014 : Debug: pap {
Thu Mar 27 21:33:31 2014 : Debug: encryption_scheme = "auto"
Thu Mar 27 21:33:31 2014 : Debug: auto_header = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_chap, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_chap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "chap"
from file /etc/freeradius/modules/chap
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_mschap, checking if
it's valid )
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_mschap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "mschap"
from fi le /etc/freeradius/modules/mschap
Thu Mar 27 21:33:31 2014 : Debug: mschap {
Thu Mar 27 21:33:31 2014 : Debug: use_mppe = yes
Thu Mar 27 21:33:31 2014 : Debug: require_encryption = no
Thu Mar 27 21:33:31 2014 : Debug: require_strong = no
Thu Mar 27 21:33:31 2014 : Debug: with_ntdomain_hack = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_unix, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_unix
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "unix"
from file /etc/freeradius/modules/unix
Thu Mar 27 21:33:31 2014 : Debug: unix {
Thu Mar 27 21:33:31 2014 : Debug: radwtmp =
"/var/log/freeradius/radwtmp"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_eap, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_eap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "eap"
from file /etc/freeradius/eap.conf
Thu Mar 27 21:33:31 2014 : Debug: eap {
Thu Mar 27 21:33:31 2014 : Debug: default_eap_type = "md5"
Thu Mar 27 21:33:31 2014 : Debug: timer_expire = 60
Thu Mar 27 21:33:31 2014 : Debug: ignore_unknown_eap_types = no
Thu Mar 27 21:33:31 2014 : Debug: cisco_accounting_username_bug = no
Thu Mar 27 21:33:31 2014 : Debug: max_sessions = 4096
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_md5
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-md5
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_leap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-leap
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_gtc
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-gtc
Thu Mar 27 21:33:31 2014 : Debug: gtc {
Thu Mar 27 21:33:31 2014 : Debug: challenge = "Password: "
Thu Mar 27 21:33:31 2014 : Debug: auth_type = "PAP"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_tls
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-tls
Thu Mar 27 21:33:31 2014 : Debug: tls {
Thu Mar 27 21:33:31 2014 : Debug: rsa_key_exchange = no
Thu Mar 27 21:33:31 2014 : Debug: dh_key_exchange = yes
Thu Mar 27 21:33:31 2014 : Debug: rsa_key_length = 512
Thu Mar 27 21:33:31 2014 : Debug: dh_key_length = 512
Thu Mar 27 21:33:31 2014 : Debug: verify_depth = 0
Thu Mar 27 21:33:31 2014 : Debug: CA_path = "/etc/freeradius/certs"
Thu Mar 27 21:33:31 2014 : Debug: pem_file_type = yes
Thu Mar 27 21:33:31 2014 : Debug: private_key_file =
"/etc/freeradius/cert s/server.key"
Thu Mar 27 21:33:31 2014 : Debug: certificate_file =
"/etc/freeradius/cert s/server.pem"
Thu Mar 27 21:33:31 2014 : Debug: CA_file =
"/etc/freeradius/certs/ca.pem"
Thu Mar 27 21:33:31 2014 : Debug: private_key_password = "whatever"
Thu Mar 27 21:33:31 2014 : Debug: dh_file = "/etc/freeradius/certs/dh"
Thu Mar 27 21:33:31 2014 : Debug: random_file = "/dev/urandom"
Thu Mar 27 21:33:31 2014 : Debug: fragment_size = 1024
Thu Mar 27 21:33:31 2014 : Debug: include_length = yes
Thu Mar 27 21:33:31 2014 : Debug: check_crl = no
Thu Mar 27 21:33:31 2014 : Debug: cipher_list = "DEFAULT"
Thu Mar 27 21:33:31 2014 : Debug: make_cert_command =
"/etc/freeradius/cer ts/bootstrap"
Thu Mar 27 21:33:31 2014 : Debug: cache {
Thu Mar 27 21:33:31 2014 : Debug: enable = no
Thu Mar 27 21:33:31 2014 : Debug: lifetime = 24
Thu Mar 27 21:33:31 2014 : Debug: max_entries = 255
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: verify {
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_ttls
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-ttls
Thu Mar 27 21:33:31 2014 : Debug: ttls {
Thu Mar 27 21:33:31 2014 : Debug: default_eap_type = "md5"
Thu Mar 27 21:33:31 2014 : Debug: copy_request_to_tunnel = no
Thu Mar 27 21:33:31 2014 : Debug: use_tunneled_reply = no
Thu Mar 27 21:33:31 2014 : Debug: virtual_server = "inner-tunnel"
Thu Mar 27 21:33:31 2014 : Debug: include_length = yes
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module rlm_eap_peap
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-peap
Thu Mar 27 21:33:31 2014 : Debug: peap {
Thu Mar 27 21:33:31 2014 : Debug: default_eap_type = "mschapv2"
Thu Mar 27 21:33:31 2014 : Debug: copy_request_to_tunnel = no
Thu Mar 27 21:33:31 2014 : Debug: use_tunneled_reply = no
Thu Mar 27 21:33:31 2014 : Debug: proxy_tunneled_request_as_eap = yes
Thu Mar 27 21:33:31 2014 : Debug: virtual_server = "inner-tunnel"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to sub-module
rlm_eap_mschapv2
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating eap-mschapv2
Thu Mar 27 21:33:31 2014 : Debug: mschapv2 {
Thu Mar 27 21:33:31 2014 : Debug: with_ntdomain_hack = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking authorize {...} for
more mod ules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_realm, checking if
it's valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_realm
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "suffix"
from fi le /etc/freeradius/modules/realm
Thu Mar 27 21:33:31 2014 : Debug: realm suffix {
Thu Mar 27 21:33:31 2014 : Debug: format = "suffix"
Thu Mar 27 21:33:31 2014 : Debug: delimiter = "@"
Thu Mar 27 21:33:31 2014 : Debug: ignore_default = no
Thu Mar 27 21:33:31 2014 : Debug: ignore_null = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_files, checking if
it's valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_files
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "files"
from fil e /etc/freeradius/modules/files
Thu Mar 27 21:33:31 2014 : Debug: files {
Thu Mar 27 21:33:31 2014 : Debug: usersfile = "/etc/freeradius/users"
Thu Mar 27 21:33:31 2014 : Debug: acctusersfile =
"/etc/freeradius/acct_us ers"
Thu Mar 27 21:33:31 2014 : Debug: preproxy_usersfile =
"/etc/freeradius/pr eproxy_users"
Thu Mar 27 21:33:31 2014 : Debug: compat = "no"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking session {...} for
more modul es to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_radutmp, checking if
it's vali d)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_radutmp
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"radutmp" from f ile /etc/freeradius/modules/radutmp
Thu Mar 27 21:33:31 2014 : Debug: radutmp {
Thu Mar 27 21:33:31 2014 : Debug: filename =
"/var/log/freeradius/radutmp"
Thu Mar 27 21:33:31 2014 : Debug: username = "%{User-Name}"
Thu Mar 27 21:33:31 2014 : Debug: case_sensitive = yes
Thu Mar 27 21:33:31 2014 : Debug: check_with_nas = yes
Thu Mar 27 21:33:31 2014 : Debug: perm = 384
Thu Mar 27 21:33:31 2014 : Debug: callerid = yes
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking post-proxy {...} for
more mo dules to load
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking post-auth {...} for
more mod ules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_attr_filter, checking
if it's valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_attr_filter
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"attr_filter.acc ess_reject" from file /etc/freeradius/modules/attr_filter
Thu Mar 27 21:33:31 2014 : Debug: attr_filter attr_filter.access_reject {
Thu Mar 27 21:33:31 2014 : Debug: attrsfile =
"/etc/freeradius/attrs.acces s_reject"
Thu Mar 27 21:33:31 2014 : Debug: key = "%{User-Name}"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: } # modules
Thu Mar 27 21:33:31 2014 : Debug: } # server
Thu Mar 27 21:33:31 2014 : Debug: server { # from file
/etc/freeradius/radiusd.c onf
Thu Mar 27 21:33:31 2014 : Debug: modules {
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking authenticate {...}
for more modules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_digest, checking if
it's valid )
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_digest
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "digest"
from fi le /etc/freeradius/modules/digest
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking authorize {...} for
more mod ules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_preprocess, checking
if it's v alid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_preprocess
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"preprocess" fro m file /etc/freeradius/modules/preprocess
Thu Mar 27 21:33:31 2014 : Debug: preprocess {
Thu Mar 27 21:33:31 2014 : Debug: huntgroups =
"/etc/freeradius/huntgroups "
Thu Mar 27 21:33:31 2014 : Debug: hints = "/etc/freeradius/hints"
Thu Mar 27 21:33:31 2014 : Debug: with_ascend_hack = no
Thu Mar 27 21:33:31 2014 : Debug: ascend_channels_per_line = 23
Thu Mar 27 21:33:31 2014 : Debug: with_ntdomain_hack = no
Thu Mar 27 21:33:31 2014 : Debug: with_specialix_jetstream_hack = no
Thu Mar 27 21:33:31 2014 : Debug: with_cisco_vsa_hack = no
Thu Mar 27 21:33:31 2014 : Debug: with_alvarion_vsa_hack = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_sql, checking if it's
valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_sql
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "sql"
from file /etc/freeradius/sql.conf
Thu Mar 27 21:33:31 2014 : Debug: sql {
Thu Mar 27 21:33:31 2014 : Debug: driver = "rlm_sql_mysql"
Thu Mar 27 21:33:31 2014 : Debug: server = "localhost"
Thu Mar 27 21:33:31 2014 : Debug: port = ""
Thu Mar 27 21:33:31 2014 : Debug: login = "radius"
Thu Mar 27 21:33:31 2014 : Debug: password = "radpass"
Thu Mar 27 21:33:31 2014 : Debug: radius_db = "radius"
Thu Mar 27 21:33:31 2014 : Debug: read_groups = yes
Thu Mar 27 21:33:31 2014 : Debug: sqltrace = no
Thu Mar 27 21:33:31 2014 : Debug: sqltracefile =
"/var/log/freeradius/sqlt race.sql"
Thu Mar 27 21:33:31 2014 : Debug: readclients = no
Thu Mar 27 21:33:31 2014 : Debug: deletestalesessions = yes
Thu Mar 27 21:33:31 2014 : Debug: num_sql_socks = 5
Thu Mar 27 21:33:31 2014 : Debug: lifetime = 0
Thu Mar 27 21:33:31 2014 : Debug: max_queries = 0
Thu Mar 27 21:33:31 2014 : Debug: sql_user_name = "%{User-Name}"
Thu Mar 27 21:33:31 2014 : Debug: default_user_profile = ""
Thu Mar 27 21:33:31 2014 : Debug: nas_query = "SELECT id, nasname,
shortna me, type, secret, server FROM nas"
Thu Mar 27 21:33:31 2014 : Debug: authorize_check_query = "SELECT
id, user name, attribute, value, op FROM radcheck
WHERE username = '% {SQL-User-Name}' ORDER BY id"
Thu Mar 27 21:33:31 2014 : Debug: authorize_reply_query = "SELECT
id, user name, attribute, value, op FROM radreply
WHERE username = '% {SQL-User-Name}' ORDER BY id"
Thu Mar 27 21:33:31 2014 : Debug: authorize_group_check_query =
"SELECT id , groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id"
Thu Mar 27 21:33:31 2014 : Debug: authorize_group_reply_query =
"SELECT id , groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id"
Thu Mar 27 21:33:31 2014 : Debug: accounting_onoff_query = " UPDA
TE radacct SET acctstoptime = '%S', a
cctsessiontime = unix_timestamp('%S') - u
nix_timestamp(acctstarttime), acctterminatecause =
'%{Acct-Termina te-Cause}', acctstopdelay =
%{%{Acct-Delay-Time}:-0} WHERE acctstoptime IS NULL AND
nasipaddress = '%{NAS-IP-Addres s}' AND acctstarttime
<= '%S'"
Thu Mar 27 21:33:31 2014 : Debug: accounting_update_query = " UP
DATE radacct SET framedipaddress =
'%{Framed-IP-Address}' , acctsessiontime =
'%{Acct-Session-Time}', acctin putoctets =
'%{%{Acct-Input-Gigawords}:-0}' << 32 |
'%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{
%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Ac
ct-Output-Octets}:-0}' WHERE acctsessionid =
'%{Acct-Session-Id}' AND username = '%{SQL-User-Name}'
AND nasipaddress = ' %{NAS-IP-Address}'"
Thu Mar 27 21:33:31 2014 : Debug: accounting_update_query_alt = "
INSERT INTO radacct (acctsessionid, acctuniqueid, username
, realm, nasipaddress, nasportid, nasp
orttype, acctstarttime, acctsessiontime, acctauthentic,
connectinfo_start, acctinputoctets, acctoutputoctets,
calledstatio nid, callingstationid, servicetype,
framedprotocol, frame dipaddress, acctstartdelay,
xascendsessionsvrkey) VALUE S ('%{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} + %{%{Ac
ct-Delay-Time}:-0}) SECOND), '%{Acct-Session-Time}',
'%{Acct-Authentic}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32
| '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-G
igawords}:-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}')"
Thu Mar 27 21:33:31 2014 : Debug: accounting_start_query = " INS
ERT INTO radacct (acctsessionid, acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype ,
acctstarttime, acctstoptime, acctsessiontime, acctauthen tic,
connectinfo_start, connectinfo_stop, acctinputoctets, acct
outputoctets, calledstationid, callingstationid,
acctterminatecaus e, 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-Protoco l}', '%{Framed-IP-Address}',
'%{%{Acct-Delay-Time}:-0}', '0', '%{X- Ascend-Session-Svr-Key}')"
Thu Mar 27 21:33:31 2014 : Debug: accounting_start_query_alt = "
UPDATE radacct SET acctstarttime = '%S', acctstar
tdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Conn
ect-Info}' WHERE acctsessionid =
'%{Acct-Session-Id}' AND u sername =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP- Address}'"
Thu Mar 27 21:33:31 2014 : Debug: accounting_stop_query = " UPDA
TE radacct SET acctstoptime = '%S', acctsessiont
ime = '%{Acct-Session-Time}', acctinputoctets =
'%{%{Acct-Inp ut-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Oct
ets}:-0}', acctoutputoctets =
'%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}',
acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay =
'%{%{Acct-Delay-Time}:-0}', connectinfo_stop =
'%{Connect-I nfo}' WHERE acctsessionid =
'%{Acct-Session-Id}' AND usern ame =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Ad dress}'"
Thu Mar 27 21:33:31 2014 : Debug: accounting_stop_query_alt = "
INSERT INTO radacct (acctsessionid, acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype, acctstarttime,
ac ctstoptime, acctsessiontime, acctauthentic,
connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets,
calle dstationid, callingstationid, acctterminatecause, servicetype,
fram edprotocol, 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-Tim e}:-0}) SECOND), '%S',
'%{Acct-Session-Time}', '%{Acct-Authentic}', '',
'%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0} ' << 32 |
'%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Outp ut-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '%{Acct-Termin ate-Cause}',
'%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-
Address}', '0', '%{%{Acct-Delay-Time}:-0}')"
Thu Mar 27 21:33:31 2014 : Debug: group_membership_query = "SELECT
groupna me FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority"
Thu Mar 27 21:33:31 2014 : Debug: connect_failure_retry_delay = 60
Thu Mar 27 21:33:31 2014 : Debug: simul_count_query = ""
Thu Mar 27 21:33:31 2014 : Debug: simul_verify_query = "SELECT
radacctid, acctsessionid, username, nasipaddress, nasportid,
framedipaddress, callingstationid,
framedprotoco l FROM radacct WHE RE
username = '%{SQL-User-Name}' AND
acctstoptime IS NULL"
Thu Mar 27 21:33:31 2014 : Debug: postauth_query = "INSERT INTO
radpostaut h (username, pass, reply, authdate)
VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply :Packet-Type}', '%S')"
Thu Mar 27 21:33:31 2014 : Debug: safe-characters =
"@abcdefghijklmnopqrst uvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Driver rlm_sql_mysql
(module rlm _sql_mysql) loaded and linked
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect to
radius@ localhost:/radius
Thu Mar 27 21:33:31 2014 : Debug: rlm_sql (sql): starting 0
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect
rlm_sql_my sql #0
Thu Mar 27 21:33:31 2014 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Connected new DB handle, #0
Thu Mar 27 21:33:31 2014 : Debug: rlm_sql (sql): starting 1
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect
rlm_sql_my sql #1
Thu Mar 27 21:33:31 2014 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #1
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Connected new DB handle, #1
Thu Mar 27 21:33:31 2014 : Debug: rlm_sql (sql): starting 2
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect
rlm_sql_my sql #2
Thu Mar 27 21:33:31 2014 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #2
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Connected new DB handle, #2
Thu Mar 27 21:33:31 2014 : Debug: rlm_sql (sql): starting 3
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect
rlm_sql_my sql #3
Thu Mar 27 21:33:31 2014 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #3
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Connected new DB handle, #3
Thu Mar 27 21:33:31 2014 : Debug: rlm_sql (sql): starting 4
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Attempting to connect
rlm_sql_my sql #4
Thu Mar 27 21:33:31 2014 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Thu Mar 27 21:33:31 2014 : Info: rlm_sql (sql): Connected new DB handle, #4
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking preacct {...} for
more modul es to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_acct_unique, checking
if it's valid)
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_acct_unique
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"acct_unique" fr om file /etc/freeradius/modules/acct_unique
Thu Mar 27 21:33:31 2014 : Debug: acct_unique {
Thu Mar 27 21:33:31 2014 : Debug: key = "User-Name,
Acct-Session-Id, NAS-I P-Address, Client-IP-Address, NAS-Port"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking accounting {...} for
more mo dules to load
Thu Mar 27 21:33:31 2014 : Debug: (Loaded rlm_detail, checking if
it's valid )
Thu Mar 27 21:33:31 2014 : Debug: Module: Linked to module rlm_detail
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module "detail"
from fi le /etc/freeradius/modules/detail
Thu Mar 27 21:33:31 2014 : Debug: detail {
Thu Mar 27 21:33:31 2014 : Debug: detailfile =
"/var/log/freeradius/radacc t/%{Client-IP-Address}/detail-%Y%m%d"
Thu Mar 27 21:33:31 2014 : Debug: header = "%t"
Thu Mar 27 21:33:31 2014 : Debug: detailperm = 384
Thu Mar 27 21:33:31 2014 : Debug: dirperm = 493
Thu Mar 27 21:33:31 2014 : Debug: locking = no
Thu Mar 27 21:33:31 2014 : Debug: log_packet_header = no
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Instantiating module
"attr_filter.acc ounting_response" from file
/etc/freeradius/modules/attr_filter
Thu Mar 27 21:33:31 2014 : Debug: attr_filter
attr_filter.accounting_response {
Thu Mar 27 21:33:31 2014 : Debug: attrsfile =
"/etc/freeradius/attrs.accou nting_response"
Thu Mar 27 21:33:31 2014 : Debug: key = "%{User-Name}"
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking session {...} for
more modul es to load
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking post-proxy {...} for
more mo dules to load
Thu Mar 27 21:33:31 2014 : Debug: Module: Checking post-auth {...} for
more mod ules to load
Thu Mar 27 21:33:31 2014 : Debug: } # modules
Thu Mar 27 21:33:31 2014 : Debug: } # server
Thu Mar 27 21:33:31 2014 : Debug: radiusd: #### Opening IP addresses and
Ports # ###
Thu Mar 27 21:33:31 2014 : Debug: listen {
Thu Mar 27 21:33:31 2014 : Debug: type = "auth"
Thu Mar 27 21:33:31 2014 : Debug: ipaddr = *
Thu Mar 27 21:33:31 2014 : Debug: port = 0
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: listen {
Thu Mar 27 21:33:31 2014 : Debug: type = "acct"
Thu Mar 27 21:33:31 2014 : Debug: ipaddr = *
Thu Mar 27 21:33:31 2014 : Debug: port = 0
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: listen {
Thu Mar 27 21:33:31 2014 : Debug: type = "auth"
Thu Mar 27 21:33:31 2014 : Debug: ipaddr = 127.0.0.1
Thu Mar 27 21:33:31 2014 : Debug: port = 18120
Thu Mar 27 21:33:31 2014 : Debug: }
Thu Mar 27 21:33:31 2014 : Debug: Listening on authentication address *
port 181 2
Thu Mar 27 21:33:31 2014 : Debug: Listening on accounting address * port
1813
Thu Mar 27 21:33:31 2014 : Debug: Listening on authentication address
127.0.0.1 port 18120 as server inner-tunnel
Thu Mar 27 21:33:31 2014 : Debug: Listening on proxy address * port 1814
Thu Mar 27 21:33:31 2014 : Info: Ready to process requests.
rad_recv: Accounting-Request packet from host 127.0.0.1 port 39179,
id=59, lengt h=257
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Mar 27 2014 21:35:52 CAT"
User-Name = "test"
Acct-Input-Octets = 101730846
Acct-Output-Octets = 4385914
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 86549
Acct-Output-Packets = 59069
Acct-Session-Time = 12303
Acct-Status-Type = Interim-Update
Acct-Session-Id = "53344d3a00000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
Thu Mar 27 21:35:53 2014 : Info: # Executing section preacct from file
/etc/free radius/sites-enabled/default
Thu Mar 27 21:35:53 2014 : Info: +- entering group preacct {...}
Thu Mar 27 21:35:53 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:35:53 2014 : Info: [acct_unique] Hashing 'NAS-Port =
2,Client-IP-A ddress = 127.0.0.1,NAS-IP-Address =
10.1.0.1,Acct-Session-Id = "53344d3a00000002 ",User-Name = "test"'
Thu Mar 27 21:35:53 2014 : Info: [acct_unique] Acct-Unique-Session-ID =
"7874c3e 20d038361".
Thu Mar 27 21:35:53 2014 : Info: ++[acct_unique] returns ok
Thu Mar 27 21:35:53 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:35:53 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:35:53 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:35:53 2014 : Info: ++[files] returns noop
Thu Mar 27 21:35:53 2014 : Info: # Executing section accounting from
file /etc/f reeradius/sites-enabled/default
Thu Mar 27 21:35:53 2014 : Info: +- entering group accounting {...}
Thu Mar 27 21:35:53 2014 : Info: [detail] expand:
/var/log/freeradius/rada cct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/127.0.0.1/ detail-20140327
Thu Mar 27 21:35:53 2014 : Info: [detail]
/var/log/freeradius/radacct/%{Client-I P-Address}/detail-%Y%m%d expands
to /var/log/freeradius/radacct/127.0.0.1/detail -20140327
Thu Mar 27 21:35:53 2014 : Info: [detail] expand: %t -> Thu Mar 27
21:35:5 3 2014
Thu Mar 27 21:35:53 2014 : Info: ++[detail] returns ok
Thu Mar 27 21:35:53 2014 : Info: ++[unix] returns noop
Thu Mar 27 21:35:53 2014 : Info: [radutmp] expand:
/var/log/freeradius/radu tmp -> /var/log/freeradius/radutmp
Thu Mar 27 21:35:53 2014 : Info: [radutmp] expand: %{User-Name} -> test
Thu Mar 27 21:35:53 2014 : Info: ++[radutmp] returns ok
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:35:53 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: %{Acct-Input-Gigawords} -> 0
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: %{Acct-Input-Octets} ->
10173084 6
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: %{Acct-Output-Gigawords}
-> 0
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: %{Acct-Output-Octets} ->
4385914
Thu Mar 27 21:35:53 2014 : Info: [sql] expand: UPDATE
radacct SET framedipaddress = '%{Framed-IP-Address}', acct
sessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{
%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Ac
ct-Input-Octets}:-0}', acctoutputoctets =
'%{%{Acct-Output-Gigaw ords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-
0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username =
'%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'
-> UPDATE radacct SET framedipaddress = '10.1.
0.7', acctsessiontime = '12303', acctinputoctets = '0'
<< 32 | '101730846', a cctoutputoctets = '0' << 32 | '4385914' WHERE
acctsessionid = '53344d3a00000002' AND username = 'test'
Thu Mar 27 21:35:53 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Thu Mar 27 21:35:53 2014 : Debug: rlm_sql (sql): Released sql socket id: 4
Thu Mar 27 21:35:53 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:35:53 2014 : Info: ++[exec] returns noop
Thu Mar 27 21:35:53 2014 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> test
Thu Mar 27 21:35:53 2014 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Thu Mar 27 21:35:53 2014 : Info: ++[attr_filter.accounting_response]
returns upd ated
Sending Accounting-Response of id 59 to 127.0.0.1 port 39179
Thu Mar 27 21:35:53 2014 : Info: Finished request 0.
Thu Mar 27 21:35:53 2014 : Info: Cleaning up request 0 ID 59 with
timestamp +142
Thu Mar 27 21:35:53 2014 : Debug: Going to the next request
Thu Mar 27 21:35:53 2014 : Info: Ready to process requests.
rad_recv: Accounting-Request packet from host 127.0.0.1 port 39179,
id=60, lengt h=263
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Mar 27 2014 21:37:24 CAT"
User-Name = "test"
Acct-Input-Octets = 101746420
Acct-Output-Octets = 4396684
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 86620
Acct-Output-Packets = 59154
Acct-Session-Time = 12395
Acct-Terminate-Cause = User-Request
Acct-Status-Type = Stop
Acct-Session-Id = "53344d3a00000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
Thu Mar 27 21:37:25 2014 : Info: # Executing section preacct from file
/etc/free radius/sites-enabled/default
Thu Mar 27 21:37:25 2014 : Info: +- entering group preacct {...}
Thu Mar 27 21:37:25 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:37:25 2014 : Info: [acct_unique] Hashing 'NAS-Port =
2,Client-IP-A ddress = 127.0.0.1,NAS-IP-Address =
10.1.0.1,Acct-Session-Id = "53344d3a00000002 ",User-Name = "test"'
Thu Mar 27 21:37:25 2014 : Info: [acct_unique] Acct-Unique-Session-ID =
"7874c3e 20d038361".
Thu Mar 27 21:37:25 2014 : Info: ++[acct_unique] returns ok
Thu Mar 27 21:37:25 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:37:25 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:37:25 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:37:25 2014 : Info: ++[files] returns noop
Thu Mar 27 21:37:25 2014 : Info: # Executing section accounting from
file /etc/f reeradius/sites-enabled/default
Thu Mar 27 21:37:25 2014 : Info: +- entering group accounting {...}
Thu Mar 27 21:37:25 2014 : Info: [detail] expand:
/var/log/freeradius/rada cct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/127.0.0.1/ detail-20140327
Thu Mar 27 21:37:25 2014 : Info: [detail]
/var/log/freeradius/radacct/%{Client-I P-Address}/detail-%Y%m%d expands
to /var/log/freeradius/radacct/127.0.0.1/detail -20140327
Thu Mar 27 21:37:25 2014 : Info: [detail] expand: %t -> Thu Mar 27
21:37:2 5 2014
Thu Mar 27 21:37:25 2014 : Info: ++[detail] returns ok
Thu Mar 27 21:37:25 2014 : Info: ++[unix] returns ok
Thu Mar 27 21:37:25 2014 : Info: [radutmp] expand:
/var/log/freeradius/radu tmp -> /var/log/freeradius/radutmp
Thu Mar 27 21:37:25 2014 : Info: [radutmp] expand: %{User-Name} -> test
Thu Mar 27 21:37:25 2014 : Info: ++[radutmp] returns ok
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:37:25 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{Acct-Input-Gigawords} -> 0
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{Acct-Input-Octets} ->
10174642 0
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{Acct-Output-Gigawords}
-> 0
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{Acct-Output-Octets} ->
4396684
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: %{Acct-Delay-Time} ->
Thu Mar 27 21:37:25 2014 : Info: [sql] ... expanding second conditional
Thu Mar 27 21:37:25 2014 : Info: [sql] expand: 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}', acctterminate cause =
'%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-D
elay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' W
HERE acctsessionid = '%{Acct-Session-Id}' AND
username = '% {SQL-User-Name}' AND nasipaddress
= '%{NAS-IP-Address}' -> UPDATE radacct SET
acctstoptime = '2014-03-27 21:37:25', acctsessiontime =
'12395', acctinputoctets = '0 ' << 32 | '101746420',
acctoutput octets = '0' <
Thu Mar 27 21:37:25 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Thu Mar 27 21:37:25 2014 : Debug: rlm_sql (sql): Released sql socket id: 3
Thu Mar 27 21:37:25 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:37:25 2014 : Info: ++[exec] returns noop
Thu Mar 27 21:37:25 2014 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> test
Thu Mar 27 21:37:25 2014 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Thu Mar 27 21:37:25 2014 : Info: ++[attr_filter.accounting_response]
returns upd ated
Sending Accounting-Response of id 60 to 127.0.0.1 port 39179
Thu Mar 27 21:37:25 2014 : Info: Finished request 1.
Thu Mar 27 21:37:25 2014 : Info: Cleaning up request 1 ID 60 with
timestamp +234
Thu Mar 27 21:37:25 2014 : Debug: Going to the next request
Thu Mar 27 21:37:25 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 46418, id=62,
length=28 7
ChilliSpot-Version = "1.3.0"
User-Name = "test"
CHAP-Challenge = 0x1fd6adcd32331a15a5bc4df75319b0ca
CHAP-Password = 0x00f2f275270c89c401db48362eb9d9ea77
Service-Type = Login-User
Acct-Session-Id = "53347df500000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
WISPr-Logoff-URL = "http://10.1.0.1:3990/logoff"
Message-Authenticator = 0x674721e8457ec33833cc33fe1529be79
Thu Mar 27 21:37:42 2014 : Info: # Executing section authorize from file
/etc/fr eeradius/sites-enabled/default
Thu Mar 27 21:37:42 2014 : Info: +- entering group authorize {...}
Thu Mar 27 21:37:42 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:37:42 2014 : Info: [chap] Setting 'Auth-Type := CHAP'
Thu Mar 27 21:37:42 2014 : Info: ++[chap] returns ok
Thu Mar 27 21:37:42 2014 : Info: ++[mschap] returns noop
Thu Mar 27 21:37:42 2014 : Info: ++[digest] returns noop
Thu Mar 27 21:37:42 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:37:42 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:37:42 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:37:42 2014 : Info: [eap] No EAP-Message, not doing EAP
Thu Mar 27 21:37:42 2014 : Info: ++[eap] returns noop
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:37:42 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:37:42 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: SELECT id, username,
attribute, value, op FROM radcheck WHERE username =
'%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value,
op FRO M radcheck WHERE username = 'test' ORDER BY id
Thu Mar 27 21:37:42 2014 : Info: [sql] User found in radcheck table
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: SELECT id, username,
attribute, value, op FROM radreply WHERE username =
'%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value,
op FRO M radreply WHERE username = 'test' ORDER BY id
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: SELECT groupname FROM
radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY pr
iority -> SELECT groupname FROM radusergroup WHERE username =
'test' ORDER BY priority
Thu Mar 27 21:37:42 2014 : Debug: rlm_sql (sql): Released sql socket id: 2
Thu Mar 27 21:37:42 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:37:42 2014 : Debug: rlm_sqlcounter: Entering module
authorize code
Thu Mar 27 21:37:42 2014 : Debug: rlm_sqlcounter: Could not find Check
item valu e pair
Thu Mar 27 21:37:42 2014 : Info: ++[chillispot_max_bytes] returns noop
Thu Mar 27 21:37:42 2014 : Debug: rlm_sqlcounter: Entering module
authorize code
Thu Mar 27 21:37:42 2014 : Debug: rlm_sqlcounter: Could not find Check
item valu e pair
Thu Mar 27 21:37:42 2014 : Info: ++[noresetcounter] returns noop
Thu Mar 27 21:37:42 2014 : Info: ++[expiration] returns noop
Thu Mar 27 21:37:42 2014 : Info: ++[logintime] returns noop
Thu Mar 27 21:37:42 2014 : Info: [pap] WARNING: Auth-Type already set.
Not sett ing to PAP
Thu Mar 27 21:37:42 2014 : Info: ++[pap] returns noop
Thu Mar 27 21:37:42 2014 : Info: Found Auth-Type = CHAP
Thu Mar 27 21:37:42 2014 : Info: # Executing group from file
/etc/freeradius/sit es-enabled/default
Thu Mar 27 21:37:42 2014 : Info: +- entering group CHAP {...}
Thu Mar 27 21:37:42 2014 : Info: [chap] login attempt by "test" with
CHAP passwo rd
Thu Mar 27 21:37:42 2014 : Info: [chap] Using clear text password "test"
for use r test authentication.
Thu Mar 27 21:37:42 2014 : Info: [chap] chap user test authenticated
succesfully
Thu Mar 27 21:37:42 2014 : Info: ++[chap] returns ok
Thu Mar 27 21:37:42 2014 : Info: # Executing section post-auth from file
/etc/fr eeradius/sites-enabled/default
Thu Mar 27 21:37:42 2014 : Info: +- entering group post-auth {...}
Thu Mar 27 21:37:42 2014 : Info: ++[exec] returns noop
Sending Access-Accept of id 62 to 127.0.0.1 port 46418
Thu Mar 27 21:37:42 2014 : Info: Finished request 2.
Thu Mar 27 21:37:42 2014 : Debug: Going to the next request
Thu Mar 27 21:37:42 2014 : Debug: Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 127.0.0.1 port 39179,
id=61, lengt h=215
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Mar 27 2014 21:37:40 CAT"
User-Name = "test"
Acct-Status-Type = Start
Acct-Session-Id = "53347df500000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
Thu Mar 27 21:37:42 2014 : Info: # Executing section preacct from file
/etc/free radius/sites-enabled/default
Thu Mar 27 21:37:42 2014 : Info: +- entering group preacct {...}
Thu Mar 27 21:37:42 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:37:42 2014 : Info: [acct_unique] Hashing 'NAS-Port =
2,Client-IP-A ddress = 127.0.0.1,NAS-IP-Address =
10.1.0.1,Acct-Session-Id = "53347df500000002 ",User-Name = "test"'
Thu Mar 27 21:37:42 2014 : Info: [acct_unique] Acct-Unique-Session-ID =
"c1c7c7a b5ce9171a".
Thu Mar 27 21:37:42 2014 : Info: ++[acct_unique] returns ok
Thu Mar 27 21:37:42 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:37:42 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:37:42 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:37:42 2014 : Info: ++[files] returns noop
Thu Mar 27 21:37:42 2014 : Info: # Executing section accounting from
file /etc/f reeradius/sites-enabled/default
Thu Mar 27 21:37:42 2014 : Info: +- entering group accounting {...}
Thu Mar 27 21:37:42 2014 : Info: [detail] expand:
/var/log/freeradius/rada cct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/127.0.0.1/ detail-20140327
Thu Mar 27 21:37:42 2014 : Info: [detail]
/var/log/freeradius/radacct/%{Client-I P-Address}/detail-%Y%m%d expands
to /var/log/freeradius/radacct/127.0.0.1/detail -20140327
Thu Mar 27 21:37:42 2014 : Info: [detail] expand: %t -> Thu Mar 27
21:37:4 2 2014
Thu Mar 27 21:37:42 2014 : Info: ++[detail] returns ok
Thu Mar 27 21:37:42 2014 : Info: ++[unix] returns ok
Thu Mar 27 21:37:42 2014 : Info: [radutmp] expand:
/var/log/freeradius/radu tmp -> /var/log/freeradius/radutmp
Thu Mar 27 21:37:42 2014 : Info: [radutmp] expand: %{User-Name} -> test
Thu Mar 27 21:37:42 2014 : Info: ++[radutmp] returns ok
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:37:42 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: %{Acct-Delay-Time} ->
Thu Mar 27 21:37:42 2014 : Info: [sql] ... expanding second conditional
Thu Mar 27 21:37:42 2014 : Info: [sql] expand: INSERT INTO
radacct (acctsessionid, acctuniqueid, username, realm,
nasipaddress, nasportid, nasporttype, acctstartti
me, acctstoptime, acctsessiontime, acctauthentic,
connectinf o_start, connectinfo_stop, acctinputoctets,
acctoutputoctets, calledstationid, callingstationid,
acctterminatecause, se rvicetype, framedprotocol,
framedipaddress, acctstartdelay, acctstopdelay,
xascendsessionsvrkey) VALUES ('%{Acct- Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Por t-Type}', '%S',
NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0',
'0', '%{Called-Station-Id}', '%{Calling-Stati on-Id}',
'', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-
Address}',
Thu Mar 27 21:37:42 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Thu Mar 27 21:37:42 2014 : Debug: rlm_sql (sql): Released sql socket id: 1
Thu Mar 27 21:37:42 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:37:42 2014 : Info: ++[exec] returns noop
Thu Mar 27 21:37:42 2014 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> test
Thu Mar 27 21:37:42 2014 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Thu Mar 27 21:37:42 2014 : Info: ++[attr_filter.accounting_response]
returns upd ated
Sending Accounting-Response of id 61 to 127.0.0.1 port 39179
Thu Mar 27 21:37:42 2014 : Info: Finished request 3.
Thu Mar 27 21:37:42 2014 : Info: Cleaning up request 3 ID 61 with
timestamp +251
Thu Mar 27 21:37:42 2014 : Debug: Going to the next request
Thu Mar 27 21:37:42 2014 : Debug: Waking up in 4.9 seconds.
Thu Mar 27 21:37:47 2014 : Info: Cleaning up request 2 ID 62 with
timestamp +251
Thu Mar 27 21:37:47 2014 : Info: Ready to process requests.
rad_recv: Accounting-Request packet from host 127.0.0.1 port 39179,
id=62, lengt h=263
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Mar 27 2014 21:37:45 CAT"
User-Name = "test"
Acct-Input-Octets = 4994
Acct-Output-Octets = 19869
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 31
Acct-Output-Packets = 36
Acct-Session-Time = 5
Acct-Terminate-Cause = User-Request
Acct-Status-Type = Stop
Acct-Session-Id = "53347df500000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
Thu Mar 27 21:37:47 2014 : Info: # Executing section preacct from file
/etc/free radius/sites-enabled/default
Thu Mar 27 21:37:47 2014 : Info: +- entering group preacct {...}
Thu Mar 27 21:37:47 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:37:47 2014 : Info: [acct_unique] Hashing 'NAS-Port =
2,Client-IP-A ddress = 127.0.0.1,NAS-IP-Address =
10.1.0.1,Acct-Session-Id = "53347df500000002 ",User-Name = "test"'
Thu Mar 27 21:37:47 2014 : Info: [acct_unique] Acct-Unique-Session-ID =
"c1c7c7a b5ce9171a".
Thu Mar 27 21:37:47 2014 : Info: ++[acct_unique] returns ok
Thu Mar 27 21:37:47 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:37:47 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:37:47 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:37:47 2014 : Info: ++[files] returns noop
Thu Mar 27 21:37:47 2014 : Info: # Executing section accounting from
file /etc/f reeradius/sites-enabled/default
Thu Mar 27 21:37:47 2014 : Info: +- entering group accounting {...}
Thu Mar 27 21:37:47 2014 : Info: [detail] expand:
/var/log/freeradius/rada cct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/127.0.0.1/ detail-20140327
Thu Mar 27 21:37:47 2014 : Info: [detail]
/var/log/freeradius/radacct/%{Client-I P-Address}/detail-%Y%m%d expands
to /var/log/freeradius/radacct/127.0.0.1/detail -20140327
Thu Mar 27 21:37:47 2014 : Info: [detail] expand: %t -> Thu Mar 27
21:37:4 7 2014
Thu Mar 27 21:37:47 2014 : Info: ++[detail] returns ok
Thu Mar 27 21:37:47 2014 : Info: ++[unix] returns ok
Thu Mar 27 21:37:47 2014 : Info: [radutmp] expand:
/var/log/freeradius/radu tmp -> /var/log/freeradius/radutmp
Thu Mar 27 21:37:47 2014 : Info: [radutmp] expand: %{User-Name} -> test
Thu Mar 27 21:37:47 2014 : Info: ++[radutmp] returns ok
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:37:47 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{Acct-Input-Gigawords} -> 0
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{Acct-Input-Octets} -> 4994
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{Acct-Output-Gigawords}
-> 0
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{Acct-Output-Octets} ->
19869
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: %{Acct-Delay-Time} ->
Thu Mar 27 21:37:47 2014 : Info: [sql] ... expanding second conditional
Thu Mar 27 21:37:47 2014 : Info: [sql] expand: 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}', acctterminate cause =
'%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-D
elay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' W
HERE acctsessionid = '%{Acct-Session-Id}' AND
username = '% {SQL-User-Name}' AND nasipaddress
= '%{NAS-IP-Address}' -> UPDATE radacct SET
acctstoptime = '2014-03-27 21:37:47', acctsessiontime =
'5', acctinputoctets = '0' << 32
| '4994', acctoutputoctets = '0' << 32 |
Thu Mar 27 21:37:47 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 0
Thu Mar 27 21:37:47 2014 : Debug: rlm_sql (sql): Released sql socket id: 0
Thu Mar 27 21:37:47 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:37:47 2014 : Info: ++[exec] returns noop
Thu Mar 27 21:37:47 2014 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> test
Thu Mar 27 21:37:47 2014 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Thu Mar 27 21:37:47 2014 : Info: ++[attr_filter.accounting_response]
returns upd ated
Sending Accounting-Response of id 62 to 127.0.0.1 port 39179
Thu Mar 27 21:37:47 2014 : Info: Finished request 4.
Thu Mar 27 21:37:47 2014 : Info: Cleaning up request 4 ID 62 with
timestamp +256
Thu Mar 27 21:37:47 2014 : Debug: Going to the next request
Thu Mar 27 21:37:47 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 43771, id=89,
length=28 7
ChilliSpot-Version = "1.3.0"
User-Name = "test"
CHAP-Challenge = 0x1fd6adcd32331a15a5bc4df75319b0ca
CHAP-Password = 0x00f2f275270c89c401db48362eb9d9ea77
Service-Type = Login-User
Acct-Session-Id = "53347e0b00000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
WISPr-Logoff-URL = "http://10.1.0.1:3990/logoff"
Message-Authenticator = 0x8e0995898c93e6afe0dab83ef79781c8
Thu Mar 27 21:38:07 2014 : Info: # Executing section authorize from file
/etc/fr eeradius/sites-enabled/default
Thu Mar 27 21:38:07 2014 : Info: +- entering group authorize {...}
Thu Mar 27 21:38:07 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:38:07 2014 : Info: [chap] Setting 'Auth-Type := CHAP'
Thu Mar 27 21:38:07 2014 : Info: ++[chap] returns ok
Thu Mar 27 21:38:07 2014 : Info: ++[mschap] returns noop
Thu Mar 27 21:38:07 2014 : Info: ++[digest] returns noop
Thu Mar 27 21:38:07 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:38:07 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:38:07 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:38:07 2014 : Info: [eap] No EAP-Message, not doing EAP
Thu Mar 27 21:38:07 2014 : Info: ++[eap] returns noop
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:38:07 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:38:07 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: SELECT id, username,
attribute, value, op FROM radcheck WHERE username =
'%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value,
op FRO M radcheck WHERE username = 'test' ORDER BY id
Thu Mar 27 21:38:07 2014 : Info: [sql] User found in radcheck table
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: SELECT id, username,
attribute, value, op FROM radreply WHERE username =
'%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value,
op FRO M radreply WHERE username = 'test' ORDER BY id
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: SELECT groupname FROM
radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY pr
iority -> SELECT groupname FROM radusergroup WHERE username =
'test' ORDER BY priority
Thu Mar 27 21:38:07 2014 : Debug: rlm_sql (sql): Released sql socket id: 4
Thu Mar 27 21:38:07 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:38:07 2014 : Debug: rlm_sqlcounter: Entering module
authorize code
Thu Mar 27 21:38:07 2014 : Debug: rlm_sqlcounter: Could not find Check
item valu e pair
Thu Mar 27 21:38:07 2014 : Info: ++[chillispot_max_bytes] returns noop
Thu Mar 27 21:38:07 2014 : Debug: rlm_sqlcounter: Entering module
authorize code
Thu Mar 27 21:38:07 2014 : Debug: rlm_sqlcounter: Could not find Check
item valu e pair
Thu Mar 27 21:38:07 2014 : Info: ++[noresetcounter] returns noop
Thu Mar 27 21:38:07 2014 : Info: ++[expiration] returns noop
Thu Mar 27 21:38:07 2014 : Info: ++[logintime] returns noop
Thu Mar 27 21:38:07 2014 : Info: [pap] WARNING: Auth-Type already set.
Not sett ing to PAP
Thu Mar 27 21:38:07 2014 : Info: ++[pap] returns noop
Thu Mar 27 21:38:07 2014 : Info: Found Auth-Type = CHAP
Thu Mar 27 21:38:07 2014 : Info: # Executing group from file
/etc/freeradius/sit es-enabled/default
Thu Mar 27 21:38:07 2014 : Info: +- entering group CHAP {...}
Thu Mar 27 21:38:07 2014 : Info: [chap] login attempt by "test" with
CHAP passwo rd
Thu Mar 27 21:38:07 2014 : Info: [chap] Using clear text password "test"
for use r test authentication.
Thu Mar 27 21:38:07 2014 : Info: [chap] chap user test authenticated
succesfully
Thu Mar 27 21:38:07 2014 : Info: ++[chap] returns ok
Thu Mar 27 21:38:07 2014 : Info: # Executing section post-auth from file
/etc/fr eeradius/sites-enabled/default
Thu Mar 27 21:38:07 2014 : Info: +- entering group post-auth {...}
Thu Mar 27 21:38:07 2014 : Info: ++[exec] returns noop
Sending Access-Accept of id 89 to 127.0.0.1 port 43771
Thu Mar 27 21:38:07 2014 : Info: Finished request 5.
Thu Mar 27 21:38:07 2014 : Debug: Going to the next request
Thu Mar 27 21:38:07 2014 : Debug: Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 127.0.0.1 port 39179,
id=63, lengt h=215
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Mar 27 2014 21:38:06 CAT"
User-Name = "test"
Acct-Status-Type = Start
Acct-Session-Id = "53347e0b00000002"
Framed-IP-Address = 10.1.0.7
NAS-Port-Type = Wireless-802.11
NAS-Port = 2
NAS-Port-Id = "00000002"
Calling-Station-Id = "D8-EB-97-22-A0-8C"
Called-Station-Id = "00-0A-CD-1F-F6-43"
NAS-IP-Address = 10.1.0.1
NAS-Identifier = "nas01"
WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
WISPr-Location-Name = "My_HotSpot"
Thu Mar 27 21:38:07 2014 : Info: # Executing section preacct from file
/etc/free radius/sites-enabled/default
Thu Mar 27 21:38:07 2014 : Info: +- entering group preacct {...}
Thu Mar 27 21:38:07 2014 : Info: ++[preprocess] returns ok
Thu Mar 27 21:38:07 2014 : Info: [acct_unique] Hashing 'NAS-Port =
2,Client-IP-A ddress = 127.0.0.1,NAS-IP-Address =
10.1.0.1,Acct-Session-Id = "53347e0b00000002 ",User-Name = "test"'
Thu Mar 27 21:38:07 2014 : Info: [acct_unique] Acct-Unique-Session-ID =
"1f7c3e3 75e42563b".
Thu Mar 27 21:38:07 2014 : Info: ++[acct_unique] returns ok
Thu Mar 27 21:38:07 2014 : Info: [suffix] No '@' in User-Name = "test",
looking up realm NULL
Thu Mar 27 21:38:07 2014 : Info: [suffix] No such realm "NULL"
Thu Mar 27 21:38:07 2014 : Info: ++[suffix] returns noop
Thu Mar 27 21:38:07 2014 : Info: ++[files] returns noop
Thu Mar 27 21:38:07 2014 : Info: # Executing section accounting from
file /etc/f reeradius/sites-enabled/default
Thu Mar 27 21:38:07 2014 : Info: +- entering group accounting {...}
Thu Mar 27 21:38:07 2014 : Info: [detail] expand:
/var/log/freeradius/rada cct/%{Client-IP-Address}/detail-%Y%m%d ->
/var/log/freeradius/radacct/127.0.0.1/ detail-20140327
Thu Mar 27 21:38:07 2014 : Info: [detail]
/var/log/freeradius/radacct/%{Client-I P-Address}/detail-%Y%m%d expands
to /var/log/freeradius/radacct/127.0.0.1/detail -20140327
Thu Mar 27 21:38:07 2014 : Info: [detail] expand: %t -> Thu Mar 27
21:38:0 7 2014
Thu Mar 27 21:38:07 2014 : Info: ++[detail] returns ok
Thu Mar 27 21:38:07 2014 : Info: ++[unix] returns ok
Thu Mar 27 21:38:07 2014 : Info: [radutmp] expand:
/var/log/freeradius/radu tmp -> /var/log/freeradius/radutmp
Thu Mar 27 21:38:07 2014 : Info: [radutmp] expand: %{User-Name} -> test
Thu Mar 27 21:38:07 2014 : Info: ++[radutmp] returns ok
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: %{User-Name} -> test
Thu Mar 27 21:38:07 2014 : Info: [sql] sql_set_user escaped user --> 'test'
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: %{Acct-Delay-Time} ->
Thu Mar 27 21:38:07 2014 : Info: [sql] ... expanding second conditional
Thu Mar 27 21:38:07 2014 : Info: [sql] expand: INSERT INTO
radacct (acctsessionid, acctuniqueid, username, realm,
nasipaddress, nasportid, nasporttype, acctstartti
me, acctstoptime, acctsessiontime, acctauthentic,
connectinf o_start, connectinfo_stop, acctinputoctets,
acctoutputoctets, calledstationid, callingstationid,
acctterminatecause, se rvicetype, framedprotocol,
framedipaddress, acctstartdelay, acctstopdelay,
xascendsessionsvrkey) VALUES ('%{Acct- Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Por t-Type}', '%S',
NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0',
'0', '%{Called-Station-Id}', '%{Calling-Stati on-Id}',
'', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-
Address}',
Thu Mar 27 21:38:07 2014 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Thu Mar 27 21:38:07 2014 : Debug: rlm_sql (sql): Released sql socket id: 3
Thu Mar 27 21:38:07 2014 : Info: ++[sql] returns ok
Thu Mar 27 21:38:07 2014 : Info: ++[exec] returns noop
Thu Mar 27 21:38:07 2014 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> test
Thu Mar 27 21:38:07 2014 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Thu Mar 27 21:38:07 2014 : Info: ++[attr_filter.accounting_response]
returns upd ated
Sending Accounting-Response of id 63 to 127.0.0.1 port 39179
Thu Mar 27 21:38:07 2014 : Info: Finished request 6.
Thu Mar 27 21:38:07 2014 : Info: Cleaning up request 6 ID 63 with
timestamp +276
Thu Mar 27 21:38:07 2014 : Debug: Going to the next request
Thu Mar 27 21:38:07 2014 : Debug: Waking up in 4.9 seconds.
Thu Mar 27 21:38:12 2014 : Info: Cleaning up request 5 ID 89 with
timestamp +276
Thu Mar 27 21:38:12 2014 : Info: Ready to process requests.
More information about the Freeradius-Users
mailing list