Here is the debugging output produced: Wed Apr 15 13:43:43 2009 : Info: FreeRADIUS Version 2.1.4, for host i386-portbld-freebsd7.1, built on Apr 13 2009 at 14:36:26 Wed Apr 15 13:43:43 2009 : Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Wed Apr 15 13:43:43 2009 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Wed Apr 15 13:43:43 2009 : Info: PARTICULAR PURPOSE. Wed Apr 15 13:43:43 2009 : Info: You may redistribute copies of FreeRADIUS under the terms of the Wed Apr 15 13:43:43 2009 : Info: GNU General Public License v2. Wed Apr 15 13:43:43 2009 : Info: Starting - reading configuration files ... Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/clients.conf Wed Apr 15 13:43:43 2009 : Debug: including files in directory /usr/local/etc/raddb/modules/ Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/wimax Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/always Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_filter Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_rewrite Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/chap Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/checkval Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/counter Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.example.com Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.log Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/digest Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/echo Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/etc_group Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/exec Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/expiration Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/expr Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/files Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/inner-eap Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/ippool Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/krb5 Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/ldap Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/linelog Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/logintime Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2ip Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2vlan Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/mschap Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/otp Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/pam Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/pap Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/passwd Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/perl Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/policy Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/preprocess Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/radutmp Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/realm Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/smbpasswd Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/smsotp Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sql_log Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/sradutmp Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/unix Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/modules/acct_unique Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/eap.conf Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/sql.conf Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/policy.conf Wed Apr 15 13:43:43 2009 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Apr 15 13:43:43 2009 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/control-socket Wed Apr 15 13:43:43 2009 : Debug: group = freeradius Wed Apr 15 13:43:43 2009 : Debug: user = freeradius Wed Apr 15 13:43:43 2009 : Debug: including dictionary file /usr/local/etc/raddb/dictionary Wed Apr 15 13:43:43 2009 : Debug: main { Wed Apr 15 13:43:43 2009 : Debug: prefix = "/usr/local" Wed Apr 15 13:43:43 2009 : Debug: localstatedir = "/var" Wed Apr 15 13:43:43 2009 : Debug: logdir = "/var/log" Wed Apr 15 13:43:43 2009 : Debug: libdir = "/usr/local/lib/freeradius-2.1.4" Wed Apr 15 13:43:43 2009 : Debug: radacctdir = "/var/log/radacct" Wed Apr 15 13:43:43 2009 : Debug: hostname_lookups = no Wed Apr 15 13:43:43 2009 : Debug: max_request_time = 30 Wed Apr 15 13:43:43 2009 : Debug: cleanup_delay = 5 Wed Apr 15 13:43:43 2009 : Debug: max_requests = 1024 Wed Apr 15 13:43:43 2009 : Debug: allow_core_dumps = no Wed Apr 15 13:43:43 2009 : Debug: pidfile = "/var/run/radiusd/radiusd.pid" Wed Apr 15 13:43:43 2009 : Debug: checkrad = "/usr/local/sbin/checkrad" Wed Apr 15 13:43:43 2009 : Debug: debug_level = 0 Wed Apr 15 13:43:43 2009 : Debug: proxy_requests = yes Wed Apr 15 13:43:43 2009 : Debug: log { Wed Apr 15 13:43:43 2009 : Debug: stripped_names = no Wed Apr 15 13:43:43 2009 : Debug: auth = yes Wed Apr 15 13:43:43 2009 : Debug: auth_badpass = yes Wed Apr 15 13:43:43 2009 : Debug: auth_goodpass = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: security { Wed Apr 15 13:43:43 2009 : Debug: max_attributes = 200 Wed Apr 15 13:43:43 2009 : Debug: reject_delay = 0 Wed Apr 15 13:43:43 2009 : Debug: status_server = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: radiusd: #### Loading Realms and Home Servers #### Wed Apr 15 13:43:43 2009 : Debug: proxy server { Wed Apr 15 13:43:43 2009 : Debug: retry_delay = 5 Wed Apr 15 13:43:43 2009 : Debug: retry_count = 3 Wed Apr 15 13:43:43 2009 : Debug: default_fallback = no Wed Apr 15 13:43:43 2009 : Debug: dead_time = 120 Wed Apr 15 13:43:43 2009 : Debug: wake_all_if_all_dead = no Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: home_server localhost { Wed Apr 15 13:43:43 2009 : Debug: ipaddr = 127.0.0.1 Wed Apr 15 13:43:43 2009 : Debug: port = 1812 Wed Apr 15 13:43:43 2009 : Debug: type = "auth" Wed Apr 15 13:43:43 2009 : Debug: secret = "testing123" Wed Apr 15 13:43:43 2009 : Debug: response_window = 20 Wed Apr 15 13:43:43 2009 : Debug: max_outstanding = 65536 Wed Apr 15 13:43:43 2009 : Debug: require_message_authenticator = no Wed Apr 15 13:43:43 2009 : Debug: zombie_period = 40 Wed Apr 15 13:43:43 2009 : Debug: status_check = "status-server" Wed Apr 15 13:43:43 2009 : Debug: ping_interval = 30 Wed Apr 15 13:43:43 2009 : Debug: check_interval = 30 Wed Apr 15 13:43:43 2009 : Debug: num_answers_to_alive = 3 Wed Apr 15 13:43:43 2009 : Debug: num_pings_to_alive = 3 Wed Apr 15 13:43:43 2009 : Debug: revive_interval = 120 Wed Apr 15 13:43:43 2009 : Debug: status_check_timeout = 4 Wed Apr 15 13:43:43 2009 : Debug: irt = 2 Wed Apr 15 13:43:43 2009 : Debug: mrt = 16 Wed Apr 15 13:43:43 2009 : Debug: mrc = 5 Wed Apr 15 13:43:43 2009 : Debug: mrd = 30 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: home_server_pool my_auth_failover { Wed Apr 15 13:43:43 2009 : Debug: type = fail-over Wed Apr 15 13:43:43 2009 : Debug: home_server = localhost Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: realm example.com { Wed Apr 15 13:43:43 2009 : Debug: auth_pool = my_auth_failover Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: realm LOCAL { Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: radiusd: #### Loading Clients #### Wed Apr 15 13:43:43 2009 : Debug: client localhost { Wed Apr 15 13:43:43 2009 : Debug: ipaddr = 127.0.0.1 Wed Apr 15 13:43:43 2009 : Debug: require_message_authenticator = no Wed Apr 15 13:43:43 2009 : Debug: secret = "testing123" Wed Apr 15 13:43:43 2009 : Debug: nastype = "other" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: radiusd: #### Instantiating modules #### Wed Apr 15 13:43:43 2009 : Debug: instantiate { Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_exec, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_exec Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating exec Wed Apr 15 13:43:43 2009 : Debug: exec { Wed Apr 15 13:43:43 2009 : Debug: wait = no Wed Apr 15 13:43:43 2009 : Debug: input_pairs = "request" Wed Apr 15 13:43:43 2009 : Debug: shell_escape = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_expr, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_expr Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating expr Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_expiration, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_expiration Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating expiration Wed Apr 15 13:43:43 2009 : Debug: expiration { Wed Apr 15 13:43:43 2009 : Debug: reply-message = "Password Has Expired " Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_logintime, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_logintime Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating logintime Wed Apr 15 13:43:43 2009 : Debug: logintime { Wed Apr 15 13:43:43 2009 : Debug: reply-message = "You are calling outside your allowed timespan " Wed Apr 15 13:43:43 2009 : Debug: minimum-timeout = 60 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: radiusd: #### Loading Virtual Servers #### Wed Apr 15 13:43:43 2009 : Debug: server inner-tunnel { Wed Apr 15 13:43:43 2009 : Debug: modules { Wed Apr 15 13:43:43 2009 : Debug: Module: Checking authenticate {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_pap, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_pap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating pap Wed Apr 15 13:43:43 2009 : Debug: pap { Wed Apr 15 13:43:43 2009 : Debug: encryption_scheme = "auto" Wed Apr 15 13:43:43 2009 : Debug: auto_header = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_chap, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_chap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating chap Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_mschap, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_mschap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating mschap Wed Apr 15 13:43:43 2009 : Debug: mschap { Wed Apr 15 13:43:43 2009 : Debug: use_mppe = yes Wed Apr 15 13:43:43 2009 : Debug: require_encryption = no Wed Apr 15 13:43:43 2009 : Debug: require_strong = no Wed Apr 15 13:43:43 2009 : Debug: with_ntdomain_hack = no Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_unix, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_unix Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating unix Wed Apr 15 13:43:43 2009 : Debug: unix { Wed Apr 15 13:43:43 2009 : Debug: radwtmp = "/var/log/radwtmp" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_eap, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_eap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap Wed Apr 15 13:43:43 2009 : Debug: eap { Wed Apr 15 13:43:43 2009 : Debug: default_eap_type = "md5" Wed Apr 15 13:43:43 2009 : Debug: timer_expire = 60 Wed Apr 15 13:43:43 2009 : Debug: ignore_unknown_eap_types = no Wed Apr 15 13:43:43 2009 : Debug: cisco_accounting_username_bug = no Wed Apr 15 13:43:43 2009 : Debug: max_sessions = 2048 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_md5 Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-md5 Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_leap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-leap Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_gtc Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-gtc Wed Apr 15 13:43:43 2009 : Debug: gtc { Wed Apr 15 13:43:43 2009 : Debug: challenge = "Password: " Wed Apr 15 13:43:43 2009 : Debug: auth_type = "PAP" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_tls Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-tls Wed Apr 15 13:43:43 2009 : Debug: tls { Wed Apr 15 13:43:43 2009 : Debug: rsa_key_exchange = no Wed Apr 15 13:43:43 2009 : Debug: dh_key_exchange = yes Wed Apr 15 13:43:43 2009 : Debug: rsa_key_length = 512 Wed Apr 15 13:43:43 2009 : Debug: dh_key_length = 512 Wed Apr 15 13:43:43 2009 : Debug: verify_depth = 0 Wed Apr 15 13:43:43 2009 : Debug: pem_file_type = yes Wed Apr 15 13:43:43 2009 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" Wed Apr 15 13:43:43 2009 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" Wed Apr 15 13:43:43 2009 : Debug: CA_file = "/usr/local/etc/raddb/certs/ca.pem" Wed Apr 15 13:43:43 2009 : Debug: private_key_password = "whatever" Wed Apr 15 13:43:43 2009 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh" Wed Apr 15 13:43:43 2009 : Debug: random_file = "/usr/local/etc/raddb/certs/random" Wed Apr 15 13:43:43 2009 : Debug: fragment_size = 1024 Wed Apr 15 13:43:43 2009 : Debug: include_length = yes Wed Apr 15 13:43:43 2009 : Debug: check_crl = no Wed Apr 15 13:43:43 2009 : Debug: cipher_list = "DEFAULT" Wed Apr 15 13:43:43 2009 : Debug: make_cert_command = "/usr/local/etc/raddb/certs/bootstrap" Wed Apr 15 13:43:43 2009 : Debug: cache { Wed Apr 15 13:43:43 2009 : Debug: enable = no Wed Apr 15 13:43:43 2009 : Debug: lifetime = 24 Wed Apr 15 13:43:43 2009 : Debug: max_entries = 255 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_ttls Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-ttls Wed Apr 15 13:43:43 2009 : Debug: ttls { Wed Apr 15 13:43:43 2009 : Debug: default_eap_type = "md5" Wed Apr 15 13:43:43 2009 : Debug: copy_request_to_tunnel = no Wed Apr 15 13:43:43 2009 : Debug: use_tunneled_reply = no Wed Apr 15 13:43:43 2009 : Debug: virtual_server = "inner-tunnel" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_peap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-peap Wed Apr 15 13:43:43 2009 : Debug: peap { Wed Apr 15 13:43:43 2009 : Debug: default_eap_type = "mschapv2" Wed Apr 15 13:43:43 2009 : Debug: copy_request_to_tunnel = no Wed Apr 15 13:43:43 2009 : Debug: use_tunneled_reply = no Wed Apr 15 13:43:43 2009 : Debug: proxy_tunneled_request_as_eap = yes Wed Apr 15 13:43:43 2009 : Debug: virtual_server = "inner-tunnel" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating eap-mschapv2 Wed Apr 15 13:43:43 2009 : Debug: mschapv2 { Wed Apr 15 13:43:43 2009 : Debug: with_ntdomain_hack = no Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking authorize {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_realm, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_realm Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating suffix Wed Apr 15 13:43:43 2009 : Debug: realm suffix { Wed Apr 15 13:43:43 2009 : Debug: format = "suffix" Wed Apr 15 13:43:43 2009 : Debug: delimiter = "@" Wed Apr 15 13:43:43 2009 : Debug: ignore_default = no Wed Apr 15 13:43:43 2009 : Debug: ignore_null = no Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_files, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_files Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating files Wed Apr 15 13:43:43 2009 : Debug: files { Wed Apr 15 13:43:43 2009 : Debug: usersfile = "/usr/local/etc/raddb/users" Wed Apr 15 13:43:43 2009 : Debug: acctusersfile = "/usr/local/etc/raddb/acct_users" Wed Apr 15 13:43:43 2009 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users" Wed Apr 15 13:43:43 2009 : Debug: compat = "no" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking session {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_radutmp, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_radutmp Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating radutmp Wed Apr 15 13:43:43 2009 : Debug: radutmp { Wed Apr 15 13:43:43 2009 : Debug: filename = "/var/log/radutmp" Wed Apr 15 13:43:43 2009 : Debug: username = "%{User-Name}" Wed Apr 15 13:43:43 2009 : Debug: case_sensitive = yes Wed Apr 15 13:43:43 2009 : Debug: check_with_nas = yes Wed Apr 15 13:43:43 2009 : Debug: perm = 384 Wed Apr 15 13:43:43 2009 : Debug: callerid = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking post-proxy {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: Module: Checking post-auth {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_attr_filter, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_attr_filter Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating attr_filter.access_reject Wed Apr 15 13:43:43 2009 : Debug: attr_filter attr_filter.access_reject { Wed Apr 15 13:43:43 2009 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.access_reject" Wed Apr 15 13:43:43 2009 : Debug: key = "%{User-Name}" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: modules { Wed Apr 15 13:43:43 2009 : Debug: Module: Checking authenticate {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_ldap, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_ldap Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating ldap Wed Apr 15 13:43:43 2009 : Debug: ldap { Wed Apr 15 13:43:43 2009 : Debug: server = "web3" Wed Apr 15 13:43:43 2009 : Debug: port = 389 Wed Apr 15 13:43:43 2009 : Debug: password = "test" Wed Apr 15 13:43:43 2009 : Debug: identity = "cn=test,dc=gwis" Wed Apr 15 13:43:43 2009 : Debug: net_timeout = 1 Wed Apr 15 13:43:43 2009 : Debug: timeout = 4 Wed Apr 15 13:43:43 2009 : Debug: timelimit = 3 Wed Apr 15 13:43:43 2009 : Debug: tls_mode = no Wed Apr 15 13:43:43 2009 : Debug: start_tls = no Wed Apr 15 13:43:43 2009 : Debug: tls_require_cert = "allow" Wed Apr 15 13:43:43 2009 : Debug: tls { Wed Apr 15 13:43:43 2009 : Debug: start_tls = no Wed Apr 15 13:43:43 2009 : Debug: require_cert = "allow" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: basedn = "dc=gwis" Wed Apr 15 13:43:43 2009 : Debug: filter = "(&(%{Ldap-User}=%{Stripped-User-Name:-%{User-Name}})(aaaenable=1))" Wed Apr 15 13:43:43 2009 : Debug: base_filter = "(objectclass=radiusprofile)" Wed Apr 15 13:43:43 2009 : Debug: password_attribute = "%{Ldap-Pass}" Wed Apr 15 13:43:43 2009 : Debug: auto_header = yes Wed Apr 15 13:43:43 2009 : Debug: access_attr_used_for_allow = yes Wed Apr 15 13:43:43 2009 : Debug: groupname_attribute = "cn" Wed Apr 15 13:43:43 2009 : Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Wed Apr 15 13:43:43 2009 : Debug: dictionary_mapping = "/usr/local/etc/raddb/ldap.attrmap" Wed Apr 15 13:43:43 2009 : Debug: ldap_debug = 0 Wed Apr 15 13:43:43 2009 : Debug: ldap_connections_number = 5 Wed Apr 15 13:43:43 2009 : Debug: compare_check_items = no Wed Apr 15 13:43:43 2009 : Debug: do_xlat = yes Wed Apr 15 13:43:43 2009 : Debug: set_auth_type = yes Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Wed Apr 15 13:43:43 2009 : Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Wed Apr 15 13:43:43 2009 : Debug: rlm_ldap: reading ldap<->radius mappings from file /usr/local/etc/raddb/ldap.attrmap Wed Apr 15 13:43:43 2009 : Debug: rlm_ldap: LDAP aaasimultaneoususe mapped to RADIUS Simultaneous-Use Wed Apr 15 13:43:43 2009 : Debug: conns: 0x2842bf60 Wed Apr 15 13:43:43 2009 : Debug: Module: Checking authorize {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_preprocess, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_preprocess Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating preprocess Wed Apr 15 13:43:43 2009 : Debug: preprocess { Wed Apr 15 13:43:43 2009 : Debug: huntgroups = "/usr/local/etc/raddb/huntgroups" Wed Apr 15 13:43:43 2009 : Debug: hints = "/usr/local/etc/raddb/hints" Wed Apr 15 13:43:43 2009 : Debug: with_ascend_hack = no Wed Apr 15 13:43:43 2009 : Debug: ascend_channels_per_line = 23 Wed Apr 15 13:43:43 2009 : Debug: with_ntdomain_hack = no Wed Apr 15 13:43:43 2009 : Debug: with_specialix_jetstream_hack = no Wed Apr 15 13:43:43 2009 : Debug: with_cisco_vsa_hack = no Wed Apr 15 13:43:43 2009 : Debug: with_alvarion_vsa_hack = no Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking preacct {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_acct_unique Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating acct_unique Wed Apr 15 13:43:43 2009 : Debug: acct_unique { Wed Apr 15 13:43:43 2009 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking accounting {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: (Loaded rlm_sql, checking if it's valid) Wed Apr 15 13:43:43 2009 : Debug: Module: Linked to module rlm_sql Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating sql Wed Apr 15 13:43:43 2009 : Debug: sql { Wed Apr 15 13:43:43 2009 : Debug: driver = "rlm_sql_mysql" Wed Apr 15 13:43:43 2009 : Debug: server = "localhost" Wed Apr 15 13:43:43 2009 : Debug: port = "" Wed Apr 15 13:43:43 2009 : Debug: login = "test" Wed Apr 15 13:43:43 2009 : Debug: password = "test" Wed Apr 15 13:43:43 2009 : Debug: radius_db = "test" Wed Apr 15 13:43:43 2009 : Debug: read_groups = yes Wed Apr 15 13:43:43 2009 : Debug: sqltrace = yes Wed Apr 15 13:43:43 2009 : Debug: sqltracefile = "/var/log/sqltrace.sql" Wed Apr 15 13:43:43 2009 : Debug: readclients = no Wed Apr 15 13:43:43 2009 : Debug: deletestalesessions = yes Wed Apr 15 13:43:43 2009 : Debug: num_sql_socks = 5 Wed Apr 15 13:43:43 2009 : Debug: lifetime = 0 Wed Apr 15 13:43:43 2009 : Debug: max_queries = 0 Wed Apr 15 13:43:43 2009 : Debug: sql_user_name = "" Wed Apr 15 13:43:43 2009 : Debug: default_user_profile = "" Wed Apr 15 13:43:43 2009 : Debug: nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" Wed Apr 15 13:43:43 2009 : Debug: authorize_check_query = "" Wed Apr 15 13:43:43 2009 : Debug: authorize_group_check_query = "" Wed Apr 15 13:43:43 2009 : Debug: authorize_group_reply_query = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_onoff_query = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_update_query = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_update_query_alt = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_start_query = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_start_query_alt = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_stop_query = "" Wed Apr 15 13:43:43 2009 : Debug: accounting_stop_query_alt = "" Wed Apr 15 13:43:43 2009 : Debug: connect_failure_retry_delay = 60 Wed Apr 15 13:43:43 2009 : Debug: simul_count_query = "" Wed Apr 15 13:43:43 2009 : Debug: simul_verify_query = "" Wed Apr 15 13:43:43 2009 : Debug: postauth_query = "" Wed Apr 15 13:43:43 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Wed Apr 15 13:43:43 2009 : Info: rlm_sql (sql): Attempting to connect to test@localhost:/visp Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): starting 0 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 Wed Apr 15 13:43:43 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Connected new DB handle, #0 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): starting 1 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 Wed Apr 15 13:43:43 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Connected new DB handle, #1 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): starting 2 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 Wed Apr 15 13:43:43 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Connected new DB handle, #2 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): starting 3 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 Wed Apr 15 13:43:43 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Connected new DB handle, #3 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): starting 4 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 Wed Apr 15 13:43:43 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Wed Apr 15 13:43:43 2009 : Debug: rlm_sql (sql): Connected new DB handle, #4 Wed Apr 15 13:43:43 2009 : Debug: Module: Instantiating attr_filter.accounting_response Wed Apr 15 13:43:43 2009 : Debug: attr_filter attr_filter.accounting_response { Wed Apr 15 13:43:43 2009 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.accounting_response" Wed Apr 15 13:43:43 2009 : Debug: key = "%{User-Name}" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Module: Checking session {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: Module: Checking post-auth {...} for more modules to load Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: radiusd: #### Opening IP addresses and Ports #### Wed Apr 15 13:43:43 2009 : Debug: listen { Wed Apr 15 13:43:43 2009 : Debug: type = "auth" Wed Apr 15 13:43:43 2009 : Debug: ipaddr = * Wed Apr 15 13:43:43 2009 : Debug: port = 1645 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: listen { Wed Apr 15 13:43:43 2009 : Debug: type = "acct" Wed Apr 15 13:43:43 2009 : Debug: ipaddr = * Wed Apr 15 13:43:43 2009 : Debug: port = 1646 Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: listen { Wed Apr 15 13:43:43 2009 : Debug: type = "control" Wed Apr 15 13:43:43 2009 : Debug: listen { Wed Apr 15 13:43:43 2009 : Debug: socket = "/var/run/radiusd/radiusd.sock" Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: } Wed Apr 15 13:43:43 2009 : Debug: Listening on authentication address * port 1645 Wed Apr 15 13:43:43 2009 : Debug: Listening on accounting address * port 1646 Wed Apr 15 13:43:43 2009 : Debug: Listening on command file /var/run/radiusd/radiusd.sock Wed Apr 15 13:43:43 2009 : Debug: Listening on proxy address * port 1647 Wed Apr 15 13:43:43 2009 : Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 62589, id=219, length=85 User-Name = "00:1f:3a:21:62:f8" User-Password = "00:1f:3a:21:62:f8" NAS-IP-Address = 10.10.10.76 NAS-Port = 1414 Wed Apr 15 13:43:45 2009 : Info: +- entering group authorize {...} Wed Apr 15 13:43:45 2009 : Info: [preprocess] expand: %{User-Name} -> 00:1f:3a:21:62:f8 Wed Apr 15 13:43:45 2009 : Info: [preprocess] hints: Matched DEFAULT at 37 Wed Apr 15 13:43:45 2009 : Info: ++[preprocess] returns ok Wed Apr 15 13:43:45 2009 : Info: [ldap] performing user authorization for 00:1f:3a:21:62:f8 Wed Apr 15 13:43:45 2009 : Info: [ldap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Wed Apr 15 13:43:45 2009 : Info: [ldap] expand: (&(%{Ldap-User}=%{Stripped-User-Name:-%{User-Name}})(aaaenable=1)) -> (&(macaddress=00:1f:3a:21:62:f8)(aaaenable=1)) Wed Apr 15 13:43:45 2009 : Info: [ldap] expand: dc=gwis -> dc=gwis Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: attempting LDAP reconnection Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: (re)connect to web3:389, authentication 0 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: bind as cn=test,dc=gwis/test to web3:389 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: waiting for bind result ... Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: Bind was successful Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: performing search in dc=gwis, with filter (&(macaddress=00:1f:3a:21:62:f8)(aaaenable=1)) Wed Apr 15 13:43:45 2009 : Info: [ldap] looking for check items in directory... Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: aaasimultaneoususe -> Simultaneous-Use == 1 Wed Apr 15 13:43:45 2009 : Info: [ldap] looking for reply items in directory... Wed Apr 15 13:43:45 2009 : Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Wed Apr 15 13:43:45 2009 : Info: [ldap] Setting Auth-Type = LDAP Wed Apr 15 13:43:45 2009 : Info: [ldap] user 00:1f:3a:21:62:f8 authorized to use remote access Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Wed Apr 15 13:43:45 2009 : Info: ++[ldap] returns ok Wed Apr 15 13:43:45 2009 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Wed Apr 15 13:43:45 2009 : Info: ++[pap] returns noop Wed Apr 15 13:43:45 2009 : Info: Found Auth-Type = LDAP Wed Apr 15 13:43:45 2009 : Info: +- entering group LDAP {...} Wed Apr 15 13:43:45 2009 : Info: [ldap] login attempt by "00:1f:3a:21:62:f8" with password "00:1f:3a:21:62:f8" Wed Apr 15 13:43:45 2009 : Info: [ldap] user DN: cn=testing1@nsab.us,dc=gwis Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: (re)connect to web3:389, authentication 1 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: bind as cn=testing1@nsab.us,dc=gwis/00:1f:3a:21:62:f8 to web3:389 Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: waiting for bind result ... Wed Apr 15 13:43:45 2009 : Debug: rlm_ldap: Bind failed with invalid credentials Wed Apr 15 13:43:45 2009 : Info: ++[ldap] returns reject Wed Apr 15 13:43:45 2009 : Info: Failed to authenticate the user. Wed Apr 15 13:43:45 2009 : Auth: Login incorrect (rlm_ldap: Bind as user failed): [00:1f:3a:21:62:f8/00:1f:3a:21:62:f8] (from client localhost port 1414) Wed Apr 15 13:43:45 2009 : Info: Using Post-Auth-Type Reject Wed Apr 15 13:43:45 2009 : Info: +- entering group REJECT {...} Wed Apr 15 13:43:45 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 00:1f:3a:21:62:f8 Wed Apr 15 13:43:45 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Wed Apr 15 13:43:45 2009 : Info: ++[attr_filter.access_reject] returns updated Sending Access-Reject of id 219 to 127.0.0.1 port 62589 Wed Apr 15 13:43:45 2009 : Info: Finished request 0. Wed Apr 15 13:43:45 2009 : Debug: Going to the next request Wed Apr 15 13:43:45 2009 : Debug: Waking up in 4.9 seconds. LDAP auth of mac addresses works if I set password_attribute = "macaddress", but not all requests will contain a mac address for a user which is why I need to make it dynamic. On Wed, Apr 15, 2009 at 11:26 AM, Alan DeKok <aland@deployingradius.com>wrote:
James Devine wrote:
That didn't seem to work. What I am trying to do is authenticate an access request in which I am given a mac address for both the username and password, so I was going to try to use the mac address attribute for both. The authorization matches my filter, but authentication fails even with auto_header turned on, although authentication succeeds with correct userPassword credentials.
Would it be possible for you to show the debugging log as suggested in the README, FAQ, INSTALL, "man" page, and daily on this list?
You have repeatedly discussed a *solution*. We don't even know what the *problem* is yet.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html