I cant figure out where I went wrong. The auth never gets to the inner-tunnel. David root@hafreeradius1://usr/local/etc/raddb# radiusd -Xxx Tue Feb 19 12:21:30 2013 : Info: radiusd: FreeRADIUS Version 2.2.1 (git #97cba57), for host x86_64-unknown-linux-gnu, built on Feb 18 2013 at 14:52:13 Tue Feb 19 12:21:30 2013 : Debug: Server was built with: Tue Feb 19 12:21:30 2013 : Debug: accounting Tue Feb 19 12:21:30 2013 : Debug: authentication Tue Feb 19 12:21:30 2013 : Debug: WITH_DHCP Tue Feb 19 12:21:30 2013 : Debug: WITH_VMPS Tue Feb 19 12:21:30 2013 : Debug: Server core libs: Tue Feb 19 12:21:30 2013 : Debug: ssl: OpenSSL 1.0.1c 10 May 2012 Tue Feb 19 12:21:30 2013 : Info: Copyright (C) 1999-2013 The FreeRADIUS server project and contributors. Tue Feb 19 12:21:30 2013 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Tue Feb 19 12:21:30 2013 : Info: PARTICULAR PURPOSE. Tue Feb 19 12:21:30 2013 : Info: You may redistribute copies of FreeRADIUS under the terms of the Tue Feb 19 12:21:30 2013 : Info: GNU General Public License. Tue Feb 19 12:21:30 2013 : Info: For more information about these matters, see the file named COPYRIGHT. Tue Feb 19 12:21:30 2013 : Info: Starting - reading configuration files ... Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf Tue Feb 19 12:21:30 2013 : Debug: including files in directory /usr/local/etc/raddb/modules/ Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/acct_unique Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/always Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_filter Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_rewrite Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/cache Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/chap Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/checkval Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/counter Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/cui Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/detail Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.example.com Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.log Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/dhcp_sqlippool Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/ippool-dhcp.conf Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/digest Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/dynamic_clients Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/echo Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/etc_group Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/exec Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/expiration Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/expr Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/files Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/inner-eap Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/ippool Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/krb5 Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/ldap Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/linelog Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/logintime Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2ip Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2vlan Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/mschap Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/ntlm_auth Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/opendirectory Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/otp Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/pam Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/pap Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/passwd Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/perl Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/policy Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/preprocess Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/radrelay Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/radutmp Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/realm Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/redis Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/rediswho Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/replicate Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/smbpasswd Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/smsotp Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/soh Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/sql Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/dialup.conf Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/sql_log Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/sradutmp Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/unix Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/modules/wimax Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/eap.conf Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/policy.conf Tue Feb 19 12:21:30 2013 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/WiMAX.com Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-available/default Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/control-socket Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/dynamic-clients Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/virtual.example.com Tue Feb 19 12:21:30 2013 : Debug: including configuration file /usr/local/etc/raddb/sites-available/default Tue Feb 19 12:21:30 2013 : Debug: main { Tue Feb 19 12:21:30 2013 : Debug: allow_core_dumps = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: including dictionary file /usr/local/etc/raddb/dictionary Tue Feb 19 12:21:30 2013 : Debug: main { Tue Feb 19 12:21:30 2013 : Debug: name = "radiusd" Tue Feb 19 12:21:30 2013 : Debug: prefix = "/usr/local" Tue Feb 19 12:21:30 2013 : Debug: localstatedir = "/usr/local/var" Tue Feb 19 12:21:30 2013 : Debug: sbindir = "/usr/local/sbin" Tue Feb 19 12:21:30 2013 : Debug: logdir = "/usr/local/var/log/radius" Tue Feb 19 12:21:30 2013 : Debug: run_dir = "/usr/local/var/run/radiusd" Tue Feb 19 12:21:30 2013 : Debug: libdir = "/usr/local/lib" Tue Feb 19 12:21:30 2013 : Debug: radacctdir = "/usr/local/var/log/radius/radacct" Tue Feb 19 12:21:30 2013 : Debug: hostname_lookups = no Tue Feb 19 12:21:30 2013 : Debug: max_request_time = 30 Tue Feb 19 12:21:30 2013 : Debug: cleanup_delay = 5 Tue Feb 19 12:21:30 2013 : Debug: max_requests = 1024 Tue Feb 19 12:21:30 2013 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid" Tue Feb 19 12:21:30 2013 : Debug: checkrad = "/usr/local/sbin/checkrad" Tue Feb 19 12:21:30 2013 : Debug: debug_level = 0 Tue Feb 19 12:21:30 2013 : Debug: proxy_requests = yes Tue Feb 19 12:21:30 2013 : Debug: log { Tue Feb 19 12:21:30 2013 : Debug: stripped_names = no Tue Feb 19 12:21:30 2013 : Debug: auth = no Tue Feb 19 12:21:30 2013 : Debug: auth_badpass = no Tue Feb 19 12:21:30 2013 : Debug: auth_goodpass = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: security { Tue Feb 19 12:21:30 2013 : Debug: max_attributes = 200 Tue Feb 19 12:21:30 2013 : Debug: reject_delay = 1 Tue Feb 19 12:21:30 2013 : Debug: status_server = yes Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: radiusd: #### Loading Realms and Home Servers #### Tue Feb 19 12:21:30 2013 : Debug: proxy server { Tue Feb 19 12:21:30 2013 : Debug: retry_delay = 5 Tue Feb 19 12:21:30 2013 : Debug: retry_count = 3 Tue Feb 19 12:21:30 2013 : Debug: default_fallback = no Tue Feb 19 12:21:30 2013 : Debug: dead_time = 120 Tue Feb 19 12:21:30 2013 : Debug: wake_all_if_all_dead = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: home_server localhost { Tue Feb 19 12:21:30 2013 : Debug: ipaddr = 127.0.0.1 Tue Feb 19 12:21:30 2013 : Debug: port = 1812 Tue Feb 19 12:21:30 2013 : Debug: type = "auth" Tue Feb 19 12:21:30 2013 : Debug: secret = "testing123" Tue Feb 19 12:21:30 2013 : Debug: response_window = 20 Tue Feb 19 12:21:30 2013 : Debug: max_outstanding = 65536 Tue Feb 19 12:21:30 2013 : Debug: require_message_authenticator = yes Tue Feb 19 12:21:30 2013 : Debug: zombie_period = 40 Tue Feb 19 12:21:30 2013 : Debug: status_check = "status-server" Tue Feb 19 12:21:30 2013 : Debug: ping_interval = 30 Tue Feb 19 12:21:30 2013 : Debug: check_interval = 30 Tue Feb 19 12:21:30 2013 : Debug: num_answers_to_alive = 3 Tue Feb 19 12:21:30 2013 : Debug: num_pings_to_alive = 3 Tue Feb 19 12:21:30 2013 : Debug: revive_interval = 120 Tue Feb 19 12:21:30 2013 : Debug: status_check_timeout = 4 Tue Feb 19 12:21:30 2013 : Debug: coa { Tue Feb 19 12:21:30 2013 : Debug: irt = 2 Tue Feb 19 12:21:30 2013 : Debug: mrt = 16 Tue Feb 19 12:21:30 2013 : Debug: mrc = 5 Tue Feb 19 12:21:30 2013 : Debug: mrd = 30 Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: realm WiMAX.com { Tue Feb 19 12:21:30 2013 : Debug: nostrip Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: realm LOCAL { Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: realm virtual.example.com { Tue Feb 19 12:21:30 2013 : Debug: virtual_server = virtual.example.com Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: home_server_pool my_auth_failover { Tue Feb 19 12:21:30 2013 : Debug: type = fail-over Tue Feb 19 12:21:30 2013 : Debug: home_server = localhost Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: radiusd: #### Loading Clients #### Tue Feb 19 12:21:30 2013 : Debug: client dynamic { Tue Feb 19 12:21:30 2013 : Debug: ipaddr = 172.16.4.0 Tue Feb 19 12:21:30 2013 : Debug: netmask = 24 Tue Feb 19 12:21:30 2013 : Debug: require_message_authenticator = no Tue Feb 19 12:21:30 2013 : Debug: dynamic_clients = "dynamic_client_server" Tue Feb 19 12:21:30 2013 : Debug: lifetime = 3600 Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: radiusd: #### Instantiating modules #### Tue Feb 19 12:21:30 2013 : Debug: instantiate { Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_exec, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_exec Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "exec" from file /usr/local/etc/raddb/modules/exec Tue Feb 19 12:21:30 2013 : Debug: exec { Tue Feb 19 12:21:30 2013 : Debug: wait = no Tue Feb 19 12:21:30 2013 : Debug: input_pairs = "request" Tue Feb 19 12:21:30 2013 : Debug: shell_escape = yes Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_expr, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_expr Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "expr" from file /usr/local/etc/raddb/modules/expr Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_expiration, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_expiration Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "expiration" from file /usr/local/etc/raddb/modules/expiration Tue Feb 19 12:21:30 2013 : Debug: expiration { Tue Feb 19 12:21:30 2013 : Debug: reply-message = "Password Has Expired " Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_logintime, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_logintime Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "logintime" from file /usr/local/etc/raddb/modules/logintime Tue Feb 19 12:21:30 2013 : Debug: logintime { Tue Feb 19 12:21:30 2013 : Debug: reply-message = "You are calling outside your allowed timespan " Tue Feb 19 12:21:30 2013 : Debug: minimum-timeout = 60 Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: radiusd: #### Loading Virtual Servers #### Tue Feb 19 12:21:30 2013 : Debug: server { # from file /usr/local/etc/raddb/radiusd.conf Tue Feb 19 12:21:30 2013 : Debug: modules { Tue Feb 19 12:21:30 2013 : Debug: Module: Creating Post-Auth-Type = REJECT Tue Feb 19 12:21:30 2013 : Debug: Module: Checking authenticate {...} for more modules to load Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_pap, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_pap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "pap" from file /usr/local/etc/raddb/modules/pap Tue Feb 19 12:21:30 2013 : Debug: pap { Tue Feb 19 12:21:30 2013 : Debug: encryption_scheme = "auto" Tue Feb 19 12:21:30 2013 : Debug: auto_header = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_chap, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_chap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "chap" from file /usr/local/etc/raddb/modules/chap Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_mschap, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_mschap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "mschap" from file /usr/local/etc/raddb/modules/mschap Tue Feb 19 12:21:30 2013 : Debug: mschap { Tue Feb 19 12:21:30 2013 : Debug: use_mppe = yes Tue Feb 19 12:21:30 2013 : Debug: require_encryption = no Tue Feb 19 12:21:30 2013 : Debug: require_strong = no Tue Feb 19 12:21:30 2013 : Debug: with_ntdomain_hack = no Tue Feb 19 12:21:30 2013 : Debug: allow_retry = yes Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_eap, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_eap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "eap" from file /usr/local/etc/raddb/eap.conf Tue Feb 19 12:21:30 2013 : Debug: eap { Tue Feb 19 12:21:30 2013 : Debug: default_eap_type = "md5" Tue Feb 19 12:21:30 2013 : Debug: timer_expire = 60 Tue Feb 19 12:21:30 2013 : Debug: ignore_unknown_eap_types = no Tue Feb 19 12:21:30 2013 : Debug: cisco_accounting_username_bug = no Tue Feb 19 12:21:30 2013 : Debug: max_sessions = 4096 Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_md5 Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-md5 Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_leap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-leap Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_gtc Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-gtc Tue Feb 19 12:21:30 2013 : Debug: gtc { Tue Feb 19 12:21:30 2013 : Debug: challenge = "Password: " Tue Feb 19 12:21:30 2013 : Debug: auth_type = "PAP" Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_tls Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-tls Tue Feb 19 12:21:30 2013 : Debug: tls { Tue Feb 19 12:21:30 2013 : Debug: rsa_key_exchange = no Tue Feb 19 12:21:30 2013 : Debug: dh_key_exchange = yes Tue Feb 19 12:21:30 2013 : Debug: rsa_key_length = 512 Tue Feb 19 12:21:30 2013 : Debug: dh_key_length = 512 Tue Feb 19 12:21:30 2013 : Debug: verify_depth = 0 Tue Feb 19 12:21:30 2013 : Debug: CA_path = "/usr/local/etc/raddb/certs" Tue Feb 19 12:21:30 2013 : Debug: pem_file_type = yes Tue Feb 19 12:21:30 2013 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" Tue Feb 19 12:21:30 2013 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" Tue Feb 19 12:21:30 2013 : Debug: CA_file = "/usr/local/etc/raddb/certs/ca.pem" Tue Feb 19 12:21:30 2013 : Debug: private_key_password = "whatever" Tue Feb 19 12:21:30 2013 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh" Tue Feb 19 12:21:30 2013 : Debug: random_file = "/usr/local/etc/raddb/certs/random" Tue Feb 19 12:21:30 2013 : Debug: fragment_size = 1024 Tue Feb 19 12:21:30 2013 : Debug: include_length = yes Tue Feb 19 12:21:30 2013 : Debug: check_crl = no Tue Feb 19 12:21:30 2013 : Debug: cipher_list = "DEFAULT" Tue Feb 19 12:21:30 2013 : Debug: make_cert_command = "/usr/local/etc/raddb/certs/bootstrap" Tue Feb 19 12:21:30 2013 : Debug: ecdh_curve = "prime256v1" Tue Feb 19 12:21:30 2013 : Debug: cache { Tue Feb 19 12:21:30 2013 : Debug: enable = no Tue Feb 19 12:21:30 2013 : Debug: lifetime = 24 Tue Feb 19 12:21:30 2013 : Debug: max_entries = 255 Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: verify { Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: ocsp { Tue Feb 19 12:21:30 2013 : Debug: enable = no Tue Feb 19 12:21:30 2013 : Debug: override_cert_url = yes Tue Feb 19 12:21:30 2013 : Debug: url = "http://127.0.0.1/ocsp/" Tue Feb 19 12:21:30 2013 : Debug: use_nonce = yes Tue Feb 19 12:21:30 2013 : Debug: timeout = 0 Tue Feb 19 12:21:30 2013 : Debug: softfail = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_ttls Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-ttls Tue Feb 19 12:21:30 2013 : Debug: ttls { Tue Feb 19 12:21:30 2013 : Debug: default_eap_type = "mschapv2" Tue Feb 19 12:21:30 2013 : Debug: copy_request_to_tunnel = yes Tue Feb 19 12:21:30 2013 : Debug: use_tunneled_reply = yes Tue Feb 19 12:21:30 2013 : Debug: virtual_server = "inner-tunnel" Tue Feb 19 12:21:30 2013 : Debug: include_length = yes Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_peap Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-peap Tue Feb 19 12:21:30 2013 : Debug: peap { Tue Feb 19 12:21:30 2013 : Debug: default_eap_type = "mschapv2" Tue Feb 19 12:21:30 2013 : Debug: copy_request_to_tunnel = no Tue Feb 19 12:21:30 2013 : Debug: use_tunneled_reply = no Tue Feb 19 12:21:30 2013 : Debug: proxy_tunneled_request_as_eap = yes Tue Feb 19 12:21:30 2013 : Debug: virtual_server = "inner-tunnel" Tue Feb 19 12:21:30 2013 : Debug: soh = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating eap-mschapv2 Tue Feb 19 12:21:30 2013 : Debug: mschapv2 { Tue Feb 19 12:21:30 2013 : Debug: with_ntdomain_hack = no Tue Feb 19 12:21:30 2013 : Debug: send_error = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: Module: Checking authorize {...} for more modules to load Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_preprocess, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_preprocess Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "preprocess" from file /usr/local/etc/raddb/modules/preprocess Tue Feb 19 12:21:30 2013 : Debug: preprocess { Tue Feb 19 12:21:30 2013 : Debug: huntgroups = "/usr/local/etc/raddb/huntgroups" Tue Feb 19 12:21:30 2013 : Debug: hints = "/usr/local/etc/raddb/hints" Tue Feb 19 12:21:30 2013 : Debug: with_ascend_hack = no Tue Feb 19 12:21:30 2013 : Debug: ascend_channels_per_line = 23 Tue Feb 19 12:21:30 2013 : Debug: with_ntdomain_hack = no Tue Feb 19 12:21:30 2013 : Debug: with_specialix_jetstream_hack = no Tue Feb 19 12:21:30 2013 : Debug: with_cisco_vsa_hack = no Tue Feb 19 12:21:30 2013 : Debug: with_alvarion_vsa_hack = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: reading pairlist file /usr/local/etc/raddb/huntgroups Tue Feb 19 12:21:30 2013 : Debug: reading pairlist file /usr/local/etc/raddb/hints Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_wimax, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_wimax Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "wimax" from file /usr/local/etc/raddb/modules/wimax Tue Feb 19 12:21:30 2013 : Debug: wimax { Tue Feb 19 12:21:30 2013 : Debug: delete_mppe_keys = yes Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_realm, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_realm Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "suffix" from file /usr/local/etc/raddb/modules/realm Tue Feb 19 12:21:30 2013 : Debug: realm suffix { Tue Feb 19 12:21:30 2013 : Debug: format = "suffix" Tue Feb 19 12:21:30 2013 : Debug: delimiter = "@" Tue Feb 19 12:21:30 2013 : Debug: ignore_default = no Tue Feb 19 12:21:30 2013 : Debug: ignore_null = no Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:30 2013 : Debug: (Loaded rlm_sql, checking if it's valid) Tue Feb 19 12:21:30 2013 : Debug: Module: Linked to module rlm_sql Tue Feb 19 12:21:30 2013 : Debug: Module: Instantiating module "sql" from file /usr/local/etc/raddb/modules/sql Tue Feb 19 12:21:30 2013 : Debug: sql { Tue Feb 19 12:21:30 2013 : Debug: driver = "rlm_sql_mysql" Tue Feb 19 12:21:30 2013 : Debug: server = "localhost" Tue Feb 19 12:21:30 2013 : Debug: port = "" Tue Feb 19 12:21:30 2013 : Debug: login = "radius" Tue Feb 19 12:21:30 2013 : Debug: password = "unl0ck" Tue Feb 19 12:21:30 2013 : Debug: radius_db = "radius" Tue Feb 19 12:21:30 2013 : Debug: read_groups = yes Tue Feb 19 12:21:30 2013 : Debug: sqltrace = no Tue Feb 19 12:21:30 2013 : Debug: sqltracefile = "/usr/local/var/log/radius/sqltrace.sql" Tue Feb 19 12:21:30 2013 : Debug: readclients = yes Tue Feb 19 12:21:30 2013 : Debug: deletestalesessions = yes Tue Feb 19 12:21:30 2013 : Debug: num_sql_socks = 5 Tue Feb 19 12:21:30 2013 : Debug: lifetime = 0 Tue Feb 19 12:21:30 2013 : Debug: max_queries = 0 Tue Feb 19 12:21:30 2013 : Debug: sql_user_name = "%{User-Name}" Tue Feb 19 12:21:30 2013 : Debug: default_user_profile = "" Tue Feb 19 12:21:30 2013 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Tue Feb 19 12:21:30 2013 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Tue Feb 19 12:21:30 2013 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Tue Feb 19 12:21:30 2013 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Feb 19 12:21:30 2013 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Tue Feb 19 12:21:30 2013 : 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'" Tue Feb 19 12:21:30 2013 : 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}'" Tue Feb 19 12:21:30 2013 : 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}')" Tue Feb 19 12:21:30 2013 : 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}')" Tue Feb 19 12:21:30 2013 : 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}'" Tue Feb 19 12:21:30 2013 : 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}'" Tue Feb 19 12:21:30 2013 : 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}')" Tue Feb 19 12:21:30 2013 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Tue Feb 19 12:21:30 2013 : Debug: connect_failure_retry_delay = 60 Tue Feb 19 12:21:30 2013 : Debug: simul_count_query = "" Tue Feb 19 12:21:30 2013 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Tue Feb 19 12:21:30 2013 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Tue Feb 19 12:21:30 2013 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Feb 19 12:21:30 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect to radius@localhost:/radius Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): starting 0 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 Tue Feb 19 12:21:31 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Connected new DB handle, #0 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): starting 1 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 Tue Feb 19 12:21:31 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Connected new DB handle, #1 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): starting 2 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 Tue Feb 19 12:21:31 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Connected new DB handle, #2 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): starting 3 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 Tue Feb 19 12:21:31 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Connected new DB handle, #3 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): starting 4 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 Tue Feb 19 12:21:31 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Feb 19 12:21:31 2013 : Info: rlm_sql (sql): Connected new DB handle, #4 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): Processing generate_sql_clients Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): Read entry nasname=172.16.4.10,shortname=Test NAS,secret=unl0ck Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): Adding client 172.16.4.10 (Test NAS, server=<none>) to clients list Tue Feb 19 12:21:31 2013 : Debug: rlm_sql (sql): Released sql socket id: 4 Tue Feb 19 12:21:31 2013 : Debug: Module: Checking preacct {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_acct_unique Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "acct_unique" from file /usr/local/etc/raddb/modules/acct_unique Tue Feb 19 12:21:31 2013 : Debug: acct_unique { Tue Feb 19 12:21:31 2013 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port" Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: Module: Checking accounting {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_detail, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_detail Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "detail" from file /usr/local/etc/raddb/modules/detail Tue Feb 19 12:21:31 2013 : Debug: detail { Tue Feb 19 12:21:31 2013 : Debug: detailfile = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src- IPv6-Address}}/detail-%Y%m%d" Tue Feb 19 12:21:31 2013 : Debug: header = "%t" Tue Feb 19 12:21:31 2013 : Debug: detailperm = 384 Tue Feb 19 12:21:31 2013 : Debug: dirperm = 493 Tue Feb 19 12:21:31 2013 : Debug: locking = no Tue Feb 19 12:21:31 2013 : Debug: log_packet_header = no Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_attr_filter Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/modules/attr_filter Tue Feb 19 12:21:31 2013 : Debug: attr_filter attr_filter.accounting_response { Tue Feb 19 12:21:31 2013 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.accounting_response" Tue Feb 19 12:21:31 2013 : Debug: key = "%{User-Name}" Tue Feb 19 12:21:31 2013 : Debug: relaxed = no Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.accounting_response Tue Feb 19 12:21:31 2013 : Debug: Module: Checking session {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_radutmp, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_radutmp Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "radutmp" from file /usr/local/etc/raddb/modules/radutmp Tue Feb 19 12:21:31 2013 : Debug: radutmp { Tue Feb 19 12:21:31 2013 : Debug: filename = "/usr/local/var/log/radius/radutmp" Tue Feb 19 12:21:31 2013 : Debug: username = "%{User-Name}" Tue Feb 19 12:21:31 2013 : Debug: case_sensitive = yes Tue Feb 19 12:21:31 2013 : Debug: check_with_nas = yes Tue Feb 19 12:21:31 2013 : Debug: perm = 384 Tue Feb 19 12:21:31 2013 : Debug: callerid = yes Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-auth {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/modules/attr_filter Tue Feb 19 12:21:31 2013 : Debug: attr_filter attr_filter.access_reject { Tue Feb 19 12:21:31 2013 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.access_reject" Tue Feb 19 12:21:31 2013 : Debug: key = "%{User-Name}" Tue Feb 19 12:21:31 2013 : Debug: relaxed = no Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.access_reject Tue Feb 19 12:21:31 2013 : Debug: } # modules Tue Feb 19 12:21:31 2013 : Debug: } # server Tue Feb 19 12:21:31 2013 : Debug: server WiMax.com { # from file /usr/local/etc/raddb/sites-enabled/WiMAX.com Tue Feb 19 12:21:31 2013 : Debug: modules { Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authenticate {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authorize {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking preacct {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking accounting {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking session {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-auth {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: } # modules Tue Feb 19 12:21:31 2013 : Debug: } # server Tue Feb 19 12:21:31 2013 : Debug: server dynamic_client_server { # from file /usr/local/etc/raddb/sites-enabled/dynamic-clients Tue Feb 19 12:21:31 2013 : Debug: modules { Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authorize {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_dynamic_clients, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_dynamic_clients Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "dynamic_clients" from file /usr/local/etc/raddb/modules/dynamic_clients Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_always, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_always Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "ok" from file /usr/local/etc/raddb/modules/always Tue Feb 19 12:21:31 2013 : Debug: always ok { Tue Feb 19 12:21:31 2013 : Debug: rcode = "ok" Tue Feb 19 12:21:31 2013 : Debug: simulcount = 0 Tue Feb 19 12:21:31 2013 : Debug: mpp = no Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: } # modules Tue Feb 19 12:21:31 2013 : Debug: } # server Tue Feb 19 12:21:31 2013 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Tue Feb 19 12:21:31 2013 : Debug: modules { Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authenticate {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authorize {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking session {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-auth {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: (Loaded rlm_sql_log, checking if it's valid) Tue Feb 19 12:21:31 2013 : Debug: Module: Linked to module rlm_sql_log Tue Feb 19 12:21:31 2013 : Debug: Module: Instantiating module "sql_log" from file /usr/local/etc/raddb/modules/sql_log Tue Feb 19 12:21:31 2013 : Debug: sql_log { Tue Feb 19 12:21:31 2013 : Debug: path = "/usr/local/var/log/radius/radacct/sql-relay" Tue Feb 19 12:21:31 2013 : Debug: Post-Auth = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ('%{User-Name}', '%{User-Password:-Chap-Password}', '%{reply:Packet-Type}', '%S');" Tue Feb 19 12:21:31 2013 : Debug: sql_user_name = "%{%{User-Name}:-DEFAULT}" Tue Feb 19 12:21:31 2013 : Debug: utf8 = no Tue Feb 19 12:21:31 2013 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: } # modules Tue Feb 19 12:21:31 2013 : Debug: } # server Tue Feb 19 12:21:31 2013 : Debug: server virtual.example.com { # from file /usr/local/etc/raddb/sites-enabled/virtual.example.com Tue Feb 19 12:21:31 2013 : Debug: modules { Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authenticate {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking authorize {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking preacct {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking accounting {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking session {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-proxy {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: Module: Checking post-auth {...} for more modules to load Tue Feb 19 12:21:31 2013 : Debug: } # modules Tue Feb 19 12:21:31 2013 : Debug: } # server Tue Feb 19 12:21:31 2013 : Debug: radiusd: #### Opening IP addresses and Ports #### Tue Feb 19 12:21:31 2013 : Debug: listen { Tue Feb 19 12:21:31 2013 : Debug: type = "auth" Tue Feb 19 12:21:31 2013 : Debug: ipaddr = * Tue Feb 19 12:21:31 2013 : Debug: port = 0 Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: listen { Tue Feb 19 12:21:31 2013 : Debug: type = "acct" Tue Feb 19 12:21:31 2013 : Debug: ipaddr = * Tue Feb 19 12:21:31 2013 : Debug: port = 0 Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: listen { Tue Feb 19 12:21:31 2013 : Debug: type = "control" Tue Feb 19 12:21:31 2013 : Debug: listen { Tue Feb 19 12:21:31 2013 : Debug: socket = "/usr/local/var/run/radiusd/radiusd.sock" Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: listen { Tue Feb 19 12:21:31 2013 : Debug: type = "auth" Tue Feb 19 12:21:31 2013 : Debug: ipaddr = 127.0.0.1 Tue Feb 19 12:21:31 2013 : Debug: port = 18120 Tue Feb 19 12:21:31 2013 : Debug: } Tue Feb 19 12:21:31 2013 : Debug: ... adding new socket proxy address * port 39057 Tue Feb 19 12:21:31 2013 : Debug: Listening on authentication address * port 1812 Tue Feb 19 12:21:31 2013 : Debug: Listening on accounting address * port 1813 Tue Feb 19 12:21:31 2013 : Debug: Listening on command file /usr/local/var/run/radiusd/radiusd.sock Tue Feb 19 12:21:31 2013 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Tue Feb 19 12:21:31 2013 : Debug: Listening on proxy address * port 1814 Tue Feb 19 12:21:31 2013 : Info: Ready to process requests. rad_recv: Access-Request packet from host 172.16.4.10 port 1812, id=108, length=240 User-Name = "{sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com" EAP-Message = 0x02010035017b736d3d317d4137413837463742334537343638393138433732434337434638 4538304534434057694d41582e636f6d Message-Authenticator = 0x6c06035e0f8f87be2df9cc3c79b59f87 NAS-IP-Address = 172.16.4.10 Calling-Station-Id = "00-26-82-C4-B2-86" WiMAX-BS-Id = 0xfff3290a162c NAS-Port-Type = Wireless-802.16 Framed-MTU = 2000 Service-Type = Framed-User WiMAX-GMT-Timezone-offset = 0 WiMAX-Release = "1.0" WiMAX-Accounting-Capabilities = IP-Session-Based WiMAX-Hotlining-Capabilities = Hotline-Profile-Id WiMAX-Attr-1793 = 0x0000028a Tue Feb 19 12:21:32 2013 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Tue Feb 19 12:21:32 2013 : Info: +- entering group authorize {...} Tue Feb 19 12:21:32 2013 : Info: ++[preprocess] returns ok Tue Feb 19 12:21:32 2013 : Info: ++[mschap] returns noop Tue Feb 19 12:21:32 2013 : Info: ++[wimax] returns ok Tue Feb 19 12:21:32 2013 : Info: [suffix] Looking up realm "WiMAX.com" for User-Name = "{sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com" Tue Feb 19 12:21:32 2013 : Info: [suffix] Found realm "WiMAX.com" Tue Feb 19 12:21:32 2013 : Info: [suffix] Adding Realm = "WiMAX.com" Tue Feb 19 12:21:32 2013 : Info: [suffix] Authentication realm is LOCAL. Tue Feb 19 12:21:32 2013 : Info: ++[suffix] returns ok Tue Feb 19 12:21:32 2013 : Info: [eap] EAP packet type response id 1 length 53 Tue Feb 19 12:21:32 2013 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Tue Feb 19 12:21:32 2013 : Info: ++[eap] returns updated Tue Feb 19 12:21:32 2013 : Info: [sql] expand: %{User-Name} -> {sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com Tue Feb 19 12:21:32 2013 : Info: [sql] sql_set_user escaped user --> '{sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com' Tue Feb 19 12:21:32 2013 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Tue Feb 19 12:21:32 2013 : 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 = '=7Bsm=3D1=7DA7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com' ORDER BY id Tue Feb 19 12:21:32 2013 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '=7Bsm=3D1=7DA7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com' ORDER BY priority Tue Feb 19 12:21:32 2013 : Debug: rlm_sql (sql): Released sql socket id: 3 Tue Feb 19 12:21:32 2013 : Info: [sql] User {sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C@WiMAX.com not found Tue Feb 19 12:21:32 2013 : Info: ++[sql] returns notfound Tue Feb 19 12:21:32 2013 : Info: ++[expiration] returns noop Tue Feb 19 12:21:32 2013 : Info: ++[logintime] returns noop Tue Feb 19 12:21:32 2013 : Info: Found Auth-Type = EAP Tue Feb 19 12:21:32 2013 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Tue Feb 19 12:21:32 2013 : Info: +- entering group authenticate {...} Tue Feb 19 12:21:32 2013 : Info: [eap] EAP Identity Tue Feb 19 12:21:32 2013 : Info: [eap] processing type md5 Tue Feb 19 12:21:32 2013 : Debug: rlm_eap_md5: Issuing Challenge Tue Feb 19 12:21:32 2013 : Info: ++[eap] returns handled Sending Access-Challenge of id 108 to 172.16.4.10 port 1812 EAP-Message = 0x0102001604100fc4f706667b63fe100609f538afe0f5 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xdc923277dc90367d008f589074a14c27 Tue Feb 19 12:21:32 2013 : Info: Finished request 0. Tue Feb 19 12:21:32 2013 : Debug: Going to the next request Tue Feb 19 12:21:32 2013 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 172.16.4.10 port 1812, id=108, length=240 Tue Feb 19 12:21:37 2013 : Info: Sending duplicate reply to client Test NAS port 1812 - ID: 108 Sending Access-Challenge of id 108 to 172.16.4.10 port 1812 Tue Feb 19 12:21:37 2013 : Info: Cleaning up request 0 ID 108 with timestamp +1 Tue Feb 19 12:21:37 2013 : Info: Ready to process requests.