advice about ldap groupfilter query

8 Nov 2011

      Hello
My name is Remon and I would like to know your opinion about the next
problem and my ldap module configuration:

I have an authentication system base on: freeradius-2.1.7 and OpenLdap
2.3.30.
Our users are authenticated against LDAP and it is getting back a role
(student or Employee).
Recently I have changed the ldap topology and after that we are having a
lot of problems.
the radius log show us a lot of lines like:
Error: Discarding duplicate request from client xxxxxxx port 32841 - ID:
112 due to unfinished request 421
Error: rlm_ldap: All ldap connections are in use

I read some post about this problem, and they say that the problem could be
a slow connection with Ldap or a indexing problem of the ldap,
My question is,
 if the reason of this problem could be my ldap module configuration and
the type of filter that I use for searching the users in the diferents
groups or only depend on ldap server configuration?

First of all, my new ldap structure is like:

dc=company,
dc=com--------------------------------------ou--------------------------------------------ou=radius
(groupOfNames, radiusprofile)
           |
|                                                      | cn=student
           |
|ou=groups (groupOfNames)                vlan-parameters
         cn=users                                                       |-
cn=student

member (user1,......)            | cn= employee

|                                                                    |-
cn=employee                                  vlan-parameters
           |-
user1                                                               member
(user2,......)
           |- user2
           |- .......

My server version is freeradius-sderver-2.1.7

My ldap module configuration is:

server = "xxx.xxx.xxx.xxx"

        identity = "cn=xxxx,dc=yyy,dc=zz"
        password = sssss

        basedn = "dc=yyy,dc=zz"
        filter = "(uid=%{Stripped-User-Name})"

        groupmembership_filter =
"(&(objectClass=groupOfNames)(member=%{control:LDAP-UserDn}))"

        access_attr = "uid"
        password_attribute = Cleartext-Password
        ldap_connections_number = 200
        timeout = 4
        timelimit = 3
        net_timeout = 1

        tls {
                start_tls = no
        }
        dictionary_mapping = ${confdir}/ldap.attrmap
        edir_account_policy_check = no

