huntgroup check problems

20 Jan 2012

      Hello everybody,

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).
We also tunneled the request to the same radius for our realm "unav.es".

I am having some problems using huntgroups to identified the origin of a
request.
I have simplified the test trying to find out the problem, but I do not
understand what it is happening:

* It works ok when I use the following users file:
----- users file -----
DEFAULT Ldap-Group=="unav.radius.empleado"
        Reply-Message = "Empleado from test switch"

DEFAULT Auth-Type := Reject
        Reply-Message = "Access not allowed."
-----

* But it fails when I check the huntgroup:
----- users file -----
DEFAULT Huntgroup-Name == "huntpruebas", Ldap-Group=="unav.radius.empleado"
        Reply-Message = "Empleado from test switch"

DEFAULT Auth-Type := Reject
        Reply-Message = "Access not allowed."
-----

(The "notworking log" is appended at the end of the message. I had to trim
it to make it shorter)

 (The "workingok log" is not attached as it made this message bigger than
allowed on this list).

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).
I also do not understand why it needs so many requests (12!) to work ok.

I will appreciate any help understanding what is happening, in order to
find a solution for my problem.
If it is needed more log or config files, I can attached them without
problem.

Thanks a lot.

====== Not working log ======
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
[trimmed]
Thu Jan 19 12:34:20 2012 : Debug: main {
Thu Jan 19 12:34:20 2012 : Debug:     prefix = "/usr/local/etc2/freeradius"
Thu Jan 19 12:34:20 2012 : Debug:     localstatedir =
"/usr/local/etc2/freeradius/var"
Thu Jan 19 12:34:20 2012 : Debug:     logdir =
"/usr/local/etc2/freeradius/var/log/radius"
Thu Jan 19 12:34:20 2012 : Debug:     libdir =
"/usr/local/etc2/freeradius/lib"
Thu Jan 19 12:34:20 2012 : Debug:     radacctdir =
"/usr/local/etc2/freeradius/var/log/radius/radacct"
Thu Jan 19 12:34:20 2012 : Debug:     hostname_lookups = no
Thu Jan 19 12:34:20 2012 : Debug:     max_request_time = 30
Thu Jan 19 12:34:20 2012 : Debug:     cleanup_delay = 5
Thu Jan 19 12:34:20 2012 : Debug:     max_requests = 1024
Thu Jan 19 12:34:20 2012 : Debug:     pidfile =
"/usr/local/etc2/freeradius/var/run/radiusd/radiusd.pid"
Thu Jan 19 12:34:20 2012 : Debug:     checkrad =
"/usr/local/etc2/freeradius/sbin/checkrad"
Thu Jan 19 12:34:20 2012 : Debug:     debug_level = 0
Thu Jan 19 12:34:20 2012 : Debug:     proxy_requests = yes
Thu Jan 19 12:34:20 2012 : Debug:  log {
Thu Jan 19 12:34:20 2012 : Debug:     stripped_names = no
Thu Jan 19 12:34:20 2012 : Debug:     auth = no
Thu Jan 19 12:34:20 2012 : Debug:     auth_badpass = no
Thu Jan 19 12:34:20 2012 : Debug:     auth_goodpass = no
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  security {
Thu Jan 19 12:34:20 2012 : Debug:     max_attributes = 200
Thu Jan 19 12:34:20 2012 : Debug:     reject_delay = 1
Thu Jan 19 12:34:20 2012 : Debug:     status_server = yes
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug: }
Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Thu Jan 19 12:34:20 2012 : Debug:  proxy server {
Thu Jan 19 12:34:20 2012 : Debug:     retry_delay = 5
Thu Jan 19 12:34:20 2012 : Debug:     retry_count = 3
Thu Jan 19 12:34:20 2012 : Debug:     default_fallback = yes
Thu Jan 19 12:34:20 2012 : Debug:     dead_time = 120
Thu Jan 19 12:34:20 2012 : Debug:     wake_all_if_all_dead = no
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  realm unav.es {
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  realm LOCAL {
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  home_server localhost {
Thu Jan 19 12:34:20 2012 : Debug:     ipaddr = 127.0.0.1
Thu Jan 19 12:34:20 2012 : Debug:     port = 1812
Thu Jan 19 12:34:20 2012 : Debug:     type = "auth+acct"
Thu Jan 19 12:34:20 2012 : Debug:     secret = "testing123"
Thu Jan 19 12:34:20 2012 : Debug:     response_window = 20
Thu Jan 19 12:34:20 2012 : Debug:     max_outstanding = 65536
Thu Jan 19 12:34:20 2012 : Debug:     require_message_authenticator = no
Thu Jan 19 12:34:20 2012 : Debug:     zombie_period = 40
Thu Jan 19 12:34:20 2012 : Debug:     status_check = "status-server"
Thu Jan 19 12:34:20 2012 : Debug:     ping_interval = 30
Thu Jan 19 12:34:20 2012 : Debug:     check_interval = 30
Thu Jan 19 12:34:20 2012 : Debug:     num_answers_to_alive = 3
Thu Jan 19 12:34:20 2012 : Debug:     num_pings_to_alive = 3
Thu Jan 19 12:34:20 2012 : Debug:     revive_interval = 120
Thu Jan 19 12:34:20 2012 : Debug:     status_check_timeout = 4
Thu Jan 19 12:34:20 2012 : Debug:     irt = 2
Thu Jan 19 12:34:20 2012 : Debug:     mrt = 16
Thu Jan 19 12:34:20 2012 : Debug:     mrc = 5
Thu Jan 19 12:34:20 2012 : Debug:     mrd = 30
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  home_server_pool my_auth_failover {
Thu Jan 19 12:34:20 2012 : Debug:     type = fail-over
Thu Jan 19 12:34:20 2012 : Debug:     home_server = localhost
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Clients ####
Thu Jan 19 12:34:20 2012 : Debug:  client localhost {
Thu Jan 19 12:34:20 2012 : Debug:     ipaddr = 127.0.0.1
Thu Jan 19 12:34:20 2012 : Debug:     require_message_authenticator = no
Thu Jan 19 12:34:20 2012 : Debug:     secret = "testing123"
Thu Jan 19 12:34:20 2012 : Debug:     nastype = "other"
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug:  client naspruebas {
Thu Jan 19 12:34:20 2012 : Debug:     ipaddr = 159.237.8.200
Thu Jan 19 12:34:20 2012 : Debug:     require_message_authenticator = no
Thu Jan 19 12:34:20 2012 : Debug:     secret = "pruebas"
Thu Jan 19 12:34:20 2012 : Debug:     shortname = "naspruebas"
Thu Jan 19 12:34:20 2012 : Debug:     nastype = "other"
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Instantiating modules ####
Thu Jan 19 12:34:20 2012 : Debug:  instantiate {
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_exec, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_exec
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating exec
Thu Jan 19 12:34:20 2012 : Debug:   exec {
Thu Jan 19 12:34:20 2012 : Debug:     wait = no
Thu Jan 19 12:34:20 2012 : Debug:     input_pairs = "request"
Thu Jan 19 12:34:20 2012 : Debug:     shell_escape = yes
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_expr, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_expr
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating expr
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_expiration, checking if
it's valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_expiration
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating expiration
Thu Jan 19 12:34:20 2012 : Debug:   expiration {
Thu Jan 19 12:34:20 2012 : Debug:     reply-message = "Password Has
Expired  "
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_logintime, checking if
it's valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_logintime
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating logintime
Thu Jan 19 12:34:20 2012 : Debug:   logintime {
Thu Jan 19 12:34:20 2012 : Debug:     reply-message = "You are calling
outside your allowed timespan  "
Thu Jan 19 12:34:20 2012 : Debug:     minimum-timeout = 60
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:  }
Thu Jan 19 12:34:20 2012 : Debug: radiusd: #### Loading Virtual Servers ####
Thu Jan 19 12:34:20 2012 : Debug: server inner-tunnel {
Thu Jan 19 12:34:20 2012 : Debug:  modules {
Thu Jan 19 12:34:20 2012 : Debug:  Module: Checking authenticate {...} for
more modules to load
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_pap, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_pap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating pap
Thu Jan 19 12:34:20 2012 : Debug:   pap {
Thu Jan 19 12:34:20 2012 : Debug:     encryption_scheme = "auto"
Thu Jan 19 12:34:20 2012 : Debug:     auto_header = no
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_chap, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_chap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating chap
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_mschap, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_mschap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating mschap
Thu Jan 19 12:34:20 2012 : Debug:   mschap {
Thu Jan 19 12:34:20 2012 : Debug:     use_mppe = yes
Thu Jan 19 12:34:20 2012 : Debug:     require_encryption = yes
Thu Jan 19 12:34:20 2012 : Debug:     require_strong = yes
Thu Jan 19 12:34:20 2012 : Debug:     with_ntdomain_hack = no
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_unix, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_unix
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating unix
Thu Jan 19 12:34:20 2012 : Debug:   unix {
Thu Jan 19 12:34:20 2012 : Debug:     radwtmp =
"/usr/local/etc2/freeradius/var/log/radius/radwtmp"
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_eap, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_eap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap
Thu Jan 19 12:34:20 2012 : Debug:   eap {
Thu Jan 19 12:34:20 2012 : Debug:     default_eap_type = "md5"
Thu Jan 19 12:34:20 2012 : Debug:     timer_expire = 60
Thu Jan 19 12:34:20 2012 : Debug:     ignore_unknown_eap_types = no
Thu Jan 19 12:34:20 2012 : Debug:     cisco_accounting_username_bug = no
Thu Jan 19 12:34:20 2012 : Debug:     max_sessions = 4096
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_md5
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-md5
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_leap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-leap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-gtc
Thu Jan 19 12:34:20 2012 : Debug:    gtc {
Thu Jan 19 12:34:20 2012 : Debug:     challenge = "Password: "
Thu Jan 19 12:34:20 2012 : Debug:     auth_type = "PAP"
Thu Jan 19 12:34:20 2012 : Debug:    }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_tls
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-tls
Thu Jan 19 12:34:20 2012 : Debug:    tls {
Thu Jan 19 12:34:20 2012 : Debug:     rsa_key_exchange = no
Thu Jan 19 12:34:20 2012 : Debug:     dh_key_exchange = yes
Thu Jan 19 12:34:20 2012 : Debug:     rsa_key_length = 512
Thu Jan 19 12:34:20 2012 : Debug:     dh_key_length = 512
Thu Jan 19 12:34:20 2012 : Debug:     verify_depth = 0
Thu Jan 19 12:34:20 2012 : Debug:     pem_file_type = yes
Thu Jan 19 12:34:20 2012 : Debug:     private_key_file =
"/usr/local/etc2/freeradius/etc/raddb/certs/radius.unav.es_privatekey.pem"
Thu Jan 19 12:34:20 2012 : Debug:     certificate_file =
"/usr/local/etc2/freeradius/etc/raddb/certs/radius.unav.es_cert.pem"
Thu Jan 19 12:34:20 2012 : Debug:     CA_file =
"/usr/local/etc2/freeradius/etc/raddb/certs/TERENASSL_PATH.pem"
Thu Jan 19 12:34:20 2012 : Debug:     dh_file =
"/usr/local/etc2/freeradius/etc/raddb/certs/dh"
Thu Jan 19 12:34:20 2012 : Debug:     random_file =
"/usr/local/etc2/freeradius/etc/raddb/certs/random"
Thu Jan 19 12:34:20 2012 : Debug:     fragment_size = 1024
Thu Jan 19 12:34:20 2012 : Debug:     include_length = yes
Thu Jan 19 12:34:20 2012 : Debug:     check_crl = no
Thu Jan 19 12:34:20 2012 : Debug:     cipher_list = "DEFAULT"
Thu Jan 19 12:34:20 2012 : Debug:     make_cert_command =
"/usr/local/etc2/freeradius/etc/raddb/certs/bootstrap"
Thu Jan 19 12:34:20 2012 : Debug:     cache {
Thu Jan 19 12:34:20 2012 : Debug:     enable = no
Thu Jan 19 12:34:20 2012 : Debug:     lifetime = 24
Thu Jan 19 12:34:20 2012 : Debug:     max_entries = 255
Thu Jan 19 12:34:20 2012 : Debug:     }
Thu Jan 19 12:34:20 2012 : Debug:    }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-ttls
Thu Jan 19 12:34:20 2012 : Debug:    ttls {
Thu Jan 19 12:34:20 2012 : Debug:     default_eap_type = "md5"
Thu Jan 19 12:34:20 2012 : Debug:     copy_request_to_tunnel = yes
Thu Jan 19 12:34:20 2012 : Debug:     use_tunneled_reply = no
Thu Jan 19 12:34:20 2012 : Debug:     virtual_server = "inner-tunnel"
Thu Jan 19 12:34:20 2012 : Debug:     include_length = yes
Thu Jan 19 12:34:20 2012 : Debug:    }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module rlm_eap_peap
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-peap
Thu Jan 19 12:34:20 2012 : Debug:    peap {
Thu Jan 19 12:34:20 2012 : Debug:     default_eap_type = "mschapv2"
Thu Jan 19 12:34:20 2012 : Debug:     copy_request_to_tunnel = yes
Thu Jan 19 12:34:20 2012 : Debug:     use_tunneled_reply = no
Thu Jan 19 12:34:20 2012 : Debug:     proxy_tunneled_request_as_eap = no
Thu Jan 19 12:34:20 2012 : Debug:     virtual_server = "inner-tunnel"
Thu Jan 19 12:34:20 2012 : Debug:    }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to sub-module
rlm_eap_mschapv2
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating eap-mschapv2
Thu Jan 19 12:34:20 2012 : Debug:    mschapv2 {
Thu Jan 19 12:34:20 2012 : Debug:     with_ntdomain_hack = no
Thu Jan 19 12:34:20 2012 : Debug:    }
Thu Jan 19 12:34:20 2012 : Debug:  Module: Checking authorize {...} for
more modules to load
Thu Jan 19 12:34:20 2012 : Debug:     (Loaded rlm_realm, checking if it's
valid)
Thu Jan 19 12:34:20 2012 : Debug:  Module: Linked to module rlm_realm
Thu Jan 19 12:34:20 2012 : Debug:  Module: Instantiating suffix
Thu Jan 19 12:34:20 2012 : Debug:   realm suffix {
Thu Jan 19 12:34:20 2012 : Debug:     format = "suffix"
Thu Jan 19 12:34:20 2012 : Debug:     delimiter = "@"
Thu Jan 19 12:34:20 2012 : Debug:     ignore_default = no
Thu Jan 19 12:34:20 2012 : Debug:     ignore_null = no
Thu Jan 19 12:34:20 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_files, checking if it's
valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_files
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating files
Thu Jan 19 12:34:21 2012 : Debug:   files {
Thu Jan 19 12:34:21 2012 : Debug:     usersfile =
"/usr/local/etc2/freeradius/etc/raddb/users"
Thu Jan 19 12:34:21 2012 : Debug:     acctusersfile =
"/usr/local/etc2/freeradius/etc/raddb/acct_users"
Thu Jan 19 12:34:21 2012 : Debug:     preproxy_usersfile =
"/usr/local/etc2/freeradius/etc/raddb/preproxy_users"
Thu Jan 19 12:34:21 2012 : Debug:     compat = "no"
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_ldap, checking if it's
valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_ldap
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating ldap
Thu Jan 19 12:34:21 2012 : Debug:   ldap {
Thu Jan 19 12:34:21 2012 : Debug:     server = "ldappre.si.unav.es"
Thu Jan 19 12:34:21 2012 : Debug:     port = 389
 Thu Jan 19 12:34:21 2012 : Debug:     password = "xxx"
Thu Jan 19 12:34:21 2012 : Debug:     identity = "cn=radiusOp,dc=unav,dc=es"
Thu Jan 19 12:34:21 2012 : Debug:     net_timeout = 1
Thu Jan 19 12:34:21 2012 : Debug:     timeout = 4
Thu Jan 19 12:34:21 2012 : Debug:     timelimit = 3
Thu Jan 19 12:34:21 2012 : Debug:     tls_mode = no
Thu Jan 19 12:34:21 2012 : Debug:     start_tls = no
Thu Jan 19 12:34:21 2012 : Debug:     tls_require_cert = "allow"
Thu Jan 19 12:34:21 2012 : Debug:    tls {
Thu Jan 19 12:34:21 2012 : Debug:     start_tls = yes
Thu Jan 19 12:34:21 2012 : Debug:     require_cert = "allow"
Thu Jan 19 12:34:21 2012 : Debug:    }
Thu Jan 19 12:34:21 2012 : Debug:     basedn =
"ou=radius,o=accounts,dc=unav,dc=es"
Thu Jan 19 12:34:21 2012 : Debug:     filter =
"(uid=%{%{Stripped-User-Name}:-%{User-Name}})"
Thu Jan 19 12:34:21 2012 : Debug:     base_filter =
"(objectclass=radiusprofile)"
Thu Jan 19 12:34:21 2012 : Debug:     password_attribute =
"unavRadiusPasswd"
Thu Jan 19 12:34:21 2012 : Debug:     auto_header = no
Thu Jan 19 12:34:21 2012 : Debug:     access_attr_used_for_allow = yes
Thu Jan 19 12:34:21 2012 : Debug:     groupname_attribute = "cn"
Thu Jan 19 12:34:21 2012 : Debug:     groupmembership_filter =
"(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))"
Thu Jan 19 12:34:21 2012 : Debug:     groupmembership_attribute = "member"
Thu Jan 19 12:34:21 2012 : Debug:     dictionary_mapping =
"/usr/local/etc2/freeradius/etc/raddb/ldap.attrmap"
Thu Jan 19 12:34:21 2012 : Debug:     ldap_debug = 104
Thu Jan 19 12:34:21 2012 : Debug:     ldap_connections_number = 10
Thu Jan 19 12:34:21 2012 : Debug:     compare_check_items = no
Thu Jan 19 12:34:21 2012 : Debug:     do_xlat = no
Thu Jan 19 12:34:21 2012 : Debug:     set_auth_type = yes
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: Registering ldap_groupcmp for
Ldap-Group
Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: Registering ldap_xlat with
xlat_name ldap
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.
Thu Jan 19 12:34:21 2012 : Debug: rlm_ldap: reading ldap<->radius mappings
from file /usr/local/etc2/freeradius/etc/raddb/ldap.attrmap
[trimmed]
Thu Jan 19 12:34:21 2012 : Debug: conns: 0x830e3c0
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking session {...} for more
modules to load
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_radutmp, checking if it's
valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_radutmp
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating radutmp
Thu Jan 19 12:34:21 2012 : Debug:   radutmp {
Thu Jan 19 12:34:21 2012 : Debug:     filename =
"/usr/local/etc2/freeradius/var/log/radius/radutmp"
Thu Jan 19 12:34:21 2012 : Debug:     username = "%{User-Name}"
Thu Jan 19 12:34:21 2012 : Debug:     case_sensitive = yes
Thu Jan 19 12:34:21 2012 : Debug:     check_with_nas = yes
Thu Jan 19 12:34:21 2012 : Debug:     perm = 384
Thu Jan 19 12:34:21 2012 : Debug:     callerid = yes
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking post-auth {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_attr_filter, checking if
it's valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_attr_filter
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating
attr_filter.access_reject
Thu Jan 19 12:34:21 2012 : Debug:   attr_filter attr_filter.access_reject {
Thu Jan 19 12:34:21 2012 : Debug:     attrsfile =
"/usr/local/etc2/freeradius/etc/raddb/attrs.access_reject"
Thu Jan 19 12:34:21 2012 : Debug:     key = "%{User-Name}"
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  } # modules
Thu Jan 19 12:34:21 2012 : Debug: } # server
Thu Jan 19 12:34:21 2012 : Debug: server {
Thu Jan 19 12:34:21 2012 : Debug:  modules {
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking authenticate {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking authorize {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_preprocess, checking if
it's valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_preprocess
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating preprocess
Thu Jan 19 12:34:21 2012 : Debug:   preprocess {
Thu Jan 19 12:34:21 2012 : Debug:     huntgroups =
"/usr/local/etc2/freeradius/etc/raddb/huntgroups"
Thu Jan 19 12:34:21 2012 : Debug:     hints =
"/usr/local/etc2/freeradius/etc/raddb/hints"
Thu Jan 19 12:34:21 2012 : Debug:     with_ascend_hack = no
Thu Jan 19 12:34:21 2012 : Debug:     ascend_channels_per_line = 23
Thu Jan 19 12:34:21 2012 : Debug:     with_ntdomain_hack = no
Thu Jan 19 12:34:21 2012 : Debug:     with_specialix_jetstream_hack = no
Thu Jan 19 12:34:21 2012 : Debug:     with_cisco_vsa_hack = no
Thu Jan 19 12:34:21 2012 : Debug:     with_alvarion_vsa_hack = no
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking preacct {...} for more
modules to load
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_acct_unique, checking if
it's valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_acct_unique
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating acct_unique
Thu Jan 19 12:34:21 2012 : Debug:   acct_unique {
Thu Jan 19 12:34:21 2012 : Debug:     key = "User-Name, Acct-Session-Id,
NAS-IP-Address, Client-IP-Address, NAS-Port"
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking accounting {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:     (Loaded rlm_detail, checking if it's
valid)
Thu Jan 19 12:34:21 2012 : Debug:  Module: Linked to module rlm_detail
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating detail
Thu Jan 19 12:34:21 2012 : Debug:   detail {
Thu Jan 19 12:34:21 2012 : Debug:     detailfile =
"/usr/local/etc2/freeradius/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Thu Jan 19 12:34:21 2012 : Debug:     header = "%t"
Thu Jan 19 12:34:21 2012 : Debug:     detailperm = 384
Thu Jan 19 12:34:21 2012 : Debug:     dirperm = 493
Thu Jan 19 12:34:21 2012 : Debug:     locking = no
Thu Jan 19 12:34:21 2012 : Debug:     log_packet_header = no
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  Module: Instantiating
attr_filter.accounting_response
Thu Jan 19 12:34:21 2012 : Debug:   attr_filter
attr_filter.accounting_response {
Thu Jan 19 12:34:21 2012 : Debug:     attrsfile =
"/usr/local/etc2/freeradius/etc/raddb/attrs.accounting_response"
Thu Jan 19 12:34:21 2012 : Debug:     key = "%{User-Name}"
Thu Jan 19 12:34:21 2012 : Debug:   }
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking session {...} for more
modules to load
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:  Module: Checking post-auth {...} for
more modules to load
Thu Jan 19 12:34:21 2012 : Debug:  } # modules
Thu Jan 19 12:34:21 2012 : Debug: } # server
Thu Jan 19 12:34:21 2012 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Thu Jan 19 12:34:21 2012 : Debug: listen {
Thu Jan 19 12:34:21 2012 : Debug:     type = "auth"
Thu Jan 19 12:34:21 2012 : Debug:     ipaddr = *
Thu Jan 19 12:34:21 2012 : Debug:     port = 0
Thu Jan 19 12:34:21 2012 : Debug: }
Thu Jan 19 12:34:21 2012 : Debug: listen {
Thu Jan 19 12:34:21 2012 : Debug:     type = "acct"
Thu Jan 19 12:34:21 2012 : Debug:     ipaddr = *
Thu Jan 19 12:34:21 2012 : Debug:     port = 0
Thu Jan 19 12:34:21 2012 : Debug: }
Thu Jan 19 12:34:21 2012 : Debug: listen {
Thu Jan 19 12:34:21 2012 : Debug:     type = "control"
Thu Jan 19 12:34:21 2012 : Debug:  listen {
Thu Jan 19 12:34:21 2012 : Debug:     socket =
"/usr/local/etc2/freeradius/var/run/radiusd/radiusd.sock"
Thu Jan 19 12:34:21 2012 : Debug:  }
Thu Jan 19 12:34:21 2012 : Debug: }
Thu Jan 19 12:34:21 2012 : Debug: Listening on authentication address *
port 1812
Thu Jan 19 12:34:21 2012 : Debug: Listening on accounting address * port
1813
Thu Jan 19 12:34:21 2012 : Debug: Listening on command file
/usr/local/etc2/freeradius/var/run/radiusd/radiusd.sock
Thu Jan 19 12:34:21 2012 : Debug: Listening on proxy address * port 1814
Thu Jan 19 12:34:21 2012 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 159.237.8.200 port 3490, id=46,
length=124
    NAS-IP-Address = 159.237.8.200
    NAS-Port-Type = Ethernet
    Service-Type = Framed-User
    Message-Authenticator = 0xb666f25ec9310bf99e0ac965a3325f71
    NAS-Port = 5
    Framed-MTU = 1490
    User-Name = "caraiz@unav.es"
    Calling-Station-Id = "D0-67-E5-13-CC-17"
    EAP-Message = 0x02ff00130163617261697a40756e61762e6573
Thu Jan 19 12:35:17 2012 : Info: +- entering group authorize {...}
Thu Jan 19 12:35:17 2012 : Info: ++[preprocess] returns ok
Thu Jan 19 12:35:17 2012 : Info: ++[chap] returns noop
Thu Jan 19 12:35:17 2012 : Info: ++[mschap] returns noop
Thu Jan 19 12:35:17 2012 : Info: [suffix] Looking up realm "unav.es" for
User-Name = "caraiz@unav.es"
Thu Jan 19 12:35:17 2012 : Info: [suffix] Found realm "unav.es"
Thu Jan 19 12:35:17 2012 : Info: [suffix] Adding Stripped-User-Name =
"caraiz"
Thu Jan 19 12:35:17 2012 : Info: [suffix] Adding Realm = "unav.es"
Thu Jan 19 12:35:17 2012 : Info: [suffix] Authentication realm is LOCAL.
Thu Jan 19 12:35:17 2012 : Info: ++[suffix] returns ok
Thu Jan 19 12:35:17 2012 : Info: [eap] EAP packet type response id 255
length 19
Thu Jan 19 12:35:17 2012 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Thu Jan 19 12:35:17 2012 : Info: ++[eap] returns updated
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] Entering ldap_groupcmp()
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
Thu Jan 19 12:35:17 2012 : Info: [files]     expand: %{Stripped-User-Name}
-> caraiz
Thu Jan 19 12:35:17 2012 : Info: [files]     expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] attempting LDAP reconnection
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] (re)connect to
ldappre.si.unav.es:389, authentication 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] starting TLS
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] bind as
cn=radiusOp,dc=unav,dc=es/RAD1bar to ldappre.si.unav.es:389
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] waiting for bind result ...
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] Bind was successful
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] performing search in
ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_release_conn: Release Id: 0
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=)))
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Got Id: 0
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=))))
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] object not found
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Got Id: 0
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=*)
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)
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] object not found
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)
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] object not found
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)
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] object not found
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)
Thu Jan 19 12:35:17 2012 : Debug: rlm_ldap::ldap_groupcmp: User found in
group unav.radius.empleado
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Thu Jan 19 12:35:17 2012 : Info: [files] users: Matched entry DEFAULT at
line 1
Thu Jan 19 12:35:17 2012 : Info: ++[files] returns ok
Thu Jan 19 12:35:17 2012 : Info: [ldap] performing user authorization for
caraiz
Thu Jan 19 12:35:17 2012 : Info: [ldap]     expand: %{Stripped-User-Name}
-> caraiz
Thu Jan 19 12:35:17 2012 : Info: [ldap]     expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)
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
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] performing search in
ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)
Thu Jan 19 12:35:17 2012 : Info: [ldap] Added User-Password = uSB8232 in
check items
Thu Jan 19 12:35:17 2012 : Info: [ldap] looking for check items in
directory...
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] unavRadiusPasswd ->
Cleartext-Password == "uSB8232"
Thu Jan 19 12:35:17 2012 : Info: [ldap] looking for reply items in
directory...
Thu Jan 19 12:35:17 2012 : Info: [ldap] user caraiz authorized to use
remote access
Thu Jan 19 12:35:17 2012 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Thu Jan 19 12:35:17 2012 : Info: ++[ldap] returns ok
Thu Jan 19 12:35:17 2012 : Info: ++[expiration] returns noop
Thu Jan 19 12:35:17 2012 : Info: ++[logintime] returns noop
Thu Jan 19 12:35:17 2012 : Info: [pap] Found existing Auth-Type, not
changing it.
Thu Jan 19 12:35:17 2012 : Info: ++[pap] returns noop
Thu Jan 19 12:35:17 2012 : Info: Found Auth-Type = EAP
Thu Jan 19 12:35:17 2012 : Info: +- entering group authenticate {...}
Thu Jan 19 12:35:17 2012 : Info: [eap] EAP Identity
Thu Jan 19 12:35:17 2012 : Info: [eap] processing type md5
Thu Jan 19 12:35:17 2012 : Debug: rlm_eap_md5: Issuing Challenge
Thu Jan 19 12:35:17 2012 : Info: ++[eap] returns handled
Sending Access-Challenge of id 46 to 159.237.8.200 port 3490
    Reply-Message = "Empleado from test switch"
    EAP-Message = 0x0100001604100355c7206b87c18d1b2f8d1f8d4e3c72
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x9739c5919739c13875490ff836b45426
Thu Jan 19 12:35:17 2012 : Info: Finished request 0.
...

