Access request always return reject

[J Kephart]

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.