huntgroup check problems
Oscar Remírez de Ganuza Satrústegui
oscarrdg at unav.es
Fri Jan 20 12:02:05 CET 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 at 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 at 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 at 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 at 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 at 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 at 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 at unav.es
Sending tunneled request
EAP-Message = 0x020800130163617261697a40756e61762e6573
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "caraiz at 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 at 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/
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120120/4e00f5e4/attachment.html>
More information about the Freeradius-Users
mailing list