Requests 1 to 8 have been trimmed to make the log shorter, but the
huntgroup is been recognized ok too.
Next is request #9 where for the first time the huntgroup check is not
working and the user get rejected:

...

Thu Jan 19 12:35:18 2012 : Info: Finished request 8.
Thu Jan 19 12:35:18 2012 : Debug: Going to the next request
Thu Jan 19 12:35:18 2012 : Debug: Waking up in 4.4 seconds.
rad_recv: Access-Request packet from host 159.237.8.200 port 3490, id=55,
length=182
    NAS-IP-Address = 159.237.8.200
    NAS-Port-Type = Ethernet
    Service-Type = Framed-User
    Message-Authenticator = 0x4e2e7f7fc86e811f98694a66f5ca6805
    NAS-Port = 5
    Framed-MTU = 1490
    User-Name = "caraiz@unav.es"
    Calling-Station-Id = "D0-67-E5-13-CC-17"
    State = 0x9739c5919f31dc3875490ff836b45426
    EAP-Message =
0x0208003b190017030100302457ac1cb0d098d7cd44203a9d979a317ba06ed8370ef62a14955f4012fb98a6721e402a122fd366d3e8d673895d20fd
Thu Jan 19 12:35:18 2012 : Info: +- entering group authorize {...}
Thu Jan 19 12:35:18 2012 : Info: ++[preprocess] returns ok
Thu Jan 19 12:35:18 2012 : Info: ++[chap] returns noop
Thu Jan 19 12:35:18 2012 : Info: ++[mschap] returns noop
Thu Jan 19 12:35:18 2012 : Info: [suffix] Looking up realm "unav.es" for
User-Name = "caraiz@unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Found realm "unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Stripped-User-Name =
"caraiz"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Realm = "unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Authentication realm is LOCAL.
Thu Jan 19 12:35:18 2012 : Info: ++[suffix] returns ok
Thu Jan 19 12:35:18 2012 : Info: [eap] EAP packet type response id 8 length
59
Thu Jan 19 12:35:18 2012 : Info: [eap] Continuing tunnel setup.
Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns ok
Thu Jan 19 12:35:18 2012 : Info: Found Auth-Type = EAP
Thu Jan 19 12:35:18 2012 : Info: +- entering group authenticate {...}
Thu Jan 19 12:35:18 2012 : Info: [eap] Request found, released from the list
Thu Jan 19 12:35:18 2012 : Info: [eap] EAP/peap
Thu Jan 19 12:35:18 2012 : Info: [eap] processing type peap
Thu Jan 19 12:35:18 2012 : Info: [peap] processing EAP-TLS
Thu Jan 19 12:35:18 2012 : Info: [peap] eaptls_verify returned 7
Thu Jan 19 12:35:18 2012 : Info: [peap] Done initial handshake
Thu Jan 19 12:35:18 2012 : Info: [peap] eaptls_process returned 7
Thu Jan 19 12:35:18 2012 : Info: [peap] EAPTLS_OK
Thu Jan 19 12:35:18 2012 : Info: [peap] Session established.  Decoding
tunneled attributes.
Thu Jan 19 12:35:18 2012 : Info: [peap] Identity - caraiz@unav.es
Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled request
    EAP-Message = 0x020800130163617261697a40756e61762e6573
