{\rtf1\ansi\ansicpg1252\deff0\deflang1033{\fonttbl{\f0\fswiss\fcharset0 Arial;}} {\*\generator Msftedit 5.41.21.2508;}\viewkind4\uc1\pard\f0\fs20 [root@Etal raddb]# radiusd -XX\par Tue Jun 9 14:56:41 2009 : Info: FreeRADIUS Version 2.1.6, for host i686-pc-linux-gnu, built on May 22 2009 at 21:12:11\par Tue Jun 9 14:56:41 2009 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.\par Tue Jun 9 14:56:41 2009 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A\par Tue Jun 9 14:56:41 2009 : Info: PARTICULAR PURPOSE.\par Tue Jun 9 14:56:41 2009 : Info: You may redistribute copies of FreeRADIUS under the terms of the\par Tue Jun 9 14:56:41 2009 : Info: GNU General Public License v2.\par Tue Jun 9 14:56:41 2009 : Info: Starting - reading configuration files ...\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/clients.conf\par Tue Jun 9 14:56:41 2009 : Debug: including files in directory /usr/local/etc/raddb/modules/\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.example.com\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/pap\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/files\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/preprocess\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/perl\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/inner-eap\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/expiration\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/expr\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/ldap\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/radutmp\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/smsotp\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/logintime\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/wimax\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/counter\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/counter.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_filter\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/smbpasswd\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2ip\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/realm\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/unix\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/exec\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/pam\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/etc_group\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/linelog\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_rewrite\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/chap\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/passwd\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/krb5\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/ippool\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/always\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/digest\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/otp\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mschap\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/acct_unique\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/policy\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sql_log\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.log\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/checkval\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2vlan\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/echo\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sradutmp\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/eap.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sql.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/dialup.conf\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/policy.conf\par Tue Jun 9 14:56:41 2009 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default\par Tue Jun 9 14:56:41 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/control-socket\par Tue Jun 9 14:56:41 2009 : Debug: including dictionary file /usr/local/etc/raddb/dictionary\par Tue Jun 9 14:56:41 2009 : Debug: main \{\par Tue Jun 9 14:56:41 2009 : Debug: prefix = "/usr/local"\par Tue Jun 9 14:56:41 2009 : Debug: localstatedir = "/usr/local/var"\par Tue Jun 9 14:56:41 2009 : Debug: logdir = "/usr/local/var/log/radius"\par Tue Jun 9 14:56:41 2009 : Debug: libdir = "/usr/local/lib"\par Tue Jun 9 14:56:41 2009 : Debug: radacctdir = "/usr/local/var/log/radius/radacct"\par Tue Jun 9 14:56:41 2009 : Debug: hostname_lookups = no\par Tue Jun 9 14:56:41 2009 : Debug: max_request_time = 30\par Tue Jun 9 14:56:41 2009 : Debug: cleanup_delay = 5\par Tue Jun 9 14:56:41 2009 : Debug: max_requests = 1024\par Tue Jun 9 14:56:41 2009 : Debug: allow_core_dumps = no\par Tue Jun 9 14:56:41 2009 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid"\par Tue Jun 9 14:56:41 2009 : Debug: checkrad = "/usr/local/sbin/checkrad"\par Tue Jun 9 14:56:41 2009 : Debug: debug_level = 0\par Tue Jun 9 14:56:41 2009 : Debug: proxy_requests = yes\par Tue Jun 9 14:56:41 2009 : Debug: log \{\par Tue Jun 9 14:56:41 2009 : Debug: stripped_names = no\par Tue Jun 9 14:56:41 2009 : Debug: auth = no\par Tue Jun 9 14:56:41 2009 : Debug: auth_badpass = no\par Tue Jun 9 14:56:41 2009 : Debug: auth_goodpass = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: security \{\par Tue Jun 9 14:56:41 2009 : Debug: max_attributes = 200\par Tue Jun 9 14:56:41 2009 : Debug: reject_delay = 1\par Tue Jun 9 14:56:41 2009 : Debug: status_server = yes\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: radiusd: #### Loading Realms and Home Servers ####\par Tue Jun 9 14:56:41 2009 : Debug: proxy server \{\par Tue Jun 9 14:56:41 2009 : Debug: retry_delay = 5\par Tue Jun 9 14:56:41 2009 : Debug: retry_count = 3\par Tue Jun 9 14:56:41 2009 : Debug: default_fallback = no\par Tue Jun 9 14:56:41 2009 : Debug: dead_time = 120\par Tue Jun 9 14:56:41 2009 : Debug: wake_all_if_all_dead = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: home_server localhost \{\par Tue Jun 9 14:56:41 2009 : Debug: ipaddr = 127.0.0.1\par Tue Jun 9 14:56:41 2009 : Debug: port = 1812\par Tue Jun 9 14:56:41 2009 : Debug: type = "auth"\par Tue Jun 9 14:56:41 2009 : Debug: secret = "testing123"\par Tue Jun 9 14:56:41 2009 : Debug: response_window = 20\par Tue Jun 9 14:56:41 2009 : Debug: max_outstanding = 65536\par Tue Jun 9 14:56:41 2009 : Debug: require_message_authenticator = no\par Tue Jun 9 14:56:41 2009 : Debug: zombie_period = 40\par Tue Jun 9 14:56:41 2009 : Debug: status_check = "status-server"\par Tue Jun 9 14:56:41 2009 : Debug: ping_interval = 30\par Tue Jun 9 14:56:41 2009 : Debug: check_interval = 30\par Tue Jun 9 14:56:41 2009 : Debug: num_answers_to_alive = 3\par Tue Jun 9 14:56:41 2009 : Debug: num_pings_to_alive = 3\par Tue Jun 9 14:56:41 2009 : Debug: revive_interval = 120\par Tue Jun 9 14:56:41 2009 : Debug: status_check_timeout = 4\par Tue Jun 9 14:56:41 2009 : Debug: irt = 2\par Tue Jun 9 14:56:41 2009 : Debug: mrt = 16\par Tue Jun 9 14:56:41 2009 : Debug: mrc = 5\par Tue Jun 9 14:56:41 2009 : Debug: mrd = 30\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: home_server_pool my_auth_failover \{\par Tue Jun 9 14:56:41 2009 : Debug: type = fail-over\par Tue Jun 9 14:56:41 2009 : Debug: home_server = localhost\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: realm example.com \{\par Tue Jun 9 14:56:41 2009 : Debug: auth_pool = my_auth_failover\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: realm LOCAL \{\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: radiusd: #### Loading Clients ####\par Tue Jun 9 14:56:41 2009 : Debug: client localhost \{\par Tue Jun 9 14:56:41 2009 : Debug: ipaddr = 127.0.0.1\par Tue Jun 9 14:56:41 2009 : Debug: require_message_authenticator = no\par Tue Jun 9 14:56:41 2009 : Debug: secret = "testing123"\par Tue Jun 9 14:56:41 2009 : Debug: nastype = "other"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: radiusd: #### Instantiating modules ####\par Tue Jun 9 14:56:41 2009 : Debug: instantiate \{\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_exec, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_exec\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating exec\par Tue Jun 9 14:56:41 2009 : Debug: exec \{\par Tue Jun 9 14:56:41 2009 : Debug: wait = no\par Tue Jun 9 14:56:41 2009 : Debug: input_pairs = "request"\par Tue Jun 9 14:56:41 2009 : Debug: shell_escape = yes\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_expr, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_expr\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating expr\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_expiration, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_expiration\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating expiration\par Tue Jun 9 14:56:41 2009 : Debug: expiration \{\par Tue Jun 9 14:56:41 2009 : Debug: reply-message = "Password Has Expired "\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_logintime, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_logintime\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating logintime\par Tue Jun 9 14:56:41 2009 : Debug: logintime \{\par Tue Jun 9 14:56:41 2009 : Debug: reply-message = "You are calling outside your allowed timespan "\par Tue Jun 9 14:56:41 2009 : Debug: minimum-timeout = 60\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: radiusd: #### Loading Virtual Servers ####\par Tue Jun 9 14:56:41 2009 : Debug: server inner-tunnel \{\par Tue Jun 9 14:56:41 2009 : Debug: modules \{\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking authenticate \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_pap, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_pap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating pap\par Tue Jun 9 14:56:41 2009 : Debug: pap \{\par Tue Jun 9 14:56:41 2009 : Debug: encryption_scheme = "auto"\par Tue Jun 9 14:56:41 2009 : Debug: auto_header = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_chap, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_chap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating chap\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_mschap, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_mschap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating mschap\par Tue Jun 9 14:56:41 2009 : Debug: mschap \{\par Tue Jun 9 14:56:41 2009 : Debug: use_mppe = yes\par Tue Jun 9 14:56:41 2009 : Debug: require_encryption = no\par Tue Jun 9 14:56:41 2009 : Debug: require_strong = no\par Tue Jun 9 14:56:41 2009 : Debug: with_ntdomain_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_unix, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_unix\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating unix\par Tue Jun 9 14:56:41 2009 : Debug: unix \{\par Tue Jun 9 14:56:41 2009 : Debug: radwtmp = "/usr/local/var/log/radius/radwtmp"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_eap, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_eap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap\par Tue Jun 9 14:56:41 2009 : Debug: eap \{\par Tue Jun 9 14:56:41 2009 : Debug: default_eap_type = "md5"\par Tue Jun 9 14:56:41 2009 : Debug: timer_expire = 60\par Tue Jun 9 14:56:41 2009 : Debug: ignore_unknown_eap_types = no\par Tue Jun 9 14:56:41 2009 : Debug: cisco_accounting_username_bug = no\par Tue Jun 9 14:56:41 2009 : Debug: max_sessions = 2048\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_md5\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-md5\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_leap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-leap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_gtc\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-gtc\par Tue Jun 9 14:56:41 2009 : Debug: gtc \{\par Tue Jun 9 14:56:41 2009 : Debug: challenge = "Password: "\par Tue Jun 9 14:56:41 2009 : Debug: auth_type = "PAP"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_tls\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-tls\par Tue Jun 9 14:56:41 2009 : Debug: tls \{\par Tue Jun 9 14:56:41 2009 : Debug: rsa_key_exchange = no\par Tue Jun 9 14:56:41 2009 : Debug: dh_key_exchange = yes\par Tue Jun 9 14:56:41 2009 : Debug: rsa_key_length = 512\par Tue Jun 9 14:56:41 2009 : Debug: dh_key_length = 512\par Tue Jun 9 14:56:41 2009 : Debug: verify_depth = 0\par Tue Jun 9 14:56:41 2009 : Debug: pem_file_type = yes\par Tue Jun 9 14:56:41 2009 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem"\par Tue Jun 9 14:56:41 2009 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem"\par Tue Jun 9 14:56:41 2009 : Debug: CA_file = "/usr/local/etc/raddb/certs/ca.pem"\par Tue Jun 9 14:56:41 2009 : Debug: private_key_password = "whatever"\par Tue Jun 9 14:56:41 2009 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh"\par Tue Jun 9 14:56:41 2009 : Debug: random_file = "/usr/local/etc/raddb/certs/random"\par Tue Jun 9 14:56:41 2009 : Debug: fragment_size = 1024\par Tue Jun 9 14:56:41 2009 : Debug: include_length = yes\par Tue Jun 9 14:56:41 2009 : Debug: check_crl = no\par Tue Jun 9 14:56:41 2009 : Debug: cipher_list = "DEFAULT"\par Tue Jun 9 14:56:41 2009 : Debug: make_cert_command = "/usr/local/etc/raddb/certs/bootstrap"\par Tue Jun 9 14:56:41 2009 : Debug: cache \{\par Tue Jun 9 14:56:41 2009 : Debug: enable = no\par Tue Jun 9 14:56:41 2009 : Debug: lifetime = 24\par Tue Jun 9 14:56:41 2009 : Debug: max_entries = 255\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_ttls\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-ttls\par Tue Jun 9 14:56:41 2009 : Debug: ttls \{\par Tue Jun 9 14:56:41 2009 : Debug: default_eap_type = "md5"\par Tue Jun 9 14:56:41 2009 : Debug: copy_request_to_tunnel = no\par Tue Jun 9 14:56:41 2009 : Debug: use_tunneled_reply = no\par Tue Jun 9 14:56:41 2009 : Debug: virtual_server = "inner-tunnel"\par Tue Jun 9 14:56:41 2009 : Debug: include_length = yes\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_peap\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-peap\par Tue Jun 9 14:56:41 2009 : Debug: peap \{\par Tue Jun 9 14:56:41 2009 : Debug: default_eap_type = "mschapv2"\par Tue Jun 9 14:56:41 2009 : Debug: copy_request_to_tunnel = no\par Tue Jun 9 14:56:41 2009 : Debug: use_tunneled_reply = no\par Tue Jun 9 14:56:41 2009 : Debug: proxy_tunneled_request_as_eap = yes\par Tue Jun 9 14:56:41 2009 : Debug: virtual_server = "inner-tunnel"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to sub-module rlm_eap_mschapv2\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating eap-mschapv2\par Tue Jun 9 14:56:41 2009 : Debug: mschapv2 \{\par Tue Jun 9 14:56:41 2009 : Debug: with_ntdomain_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking authorize \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_realm, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_realm\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating suffix\par Tue Jun 9 14:56:41 2009 : Debug: realm suffix \{\par Tue Jun 9 14:56:41 2009 : Debug: format = "suffix"\par Tue Jun 9 14:56:41 2009 : Debug: delimiter = "@"\par Tue Jun 9 14:56:41 2009 : Debug: ignore_default = no\par Tue Jun 9 14:56:41 2009 : Debug: ignore_null = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_files, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_files\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating files\par Tue Jun 9 14:56:41 2009 : Debug: files \{\par Tue Jun 9 14:56:41 2009 : Debug: usersfile = "/usr/local/etc/raddb/users"\par Tue Jun 9 14:56:41 2009 : Debug: acctusersfile = "/usr/local/etc/raddb/acct_users"\par Tue Jun 9 14:56:41 2009 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users"\par Tue Jun 9 14:56:41 2009 : Debug: compat = "no"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking session \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_radutmp, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_radutmp\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating radutmp\par Tue Jun 9 14:56:41 2009 : Debug: radutmp \{\par Tue Jun 9 14:56:41 2009 : Debug: filename = "/usr/local/var/log/radius/radutmp"\par Tue Jun 9 14:56:41 2009 : Debug: username = "%\{User-Name\}"\par Tue Jun 9 14:56:41 2009 : Debug: case_sensitive = yes\par Tue Jun 9 14:56:41 2009 : Debug: check_with_nas = yes\par Tue Jun 9 14:56:41 2009 : Debug: perm = 384\par Tue Jun 9 14:56:41 2009 : Debug: callerid = yes\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking post-proxy \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking post-auth \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_attr_filter, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_attr_filter\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating attr_filter.access_reject\par Tue Jun 9 14:56:41 2009 : Debug: attr_filter attr_filter.access_reject \{\par Tue Jun 9 14:56:41 2009 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.access_reject"\par Tue Jun 9 14:56:41 2009 : Debug: key = "%\{User-Name\}"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: \} # modules\par Tue Jun 9 14:56:41 2009 : Debug: \} # server\par Tue Jun 9 14:56:41 2009 : Debug: server \{\par Tue Jun 9 14:56:41 2009 : Debug: modules \{\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking authenticate \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking authorize \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_preprocess, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_preprocess\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating preprocess\par Tue Jun 9 14:56:41 2009 : Debug: preprocess \{\par Tue Jun 9 14:56:41 2009 : Debug: huntgroups = "/usr/local/etc/raddb/huntgroups"\par Tue Jun 9 14:56:41 2009 : Debug: hints = "/usr/local/etc/raddb/hints"\par Tue Jun 9 14:56:41 2009 : Debug: with_ascend_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: ascend_channels_per_line = 23\par Tue Jun 9 14:56:41 2009 : Debug: with_ntdomain_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: with_specialix_jetstream_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: with_cisco_vsa_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: with_alvarion_vsa_hack = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_sql, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_sql\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating sql\par Tue Jun 9 14:56:41 2009 : Debug: sql \{\par Tue Jun 9 14:56:41 2009 : Debug: driver = "rlm_sql_mysql"\par Tue Jun 9 14:56:41 2009 : Debug: server = "localhost"\par Tue Jun 9 14:56:41 2009 : Debug: port = ""\par Tue Jun 9 14:56:41 2009 : Debug: login = "root"\par Tue Jun 9 14:56:41 2009 : Debug: password = "Ch1ll1"\par Tue Jun 9 14:56:41 2009 : Debug: radius_db = "radiusd"\par Tue Jun 9 14:56:41 2009 : Debug: read_groups = yes\par Tue Jun 9 14:56:41 2009 : Debug: sqltrace = no\par Tue Jun 9 14:56:41 2009 : Debug: sqltracefile = "/usr/local/var/log/radius/sqltrace.sql"\par Tue Jun 9 14:56:41 2009 : Debug: readclients = no\par Tue Jun 9 14:56:41 2009 : Debug: deletestalesessions = yes\par Tue Jun 9 14:56:41 2009 : Debug: num_sql_socks = 5\par Tue Jun 9 14:56:41 2009 : Debug: lifetime = 0\par Tue Jun 9 14:56:41 2009 : Debug: max_queries = 0\par Tue Jun 9 14:56:41 2009 : Debug: sql_user_name = "%\{User-Name\}"\par Tue Jun 9 14:56:41 2009 : Debug: default_user_profile = ""\par Tue Jun 9 14:56:41 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas"\par Tue Jun 9 14:56:41 2009 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%\{SQL-User-Name\}' ORDER BY id"\par Tue Jun 9 14:56:41 2009 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%\{SQL-User-Name\}' ORDER BY id"\par Tue Jun 9 14:56:41 2009 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%\{Sql-Group\}' ORDER BY id"\par Tue Jun 9 14:56:41 2009 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%\{Sql-Group\}' ORDER BY id"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_onoff_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = unix_timestamp('%S') - unix_timestamp(acctstarttime), acctterminatecause = '%\{Acct-Terminate-Cause\}', acctstopdelay = %\{%\{Acct-Delay-Time\}:-0\} WHERE acctstoptime IS NULL AND nasipaddress = '%\{NAS-IP-Address\}' AND acctstarttime <= '%S'"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_update_query = " UPDATE radacct SET framedipaddress = '%\{Framed-IP-Address\}', acctsessiontime = '%\{Acct-Session-Time\}', acctinputoctets = '%\{%\{Acct-Input-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Input-Octets\}:-0\}', acctoutputoctets = '%\{%\{Acct-Output-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Output-Octets\}:-0\}' WHERE acctsessionid = '%\{Acct-Session-Id\}' AND username = '%\{SQL-User-Name\}' AND nasipaddress = '%\{NAS-IP-Address\}'"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_update_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey) VALUES ('%\{Acct-Session-Id\}', '%\{Acct-Unique-Session-Id\}', '%\{SQL-User-Name\}', '%\{Realm\}', '%\{NAS-IP-Address\}', '%\{NAS-Port\}', '%\{NAS-Port-Type\}', DATE_SUB('%S', INTERVAL (%\{%\{Acct-Session-Time\}:-0\} + %\{%\{Acct-Delay-Time\}:-0\}) SECOND), '%\{Acct-Session-Time\}', '%\{Acct-Authentic\}', '', '%\{%\{Acct-Input-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Input-Octets\}:-0\}', '%\{%\{Acct-Output-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Output-Octets\}:-0\}', '%\{Called-Station-Id\}', '%\{Calling-Station-Id\}', '%\{Service-Type\}', '%\{Framed-Protocol\}', '%\{Framed-IP-Address\}', '0', '%\{X-Ascend-Session-Svr-Key\}')"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_start_query = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%\{Acct-Session-Id\}', '%\{Acct-Unique-Session-Id\}', '%\{SQL-User-Name\}', '%\{Realm\}', '%\{NAS-IP-Address\}', '%\{NAS-Port\}', '%\{NAS-Port-Type\}', '%S', NULL, '0', '%\{Acct-Authentic\}', '%\{Connect-Info\}', '', '0', '0', '%\{Called-Station-Id\}', '%\{Calling-Station-Id\}', '', '%\{Service-Type\}', '%\{Framed-Protocol\}', '%\{Framed-IP-Address\}', '%\{%\{Acct-Delay-Time\}:-0\}', '0', '%\{X-Ascend-Session-Svr-Key\}')"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_start_query_alt = " UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%\{%\{Acct-Delay-Time\}:-0\}', connectinfo_start = '%\{Connect-Info\}' WHERE acctsessionid = '%\{Acct-Session-Id\}' AND username = '%\{SQL-User-Name\}' AND nasipaddress = '%\{NAS-IP-Address\}'"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_stop_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%\{Acct-Session-Time\}', acctinputoctets = '%\{%\{Acct-Input-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Input-Octets\}:-0\}', acctoutputoctets = '%\{%\{Acct-Output-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Output-Octets\}:-0\}', acctterminatecause = '%\{Acct-Terminate-Cause\}', acctstopdelay = '%\{%\{Acct-Delay-Time\}:-0\}', connectinfo_stop = '%\{Connect-Info\}' WHERE acctsessionid = '%\{Acct-Session-Id\}' AND username = '%\{SQL-User-Name\}' AND nasipaddress = '%\{NAS-IP-Address\}'"\par Tue Jun 9 14:56:41 2009 : Debug: accounting_stop_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%\{Acct-Session-Id\}', '%\{Acct-Unique-Session-Id\}', '%\{SQL-User-Name\}', '%\{Realm\}', '%\{NAS-IP-Address\}', '%\{NAS-Port\}', '%\{NAS-Port-Type\}', DATE_SUB('%S', INTERVAL (%\{%\{Acct-Session-Time\}:-0\} + %\{%\{Acct-Delay-Time\}:-0\}) SECOND), '%S', '%\{Acct-Session-Time\}', '%\{Acct-Authentic\}', '', '%\{Connect-Info\}', '%\{%\{Acct-Input-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Input-Octets\}:-0\}', '%\{%\{Acct-Output-Gigawords\}:-0\}' << 32 | '%\{%\{Acct-Output-Octets\}:-0\}', '%\{Called-Station-Id\}', '%\{Calling-Station-Id\}', '%\{Acct-Terminate-Cause\}', '%\{Service-Type\}', '%\{Framed-Protocol\}', '%\{Framed-IP-Address\}', '0', '%\{%\{Acct-Delay-Time\}:-0\}')"\par Tue Jun 9 14:56:41 2009 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%\{SQL-User-Name\}' ORDER BY priority"\par Tue Jun 9 14:56:41 2009 : Debug: connect_failure_retry_delay = 60\par Tue Jun 9 14:56:41 2009 : Debug: simul_count_query = ""\par Tue Jun 9 14:56:41 2009 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%\{SQL-User-Name\}' AND acctstoptime IS NULL"\par Tue Jun 9 14:56:41 2009 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%\{User-Name\}', '%\{%\{User-Password\}:-%\{Chap-Password\}\}', '%\{reply:Packet-Type\}', '%S')"\par Tue Jun 9 14:56:41 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql (sql): Attempting to connect to root@localhost:/radiusd\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): starting 0\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Connected new DB handle, #0\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): starting 1\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Connected new DB handle, #1\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): starting 2\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Connected new DB handle, #2\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): starting 3\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Connected new DB handle, #3\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): starting 4\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4\par Tue Jun 9 14:56:41 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sql (sql): Connected new DB handle, #4\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_sqlcounter, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_sqlcounter\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating validity\par Tue Jun 9 14:56:41 2009 : Debug: sqlcounter validity \{\par Tue Jun 9 14:56:41 2009 : Debug: counter-name = "All-Secs-Usable"\par Tue Jun 9 14:56:41 2009 : Debug: check-name = "Max-Secs-Usable"\par Tue Jun 9 14:56:41 2009 : Debug: key = "User-Name"\par Tue Jun 9 14:56:41 2009 : Debug: sqlmod-inst = "sql"\par Tue Jun 9 14:56:41 2009 : Debug: query = "SELECT UNIX_TIMESTAMP() - UNIX_TIMESTAMP(AcctStartTime) secs_passed_since_start FROM radacct WHERE UserName = '%\{%k\}' LIMIT 1"\par Tue Jun 9 14:56:41 2009 : Debug: reset = "never"\par Tue Jun 9 14:56:41 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Reply attribute set to Session-Timeout.\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Counter attribute All-Secs-Usable is number 11273\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Check attribute Max-Secs-Usable is number 3000\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Next reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Prev reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating noresetcounter\par Tue Jun 9 14:56:41 2009 : Debug: sqlcounter noresetcounter \{\par Tue Jun 9 14:56:41 2009 : Debug: counter-name = "Max-All-Session-Time"\par Tue Jun 9 14:56:41 2009 : Debug: check-name = "Max-All-Session"\par Tue Jun 9 14:56:41 2009 : Debug: key = "User-Name"\par Tue Jun 9 14:56:41 2009 : Debug: sqlmod-inst = "sql"\par Tue Jun 9 14:56:41 2009 : Debug: query = "SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%\{%k\}'"\par Tue Jun 9 14:56:41 2009 : Debug: reset = "never"\par Tue Jun 9 14:56:41 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Reply attribute set to Session-Timeout.\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Counter attribute Max-All-Session-Time is number 11274\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Check attribute Max-All-Session is number 11275\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Next reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Prev reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating hotspotcontrol\par Tue Jun 9 14:56:41 2009 : Debug: sqlcounter hotspotcontrol \{\par Tue Jun 9 14:56:41 2009 : Debug: counter-name = "All-Secs-Passed"\par Tue Jun 9 14:56:41 2009 : Debug: check-name = "Max-Secs-Passed"\par Tue Jun 9 14:56:41 2009 : Debug: reply-name = "Session-TimeOut"\par Tue Jun 9 14:56:41 2009 : Debug: key = "User-Name"\par Tue Jun 9 14:56:41 2009 : Debug: sqlmod-inst = "sql"\par Tue Jun 9 14:56:41 2009 : Debug: query = "SELECT IFNULL(SUM(AcctSessionTime),0) FROM radacct WHERE UserName='%\{%k\}'"\par Tue Jun 9 14:56:41 2009 : Debug: reset = "never"\par Tue Jun 9 14:56:41 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Reply attribute Session-TimeOut is number 27\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Counter attribute All-Secs-Passed is number 11276\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Check attribute Max-Secs-Passed is number 3001\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Next reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: rlm_sqlcounter: Current Time: 1244555801 [2009-06-09 14:56:41], Prev reset 0 [2009-06-09 14:00:00]\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking preacct \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_acct_unique, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_acct_unique\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating acct_unique\par Tue Jun 9 14:56:41 2009 : Debug: acct_unique \{\par Tue Jun 9 14:56:41 2009 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking accounting \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: (Loaded rlm_detail, checking if it's valid)\par Tue Jun 9 14:56:41 2009 : Debug: Module: Linked to module rlm_detail\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating detail\par Tue Jun 9 14:56:41 2009 : Debug: detail \{\par Tue Jun 9 14:56:41 2009 : Debug: detailfile = "/usr/local/var/log/radius/radacct/%\{Client-IP-Address\}/detail-%Y%m%d"\par Tue Jun 9 14:56:41 2009 : Debug: header = "%t"\par Tue Jun 9 14:56:41 2009 : Debug: detailperm = 384\par Tue Jun 9 14:56:41 2009 : Debug: dirperm = 493\par Tue Jun 9 14:56:41 2009 : Debug: locking = no\par Tue Jun 9 14:56:41 2009 : Debug: log_packet_header = no\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Instantiating attr_filter.accounting_response\par Tue Jun 9 14:56:41 2009 : Debug: attr_filter attr_filter.accounting_response \{\par Tue Jun 9 14:56:41 2009 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.accounting_response"\par Tue Jun 9 14:56:41 2009 : Debug: key = "%\{User-Name\}"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking session \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking post-proxy \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: Module: Checking post-auth \{...\} for more modules to load\par Tue Jun 9 14:56:41 2009 : Debug: \} # modules\par Tue Jun 9 14:56:41 2009 : Debug: \} # server\par Tue Jun 9 14:56:41 2009 : Debug: radiusd: #### Opening IP addresses and Ports ####\par Tue Jun 9 14:56:41 2009 : Debug: listen \{\par Tue Jun 9 14:56:41 2009 : Debug: type = "auth"\par Tue Jun 9 14:56:41 2009 : Debug: ipaddr = *\par Tue Jun 9 14:56:41 2009 : Debug: port = 0\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: listen \{\par Tue Jun 9 14:56:41 2009 : Debug: type = "acct"\par Tue Jun 9 14:56:41 2009 : Debug: ipaddr = *\par Tue Jun 9 14:56:41 2009 : Debug: port = 0\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: listen \{\par Tue Jun 9 14:56:41 2009 : Debug: type = "control"\par Tue Jun 9 14:56:41 2009 : Debug: listen \{\par Tue Jun 9 14:56:41 2009 : Debug: socket = "/usr/local/var/run/radiusd/radiusd.sock"\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: \}\par Tue Jun 9 14:56:41 2009 : Debug: Listening on authentication address * port 1812\par Tue Jun 9 14:56:41 2009 : Debug: Listening on accounting address * port 1813\par Tue Jun 9 14:56:41 2009 : Debug: Listening on command file /usr/local/var/run/radiusd/radiusd.sock\par Tue Jun 9 14:56:41 2009 : Debug: Listening on proxy address * port 1814\par Tue Jun 9 14:56:41 2009 : Debug: Ready to process requests.\par rad_recv: Access-Request packet from host 127.0.0.1 port 44600, id=0, length=189\par ChilliSpot-Max-Input-Octets = 0x32333435363738393031\par ChilliSpot-Max-Output-Octets = 0\par NAS-IP-Address = 127.0.0.1\par Service-Type = Login-User\par Framed-IP-Address = 192.168.182.2\par Calling-Station-Id = "00-1F-29-80-62-F3"\par Called-Station-Id = "00-50-DA-0C-C9-B0"\par NAS-Identifier = "nas01"\par Acct-Session-Id = "4a2e6a7700000000"\par NAS-Port-Type = Wireless-802.11\par NAS-Port = 0\par Message-Authenticator = 0xf2ee6add34820fb96dcceef08c07bbc5\par WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff"\par Tue Jun 9 14:59:48 2009 : Info: +- entering group authorize \{...\}\par Tue Jun 9 14:59:48 2009 : Info: ++[preprocess] returns ok\par Tue Jun 9 14:59:48 2009 : Info: ++[mschap] returns noop\par Tue Jun 9 14:59:48 2009 : Info: [suffix] No '@' in User-Name = "2345678901", looking up realm NULL\par Tue Jun 9 14:59:48 2009 : Info: [suffix] No such realm "NULL"\par Tue Jun 9 14:59:48 2009 : Info: ++[suffix] returns noop\par Tue Jun 9 14:59:48 2009 : Info: [eap] No EAP-Message, not doing EAP\par Tue Jun 9 14:59:48 2009 : Info: ++[eap] returns noop\par Tue Jun 9 14:59:48 2009 : Info: ++[unix] returns notfound\par Tue Jun 9 14:59:48 2009 : Info: ++[files] returns noop\par Tue Jun 9 14:59:48 2009 : Info: [sql] expand: %\{User-Name\} -> 0x32333435363738393031\par Tue Jun 9 14:59:48 2009 : Info: [sql] sql_set_user escaped user --> '0x32333435363738393031'\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 4\par Tue Jun 9 14:59:48 2009 : 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 FROM radcheck WHERE username = '0x32333435363738393031' ORDER BY id\par Tue Jun 9 14:59:48 2009 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%\{SQL-User-Name\}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '0x32333435363738393031' ORDER BY priority\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sql (sql): Released sql socket id: 4\par Tue Jun 9 14:59:48 2009 : Info: [sql] User 0x32333435363738393031 not found\par Tue Jun 9 14:59:48 2009 : Info: ++[sql] returns notfound\par Tue Jun 9 14:59:48 2009 : Info: ++[expiration] returns noop\par Tue Jun 9 14:59:48 2009 : Info: ++[logintime] returns noop\par Tue Jun 9 14:59:48 2009 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.\par Tue Jun 9 14:59:48 2009 : Info: ++[pap] returns noop\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Entering module authorize code\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair\par Tue Jun 9 14:59:48 2009 : Info: ++[validity] returns noop\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Entering module authorize code\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair\par Tue Jun 9 14:59:48 2009 : Info: ++[noresetcounter] returns noop\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Entering module authorize code\par Tue Jun 9 14:59:48 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair\par Tue Jun 9 14:59:48 2009 : Info: ++[hotspotcontrol] returns noop\par Tue Jun 9 14:59:48 2009 : Info: No authenticate method (Auth-Type) configuration found for the request: Rejecting the user\par Tue Jun 9 14:59:48 2009 : Info: Failed to authenticate the user.\par Tue Jun 9 14:59:48 2009 : Info: Using Post-Auth-Type Reject\par Tue Jun 9 14:59:48 2009 : Info: +- entering group REJECT \{...\}\par Tue Jun 9 14:59:48 2009 : Info: [attr_filter.access_reject] expand: %\{User-Name\} -> 0x32333435363738393031\par Tue Jun 9 14:59:48 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11\par Tue Jun 9 14:59:48 2009 : Info: ++[attr_filter.access_reject] returns updated\par Tue Jun 9 14:59:48 2009 : Info: Delaying reject of request 0 for 1 seconds\par Tue Jun 9 14:59:48 2009 : Debug: Going to the next request\par Tue Jun 9 14:59:48 2009 : Debug: Waking up in 0.9 seconds.\par Tue Jun 9 14:59:49 2009 : Info: Sending delayed reject for request 0\par Sending Access-Reject of id 0 to 127.0.0.1 port 44600\par Tue Jun 9 14:59:49 2009 : Debug: Waking up in 4.9 seconds.\par Tue Jun 9 14:59:54 2009 : Info: Cleaning up request 0 ID 0 with timestamp +187\par Tue Jun 9 14:59:54 2009 : Debug: Ready to process requests.\par Tue Jun 9 14:59:54 2009 : Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 33437, id=0, length=189 ChilliSpot-Max-Input-Octets = 0x31323334353637383930 ChilliSpot-Max-Output-Octets = 0 NAS-IP-Address = 127.0.0.1 Service-Type = Login-User Framed-IP-Address = 192.168.182.2 Calling-Station-Id = "00-1F-29-80-62-F3" Called-Station-Id = "00-50-DA-0C-C9-B0" NAS-Identifier = "nas01" Acct-Session-Id = "4a2e6a7700000000" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Message-Authenticator = 0xb96112f3b8a81ce98d1209ee0cc7a3cc WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff" Tue Jun 9 15:00:26 2009 : Info: +- entering group authorize {...} Tue Jun 9 15:00:26 2009 : Info: ++[preprocess] returns ok Tue Jun 9 15:00:26 2009 : Info: ++[mschap] returns noop Tue Jun 9 15:00:26 2009 : Info: [suffix] No '@' in User-Name = "1234567890", looking up realm NULL Tue Jun 9 15:00:26 2009 : Info: [suffix] No such realm "NULL" Tue Jun 9 15:00:26 2009 : Info: ++[suffix] returns noop Tue Jun 9 15:00:26 2009 : Info: [eap] No EAP-Message, not doing EAP Tue Jun 9 15:00:26 2009 : Info: ++[eap] returns noop Tue Jun 9 15:00:26 2009 : Info: ++[unix] returns notfound Tue Jun 9 15:00:26 2009 : Info: ++[files] returns noop Tue Jun 9 15:00:26 2009 : Info: [sql] expand: %{User-Name} -> 0x31323334353637383930 Tue Jun 9 15:00:26 2009 : Info: [sql] sql_set_user escaped user --> '0x31323334353637383930' Tue Jun 9 15:00:26 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Tue Jun 9 15:00:26 2009 : 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 FROM radcheck WHERE username = '0x31323334353637383930' ORDER BY id Tue Jun 9 15:00:26 2009 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '0x31323334353637383930' ORDER BY priority Tue Jun 9 15:00:26 2009 : Debug: rlm_sql (sql): Released sql socket id: 3 Tue Jun 9 15:00:26 2009 : Info: [sql] User 0x31323334353637383930 not found Tue Jun 9 15:00:26 2009 : Info: ++[sql] returns notfound Tue Jun 9 15:00:26 2009 : Info: ++[expiration] returns noop Tue Jun 9 15:00:26 2009 : Info: ++[logintime] returns noop Tue Jun 9 15:00:26 2009 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Tue Jun 9 15:00:26 2009 : Info: ++[pap] returns noop Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Entering module authorize code Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair Tue Jun 9 15:00:26 2009 : Info: ++[validity] returns noop Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Entering module authorize code Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair Tue Jun 9 15:00:26 2009 : Info: ++[noresetcounter] returns noop Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Entering module authorize code Tue Jun 9 15:00:26 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair Tue Jun 9 15:00:26 2009 : Info: ++[hotspotcontrol] returns noop Tue Jun 9 15:00:26 2009 : Info: No authenticate method (Auth-Type) configuration found for the request: Rejecting the user Tue Jun 9 15:00:26 2009 : Info: Failed to authenticate the user. Tue Jun 9 15:00:26 2009 : Info: Using Post-Auth-Type Reject Tue Jun 9 15:00:26 2009 : Info: +- entering group REJECT {...} Tue Jun 9 15:00:26 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 0x31323334353637383930 Tue Jun 9 15:00:26 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Tue Jun 9 15:00:26 2009 : Info: ++[attr_filter.access_reject] returns updated Tue Jun 9 15:00:26 2009 : Info: Delaying reject of request 1 for 1 seconds Tue Jun 9 15:00:26 2009 : Debug: Going to the next request Tue Jun 9 15:00:26 2009 : Debug: Waking up in 0.9 seconds. Tue Jun 9 15:00:27 2009 : Info: Sending delayed reject for request 1 Sending Access-Reject of id 0 to 127.0.0.1 port 33437 Tue Jun 9 15:00:27 2009 : Debug: Waking up in 4.9 seconds. Tue Jun 9 15:00:32 2009 : Info: Cleaning up request 1 ID 0 with timestamp +225 Tue Jun 9 15:00:32 2009 : Debug: Ready to process requests. }