Hello everybody,<br><div class="gmail_quote"><div class="gmail_quote"><div class="gmail_quote"><div class="gmail_quote"><div class="im"><div><br>We are using freeradius (Version 2.1.9) to serve access requests for 802.1x, using PEAP/EAP/MSCHAPv2 (windows7). We use LDAP for authentication (user accounts) and authorization (Ldap-Groups).<br>
We also tunneled the request to the same radius for our realm "<a href="http://unav.es" target="_blank">unav.es</a>".<br>
<br>I am having some problems using huntgroups to identified the origin of a request.<br>I have simplified the test trying to find out the problem, but I do not understand what it is happening:<br><br>* It works ok when I use the following users file:<br>
----- users file ----- <br>DEFAULT Ldap-Group=="unav.radius.empleado"<br> Reply-Message = "Empleado from test switch"<br><br>DEFAULT Auth-Type := Reject<br> Reply-Message = "Access not allowed."<br>
----- <br><br></div>* But it fails when I check the huntgroup:<br><div>----- users file ----- <br>DEFAULT Huntgroup-Name == "huntpruebas", Ldap-Group=="unav.radius.empleado"<br> Reply-Message = "Empleado from test switch"<br>
<br>DEFAULT Auth-Type := Reject<br> Reply-Message = "Access not allowed."<br>----- <br><br></div></div>(The "notworking log" is appended at the end of the message. I had to trim it to make it shorter)<div>
<div class="h5"><br>
<div><div>
(The "workingok log" is not attached as it made this message bigger than allowed on this list).<br>
<br>I can see in the "not working log" that on the first requests the huntgroup is been recognised ok. I just do not understand why it tries again to check it, until it fails (request #9).<br>I also do not understand why it needs so many requests (12!) to work ok.<br>
<br>I will appreciate any help understanding what is happening, in order to find a solution for my problem.<br>If it is needed more log or config files, I can attached them without problem.<br><br>Thanks a lot.<br><br>====== Not working log ====== <br>
Thu Jan 19 12:34:20 2012 : Info: FreeRADIUS Version 2.1.9, for host i686-pc-linux-gnu, built on Oct 4 2010 at 13:35:26<br>[trimmed]<br>
Thu Jan 19 12:34:20 2012 : Debug: main {<br>Thu Jan 19 12:34:20 2012 : Debug: prefix = "/usr/local/etc2/freeradius"<br>Thu Jan 19 12:34:20 2012 : Debug: localstatedir = "/usr/local/etc2/freeradius/var"<br>
Thu Jan 19 12:34:20 2012 : Debug: logdir = "/usr/local/etc2/freeradius/var/log/radius"<br>Thu Jan 19 12:34:20 2012 : Debug: libdir = "/usr/local/etc2/freeradius/lib"<br>Thu Jan 19 12:34:20 2012 : Debug: radacctdir = "/usr/local/etc2/freeradius/var/log/radius/radacct"<br>
Thu Jan 19 12:34:20 2012 : Debug: hostname_lookups = no<br>Thu Jan 19 12:34:20 2012 : Debug: max_request_time = 30<br>Thu Jan 19 12:34:20 2012 : Debug: cleanup_delay = 5<br>Thu Jan 19 12:34:20 2012 : Debug: max_requests = 1024<br>
Thu Jan 19 12:34:20 2012 : Debug: pidfile = "/usr/local/etc2/freeradius/var/run/radiusd/radiusd.pid"<br>Thu Jan 19 12:34:20 2012 : Debug: checkrad = "/usr/local/etc2/freeradius/sbin/checkrad"<br>
Thu Jan 19 12:34:20 2012 : Debug: debug_level = 0<br>Thu Jan 19 12:34:20 2012 : Debug: proxy_requests = yes<br>Thu Jan 19 12:34:20 2012 : Debug: log {<br>Thu Jan 19 12:34:20 2012 : Debug: stripped_names = no<br>
Thu Jan 19 12:34:20 2012 : Debug: auth = no<br>Thu Jan 19 12:34:20 2012 : Debug: auth_badpass = no<br>Thu Jan 19 12:34:20 2012 : Debug: auth_goodpass = no<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: security {<br>
Thu Jan 19 12:34:20 2012 : Debug: max_attributes = 200<br>Thu Jan 19 12:34:20 2012 : Debug: reject_delay = 1<br>Thu Jan 19 12:34:20 2012 : Debug: status_server = yes<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Realms and Home Servers ####<br>Thu Jan 19 12:34:20 2012 : Debug: proxy server {<br>Thu Jan 19 12:34:20 2012 : Debug: retry_delay = 5<br>
Thu Jan 19 12:34:20 2012 : Debug: retry_count = 3<br>Thu Jan 19 12:34:20 2012 : Debug: default_fallback = yes<br>Thu Jan 19 12:34:20 2012 : Debug: dead_time = 120<br>Thu Jan 19 12:34:20 2012 : Debug: wake_all_if_all_dead = no<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: realm <a href="http://unav.es" target="_blank">unav.es</a> {<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: realm LOCAL {<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:20 2012 : Debug: home_server localhost {<br>Thu Jan 19 12:34:20 2012 : Debug: ipaddr = 127.0.0.1<br>Thu Jan 19 12:34:20 2012 : Debug: port = 1812<br>Thu Jan 19 12:34:20 2012 : Debug: type = "auth+acct"<br>
Thu Jan 19 12:34:20 2012 : Debug: secret = "testing123"<br>Thu Jan 19 12:34:20 2012 : Debug: response_window = 20<br>Thu Jan 19 12:34:20 2012 : Debug: max_outstanding = 65536<br>Thu Jan 19 12:34:20 2012 : Debug: require_message_authenticator = no<br>
Thu Jan 19 12:34:20 2012 : Debug: zombie_period = 40<br>Thu Jan 19 12:34:20 2012 : Debug: status_check = "status-server"<br>Thu Jan 19 12:34:20 2012 : Debug: ping_interval = 30<br>Thu Jan 19 12:34:20 2012 : Debug: check_interval = 30<br>
Thu Jan 19 12:34:20 2012 : Debug: num_answers_to_alive = 3<br>Thu Jan 19 12:34:20 2012 : Debug: num_pings_to_alive = 3<br>Thu Jan 19 12:34:20 2012 : Debug: revive_interval = 120<br>Thu Jan 19 12:34:20 2012 : Debug: status_check_timeout = 4<br>
Thu Jan 19 12:34:20 2012 : Debug: irt = 2<br>Thu Jan 19 12:34:20 2012 : Debug: mrt = 16<br>Thu Jan 19 12:34:20 2012 : Debug: mrc = 5<br>Thu Jan 19 12:34:20 2012 : Debug: mrd = 30<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:20 2012 : Debug: home_server_pool my_auth_failover {<br>Thu Jan 19 12:34:20 2012 : Debug: type = fail-over<br>Thu Jan 19 12:34:20 2012 : Debug: home_server = localhost<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Clients ####<br>Thu Jan 19 12:34:20 2012 : Debug: client localhost {<br>Thu Jan 19 12:34:20 2012 : Debug: ipaddr = 127.0.0.1<br>Thu Jan 19 12:34:20 2012 : Debug: require_message_authenticator = no<br>
Thu Jan 19 12:34:20 2012 : Debug: secret = "testing123"<br>Thu Jan 19 12:34:20 2012 : Debug: nastype = "other"<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: client naspruebas {<br>
Thu Jan 19 12:34:20 2012 : Debug: ipaddr = 159.237.8.200<br>Thu Jan 19 12:34:20 2012 : Debug: require_message_authenticator = no<br>Thu Jan 19 12:34:20 2012 : Debug: secret = "pruebas"<br>Thu Jan 19 12:34:20 2012 : Debug: shortname = "naspruebas"<br>
Thu Jan 19 12:34:20 2012 : Debug: nastype = "other"<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Instantiating modules ####<br>Thu Jan 19 12:34:20 2012 : Debug: instantiate {<br>
Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_exec, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_exec<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating exec<br>
Thu Jan 19 12:34:20 2012 : Debug: exec {<br>Thu Jan 19 12:34:20 2012 : Debug: wait = no<br>Thu Jan 19 12:34:20 2012 : Debug: input_pairs = "request"<br>Thu Jan 19 12:34:20 2012 : Debug: shell_escape = yes<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_expr, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_expr<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating expr<br>
Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_expiration, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_expiration<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating expiration<br>
Thu Jan 19 12:34:20 2012 : Debug: expiration {<br>Thu Jan 19 12:34:20 2012 : Debug: reply-message = "Password Has Expired "<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_logintime, checking if it's valid)<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_logintime<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating logintime<br>Thu Jan 19 12:34:20 2012 : Debug: logintime {<br>Thu Jan 19 12:34:20 2012 : Debug: reply-message = "You are calling outside your allowed timespan "<br>
Thu Jan 19 12:34:20 2012 : Debug: minimum-timeout = 60<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Virtual Servers ####<br>
Thu Jan 19 12:34:20 2012 : Debug: server inner-tunnel {<br>Thu Jan 19 12:34:20 2012 : Debug: modules {<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Checking authenticate {...} for more modules to load<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_pap, checking if it's valid)<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_pap<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating pap<br>Thu Jan 19 12:34:20 2012 : Debug: pap {<br>Thu Jan 19 12:34:20 2012 : Debug: encryption_scheme = "auto"<br>
Thu Jan 19 12:34:20 2012 : Debug: auto_header = no<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_chap, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_chap<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating chap<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_mschap, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_mschap<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating mschap<br>Thu Jan 19 12:34:20 2012 : Debug: mschap {<br>Thu Jan 19 12:34:20 2012 : Debug: use_mppe = yes<br>Thu Jan 19 12:34:20 2012 : Debug: require_encryption = yes<br>
Thu Jan 19 12:34:20 2012 : Debug: require_strong = yes<br>Thu Jan 19 12:34:20 2012 : Debug: with_ntdomain_hack = no<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_unix, checking if it's valid)<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_unix<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating unix<br>Thu Jan 19 12:34:20 2012 : Debug: unix {<br>Thu Jan 19 12:34:20 2012 : Debug: radwtmp = "/usr/local/etc2/freeradius/var/log/radius/radwtmp"<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_eap, checking if it's valid)<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_eap<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap<br>
Thu Jan 19 12:34:20 2012 : Debug: eap {<br>Thu Jan 19 12:34:20 2012 : Debug: default_eap_type = "md5"<br>Thu Jan 19 12:34:20 2012 : Debug: timer_expire = 60<br>Thu Jan 19 12:34:20 2012 : Debug: ignore_unknown_eap_types = no<br>
Thu Jan 19 12:34:20 2012 : Debug: cisco_accounting_username_bug = no<br>Thu Jan 19 12:34:20 2012 : Debug: max_sessions = 4096<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_md5<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-md5<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_leap<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-leap<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_gtc<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-gtc<br>Thu Jan 19 12:34:20 2012 : Debug: gtc {<br>Thu Jan 19 12:34:20 2012 : Debug: challenge = "Password: "<br>Thu Jan 19 12:34:20 2012 : Debug: auth_type = "PAP"<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_tls<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-tls<br>Thu Jan 19 12:34:20 2012 : Debug: tls {<br>
Thu Jan 19 12:34:20 2012 : Debug: rsa_key_exchange = no<br>Thu Jan 19 12:34:20 2012 : Debug: dh_key_exchange = yes<br>Thu Jan 19 12:34:20 2012 : Debug: rsa_key_length = 512<br>Thu Jan 19 12:34:20 2012 : Debug: dh_key_length = 512<br>
Thu Jan 19 12:34:20 2012 : Debug: verify_depth = 0<br>Thu Jan 19 12:34:20 2012 : Debug: pem_file_type = yes<br>Thu Jan 19 12:34:20 2012 : Debug: private_key_file = "/usr/local/etc2/freeradius/etc/raddb/certs/radius.unav.es_privatekey.pem"<br>
Thu Jan 19 12:34:20 2012 : Debug: certificate_file = "/usr/local/etc2/freeradius/etc/raddb/certs/radius.unav.es_cert.pem"<br>Thu Jan 19 12:34:20 2012 : Debug: CA_file = "/usr/local/etc2/freeradius/etc/raddb/certs/TERENASSL_PATH.pem"<br>
Thu Jan 19 12:34:20 2012 : Debug: dh_file = "/usr/local/etc2/freeradius/etc/raddb/certs/dh"<br>Thu Jan 19 12:34:20 2012 : Debug: random_file = "/usr/local/etc2/freeradius/etc/raddb/certs/random"<br>
Thu Jan 19 12:34:20 2012 : Debug: fragment_size = 1024<br>Thu Jan 19 12:34:20 2012 : Debug: include_length = yes<br>Thu Jan 19 12:34:20 2012 : Debug: check_crl = no<br>Thu Jan 19 12:34:20 2012 : Debug: cipher_list = "DEFAULT"<br>
Thu Jan 19 12:34:20 2012 : Debug: make_cert_command = "/usr/local/etc2/freeradius/etc/raddb/certs/bootstrap"<br>Thu Jan 19 12:34:20 2012 : Debug: cache {<br>Thu Jan 19 12:34:20 2012 : Debug: enable = no<br>
Thu Jan 19 12:34:20 2012 : Debug: lifetime = 24<br>Thu Jan 19 12:34:20 2012 : Debug: max_entries = 255<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_ttls<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-ttls<br>Thu Jan 19 12:34:20 2012 : Debug: ttls {<br>Thu Jan 19 12:34:20 2012 : Debug: default_eap_type = "md5"<br>Thu Jan 19 12:34:20 2012 : Debug: copy_request_to_tunnel = yes<br>
Thu Jan 19 12:34:20 2012 : Debug: use_tunneled_reply = no<br>Thu Jan 19 12:34:20 2012 : Debug: virtual_server = "inner-tunnel"<br>Thu Jan 19 12:34:20 2012 : Debug: include_length = yes<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_peap<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-peap<br>Thu Jan 19 12:34:20 2012 : Debug: peap {<br>Thu Jan 19 12:34:20 2012 : Debug: default_eap_type = "mschapv2"<br>
Thu Jan 19 12:34:20 2012 : Debug: copy_request_to_tunnel = yes<br>Thu Jan 19 12:34:20 2012 : Debug: use_tunneled_reply = no<br>Thu Jan 19 12:34:20 2012 : Debug: proxy_tunneled_request_as_eap = no<br>Thu Jan 19 12:34:20 2012 : Debug: virtual_server = "inner-tunnel"<br>
Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to sub-module rlm_eap_mschapv2<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating eap-mschapv2<br>Thu Jan 19 12:34:20 2012 : Debug: mschapv2 {<br>
Thu Jan 19 12:34:20 2012 : Debug: with_ntdomain_hack = no<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Checking authorize {...} for more modules to load<br>Thu Jan 19 12:34:20 2012 : Debug: (Loaded rlm_realm, checking if it's valid)<br>
Thu Jan 19 12:34:20 2012 : Debug: Module: Linked to module rlm_realm<br>Thu Jan 19 12:34:20 2012 : Debug: Module: Instantiating suffix<br>Thu Jan 19 12:34:20 2012 : Debug: realm suffix {<br>Thu Jan 19 12:34:20 2012 : Debug: format = "suffix"<br>
Thu Jan 19 12:34:20 2012 : Debug: delimiter = "@"<br>Thu Jan 19 12:34:20 2012 : Debug: ignore_default = no<br>Thu Jan 19 12:34:20 2012 : Debug: ignore_null = no<br>Thu Jan 19 12:34:20 2012 : Debug: }<br>
Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_files, checking if it's valid)<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_files<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating files<br>
Thu Jan 19 12:34:21 2012 : Debug: files {<br>Thu Jan 19 12:34:21 2012 : Debug: usersfile = "/usr/local/etc2/freeradius/etc/raddb/users"<br>Thu Jan 19 12:34:21 2012 : Debug: acctusersfile = "/usr/local/etc2/freeradius/etc/raddb/acct_users"<br>
Thu Jan 19 12:34:21 2012 : Debug: preproxy_usersfile = "/usr/local/etc2/freeradius/etc/raddb/preproxy_users"<br>Thu Jan 19 12:34:21 2012 : Debug: compat = "no"<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>
Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_ldap, checking if it's valid)<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_ldap<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating ldap<br>
Thu Jan 19 12:34:21 2012 : Debug: ldap {<br>Thu Jan 19 12:34:21 2012 : Debug: server = "<a href="http://ldappre.si.unav.es" target="_blank">ldappre.si.unav.es</a>"<br>Thu Jan 19 12:34:21 2012 : Debug: port = 389<br>
</div></div>
Thu Jan 19 12:34:21 2012 : Debug: password = "xxx"<br></div></div><div><div><div><div class="h5">
Thu Jan 19 12:34:21 2012 : Debug: identity = "cn=radiusOp,dc=unav,dc=es"<br>Thu Jan 19 12:34:21 2012 : Debug: net_timeout = 1<br>Thu Jan 19 12:34:21 2012 : Debug: timeout = 4<br>Thu Jan 19 12:34:21 2012 : Debug: timelimit = 3<br>
Thu Jan 19 12:34:21 2012 : Debug: tls_mode = no<br>Thu Jan 19 12:34:21 2012 : Debug: start_tls = no<br>Thu Jan 19 12:34:21 2012 : Debug: tls_require_cert = "allow"<br>Thu Jan 19 12:34:21 2012 : Debug: tls {<br>
Thu Jan 19 12:34:21 2012 : Debug: start_tls = yes<br>Thu Jan 19 12:34:21 2012 : Debug: require_cert = "allow"<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: basedn = "ou=radius,o=accounts,dc=unav,dc=es"<br>
Thu Jan 19 12:34:21 2012 : Debug: filter = "(uid=%{%{Stripped-User-Name}:-%{User-Name}})"<br>Thu Jan 19 12:34:21 2012 : Debug: base_filter = "(objectclass=radiusprofile)"<br>Thu Jan 19 12:34:21 2012 : Debug: password_attribute = "unavRadiusPasswd"<br>
Thu Jan 19 12:34:21 2012 : Debug: auto_header = no<br>Thu Jan 19 12:34:21 2012 : Debug: access_attr_used_for_allow = yes<br>Thu Jan 19 12:34:21 2012 : Debug: groupname_attribute = "cn"<br>Thu Jan 19 12:34:21 2012 : Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))"<br>
Thu Jan 19 12:34:21 2012 : Debug: groupmembership_attribute = "member"<br>Thu Jan 19 12:34:21 2012 : Debug: dictionary_mapping = "/usr/local/etc2/freeradius/etc/raddb/ldap.attrmap"<br>Thu Jan 19 12:34:21 2012 : Debug: ldap_debug = 104<br>
Thu Jan 19 12:34:21 2012 : Debug: ldap_connections_number = 10<br>Thu Jan 19 12:34:21 2012 : Debug: compare_check_items = no<br>Thu Jan 19 12:34:21 2012 : Debug: do_xlat = no<br>Thu Jan 19 12:34:21 2012 : Debug: set_auth_type = yes<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group<br>Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap<br>Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: Over-riding set_auth_type, as there is no module ldap listed in the "authenticate" section.<br>
Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: reading ldap<->radius mappings from file /usr/local/etc2/freeradius/etc/raddb/ldap.attrmap<br>[trimmed]<br>Thu Jan 19 12:34:21 2012 : Debug: conns: 0x830e3c0<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking session {...} for more modules to load<br>
Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_radutmp, checking if it's valid)<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_radutmp<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating radutmp<br>
Thu Jan 19 12:34:21 2012 : Debug: radutmp {<br>Thu Jan 19 12:34:21 2012 : Debug: filename = "/usr/local/etc2/freeradius/var/log/radius/radutmp"<br>Thu Jan 19 12:34:21 2012 : Debug: username = "%{User-Name}"<br>
Thu Jan 19 12:34:21 2012 : Debug: case_sensitive = yes<br>Thu Jan 19 12:34:21 2012 : Debug: check_with_nas = yes<br>Thu Jan 19 12:34:21 2012 : Debug: perm = 384<br>Thu Jan 19 12:34:21 2012 : Debug: callerid = yes<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking post-proxy {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking post-auth {...} for more modules to load<br>
Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_attr_filter, checking if it's valid)<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_attr_filter<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating attr_filter.access_reject<br>
Thu Jan 19 12:34:21 2012 : Debug: attr_filter attr_filter.access_reject {<br>Thu Jan 19 12:34:21 2012 : Debug: attrsfile = "/usr/local/etc2/freeradius/etc/raddb/attrs.access_reject"<br>Thu Jan 19 12:34:21 2012 : Debug: key = "%{User-Name}"<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: } # modules<br>Thu Jan 19 12:34:21 2012 : Debug: } # server<br>Thu Jan 19 12:34:21 2012 : Debug: server {<br>Thu Jan 19 12:34:21 2012 : Debug: modules {<br>
Thu Jan 19 12:34:21 2012 : Debug: Module: Checking authenticate {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking authorize {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_preprocess, checking if it's valid)<br>
Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_preprocess<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating preprocess<br>Thu Jan 19 12:34:21 2012 : Debug: preprocess {<br>Thu Jan 19 12:34:21 2012 : Debug: huntgroups = "/usr/local/etc2/freeradius/etc/raddb/huntgroups"<br>
Thu Jan 19 12:34:21 2012 : Debug: hints = "/usr/local/etc2/freeradius/etc/raddb/hints"<br>Thu Jan 19 12:34:21 2012 : Debug: with_ascend_hack = no<br>Thu Jan 19 12:34:21 2012 : Debug: ascend_channels_per_line = 23<br>
Thu Jan 19 12:34:21 2012 : Debug: with_ntdomain_hack = no<br>Thu Jan 19 12:34:21 2012 : Debug: with_specialix_jetstream_hack = no<br>Thu Jan 19 12:34:21 2012 : Debug: with_cisco_vsa_hack = no<br>Thu Jan 19 12:34:21 2012 : Debug: with_alvarion_vsa_hack = no<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking preacct {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_acct_unique, checking if it's valid)<br>
Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_acct_unique<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating acct_unique<br>Thu Jan 19 12:34:21 2012 : Debug: acct_unique {<br>Thu Jan 19 12:34:21 2012 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking accounting {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: (Loaded rlm_detail, checking if it's valid)<br>
Thu Jan 19 12:34:21 2012 : Debug: Module: Linked to module rlm_detail<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating detail<br>Thu Jan 19 12:34:21 2012 : Debug: detail {<br>Thu Jan 19 12:34:21 2012 : Debug: detailfile = "/usr/local/etc2/freeradius/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"<br>
Thu Jan 19 12:34:21 2012 : Debug: header = "%t"<br>Thu Jan 19 12:34:21 2012 : Debug: detailperm = 384<br>Thu Jan 19 12:34:21 2012 : Debug: dirperm = 493<br>Thu Jan 19 12:34:21 2012 : Debug: locking = no<br>
Thu Jan 19 12:34:21 2012 : Debug: log_packet_header = no<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Instantiating attr_filter.accounting_response<br>Thu Jan 19 12:34:21 2012 : Debug: attr_filter attr_filter.accounting_response {<br>
Thu Jan 19 12:34:21 2012 : Debug: attrsfile = "/usr/local/etc2/freeradius/etc/raddb/attrs.accounting_response"<br>Thu Jan 19 12:34:21 2012 : Debug: key = "%{User-Name}"<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>
Thu Jan 19 12:34:21 2012 : Debug: Module: Checking session {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking post-proxy {...} for more modules to load<br>Thu Jan 19 12:34:21 2012 : Debug: Module: Checking post-auth {...} for more modules to load<br>
Thu Jan 19 12:34:21 2012 : Debug: } # modules<br>Thu Jan 19 12:34:21 2012 : Debug: } # server<br>Thu Jan 19 12:34:21 2012 : Debug: radiusd: #### Opening IP addresses and Ports ####<br>Thu Jan 19 12:34:21 2012 : Debug: listen {<br>
Thu Jan 19 12:34:21 2012 : Debug: type = "auth"<br>Thu Jan 19 12:34:21 2012 : Debug: ipaddr = *<br>Thu Jan 19 12:34:21 2012 : Debug: port = 0<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: listen {<br>
Thu Jan 19 12:34:21 2012 : Debug: type = "acct"<br>Thu Jan 19 12:34:21 2012 : Debug: ipaddr = *<br>Thu Jan 19 12:34:21 2012 : Debug: port = 0<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: listen {<br>
Thu Jan 19 12:34:21 2012 : Debug: type = "control"<br>Thu Jan 19 12:34:21 2012 : Debug: listen {<br>Thu Jan 19 12:34:21 2012 : Debug: socket = "/usr/local/etc2/freeradius/var/run/radiusd/radiusd.sock"<br>
Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: }<br>Thu Jan 19 12:34:21 2012 : Debug: Listening on authentication address * port 1812<br>Thu Jan 19 12:34:21 2012 : Debug: Listening on accounting address * port 1813<br>
Thu Jan 19 12:34:21 2012 : Debug: Listening on command file /usr/local/etc2/freeradius/var/run/radiusd/radiusd.sock<br>Thu Jan 19 12:34:21 2012 : Debug: Listening on proxy address * port 1814<br>Thu Jan 19 12:34:21 2012 : Info: Ready to process requests.<br>
rad_recv: Access-Request packet from host 159.237.8.200 port 3490, id=46, length=124<br> NAS-IP-Address = 159.237.8.200<br> NAS-Port-Type = Ethernet<br> Service-Type = Framed-User<br> Message-Authenticator = 0xb666f25ec9310bf99e0ac965a3325f71<br>
NAS-Port = 5<br> Framed-MTU = 1490<br> User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br> Calling-Station-Id = "D0-67-E5-13-CC-17"<br> EAP-Message = 0x02ff00130163617261697a40756e61762e6573<br>
Thu Jan 19 12:35:17 2012 : Info: +- entering group authorize {...}<br>Thu Jan 19 12:35:17 2012 : Info: ++[preprocess] returns ok<br>Thu Jan 19 12:35:17 2012 : Info: ++[chap] returns noop<br>Thu Jan 19 12:35:17 2012 : Info: ++[mschap] returns noop<br>
Thu Jan 19 12:35:17 2012 : Info: [suffix] Looking up realm "<a href="http://unav.es" target="_blank">unav.es</a>" for User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br>
Thu Jan 19 12:35:17 2012 : Info: [suffix] Found realm "<a href="http://unav.es" target="_blank">unav.es</a>"<br>
Thu Jan 19 12:35:17 2012 : Info: [suffix] Adding Stripped-User-Name = "caraiz"<br>Thu Jan 19 12:35:17 2012 : Info: [suffix] Adding Realm = "<a href="http://unav.es" target="_blank">unav.es</a>"<br>Thu Jan 19 12:35:17 2012 : Info: [suffix] Authentication realm is LOCAL.<br>
Thu Jan 19 12:35:17 2012 : Info: ++[suffix] returns ok<br>Thu Jan 19 12:35:17 2012 : Info: [eap] EAP packet type response id 255 length 19<br>Thu Jan 19 12:35:17 2012 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation<br>
Thu Jan 19 12:35:17 2012 : Info: ++[eap] returns updated<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] Entering ldap_groupcmp()<br>Thu Jan 19 12:35:17 2012 : Info: [files] expand: ou=radius,o=accounts,dc=unav,dc=es -> ou=radius,o=accounts,dc=unav,dc=es<br>
Thu Jan 19 12:35:17 2012 : Info: [files] expand: %{Stripped-User-Name} -> caraiz<br>Thu Jan 19 12:35:17 2012 : Info: [files] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Checking Id: 0<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Got Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] attempting LDAP reconnection<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] (re)connect to <a href="http://ldappre.si.unav.es:389" target="_blank">ldappre.si.unav.es:389</a>, authentication 0<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] starting TLS<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] bind as cn=radiusOp,dc=unav,dc=es/RAD1bar to <a href="http://ldappre.si.unav.es:389" target="_blank">ldappre.si.unav.es:389</a><br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] waiting for bind result ...<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] Bind was successful<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_release_conn: Release Id: 0<br>
Thu Jan 19 12:35:17 2012 : Info: [files] expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Checking Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Got Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in ou=radius,o=accounts,dc=unav,dc=es, with filter (&(cn=unav.radius.empleado)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))))<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] object not found<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_release_conn: Release Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Checking Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Got Id: 0<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in uid=caraiz,ou=radius,o=accounts,dc=unav,dc=es, with filter (objectclass=*)<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in uid=unav.radius.arun,ou=groups,ou=radius,o=accounts,dc=unav,dc=es, with filter (cn=unav.radius.empleado)<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] object not found<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in uid=unav.radius.vpn,ou=groups,ou=radius,o=accounts,dc=unav,dc=es, with filter (cn=unav.radius.empleado)<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] object not found<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in uid=unav.radius.wireless,ou=groups,ou=radius,o=accounts,dc=unav,dc=es, with filter (cn=unav.radius.empleado)<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] object not found<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in uid=unav.radius.empleado,ou=groups,ou=radius,o=accounts,dc=unav,dc=es, with filter (cn=unav.radius.empleado)<br>
Thu Jan 19 12:35:17 2012 : Debug: rlm_ldap::ldap_groupcmp: User found in group unav.radius.empleado<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_release_conn: Release Id: 0<br>Thu Jan 19 12:35:17 2012 : Info: [files] users: Matched entry DEFAULT at line 1<br>
Thu Jan 19 12:35:17 2012 : Info: ++[files] returns ok<br>Thu Jan 19 12:35:17 2012 : Info: [ldap] performing user authorization for caraiz<br>Thu Jan 19 12:35:17 2012 : Info: [ldap] expand: %{Stripped-User-Name} -> caraiz<br>
Thu Jan 19 12:35:17 2012 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)<br>Thu Jan 19 12:35:17 2012 : Info: [ldap] expand: ou=radius,o=accounts,dc=unav,dc=es -> ou=radius,o=accounts,dc=unav,dc=es<br>
Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Checking Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_get_conn: Got Id: 0<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] performing search in ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)<br>
Thu Jan 19 12:35:17 2012 : Info: [ldap] Added User-Password = uSB8232 in check items<br>Thu Jan 19 12:35:17 2012 : Info: [ldap] looking for check items in directory...<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] unavRadiusPasswd -> Cleartext-Password == "uSB8232"<br>
Thu Jan 19 12:35:17 2012 : Info: [ldap] looking for reply items in directory...<br>Thu Jan 19 12:35:17 2012 : Info: [ldap] user caraiz authorized to use remote access<br>Thu Jan 19 12:35:17 2012 : Debug: [ldap] ldap_release_conn: Release Id: 0<br>
Thu Jan 19 12:35:17 2012 : Info: ++[ldap] returns ok<br>Thu Jan 19 12:35:17 2012 : Info: ++[expiration] returns noop<br>Thu Jan 19 12:35:17 2012 : Info: ++[logintime] returns noop<br>Thu Jan 19 12:35:17 2012 : Info: [pap] Found existing Auth-Type, not changing it.<br>
Thu Jan 19 12:35:17 2012 : Info: ++[pap] returns noop<br>Thu Jan 19 12:35:17 2012 : Info: Found Auth-Type = EAP<br>Thu Jan 19 12:35:17 2012 : Info: +- entering group authenticate {...}<br>Thu Jan 19 12:35:17 2012 : Info: [eap] EAP Identity<br>
Thu Jan 19 12:35:17 2012 : Info: [eap] processing type md5<br>Thu Jan 19 12:35:17 2012 : Debug: rlm_eap_md5: Issuing Challenge<br>Thu Jan 19 12:35:17 2012 : Info: ++[eap] returns handled<br>Sending Access-Challenge of id 46 to 159.237.8.200 port 3490<br>
Reply-Message = "Empleado from test switch"<br> EAP-Message = 0x0100001604100355c7206b87c18d1b2f8d1f8d4e3c72<br> Message-Authenticator = 0x00000000000000000000000000000000<br> State = 0x9739c5919739c13875490ff836b45426<br>
Thu Jan 19 12:35:17 2012 : Info: Finished request 0.<br></div></div>...<br></div></div><div class="im"><br>Requests 1 to 8 have been trimmed to make the log shorter, but the huntgroup is been recognized ok too.<br></div>
<div class="im">
Next is request #9 where for the first time the huntgroup check is not working and the user get rejected:<br></div><div><div><br>...<div><div class="h5"><br>Thu Jan 19 12:35:18 2012 : Info: Finished request 8.<br>Thu Jan 19 12:35:18 2012 : Debug: Going to the next request<br>
Thu Jan 19 12:35:18 2012 : Debug: Waking up in 4.4 seconds.<br>rad_recv: Access-Request packet from host 159.237.8.200 port 3490, id=55, length=182<br> NAS-IP-Address = 159.237.8.200<br> NAS-Port-Type = Ethernet<br>
Service-Type = Framed-User<br> Message-Authenticator = 0x4e2e7f7fc86e811f98694a66f5ca6805<br> NAS-Port = 5<br> Framed-MTU = 1490<br> User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br>
Calling-Station-Id = "D0-67-E5-13-CC-17"<br> State = 0x9739c5919f31dc3875490ff836b45426<br> EAP-Message = 0x0208003b190017030100302457ac1cb0d098d7cd44203a9d979a317ba06ed8370ef62a14955f4012fb98a6721e402a122fd366d3e8d673895d20fd<br>
Thu Jan 19 12:35:18 2012 : Info: +- entering group authorize {...}<br>Thu Jan 19 12:35:18 2012 : Info: ++[preprocess] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: ++[chap] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: ++[mschap] returns noop<br>
Thu Jan 19 12:35:18 2012 : Info: [suffix] Looking up realm "<a href="http://unav.es" target="_blank">unav.es</a>" for User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br>
Thu Jan 19 12:35:18 2012 : Info: [suffix] Found realm "<a href="http://unav.es" target="_blank">unav.es</a>"<br>
Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Stripped-User-Name = "caraiz"<br>Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Realm = "<a href="http://unav.es" target="_blank">unav.es</a>"<br>Thu Jan 19 12:35:18 2012 : Info: [suffix] Authentication realm is LOCAL.<br>
Thu Jan 19 12:35:18 2012 : Info: ++[suffix] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: [eap] EAP packet type response id 8 length 59<br>Thu Jan 19 12:35:18 2012 : Info: [eap] Continuing tunnel setup.<br>Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns ok<br>
Thu Jan 19 12:35:18 2012 : Info: Found Auth-Type = EAP<br>Thu Jan 19 12:35:18 2012 : Info: +- entering group authenticate {...}<br>Thu Jan 19 12:35:18 2012 : Info: [eap] Request found, released from the list<br>Thu Jan 19 12:35:18 2012 : Info: [eap] EAP/peap<br>
Thu Jan 19 12:35:18 2012 : Info: [eap] processing type peap<br>Thu Jan 19 12:35:18 2012 : Info: [peap] processing EAP-TLS<br>Thu Jan 19 12:35:18 2012 : Info: [peap] eaptls_verify returned 7 <br>Thu Jan 19 12:35:18 2012 : Info: [peap] Done initial handshake<br>
Thu Jan 19 12:35:18 2012 : Info: [peap] eaptls_process returned 7 <br>Thu Jan 19 12:35:18 2012 : Info: [peap] EAPTLS_OK<br>Thu Jan 19 12:35:18 2012 : Info: [peap] Session established. Decoding tunneled attributes.<br>Thu Jan 19 12:35:18 2012 : Info: [peap] Identity - <a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a><br>
Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled request<br> EAP-Message = 0x020800130163617261697a40756e61762e6573<br>server {<br>Thu Jan 19 12:35:18 2012 : Debug: PEAP: Got tunneled identity of <a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a><br>
Thu Jan 19 12:35:18 2012 : Debug: PEAP: Setting default EAP type for tunneled EAP session.<br>Thu Jan 19 12:35:18 2012 : Debug: PEAP: Setting User-Name to <a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a><br>
Sending tunneled request<br>
EAP-Message = 0x020800130163617261697a40756e61762e6573<br> FreeRADIUS-Proxied-To = 127.0.0.1<br> User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br> NAS-IP-Address = 159.237.8.200<br>
NAS-Port-Type = Ethernet<br> Service-Type = Framed-User<br> NAS-Port = 5<br> Framed-MTU = 1490<br> Calling-Station-Id = "D0-67-E5-13-CC-17"<br>server inner-tunnel {<br>Thu Jan 19 12:35:18 2012 : Info: +- entering group authorize {...}<br>
Thu Jan 19 12:35:18 2012 : Info: ++[chap] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: ++[mschap] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: ++[unix] returns notfound<br>Thu Jan 19 12:35:18 2012 : Info: [suffix] Looking up realm "<a href="http://unav.es" target="_blank">unav.es</a>" for User-Name = "<a href="mailto:caraiz@unav.es" target="_blank">caraiz@unav.es</a>"<br>
Thu Jan 19 12:35:18 2012 : Info: [suffix] Found realm "<a href="http://unav.es" target="_blank">unav.es</a>"<br>Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Stripped-User-Name = "caraiz"<br>Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Realm = "<a href="http://unav.es" target="_blank">unav.es</a>"<br>
Thu Jan 19 12:35:18 2012 : Info: [suffix] Authentication realm is LOCAL.<br>Thu Jan 19 12:35:18 2012 : Info: ++[suffix] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: ++[control] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: [eap] EAP packet type response id 8 length 19<br>
Thu Jan 19 12:35:18 2012 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation<br>Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns updated<br>Thu Jan 19 12:35:18 2012 : Info: [files] users: Matched entry DEFAULT at line 4<br>
Thu Jan 19 12:35:18 2012 : Info: ++[files] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: [ldap] performing user authorization for caraiz<br>Thu Jan 19 12:35:18 2012 : Info: [ldap] expand: %{Stripped-User-Name} -> caraiz<br>
Thu Jan 19 12:35:18 2012 : Info: [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)<br>Thu Jan 19 12:35:18 2012 : Info: [ldap] expand: ou=radius,o=accounts,dc=unav,dc=es -> ou=radius,o=accounts,dc=unav,dc=es<br>
Thu Jan 19 12:35:18 2012 : Debug: [ldap] ldap_get_conn: Checking Id: 0<br>Thu Jan 19 12:35:18 2012 : Debug: [ldap] ldap_get_conn: Got Id: 0<br>Thu Jan 19 12:35:18 2012 : Debug: [ldap] performing search in ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)<br>
Thu Jan 19 12:35:18 2012 : Info: [ldap] Added User-Password = uSB8232 in check items<br>Thu Jan 19 12:35:18 2012 : Info: [ldap] looking for check items in directory...<br>Thu Jan 19 12:35:18 2012 : Debug: [ldap] unavRadiusPasswd -> Cleartext-Password == "uSB8232"<br>
Thu Jan 19 12:35:18 2012 : Info: [ldap] looking for reply items in directory...<br>Thu Jan 19 12:35:18 2012 : Info: [ldap] user caraiz authorized to use remote access<br>Thu Jan 19 12:35:18 2012 : Debug: [ldap] ldap_release_conn: Release Id: 0<br>
Thu Jan 19 12:35:18 2012 : Info: ++[ldap] returns ok<br>Thu Jan 19 12:35:18 2012 : Info: ++[expiration] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: ++[logintime] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: [pap] Found existing Auth-Type, not changing it.<br>
Thu Jan 19 12:35:18 2012 : Info: ++[pap] returns noop<br>Thu Jan 19 12:35:18 2012 : Info: Found Auth-Type = Reject<br>Thu Jan 19 12:35:18 2012 : Info: Auth-Type = Reject, rejecting user<br>Thu Jan 19 12:35:18 2012 : Info: Failed to authenticate the user.<br>
} # server inner-tunnel<br>Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled reply code 3<br> Reply-Message = "Access not allowed."<br>Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled reply RADIUS code 3<br>
Reply-Message = "Access not allowed."<br>Thu Jan 19 12:35:18 2012 : Info: [peap] Tunneled authentication was rejected.<br>Thu Jan 19 12:35:18 2012 : Info: [peap] FAILURE<br>Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns handled<br>
Sending Access-Challenge of id 55 to 159.237.8.200 port 3490<br> EAP-Message = 0x0109002b19001703010020419852f0a6019cefb1881bb24d6bacc3bc6ca4cb0712da325d9708366a31c62d<br> Message-Authenticator = 0x00000000000000000000000000000000<br>
State = 0x9739c5919e30dc3875490ff836b45426<br>Thu Jan 19 12:35:18 2012 : Info: Finished request 9.<br></div></div>...<br><br>Then it comes request #10 that is rejected too as the user session weas rejected before:<br clear="all">
<div class="im"><span><font color="#888888"><span><font color="#888888">
<font><font color="#888888"><b><br>Oscar Remírez de Ganuza Satrústegui</b> <br>
Servicios Informáticos (Área de Infraestructuras)<br>
Universidad de Navarra <br>
Tel. <a value="+34948425600">+34 948425600</a> x3130<br>
<a href="http://www.unav.es/SI/" target="_blank">http://www.unav.es/SI/</a></font></font><br>
</font></span></font></span></div></div></div></div><br>
</div><br>
</div><br>
</div><br>