server  {
Thu Jan 19 12:35:18 2012 : Debug:   PEAP: Got tunneled identity of
caraiz@unav.es
Thu Jan 19 12:35:18 2012 : Debug:   PEAP: Setting default EAP type for
tunneled EAP session.
Thu Jan 19 12:35:18 2012 : Debug:   PEAP: Setting User-Name to
caraiz@unav.es
Sending tunneled request
    EAP-Message = 0x020800130163617261697a40756e61762e6573
    FreeRADIUS-Proxied-To = 127.0.0.1
    User-Name = "caraiz@unav.es"
    NAS-IP-Address = 159.237.8.200
    NAS-Port-Type = Ethernet
    Service-Type = Framed-User
    NAS-Port = 5
    Framed-MTU = 1490
    Calling-Station-Id = "D0-67-E5-13-CC-17"
server inner-tunnel {
Thu Jan 19 12:35:18 2012 : Info: +- entering group authorize {...}
Thu Jan 19 12:35:18 2012 : Info: ++[chap] returns noop
Thu Jan 19 12:35:18 2012 : Info: ++[mschap] returns noop
Thu Jan 19 12:35:18 2012 : Info: ++[unix] returns notfound
Thu Jan 19 12:35:18 2012 : Info: [suffix] Looking up realm "unav.es" for
User-Name = "caraiz@unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Found realm "unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Stripped-User-Name =
"caraiz"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Adding Realm = "unav.es"
Thu Jan 19 12:35:18 2012 : Info: [suffix] Authentication realm is LOCAL.
Thu Jan 19 12:35:18 2012 : Info: ++[suffix] returns ok
Thu Jan 19 12:35:18 2012 : Info: ++[control] returns ok
Thu Jan 19 12:35:18 2012 : Info: [eap] EAP packet type response id 8 length
19
Thu Jan 19 12:35:18 2012 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns updated
Thu Jan 19 12:35:18 2012 : Info: [files] users: Matched entry DEFAULT at
line 4
Thu Jan 19 12:35:18 2012 : Info: ++[files] returns ok
Thu Jan 19 12:35:18 2012 : Info: [ldap] performing user authorization for
caraiz
Thu Jan 19 12:35:18 2012 : Info: [ldap]     expand: %{Stripped-User-Name}
-> caraiz
Thu Jan 19 12:35:18 2012 : Info: [ldap]     expand:
(uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=caraiz)
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
Thu Jan 19 12:35:18 2012 : Debug:   [ldap] ldap_get_conn: Checking Id: 0
Thu Jan 19 12:35:18 2012 : Debug:   [ldap] ldap_get_conn: Got Id: 0
Thu Jan 19 12:35:18 2012 : Debug:   [ldap] performing search in
ou=radius,o=accounts,dc=unav,dc=es, with filter (uid=caraiz)
Thu Jan 19 12:35:18 2012 : Info: [ldap] Added User-Password = uSB8232 in
check items
Thu Jan 19 12:35:18 2012 : Info: [ldap] looking for check items in
directory...
Thu Jan 19 12:35:18 2012 : Debug:   [ldap] unavRadiusPasswd ->
Cleartext-Password == "uSB8232"
Thu Jan 19 12:35:18 2012 : Info: [ldap] looking for reply items in
directory...
Thu Jan 19 12:35:18 2012 : Info: [ldap] user caraiz authorized to use
remote access
Thu Jan 19 12:35:18 2012 : Debug:   [ldap] ldap_release_conn: Release Id: 0
Thu Jan 19 12:35:18 2012 : Info: ++[ldap] returns ok
Thu Jan 19 12:35:18 2012 : Info: ++[expiration] returns noop
Thu Jan 19 12:35:18 2012 : Info: ++[logintime] returns noop
Thu Jan 19 12:35:18 2012 : Info: [pap] Found existing Auth-Type, not
changing it.
Thu Jan 19 12:35:18 2012 : Info: ++[pap] returns noop
Thu Jan 19 12:35:18 2012 : Info: Found Auth-Type = Reject
Thu Jan 19 12:35:18 2012 : Info: Auth-Type = Reject, rejecting user
Thu Jan 19 12:35:18 2012 : Info: Failed to authenticate the user.
} # server inner-tunnel
Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled reply code 3
    Reply-Message = "Access not allowed."
Thu Jan 19 12:35:18 2012 : Info: [peap] Got tunneled reply RADIUS code 3
    Reply-Message = "Access not allowed."
Thu Jan 19 12:35:18 2012 : Info: [peap] Tunneled authentication was
rejected.
Thu Jan 19 12:35:18 2012 : Info: [peap] FAILURE
Thu Jan 19 12:35:18 2012 : Info: ++[eap] returns handled
Sending Access-Challenge of id 55 to 159.237.8.200 port 3490
    EAP-Message =
0x0109002b19001703010020419852f0a6019cefb1881bb24d6bacc3bc6ca4cb0712da325d9708366a31c62d
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x9739c5919e30dc3875490ff836b45426
Thu Jan 19 12:35:18 2012 : Info: Finished request 9.
...

Then it comes request #10 that is rejected too as the user session weas
rejected before:
*
Oscar Remírez de Ganuza Satrústegui*
Servicios Informáticos (Área de Infraestructuras)
Universidad de Navarra
Tel. +34 948425600 x3130
http://www.unav.es/SI/