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