I send you the output when a user "student13" is authenticated :
Tue Nov  8 10:05:54 2011 : Info: FreeRADIUS Version 2.1.7, for host
i686-pc-linux-gnu, built on Feb 11 2010 at 17:23:35
Tue Nov  8 10:05:54 2011 : Info: Copyright (C) 1999-2009 The FreeRADIUS
server project and contributors.
Tue Nov  8 10:05:54 2011 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A
Tue Nov  8 10:05:54 2011 : Info: PARTICULAR PURPOSE.
Tue Nov  8 10:05:54 2011 : Info: You may redistribute copies of FreeRADIUS
under the terms of the
Tue Nov  8 10:05:54 2011 : Info: GNU General Public License v2.
Tue Nov  8 10:05:54 2011 : Info: Starting - reading configuration files ...
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/radiusd.conf
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/proxy.conf
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/clients.conf
Tue Nov  8 10:05:54 2011 : Debug: including files in directory
/usr/local/etc/raddb/modules/
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/policy
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/unix
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/echo
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/smbpasswd
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/acct_unique
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/files
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.log
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/checkval
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/etc_group
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/pam
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ippool
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/chap
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/krb5
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/passwd
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/inner-eap
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.example.com
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/logintime
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/expiration
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2ip
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_filter
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/smsotp
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mschap
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/counter
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/pap
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/digest
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/expr
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/preprocess
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sradutmp
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/otp
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/wimax
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/realm
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/radutmp
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/perl
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/cui
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2vlan
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/linelog
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/always
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sqlcounter_expire_on_login
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/exec
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/sql_log
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/ldap
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_rewrite
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/eap.conf
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/policy.conf
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/default
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/control-socket
Tue Nov  8 10:05:54 2011 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
Tue Nov  8 10:05:54 2011 : Debug: group = freerad
Tue Nov  8 10:05:54 2011 : Debug: user = freerad
Tue Nov  8 10:05:54 2011 : Debug: including dictionary file
/usr/local/etc/raddb/dictionary
Tue Nov  8 10:05:54 2011 : Debug: main {
Tue Nov  8 10:05:54 2011 : Debug:     prefix = "/usr/local"
Tue Nov  8 10:05:54 2011 : Debug:     localstatedir = "/usr/local/var"
Tue Nov  8 10:05:54 2011 : Debug:     logdir = "/usr/local/var/log/radius"
Tue Nov  8 10:05:54 2011 : Debug:     libdir = "/usr/local/lib"
Tue Nov  8 10:05:54 2011 : Debug:     radacctdir =
"/usr/local/var/log/radius/radacct"
Tue Nov  8 10:05:54 2011 : Debug:     hostname_lookups = no
Tue Nov  8 10:05:54 2011 : Debug:     max_request_time = 30
Tue Nov  8 10:05:54 2011 : Debug:     cleanup_delay = 5
Tue Nov  8 10:05:54 2011 : Debug:     max_requests = 1024
Tue Nov  8 10:05:54 2011 : Debug:     allow_core_dumps = no
Tue Nov  8 10:05:54 2011 : Debug:     pidfile =
"/usr/local/var/run/radiusd/radiusd.pid"
Tue Nov  8 10:05:54 2011 : Debug:     checkrad = "/usr/local/sbin/checkrad"
Tue Nov  8 10:05:54 2011 : Debug:     debug_level = 0
Tue Nov  8 10:05:54 2011 : Debug:     proxy_requests = yes
Tue Nov  8 10:05:54 2011 : Debug:  log {
Tue Nov  8 10:05:54 2011 : Debug:     stripped_names = no
Tue Nov  8 10:05:54 2011 : Debug:     auth = yes
Tue Nov  8 10:05:54 2011 : Debug:     auth_badpass = no
Tue Nov  8 10:05:54 2011 : Debug:     auth_goodpass = no
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  security {
Tue Nov  8 10:05:54 2011 : Debug:     max_attributes = 200
Tue Nov  8 10:05:54 2011 : Debug:     reject_delay = 1
Tue Nov  8 10:05:54 2011 : Debug:     status_server = yes
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug: }
Tue Nov  8 10:05:54 2011 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Tue Nov  8 10:05:54 2011 : Debug:  proxy server {
Tue Nov  8 10:05:54 2011 : Debug:     retry_delay = 5
Tue Nov  8 10:05:54 2011 : Debug:     retry_count = 3
Tue Nov  8 10:05:54 2011 : Debug:     default_fallback = yes
Tue Nov  8 10:05:54 2011 : Debug:     dead_time = 120
Tue Nov  8 10:05:54 2011 : Debug:     wake_all_if_all_dead = no
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  realm LOCAL {
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  realm NULL {
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  home_server radius_proxy {
Tue Nov  8 10:05:54 2011 : Debug:     ipaddr = xxx.xxx.xxx.xxx
Tue Nov  8 10:05:54 2011 : Debug:     port = 1812
Tue Nov  8 10:05:54 2011 : Debug:     type = "auth+acct"
Tue Nov  8 10:05:54 2011 : Debug:     secret = "xxxxxxx"
Tue Nov  8 10:05:54 2011 : Debug:     response_window = 20
Tue Nov  8 10:05:54 2011 : Debug:     max_outstanding = 65536
Tue Nov  8 10:05:54 2011 : Debug:     zombie_period = 40
Tue Nov  8 10:05:54 2011 : Debug:     status_check = "none"
Tue Nov  8 10:05:54 2011 : Debug:     ping_interval = 30
Tue Nov  8 10:05:54 2011 : Debug:     check_interval = 30
Tue Nov  8 10:05:54 2011 : Debug:     num_answers_to_alive = 3
Tue Nov  8 10:05:54 2011 : Debug:     num_pings_to_alive = 3
Tue Nov  8 10:05:54 2011 : Debug:     revive_interval = 60
Tue Nov  8 10:05:54 2011 : Debug:     status_check_timeout = 4
Tue Nov  8 10:05:54 2011 : Debug:     irt = 2
Tue Nov  8 10:05:54 2011 : Debug:     mrt = 16
Tue Nov  8 10:05:54 2011 : Debug:     mrc = 5
Tue Nov  8 10:05:54 2011 : Debug:     mrd = 30
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  home_server radius_24 {
Tue Nov  8 10:05:54 2011 : Debug:     ipaddr = xxx.xxx.xxx.xxx
Tue Nov  8 10:05:54 2011 : Debug:     port = 1812
Tue Nov  8 10:05:54 2011 : Debug:     type = "auth+acct"
Tue Nov  8 10:05:54 2011 : Debug:     secret = "xxxxxxx"
Tue Nov  8 10:05:54 2011 : Debug:     response_window = 20
Tue Nov  8 10:05:54 2011 : Debug:     max_outstanding = 65536
Tue Nov  8 10:05:54 2011 : Debug:     zombie_period = 40
Tue Nov  8 10:05:54 2011 : Debug:     status_check = "none"
Tue Nov  8 10:05:54 2011 : Debug:     ping_interval = 30
Tue Nov  8 10:05:54 2011 : Debug:     check_interval = 30
Tue Nov  8 10:05:54 2011 : Debug:     num_answers_to_alive = 3
Tue Nov  8 10:05:54 2011 : Debug:     num_pings_to_alive = 3
Tue Nov  8 10:05:54 2011 : Debug:     revive_interval = 60
Tue Nov  8 10:05:54 2011 : Debug:     status_check_timeout = 4
Tue Nov  8 10:05:54 2011 : Debug:     irt = 2
Tue Nov  8 10:05:54 2011 : Debug:     mrt = 16
Tue Nov  8 10:05:54 2011 : Debug:     mrc = 5
Tue Nov  8 10:05:54 2011 : Debug:     mrd = 30
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug:  home_server_pool radius_29 {
Tue Nov  8 10:05:54 2011 : Debug:     type = fail-over
Tue Nov  8 10:05:54 2011 : Debug:     home_server = radius_24
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug: radiusd: #### Loading Clients ####
Tue Nov  8 10:05:54 2011 : Debug:  client localhost {
Tue Nov  8 10:05:54 2011 : Debug:     ipaddr = 127.0.0.1
Tue Nov  8 10:05:54 2011 : Debug:     require_message_authenticator = no
Tue Nov  8 10:05:54 2011 : Debug:     secret = "xxxxxx"
Tue Nov  8 10:05:54 2011 : Debug:     shortname = "localhost"
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug: radiusd: #### Instantiating modules ####
Tue Nov  8 10:05:54 2011 : Debug:  instantiate {
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_exec, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_exec
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating exec
Tue Nov  8 10:05:54 2011 : Debug:   exec {
Tue Nov  8 10:05:54 2011 : Debug:     wait = no
Tue Nov  8 10:05:54 2011 : Debug:     input_pairs = "request"
Tue Nov  8 10:05:54 2011 : Debug:     shell_escape = yes
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_expr, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_expr
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating expr
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_expiration, checking if
it's valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_expiration
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating expiration
Tue Nov  8 10:05:54 2011 : Debug:   expiration {
Tue Nov  8 10:05:54 2011 : Debug:     reply-message = "Password Has
Expired  "
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_logintime, checking if
it's valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_logintime
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating logintime
Tue Nov  8 10:05:54 2011 : Debug:   logintime {
Tue Nov  8 10:05:54 2011 : Debug:     reply-message = "You are calling
outside your allowed timespan  "
Tue Nov  8 10:05:54 2011 : Debug:     minimum-timeout = 60
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug: radiusd: #### Loading Virtual Servers ####
Tue Nov  8 10:05:54 2011 : Debug: server wifi2 {
Tue Nov  8 10:05:54 2011 : Debug:  modules {
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_pap, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_pap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating pap
Tue Nov  8 10:05:54 2011 : Debug:   pap {
Tue Nov  8 10:05:54 2011 : Debug:     encryption_scheme = "auto"
Tue Nov  8 10:05:54 2011 : Debug:     auto_header = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_unix, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_unix
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating unix
Tue Nov  8 10:05:54 2011 : Debug:   unix {
Tue Nov  8 10:05:54 2011 : Debug:     radwtmp =
"/usr/local/var/log/radius/radwtmp"
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_ldap, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_ldap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating ldap
Tue Nov  8 10:05:54 2011 : Debug:   ldap {
Tue Nov  8 10:05:54 2011 : Debug:     server = "xxx.xxx.xxx.xxx"
Tue Nov  8 10:05:54 2011 : Debug:     port = 389
Tue Nov  8 10:05:54 2011 : Debug:     password = "xxxxxx"
Tue Nov  8 10:05:54 2011 : Debug:     identity =
"cn=admin,dc=company,dc=com"
Tue Nov  8 10:05:54 2011 : Debug:     net_timeout = 50
Tue Nov  8 10:05:54 2011 : Debug:     timeout = 50
Tue Nov  8 10:05:54 2011 : Debug:     timelimit = 10
Tue Nov  8 10:05:54 2011 : Debug:     tls_mode = no
Tue Nov  8 10:05:54 2011 : Debug:     start_tls = no
Tue Nov  8 10:05:54 2011 : Debug:     tls_require_cert = "allow"
Tue Nov  8 10:05:54 2011 : Debug:    tls {
Tue Nov  8 10:05:54 2011 : Debug:     start_tls = no
Tue Nov  8 10:05:54 2011 : Debug:     require_cert = "allow"
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:     basedn = "dc=company,dc=com"
Tue Nov  8 10:05:54 2011 : Debug:     filter = "(uid=%{Stripped-User-Name})"
Tue Nov  8 10:05:54 2011 : Debug:     base_filter =
"(objectclass=radiusprofile)"
Tue Nov  8 10:05:54 2011 : Debug:     password_attribute =
"Cleartext-Password"
Tue Nov  8 10:05:54 2011 : Debug:     auto_header = no
Tue Nov  8 10:05:54 2011 : Debug:     access_attr = "uid"
Tue Nov  8 10:05:54 2011 : Debug:     access_attr_used_for_allow = yes
Tue Nov  8 10:05:54 2011 : Debug:     groupname_attribute = "cn"
Tue Nov  8 10:05:54 2011 : Debug:     groupmembership_filter =
"(&(objectClass=groupOfNames)(member=%{control:LDAP-UserDn}))"
Tue Nov  8 10:05:54 2011 : Debug:     dictionary_mapping =
"/usr/local/etc/raddb/ldap.attrmap"
Tue Nov  8 10:05:54 2011 : Debug:     ldap_debug = 0
Tue Nov  8 10:05:54 2011 : Debug:     ldap_connections_number = 200
Tue Nov  8 10:05:54 2011 : Debug:     compare_check_items = no
Tue Nov  8 10:05:54 2011 : Debug:     do_xlat = yes
Tue Nov  8 10:05:54 2011 : Debug:     set_auth_type = yes
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: Registering ldap_groupcmp for
Ldap-Group
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: Registering ldap_xlat with
xlat_name ldap
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: reading ldap<->radius mappings
from file /usr/local/etc/raddb/ldap.attrmap
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to
RADIUS $GENERIC$
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to
RADIUS $GENERIC$
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusAuthType mapped to
RADIUS Auth-Type
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusSimultaneousUse
mapped to RADIUS Simultaneous-Use
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusCalledStationId
mapped to RADIUS Called-Station-Id
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusCallingStationId
mapped to RADIUS Calling-Station-Id
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP sambaLmPassword mapped to
RADIUS LM-Password
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP sambaNtPassword mapped to
RADIUS NT-Password
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS
SMB-Account-CTRL-TEXT
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusExpiration mapped to
RADIUS Expiration
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped
to RADIUS NAS-IP-Address
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusServiceType mapped
to RADIUS Service-Type
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedProtocol
mapped to RADIUS Framed-Protocol
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedIPAddress
mapped to RADIUS Framed-IP-Address
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask
mapped to RADIUS Framed-IP-Netmask
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped
to RADIUS Framed-Route
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped
to RADIUS Framed-Routing
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFilterId mapped to
RADIUS Filter-Id
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to
RADIUS Framed-MTU
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedCompression
mapped to RADIUS Framed-Compression
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginService mapped
to RADIUS Login-Service
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped
to RADIUS Login-TCP-Port
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusCallbackNumber
mapped to RADIUS Callback-Number
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to
RADIUS Callback-Id
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork
mapped to RADIUS Framed-IPX-Network
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusClass mapped to
RADIUS Class
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusSessionTimeout
mapped to RADIUS Session-Timeout
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped
to RADIUS Idle-Timeout
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusTerminationAction
mapped to RADIUS Termination-Action
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginLATService
mapped to RADIUS Login-LAT-Service
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped
to RADIUS Login-LAT-Node
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped
to RADIUS Login-LAT-Group
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink
mapped to RADIUS Framed-AppleTalk-Link
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP
radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone
mapped to RADIUS Framed-AppleTalk-Zone
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to
RADIUS Port-Limit
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped
to RADIUS Login-LAT-Port
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped
to RADIUS Reply-Message
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusTunnelType mapped to
RADIUS Tunnel-Type
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusTunnelMediumType
mapped to RADIUS Tunnel-Medium-Type
Tue Nov  8 10:05:54 2011 : Debug: rlm_ldap: LDAP radiusTunnelPrivateGroupId
mapped to RADIUS Tunnel-Private-Group-Id
Tue Nov  8 10:05:54 2011 : Debug: conns: 0x8174a38
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_eap, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_eap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap
Tue Nov  8 10:05:54 2011 : Debug:   eap {
Tue Nov  8 10:05:54 2011 : Debug:     default_eap_type = "tls"
Tue Nov  8 10:05:54 2011 : Debug:     timer_expire = 60
Tue Nov  8 10:05:54 2011 : Debug:     ignore_unknown_eap_types = no
Tue Nov  8 10:05:54 2011 : Debug:     cisco_accounting_username_bug = no
Tue Nov  8 10:05:54 2011 : Debug:     max_sessions = 2048
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_md5
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-md5
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_leap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-leap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-gtc
Tue Nov  8 10:05:54 2011 : Debug:    gtc {
Tue Nov  8 10:05:54 2011 : Debug:     challenge = "Password: "
Tue Nov  8 10:05:54 2011 : Debug:     auth_type = "PAP"
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_tls
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-tls
Tue Nov  8 10:05:54 2011 : Debug:    tls {
Tue Nov  8 10:05:54 2011 : Debug:     rsa_key_exchange = no
Tue Nov  8 10:05:54 2011 : Debug:     dh_key_exchange = yes
Tue Nov  8 10:05:54 2011 : Debug:     rsa_key_length = 512
Tue Nov  8 10:05:54 2011 : Debug:     dh_key_length = 512
Tue Nov  8 10:05:54 2011 : Debug:     verify_depth = 0
Tue Nov  8 10:05:54 2011 : Debug:     pem_file_type = yes
Tue Nov  8 10:05:54 2011 : Debug:     private_key_file =
"/usr/local/etc/raddb/eduroam_CA/10076494/radius.es_privatekey.pem"
Tue Nov  8 10:05:54 2011 : Debug:     certificate_file =
"/usr/local/etc/raddb/eduroam_CA/10076494/10076494.crt"
Tue Nov  8 10:05:54 2011 : Debug:     CA_file =
"/usr/local/etc/raddb/eduroam_CA/10076494/TERENASSL_PATH.pem"
Tue Nov  8 10:05:54 2011 : Debug:     dh_file =
"/usr/local/etc/raddb/eduroam_CA/10076494/dh"
Tue Nov  8 10:05:54 2011 : Debug:     random_file =
"/usr/local/etc/raddb/eduroam_CA/10076494/random"
Tue Nov  8 10:05:54 2011 : Debug:     fragment_size = 1024
Tue Nov  8 10:05:54 2011 : Debug:     include_length = yes
Tue Nov  8 10:05:54 2011 : Debug:     check_crl = no
Tue Nov  8 10:05:54 2011 : Debug:     cipher_list = "DEFAULT"
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-ttls
Tue Nov  8 10:05:54 2011 : Debug:    ttls {
Tue Nov  8 10:05:54 2011 : Debug:     default_eap_type = "md5"
Tue Nov  8 10:05:54 2011 : Debug:     copy_request_to_tunnel = no
Tue Nov  8 10:05:54 2011 : Debug:     use_tunneled_reply = yes
Tue Nov  8 10:05:54 2011 : Debug:     virtual_server = "wifi2"
Tue Nov  8 10:05:54 2011 : Debug:     include_length = yes
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module rlm_eap_peap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-peap
Tue Nov  8 10:05:54 2011 : Debug:    peap {
Tue Nov  8 10:05:54 2011 : Debug:     default_eap_type = "mschapv2"
Tue Nov  8 10:05:54 2011 : Debug:     copy_request_to_tunnel = no
Tue Nov  8 10:05:54 2011 : Debug:     use_tunneled_reply = yes
Tue Nov  8 10:05:54 2011 : Debug:     proxy_tunneled_request_as_eap = yes
Tue Nov  8 10:05:54 2011 : Debug:     virtual_server = "inner-tunnel"
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to sub-module
rlm_eap_mschapv2
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating eap-mschapv2
Tue Nov  8 10:05:54 2011 : Debug:    mschapv2 {
Tue Nov  8 10:05:54 2011 : Debug:     with_ntdomain_hack = no
Tue Nov  8 10:05:54 2011 : Debug:    }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authorize {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_detail, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_detail
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating auth_log
Tue Nov  8 10:05:54 2011 : Debug:   detail auth_log {
Tue Nov  8 10:05:54 2011 : Debug:     detailfile =
"/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
Tue Nov  8 10:05:54 2011 : Debug:     header = "%t"
Tue Nov  8 10:05:54 2011 : Debug:     detailperm = 384
Tue Nov  8 10:05:54 2011 : Debug:     dirperm = 493
Tue Nov  8 10:05:54 2011 : Debug:     locking = no
Tue Nov  8 10:05:54 2011 : Debug:     log_packet_header = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_preprocess, checking if
it's valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_preprocess
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating preprocess
Tue Nov  8 10:05:54 2011 : Debug:   preprocess {
Tue Nov  8 10:05:54 2011 : Debug:     huntgroups =
"/usr/local/etc/raddb/huntgroups"
Tue Nov  8 10:05:54 2011 : Debug:     hints = "/usr/local/etc/raddb/hints"
Tue Nov  8 10:05:54 2011 : Debug:     with_ascend_hack = no
Tue Nov  8 10:05:54 2011 : Debug:     ascend_channels_per_line = 23
Tue Nov  8 10:05:54 2011 : Debug:     with_ntdomain_hack = no
Tue Nov  8 10:05:54 2011 : Debug:     with_specialix_jetstream_hack = no
Tue Nov  8 10:05:54 2011 : Debug:     with_cisco_vsa_hack = no
Tue Nov  8 10:05:54 2011 : Debug:     with_alvarion_vsa_hack = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_realm, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_realm
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating suffix
Tue Nov  8 10:05:54 2011 : Debug:   realm suffix {
Tue Nov  8 10:05:54 2011 : Debug:     format = "suffix"
Tue Nov  8 10:05:54 2011 : Debug:     delimiter = "@"
Tue Nov  8 10:05:54 2011 : Debug:     ignore_default = no
Tue Nov  8 10:05:54 2011 : Debug:     ignore_null = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_files, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_files
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating files
Tue Nov  8 10:05:54 2011 : Debug:   files {
Tue Nov  8 10:05:54 2011 : Debug:     usersfile =
"/usr/local/etc/raddb/users"
Tue Nov  8 10:05:54 2011 : Debug:     acctusersfile =
"/usr/local/etc/raddb/acct_users"
Tue Nov  8 10:05:54 2011 : Debug:     preproxy_usersfile =
"/usr/local/etc/raddb/preproxy_users"
Tue Nov  8 10:05:54 2011 : Debug:     compat = "no"
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking preacct {...} for more
modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_acct_unique, checking if
it's valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_acct_unique
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating acct_unique
Tue Nov  8 10:05:54 2011 : Debug:   acct_unique {
Tue Nov  8 10:05:54 2011 : Debug:     key = "User-Name, Acct-Session-Id,
NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking accounting {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating detail
Tue Nov  8 10:05:54 2011 : Debug:   detail {
Tue Nov  8 10:05:54 2011 : Debug:     detailfile =
"/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Tue Nov  8 10:05:54 2011 : Debug:     header = "%t"
Tue Nov  8 10:05:54 2011 : Debug:     detailperm = 384
Tue Nov  8 10:05:54 2011 : Debug:     dirperm = 493
Tue Nov  8 10:05:54 2011 : Debug:     locking = no
Tue Nov  8 10:05:54 2011 : Debug:     log_packet_header = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_always, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_always
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating ok
Tue Nov  8 10:05:54 2011 : Debug:   always ok {
Tue Nov  8 10:05:54 2011 : Debug:     rcode = "ok"
Tue Nov  8 10:05:54 2011 : Debug:     simulcount = 0
Tue Nov  8 10:05:54 2011 : Debug:     mpp = no
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking session {...} for more
modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_radutmp, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_radutmp
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating radutmp
Tue Nov  8 10:05:54 2011 : Debug:   radutmp {
Tue Nov  8 10:05:54 2011 : Debug:     filename =
"/usr/local/var/log/radius/radutmp"
Tue Nov  8 10:05:54 2011 : Debug:     username = "%{User-Name}"
Tue Nov  8 10:05:54 2011 : Debug:     case_sensitive = yes
Tue Nov  8 10:05:54 2011 : Debug:     check_with_nas = yes
Tue Nov  8 10:05:54 2011 : Debug:     perm = 384
Tue Nov  8 10:05:54 2011 : Debug:     callerid = yes
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-auth {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_attr_filter, checking if
it's valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_attr_filter
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating
attr_filter.access_reject
Tue Nov  8 10:05:54 2011 : Debug:   attr_filter attr_filter.access_reject {
Tue Nov  8 10:05:54 2011 : Debug:     attrsfile =
"/usr/local/etc/raddb/attrs.access_reject"
Tue Nov  8 10:05:54 2011 : Debug:     key = "%{User-Name}"
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  } # modules
Tue Nov  8 10:05:54 2011 : Debug: } # server
Tue Nov  8 10:05:54 2011 : Debug: server inner-tunnel {
Tue Nov  8 10:05:54 2011 : Debug:  modules {
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_chap, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_chap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating chap
Tue Nov  8 10:05:54 2011 : Debug:     (Loaded rlm_mschap, checking if it's
valid)
Tue Nov  8 10:05:54 2011 : Debug:  Module: Linked to module rlm_mschap
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating mschap
Tue Nov  8 10:05:54 2011 : Debug:   mschap {
Tue Nov  8 10:05:54 2011 : Debug:     use_mppe = yes
Tue Nov  8 10:05:54 2011 : Debug:     require_encryption = no
Tue Nov  8 10:05:54 2011 : Debug:     require_strong = no
Tue Nov  8 10:05:54 2011 : Debug:     with_ntdomain_hack = yes
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authorize {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking session {...} for more
modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-auth {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  } # modules
Tue Nov  8 10:05:54 2011 : Debug: } # server
Tue Nov  8 10:05:54 2011 : Debug: server {
Tue Nov  8 10:05:54 2011 : Debug:  modules {
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authenticate {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking authorize {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking preacct {...} for more
modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking accounting {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Instantiating
attr_filter.accounting_response
Tue Nov  8 10:05:54 2011 : Debug:   attr_filter
attr_filter.accounting_response {
Tue Nov  8 10:05:54 2011 : Debug:     attrsfile =
"/usr/local/etc/raddb/attrs.accounting_response"
Tue Nov  8 10:05:54 2011 : Debug:     key = "%{User-Name}"
Tue Nov  8 10:05:54 2011 : Debug:   }
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking session {...} for more
modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-proxy {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  Module: Checking post-auth {...} for
more modules to load
Tue Nov  8 10:05:54 2011 : Debug:  } # modules
Tue Nov  8 10:05:54 2011 : Debug: } # server
Tue Nov  8 10:05:54 2011 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Tue Nov  8 10:05:54 2011 : Debug: listen {
Tue Nov  8 10:05:54 2011 : Debug:     type = "auth"
Tue Nov  8 10:05:54 2011 : Debug:     ipaddr = *
Tue Nov  8 10:05:54 2011 : Debug:     port = 0
Tue Nov  8 10:05:54 2011 : Debug: }
Tue Nov  8 10:05:54 2011 : Debug: listen {
Tue Nov  8 10:05:54 2011 : Debug:     type = "acct"
Tue Nov  8 10:05:54 2011 : Debug:     ipaddr = *
Tue Nov  8 10:05:54 2011 : Debug:     port = 0
Tue Nov  8 10:05:54 2011 : Debug: }
Tue Nov  8 10:05:54 2011 : Debug: listen {
Tue Nov  8 10:05:54 2011 : Debug:     type = "control"
Tue Nov  8 10:05:54 2011 : Debug:  listen {
Tue Nov  8 10:05:54 2011 : Debug:     socket =
"/usr/local/var/run/radiusd/radiusd.sock"
Tue Nov  8 10:05:54 2011 : Debug:  }
Tue Nov  8 10:05:54 2011 : Debug: }
Tue Nov  8 10:05:54 2011 : Debug: Listening on authentication address *
port 1812
Tue Nov  8 10:05:54 2011 : Debug: Listening on accounting address * port
1813
Tue Nov  8 10:05:54 2011 : Debug: Listening on command file
/usr/local/var/run/radiusd/radiusd.sock
Tue Nov  8 10:05:54 2011 : Debug: Listening on proxy address * port 1814
Tue Nov  8 10:05:54 2011 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host xxx.xxx.xxx.xxx port 32928,
id=80, length=61
    User-Name = "student13"
    User-Password = "xxxxxxx"
    NAS-IP-Address = xxx.xxx.xxx.xxx
    NAS-Port = 10
Tue Nov  8 10:06:21 2011 : Info: +- entering group authorize {...}
Tue Nov  8 10:06:21 2011 : Info: ++[preprocess] returns ok
Tue Nov  8 10:06:21 2011 : Info: ++[chap] returns noop
Tue Nov  8 10:06:21 2011 : Info: ++[mschap] returns noop
Tue Nov  8 10:06:21 2011 : Info: [suffix] No '@' in User-Name =
"student13", looking up realm NULL
Tue Nov  8 10:06:21 2011 : Info: [suffix] Found realm "NULL"
Tue Nov  8 10:06:21 2011 : Info: [suffix] Adding Stripped-User-Name =
"student13"
Tue Nov  8 10:06:21 2011 : Info: [suffix] Adding Realm = "NULL"
Tue Nov  8 10:06:21 2011 : Info: [suffix] Authentication realm is LOCAL.
Tue Nov  8 10:06:21 2011 : Info: ++[suffix] returns ok
Tue Nov  8 10:06:21 2011 : Info: [eap] No EAP-Message, not doing EAP
Tue Nov  8 10:06:21 2011 : Info: ++[eap] returns noop
Tue Nov  8 10:06:21 2011 : Info: ++[unix] returns notfound
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: Entering ldap_groupcmp()
Tue Nov  8 10:06:21 2011 : Info: [files]     expand: dc=company,dc=com ->
dc=company,dc=com
Tue Nov  8 10:06:21 2011 : Info: [files]     expand:
(uid=%{Stripped-User-Name}) -> (uid=student13)
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: attempting LDAP reconnection
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: (re)connect to
xxx.xxx.xxx.xxx:389, authentication 0
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: bind as
cn=xxxxx,dc=company,dc=com/pppp to xxx.xxx.xxx.xxx:389
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: waiting for bind result ...
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: Bind was successful
Tue Nov  8 10:06:21 2011 : Debug: rlm_ldap: performing search in
dc=company,dc=com, with filter (uid=student13)
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Tue Nov  8 10:06:22 2011 : Info: [files]     expand:
(&(objectClass=groupOfNames)(member=%{control:LDAP-UserDn})) ->
(&(objectClass=groupOfNames)(member=cn\3dstudent13\2ccn\3dusers\2cdc\3dcompany\2cdc\3dcom))
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: performing search in
dc=company,dc=com, with filter
(&(cn=student13)(&(objectClass=groupOfNames)(member=cn\3dstudent13\2ccn\3dusers\2cdc\3dcompany\2cdc\3dcom)))
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap::ldap_groupcmp: User found in
group student
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Tue Nov  8 10:06:22 2011 : Info: [files] users: Matched entry DEFAULT at
line 5
Tue Nov  8 10:06:22 2011 : Info: ++[files] returns ok
Tue Nov  8 10:06:22 2011 : Info: [ldap] performing user authorization for
student13
Tue Nov  8 10:06:22 2011 : Info: [ldap]     expand:
(uid=%{Stripped-User-Name}) -> (uid=student13)
Tue Nov  8 10:06:22 2011 : Info: [ldap]     expand: dc=company,dc=com ->
dc=company,dc=com
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Tue Nov  8 10:06:22 2011 : Debug: rlm_ldap: performing search in
dc=company,dc=com, with filter (uid=student13)
Tue Nov  8 10:06:23 2011 : Info: [ldap] checking if remote access for
student13 is allowed by uid
Tue Nov  8 10:06:23 2011 : Info: [ldap] looking for check items in
directory...
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: sambaNtPassword -> NT-Password
== 0x555463443354631374445413844464334304134353244313042453044433445
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: sambaLmPassword -> LM-Password
== 0x4323314245313638353037463743464341414433423433354235313430344545
Tue Nov  8 10:06:23 2011 : Info: [ldap] looking for reply items in
directory...
Tue Nov  8 10:06:23 2011 : Debug: WARNING: No "known good" password was
found in LDAP.  Are you sure that the user is configured correctly?
Tue Nov  8 10:06:23 2011 : Info: [ldap] Setting Auth-Type = LDAP
Tue Nov  8 10:06:23 2011 : Info: [ldap] user student13 authorized to use
remote access
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Tue Nov  8 10:06:23 2011 : Info: ++[ldap] returns ok
Tue Nov  8 10:06:23 2011 : Info: ++[expiration] returns noop
Tue Nov  8 10:06:23 2011 : Info: ++[logintime] returns noop
Tue Nov  8 10:06:23 2011 : Info: [pap] Normalizing NT-Password from hex
encoding
Tue Nov  8 10:06:23 2011 : Info: [pap] Normalizing LM-Password from hex
encoding
Tue Nov  8 10:06:23 2011 : Info: [pap] Found existing Auth-Type, not
changing it.
Tue Nov  8 10:06:23 2011 : Info: ++[pap] returns noop
Tue Nov  8 10:06:23 2011 : Info: Found Auth-Type = LDAP
Tue Nov  8 10:06:23 2011 : Info: +- entering group LDAP {...}
Tue Nov  8 10:06:23 2011 : Info: [ldap] login attempt by "student13" with
password "xxxxxx"
Tue Nov  8 10:06:23 2011 : Info: [ldap] user DN:
cn=student13,cn=users,dc=company,dc=com
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: (re)connect to
xxx.xxx.xxx.xxx:389, authentication 1
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: bind as
cn=student13,cn=users,dc=company,dc=com/xxxxxx to xxx.xxx.xxx.xxx:389
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: waiting for bind result ...
Tue Nov  8 10:06:23 2011 : Debug: rlm_ldap: Bind was successful
Tue Nov  8 10:06:23 2011 : Info: [ldap] user student13 authenticated
succesfully
Tue Nov  8 10:06:23 2011 : Info: ++[ldap] returns ok
Tue Nov  8 10:06:23 2011 : Auth: Login OK: [student13] (from client radius
port 10)
Tue Nov  8 10:06:23 2011 : Info: +- entering group post-auth {...}
Tue Nov  8 10:06:23 2011 : Info: ++[exec] returns noop
Sending Access-Accept of id 80 to xxx.xxx.xxx.xxx port 32928
    Aruba-User-Role = "student"
Tue Nov  8 10:06:23 2011 : Info: Finished request 0.
Tue Nov  8 10:06:23 2011 : Debug: Going to the next request
Tue Nov  8 10:06:23 2011 : Debug: Waking up in 4.9 seconds.
Tue Nov  8 10:06:28 2011 : Info: Cleaning up request 0 ID 80 with timestamp
+27
Tue Nov  8 10:06:28 2011 : Debug: Ready to process requests.

Thank you in advance
Remon

advice about ldap groupfilter query

Juan remon