New Server EAP issue
David Peterson
davidp at wirelessconnections.net
Tue Feb 19 19:48:40 CET 2013
I can’t figure out where I went wrong. The auth never gets to the
inner-tunnel.
David
root at 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 at 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 at 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 at 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 at WiMAX.com
Tue Feb 19 12:21:32 2013 : Info: [sql] sql_set_user escaped user -->
'{sm=1}A7A87F7B3E7468918C72CC7CF8E80E4C at 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 at 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 at 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 at 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.
More information about the Freeradius-Users
mailing list