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/