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.