Access request always return reject

Good day! We've just compiled FR 2.2.7 on a CentOS 6.6 system, preparatory to migrating from our old 2.1.12 release. When we ran the initial test, under "radius -X," we got the expected reject, because there was no user named "test." We then added that user to the users file (the only change we made), with just the username and cleartext-password, and ran the test again, and it still returned a reject. I'm posting the output from "radius -X" below. We've essentially the same config on the older server, and we've never encountered the problem there, so it seems fairly obvious that something's wrong; we just can't tell what it is. I do see that it says "++[reject] = reject", but I'm not seeing the cause. One note however: In the output, at line 190, we see "server { # from file /usr/loc" followed by a bunch of gibberish. I'm not sure that's a real concern, but it does seem odd. In any case, the debug output is below. I'd appreciate it if someone could point me to the problem. Many thanks! Jim 1: Wed May 20 16:46:25 2015 : Info: radiusd: FreeRADIUS Version 2.2.7, for host x86_64-unknown-linux-gnu, built on May 20 2015 at 16:45:16 2: Wed May 20 16:46:25 2015 : Debug: Server was built with: 3: Wed May 20 16:46:25 2015 : Debug: accounting 4: Wed May 20 16:46:25 2015 : Debug: authentication 5: Wed May 20 16:46:25 2015 : Debug: WITH_DHCP 6: Wed May 20 16:46:25 2015 : Debug: WITH_VMPS 7: Wed May 20 16:46:25 2015 : Debug: Server core libs: 8: Wed May 20 16:46:25 2015 : Debug: ssl: OpenSSL 1.0.1e-fips 11 Feb 2013 9: Wed May 20 16:46:25 2015 : Info: Copyright (C) 1999-2015 The FreeRADIUS server project and contributors. 10: Wed May 20 16:46:25 2015 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A 11: Wed May 20 16:46:25 2015 : Info: PARTICULAR PURPOSE. 12: Wed May 20 16:46:25 2015 : Info: You may redistribute copies of FreeRADIUS under the terms of the 13: Wed May 20 16:46:25 2015 : Info: GNU General Public License. 14: Wed May 20 16:46:25 2015 : Info: For more information about these matters, see the file named COPYRIGHT. 15: Wed May 20 16:46:25 2015 : Info: Starting - reading configuration files ... 16: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/radiusd.conf 17: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/proxy.conf 18: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/clients.conf 19: Wed May 20 16:46:25 2015 : Debug: including files in directory /usr/local/etc/raddb/modules/ 20: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/wimax 21: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/chap 22: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/unix 23: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.example.com 24: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/always 25: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/mschap 26: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/detail 27: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/redis 28: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/detail.log 29: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/perl 30: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/radrelay 31: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/pap 32: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/preprocess 33: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/smsotp 34: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/otp 35: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/passwd 36: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/files 37: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/digest 38: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/policy 39: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/realm 40: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/dynamic_clients 41: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/opendirectory 42: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/sradutmp 43: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/smbpasswd 44: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/echo 45: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/exec 46: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/logintime 47: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/cui 48: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/radutmp 49: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/expiration 50: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/acct_unique 51: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/krb5 52: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/ntlm_auth 53: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/checkval 54: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_filter 55: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/sql_log 56: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/counter 57: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/dhcp_sqlippool 58: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/sql/mysql/ippool-dhcp.conf 59: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/expr 60: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/cache 61: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/attr_rewrite 62: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2ip 63: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/ippool 64: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/linelog 65: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/pam 66: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/soh 67: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/ldap 68: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/sqlcounter_expire_on_login 69: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/inner-eap 70: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/mac2vlan 71: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/replicate 72: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/etc_group 73: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/modules/rediswho 74: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/eap.conf 75: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/policy.conf 76: Wed May 20 16:46:25 2015 : Debug: including files in directory /usr/local/etc/raddb/sites-enabled/ 77: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/default 78: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel 79: Wed May 20 16:46:25 2015 : Debug: including configuration file /usr/local/etc/raddb/sites-enabled/control-socket 80: Wed May 20 16:46:25 2015 : Debug: main { 81: Wed May 20 16:46:25 2015 : Debug: allow_core_dumps = no 82: Wed May 20 16:46:25 2015 : Debug: } 83: Wed May 20 16:46:25 2015 : Debug: including dictionary file /usr/local/etc/raddb/dictionary 84: Wed May 20 16:46:25 2015 : Debug: main { 85: Wed May 20 16:46:25 2015 : Debug: name = "radiusd" 86: Wed May 20 16:46:25 2015 : Debug: prefix = "/usr/local" 87: Wed May 20 16:46:25 2015 : Debug: localstatedir = "/usr/local/var" 88: Wed May 20 16:46:25 2015 : Debug: sbindir = "/usr/local/sbin" 89: Wed May 20 16:46:25 2015 : Debug: logdir = "/var/log/radius" 90: Wed May 20 16:46:25 2015 : Debug: run_dir = "/usr/local/var/run/radiusd" 91: Wed May 20 16:46:25 2015 : Debug: libdir = "/usr/local/lib" 92: Wed May 20 16:46:25 2015 : Debug: radacctdir = "/var/log/radius/radacct" 93: Wed May 20 16:46:25 2015 : Debug: hostname_lookups = no 94: Wed May 20 16:46:25 2015 : Debug: max_request_time = 30 95: Wed May 20 16:46:25 2015 : Debug: cleanup_delay = 5 96: Wed May 20 16:46:25 2015 : Debug: max_requests = 1024 97: Wed May 20 16:46:25 2015 : Debug: pidfile = "/usr/local/var/run/radiusd/radiusd.pid" 98: Wed May 20 16:46:25 2015 : Debug: checkrad = "/usr/local/sbin/checkrad" 99: Wed May 20 16:46:25 2015 : Debug: debug_level = 0 100: Wed May 20 16:46:25 2015 : Debug: proxy_requests = yes 101: Wed May 20 16:46:25 2015 : Debug: log { 102: Wed May 20 16:46:25 2015 : Debug: stripped_names = no 103: Wed May 20 16:46:25 2015 : Debug: auth = no 104: Wed May 20 16:46:25 2015 : Debug: auth_badpass = no 105: Wed May 20 16:46:25 2015 : Debug: auth_goodpass = no 106: Wed May 20 16:46:25 2015 : Debug: } 107: Wed May 20 16:46:25 2015 : Debug: security { 108: Wed May 20 16:46:25 2015 : Debug: max_attributes = 200 109: Wed May 20 16:46:25 2015 : Debug: reject_delay = 1 110: Wed May 20 16:46:25 2015 : Debug: status_server = yes 111: Wed May 20 16:46:25 2015 : Debug: allow_vulnerable_openssl = yes 112: Wed May 20 16:46:25 2015 : Debug: } 113: Wed May 20 16:46:25 2015 : Debug: } 114: Wed May 20 16:46:25 2015 : Debug: radiusd: #### Loading Realms and Home Servers #### 115: Wed May 20 16:46:25 2015 : Debug: proxy server { 116: Wed May 20 16:46:25 2015 : Debug: retry_delay = 5 117: Wed May 20 16:46:25 2015 : Debug: retry_count = 3 118: Wed May 20 16:46:25 2015 : Debug: default_fallback = no 119: Wed May 20 16:46:25 2015 : Debug: dead_time = 120 120: Wed May 20 16:46:25 2015 : Debug: wake_all_if_all_dead = no 121: Wed May 20 16:46:25 2015 : Debug: } 122: Wed May 20 16:46:25 2015 : Debug: home_server localhost { 123: Wed May 20 16:46:25 2015 : Debug: ipaddr = 127.0.0.1 124: Wed May 20 16:46:25 2015 : Debug: port = 1812 125: Wed May 20 16:46:25 2015 : Debug: type = "auth" 126: Wed May 20 16:46:25 2015 : Debug: secret = "testing123" 127: Wed May 20 16:46:25 2015 : Debug: response_window = 20 128: Wed May 20 16:46:25 2015 : Debug: max_outstanding = 65536 129: Wed May 20 16:46:25 2015 : Debug: require_message_authenticator = yes 130: Wed May 20 16:46:25 2015 : Debug: zombie_period = 40 131: Wed May 20 16:46:25 2015 : Debug: status_check = "status-server" 132: Wed May 20 16:46:25 2015 : Debug: ping_interval = 30 133: Wed May 20 16:46:25 2015 : Debug: check_interval = 30 134: Wed May 20 16:46:25 2015 : Debug: num_answers_to_alive = 3 135: Wed May 20 16:46:25 2015 : Debug: num_pings_to_alive = 3 136: Wed May 20 16:46:25 2015 : Debug: revive_interval = 120 137: Wed May 20 16:46:25 2015 : Debug: status_check_timeout = 4 138: Wed May 20 16:46:25 2015 : Debug: coa { 139: Wed May 20 16:46:25 2015 : Debug: irt = 2 140: Wed May 20 16:46:25 2015 : Debug: mrt = 16 141: Wed May 20 16:46:25 2015 : Debug: mrc = 5 142: Wed May 20 16:46:25 2015 : Debug: mrd = 30 143: Wed May 20 16:46:25 2015 : Debug: } 144: Wed May 20 16:46:25 2015 : Debug: } 145: Wed May 20 16:46:25 2015 : Debug: home_server_pool my_auth_failover { 146: Wed May 20 16:46:25 2015 : Debug: type = fail-over 147: Wed May 20 16:46:25 2015 : Debug: home_server = localhost 148: Wed May 20 16:46:25 2015 : Debug: } 149: Wed May 20 16:46:25 2015 : Debug: realm example.com { 150: Wed May 20 16:46:25 2015 : Debug: auth_pool = my_auth_failover 151: Wed May 20 16:46:25 2015 : Debug: } 152: Wed May 20 16:46:25 2015 : Debug: realm LOCAL { 153: Wed May 20 16:46:25 2015 : Debug: } 154: Wed May 20 16:46:25 2015 : Debug: radiusd: #### Loading Clients #### 155: Wed May 20 16:46:25 2015 : Debug: client localhost { 156: Wed May 20 16:46:25 2015 : Debug: ipaddr = 127.0.0.1 157: Wed May 20 16:46:25 2015 : Debug: require_message_authenticator = no 158: Wed May 20 16:46:25 2015 : Debug: secret = "testing123" 159: Wed May 20 16:46:25 2015 : Debug: nastype = "other" 160: Wed May 20 16:46:25 2015 : Debug: } 161: Wed May 20 16:46:25 2015 : Debug: radiusd: #### Instantiating modules #### 162: Wed May 20 16:46:25 2015 : Debug: instantiate { 163: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_exec, checking if it's valid) 164: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_exec 165: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "exec" from file /usr/local/etc/raddb/modules/exec 166: Wed May 20 16:46:25 2015 : Debug: exec { 167: Wed May 20 16:46:25 2015 : Debug: wait = no 168: Wed May 20 16:46:25 2015 : Debug: input_pairs = "request" 169: Wed May 20 16:46:25 2015 : Debug: shell_escape = yes 170: Wed May 20 16:46:25 2015 : Debug: timeout = 10 171: Wed May 20 16:46:25 2015 : Debug: } 172: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_expr, checking if it's valid) 173: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_expr 174: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "expr" from file /usr/local/etc/raddb/modules/expr 175: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_expiration, checking if it's valid) 176: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_expiration 177: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "expiration" from file /usr/local/etc/raddb/modules/expiration 178: Wed May 20 16:46:25 2015 : Debug: expiration { 179: Wed May 20 16:46:25 2015 : Debug: reply-message = "Password Has Expired " 180: Wed May 20 16:46:25 2015 : Debug: } 181: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_logintime, checking if it's valid) 182: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_logintime 183: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "logintime" from file /usr/local/etc/raddb/modules/logintime 184: Wed May 20 16:46:25 2015 : Debug: logintime { 185: Wed May 20 16:46:25 2015 : Debug: reply-message = "You are calling outside your allowed timespan " 186: Wed May 20 16:46:25 2015 : Debug: minimum-timeout = 60 187: Wed May 20 16:46:25 2015 : Debug: } 188: Wed May 20 16:46:25 2015 : Debug: } 189: Wed May 20 16:46:25 2015 : Debug: radiusd: #### Loading Virtual Servers #### 190: Wed May 20 16:46:25 2015 : Debug: server { # from file /usr/loc\E0?Y\FD\FF 191: Wed May 20 16:46:25 2015 : Debug: modules { 192: Wed May 20 16:46:25 2015 : Debug: Module: Creating Auth-Type = digest 193: Wed May 20 16:46:25 2015 : Debug: Module: Checking authenticate {...} for more modules to load 194: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_pap, checking if it's valid) 195: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_pap 196: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "pap" from file /usr/local/etc/raddb/modules/pap 197: Wed May 20 16:46:25 2015 : Debug: pap { 198: Wed May 20 16:46:25 2015 : Debug: encryption_scheme = "auto" 199: Wed May 20 16:46:25 2015 : Debug: auto_header = no 200: Wed May 20 16:46:25 2015 : Debug: } 201: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_chap, checking if it's valid) 202: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_chap 203: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "chap" from file /usr/local/etc/raddb/modules/chap 204: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_mschap, checking if it's valid) 205: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_mschap 206: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "mschap" from file /usr/local/etc/raddb/modules/mschap 207: Wed May 20 16:46:25 2015 : Debug: mschap { 208: Wed May 20 16:46:25 2015 : Debug: use_mppe = yes 209: Wed May 20 16:46:25 2015 : Debug: require_encryption = no 210: Wed May 20 16:46:25 2015 : Debug: require_strong = no 211: Wed May 20 16:46:25 2015 : Debug: with_ntdomain_hack = no 212: Wed May 20 16:46:25 2015 : Debug: allow_retry = yes 213: Wed May 20 16:46:25 2015 : Debug: } 214: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_digest, checking if it's valid) 215: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_digest 216: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "digest" from file /usr/local/etc/raddb/modules/digest 217: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_unix, checking if it's valid) 218: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_unix 219: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "unix" from file /usr/local/etc/raddb/modules/unix 220: Wed May 20 16:46:25 2015 : Debug: unix { 221: Wed May 20 16:46:25 2015 : Debug: radwtmp = "/var/log/radius/radwtmp" 222: Wed May 20 16:46:25 2015 : Debug: } 223: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_eap, checking if it's valid) 224: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_eap 225: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "eap" from file /usr/local/etc/raddb/eap.conf 226: Wed May 20 16:46:25 2015 : Debug: eap { 227: Wed May 20 16:46:25 2015 : Debug: default_eap_type = "md5" 228: Wed May 20 16:46:25 2015 : Debug: timer_expire = 60 229: Wed May 20 16:46:25 2015 : Debug: ignore_unknown_eap_types = no 230: Wed May 20 16:46:25 2015 : Debug: cisco_accounting_username_bug = no 231: Wed May 20 16:46:25 2015 : Debug: max_sessions = 1024 232: Wed May 20 16:46:25 2015 : Debug: } 233: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_md5 234: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-md5 235: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_leap 236: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-leap 237: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_gtc 238: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-gtc 239: Wed May 20 16:46:25 2015 : Debug: gtc { 240: Wed May 20 16:46:25 2015 : Debug: challenge = "Password: " 241: Wed May 20 16:46:25 2015 : Debug: auth_type = "PAP" 242: Wed May 20 16:46:25 2015 : Debug: } 243: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_tls 244: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-tls 245: Wed May 20 16:46:25 2015 : Debug: tls { 246: Wed May 20 16:46:25 2015 : Debug: rsa_key_exchange = no 247: Wed May 20 16:46:25 2015 : Debug: dh_key_exchange = yes 248: Wed May 20 16:46:25 2015 : Debug: rsa_key_length = 512 249: Wed May 20 16:46:25 2015 : Debug: dh_key_length = 512 250: Wed May 20 16:46:25 2015 : Debug: verify_depth = 0 251: Wed May 20 16:46:25 2015 : Debug: CA_path = "/usr/local/etc/raddb/certs" 252: Wed May 20 16:46:25 2015 : Debug: pem_file_type = yes 253: Wed May 20 16:46:25 2015 : Debug: private_key_file = "/usr/local/etc/raddb/certs/server.pem" 254: Wed May 20 16:46:25 2015 : Debug: certificate_file = "/usr/local/etc/raddb/certs/server.pem" 255: Wed May 20 16:46:25 2015 : Debug: CA_file = "/usr/local/etc/raddb/certs/ca.pem" 256: Wed May 20 16:46:25 2015 : Debug: private_key_password = "whatever" 257: Wed May 20 16:46:25 2015 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh" 258: Wed May 20 16:46:25 2015 : Debug: fragment_size = 1024 259: Wed May 20 16:46:25 2015 : Debug: include_length = yes 260: Wed May 20 16:46:25 2015 : Debug: check_crl = no 261: Wed May 20 16:46:25 2015 : Debug: cipher_list = "DEFAULT" 262: Wed May 20 16:46:25 2015 : Debug: make_cert_command = "/usr/local/etc/raddb/certs/bootstrap" 263: Wed May 20 16:46:25 2015 : Debug: ecdh_curve = "prime256v1" 264: Wed May 20 16:46:25 2015 : Debug: cache { 265: Wed May 20 16:46:25 2015 : Debug: enable = no 266: Wed May 20 16:46:25 2015 : Debug: lifetime = 24 267: Wed May 20 16:46:25 2015 : Debug: max_entries = 255 268: Wed May 20 16:46:25 2015 : Debug: } 269: Wed May 20 16:46:25 2015 : Debug: verify { 270: Wed May 20 16:46:25 2015 : Debug: } 271: Wed May 20 16:46:25 2015 : Debug: ocsp { 272: Wed May 20 16:46:25 2015 : Debug: enable = no 273: Wed May 20 16:46:25 2015 : Debug: override_cert_url = yes 274: Wed May 20 16:46:25 2015 : Debug: url = "http://127.0.0.1/ocsp/" 275: Wed May 20 16:46:25 2015 : Debug: use_nonce = yes 276: Wed May 20 16:46:25 2015 : Debug: timeout = 0 277: Wed May 20 16:46:25 2015 : Debug: softfail = no 278: Wed May 20 16:46:25 2015 : Debug: } 279: Wed May 20 16:46:25 2015 : Debug: } 280: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_ttls 281: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-ttls 282: Wed May 20 16:46:25 2015 : Debug: ttls { 283: Wed May 20 16:46:25 2015 : Debug: default_eap_type = "md5" 284: Wed May 20 16:46:25 2015 : Debug: copy_request_to_tunnel = no 285: Wed May 20 16:46:25 2015 : Debug: use_tunneled_reply = no 286: Wed May 20 16:46:25 2015 : Debug: virtual_server = "inner-tunnel" 287: Wed May 20 16:46:25 2015 : Debug: include_length = yes 288: Wed May 20 16:46:25 2015 : Debug: } 289: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_peap 290: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-peap 291: Wed May 20 16:46:25 2015 : Debug: peap { 292: Wed May 20 16:46:25 2015 : Debug: default_eap_type = "mschapv2" 293: Wed May 20 16:46:25 2015 : Debug: copy_request_to_tunnel = no 294: Wed May 20 16:46:25 2015 : Debug: use_tunneled_reply = no 295: Wed May 20 16:46:25 2015 : Debug: proxy_tunneled_request_as_eap = yes 296: Wed May 20 16:46:25 2015 : Debug: virtual_server = "inner-tunnel" 297: Wed May 20 16:46:25 2015 : Debug: soh = no 298: Wed May 20 16:46:25 2015 : Debug: } 299: Wed May 20 16:46:25 2015 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 300: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating eap-mschapv2 301: Wed May 20 16:46:25 2015 : Debug: mschapv2 { 302: Wed May 20 16:46:25 2015 : Debug: with_ntdomain_hack = no 303: Wed May 20 16:46:25 2015 : Debug: send_error = no 304: Wed May 20 16:46:25 2015 : Debug: } 305: Wed May 20 16:46:25 2015 : Debug: Module: Checking authorize {...} for more modules to load 306: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_preprocess, checking if it's valid) 307: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_preprocess 308: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "preprocess" from file /usr/local/etc/raddb/modules/preprocess 309: Wed May 20 16:46:25 2015 : Debug: preprocess { 310: Wed May 20 16:46:25 2015 : Debug: huntgroups = "/usr/local/etc/raddb/huntgroups" 311: Wed May 20 16:46:25 2015 : Debug: hints = "/usr/local/etc/raddb/hints" 312: Wed May 20 16:46:25 2015 : Debug: with_ascend_hack = no 313: Wed May 20 16:46:25 2015 : Debug: ascend_channels_per_line = 23 314: Wed May 20 16:46:25 2015 : Debug: with_ntdomain_hack = no 315: Wed May 20 16:46:25 2015 : Debug: with_specialix_jetstream_hack = no 316: Wed May 20 16:46:25 2015 : Debug: with_cisco_vsa_hack = no 317: Wed May 20 16:46:25 2015 : Debug: with_alvarion_vsa_hack = no 318: Wed May 20 16:46:25 2015 : Debug: } 319: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/huntgroups 320: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/hints 321: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_realm, checking if it's valid) 322: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_realm 323: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "suffix" from file /usr/local/etc/raddb/modules/realm 324: Wed May 20 16:46:25 2015 : Debug: realm suffix { 325: Wed May 20 16:46:25 2015 : Debug: format = "suffix" 326: Wed May 20 16:46:25 2015 : Debug: delimiter = "@" 327: Wed May 20 16:46:25 2015 : Debug: ignore_default = no 328: Wed May 20 16:46:25 2015 : Debug: ignore_null = no 329: Wed May 20 16:46:25 2015 : Debug: } 330: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_always, checking if it's valid) 331: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_always 332: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "reject" from file /usr/local/etc/raddb/modules/always 333: Wed May 20 16:46:25 2015 : Debug: always reject { 334: Wed May 20 16:46:25 2015 : Debug: rcode = "reject" 335: Wed May 20 16:46:25 2015 : Debug: simulcount = 0 336: Wed May 20 16:46:25 2015 : Debug: mpp = no 337: Wed May 20 16:46:25 2015 : Debug: } 338: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_files, checking if it's valid) 339: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_files 340: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "files" from file /usr/local/etc/raddb/modules/files 341: Wed May 20 16:46:25 2015 : Debug: files { 342: Wed May 20 16:46:25 2015 : Debug: usersfile = "/usr/local/etc/raddb/users" 343: Wed May 20 16:46:25 2015 : Debug: acctusersfile = "/usr/local/etc/raddb/acct_users" 344: Wed May 20 16:46:25 2015 : Debug: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users" 345: Wed May 20 16:46:25 2015 : Debug: compat = "no" 346: Wed May 20 16:46:25 2015 : Debug: } 347: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/users 348: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/acct_users 349: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/preproxy_users 350: Wed May 20 16:46:25 2015 : Debug: Module: Checking preacct {...} for more modules to load 351: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_acct_unique, checking if it's valid) 352: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_acct_unique 353: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "acct_unique" from file /usr/local/etc/raddb/modules/acct_unique 354: Wed May 20 16:46:25 2015 : Debug: acct_unique { 355: Wed May 20 16:46:25 2015 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, NAS-Identifier, NAS-Port" 356: Wed May 20 16:46:25 2015 : Debug: } 357: Wed May 20 16:46:25 2015 : Debug: Module: Checking accounting {...} for more modules to load 358: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_detail, checking if it's valid) 359: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_detail 360: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "detail" from file /usr/local/etc/raddb/modules/detail 361: Wed May 20 16:46:25 2015 : Debug: detail { 362: Wed May 20 16:46:25 2015 : Debug: detailfile = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" 363: Wed May 20 16:46:25 2015 : Debug: header = "%t" 364: Wed May 20 16:46:25 2015 : Debug: detailperm = 384 365: Wed May 20 16:46:25 2015 : Debug: dirperm = 493 366: Wed May 20 16:46:25 2015 : Debug: locking = no 367: Wed May 20 16:46:25 2015 : Debug: log_packet_header = no 368: Wed May 20 16:46:25 2015 : Debug: escape_filenames = no 369: Wed May 20 16:46:25 2015 : Debug: } 370: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_attr_filter, checking if it's valid) 371: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_attr_filter 372: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/modules/attr_filter 373: Wed May 20 16:46:25 2015 : Debug: attr_filter attr_filter.accounting_response { 374: Wed May 20 16:46:25 2015 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.accounting_response" 375: Wed May 20 16:46:25 2015 : Debug: key = "%{User-Name}" 376: Wed May 20 16:46:25 2015 : Debug: relaxed = no 377: Wed May 20 16:46:25 2015 : Debug: } 378: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.accounting_response 379: Wed May 20 16:46:25 2015 : Debug: Module: Checking session {...} for more modules to load 380: Wed May 20 16:46:25 2015 : Debug: (Loaded rlm_radutmp, checking if it's valid) 381: Wed May 20 16:46:25 2015 : Debug: Module: Linked to module rlm_radutmp 382: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "radutmp" from file /usr/local/etc/raddb/modules/radutmp 383: Wed May 20 16:46:25 2015 : Debug: radutmp { 384: Wed May 20 16:46:25 2015 : Debug: filename = "/var/log/radius/radutmp" 385: Wed May 20 16:46:25 2015 : Debug: username = "%{User-Name}" 386: Wed May 20 16:46:25 2015 : Debug: case_sensitive = yes 387: Wed May 20 16:46:25 2015 : Debug: check_with_nas = yes 388: Wed May 20 16:46:25 2015 : Debug: perm = 384 389: Wed May 20 16:46:25 2015 : Debug: callerid = yes 390: Wed May 20 16:46:25 2015 : Debug: } 391: Wed May 20 16:46:25 2015 : Debug: Module: Checking post-proxy {...} for more modules to load 392: Wed May 20 16:46:25 2015 : Debug: Module: Checking post-auth {...} for more modules to load 393: Wed May 20 16:46:25 2015 : Debug: Module: Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/modules/attr_filter 394: Wed May 20 16:46:25 2015 : Debug: attr_filter attr_filter.access_reject { 395: Wed May 20 16:46:25 2015 : Debug: attrsfile = "/usr/local/etc/raddb/attrs.access_reject" 396: Wed May 20 16:46:25 2015 : Debug: key = "%{User-Name}" 397: Wed May 20 16:46:25 2015 : Debug: relaxed = no 398: Wed May 20 16:46:25 2015 : Debug: } 399: Wed May 20 16:46:25 2015 : Debug: reading pairlist file /usr/local/etc/raddb/attrs.access_reject 400: Wed May 20 16:46:25 2015 : Debug: } # modules 401: Wed May 20 16:46:25 2015 : Debug: } # server 402: Wed May 20 16:46:25 2015 : Debug: server inner-tunnel { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel 403: Wed May 20 16:46:25 2015 : Debug: modules { 404: Wed May 20 16:46:25 2015 : Debug: Module: Checking authenticate {...} for more modules to load 405: Wed May 20 16:46:25 2015 : Debug: Module: Checking authorize {...} for more modules to load 406: Wed May 20 16:46:25 2015 : Debug: Module: Checking session {...} for more modules to load 407: Wed May 20 16:46:25 2015 : Debug: Module: Checking post-proxy {...} for more modules to load 408: Wed May 20 16:46:25 2015 : Debug: Module: Checking post-auth {...} for more modules to load 409: Wed May 20 16:46:25 2015 : Debug: } # modules 410: Wed May 20 16:46:25 2015 : Debug: } # server 411: Wed May 20 16:46:25 2015 : Debug: radiusd: #### Opening IP addresses and Ports #### 412: Wed May 20 16:46:25 2015 : Debug: listen { 413: Wed May 20 16:46:25 2015 : Debug: type = "auth" 414: Wed May 20 16:46:25 2015 : Debug: ipaddr = * 415: Wed May 20 16:46:25 2015 : Debug: port = 0 416: Wed May 20 16:46:25 2015 : Debug: } 417: Wed May 20 16:46:25 2015 : Debug: listen { 418: Wed May 20 16:46:25 2015 : Debug: type = "acct" 419: Wed May 20 16:46:25 2015 : Debug: ipaddr = * 420: Wed May 20 16:46:25 2015 : Debug: port = 0 421: Wed May 20 16:46:25 2015 : Debug: } 422: Wed May 20 16:46:25 2015 : Debug: listen { 423: Wed May 20 16:46:25 2015 : Debug: type = "control" 424: Wed May 20 16:46:25 2015 : Debug: listen { 425: Wed May 20 16:46:25 2015 : Debug: socket = "/usr/local/var/run/radiusd/radiusd.sock" 426: Wed May 20 16:46:25 2015 : Debug: } 427: Wed May 20 16:46:25 2015 : Debug: } 428: Wed May 20 16:46:25 2015 : Debug: listen { 429: Wed May 20 16:46:25 2015 : Debug: type = "auth" 430: Wed May 20 16:46:25 2015 : Debug: ipaddr = 127.0.0.1 431: Wed May 20 16:46:25 2015 : Debug: port = 18120 432: Wed May 20 16:46:25 2015 : Debug: } 433: Wed May 20 16:46:25 2015 : Debug: ... adding new socket proxy address * port 49326 434: Wed May 20 16:46:25 2015 : Debug: Listening on authentication address * port 1812 435: Wed May 20 16:46:25 2015 : Debug: Listening on accounting address * port 1813 436: Wed May 20 16:46:25 2015 : Debug: Listening on command file /usr/local/var/run/radiusd/radiusd.sock 437: Wed May 20 16:46:25 2015 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel 438: Wed May 20 16:46:25 2015 : Debug: Listening on proxy address * port 1814 439: Wed May 20 16:46:25 2015 : Info: Ready to process requests. 440: rad_recv: Access-Request packet from host 127.0.0.1 port 38078, id=59, length=74 441: User-Name = "test" 442: User-Password = "test" 443: NAS-IP-Address = xx.xx.xx.xx 444: NAS-Port = 0 445: Message-Authenticator = 0x7aa095c3bdfd6bc29db406eaa142ef44 446: Wed May 20 16:46:28 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default 447: Wed May 20 16:46:28 2015 : Info: +group authorize { 448: Wed May 20 16:46:28 2015 : Info: ++[preprocess] = ok 449: Wed May 20 16:46:28 2015 : Info: ++[chap] = noop 450: Wed May 20 16:46:28 2015 : Info: ++[mschap] = noop 451: Wed May 20 16:46:28 2015 : Info: ++[digest] = noop 452: Wed May 20 16:46:28 2015 : Info: [suffix] No '@' in User-Name = "test", looking up realm NULL 453: Wed May 20 16:46:28 2015 : Info: [suffix] No such realm "NULL" 454: Wed May 20 16:46:28 2015 : Info: ++[suffix] = noop 455: Wed May 20 16:46:28 2015 : Info: [eap] No EAP-Message, not doing EAP 456: Wed May 20 16:46:28 2015 : Info: ++[eap] = noop 457: Wed May 20 16:46:28 2015 : Info: ++[reject] = reject 458: Wed May 20 16:46:28 2015 : Info: +} # group authorize = reject 459: Wed May 20 16:46:28 2015 : Info: Using Post-Auth-Type Reject 460: Wed May 20 16:46:28 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default 461: Wed May 20 16:46:28 2015 : Info: +group REJECT { 462: Wed May 20 16:46:28 2015 : Info: [eap] Request didn't contain an EAP-Message, not inserting EAP-Failure 463: Wed May 20 16:46:28 2015 : Info: ++[eap] = noop 464: Wed May 20 16:46:28 2015 : Info: [attr_filter.access_reject] expand: %{User-Name} -> test 465: Wed May 20 16:46:28 2015 : Debug: attr_filter: Matched entry DEFAULT at line 11 466: Wed May 20 16:46:28 2015 : Info: ++[attr_filter.access_reject] = updated 467: Wed May 20 16:46:28 2015 : Info: +} # group REJECT = updated 468: Wed May 20 16:46:28 2015 : Info: Delaying reject of request 0 for 1 seconds 469: Wed May 20 16:46:28 2015 : Debug: Going to the next request 470: Wed May 20 16:46:28 2015 : Debug: Waking up in 0.9 seconds. 471: Wed May 20 16:46:29 2015 : Info: Sending delayed reject for request 0 472: Sending Access-Reject of id 59 to 127.0.0.1 port 38078 473: Wed May 20 16:46:29 2015 : Debug: Waking up in 4.9 seconds. 474: Wed May 20 16:46:34 2015 : Info: Cleaning up request 0 ID 59 with timestamp +3 475: Wed May 20 16:46:34 2015 : Info: Ready to process requests.