Post the full debug for a radtest request with uppercase username. That logging function should go before you work with attributes. debug already logs what comes after.
Hello Ivan, Here is the debug using radtest radtest RadUser R@diust3st localhost 10 testing123 FreeRADIUS Version 2.0.5, for host x86_64-redhat-linux-gnu, built on Jul 30 2008 at 10:40:47 Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License v2. Starting - reading configuration files ... including configuration file /etc/raddb/radiusd.conf including configuration file /etc/raddb/proxy.conf including configuration file /etc/raddb/clients.conf including configuration file /etc/raddb/snmp.conf including configuration file /etc/raddb/eap.conf including configuration file /etc/raddb/policy.conf including files in directory /etc/raddb/sites-enabled/ including configuration file /etc/raddb/sites-enabled/inner-tunnel including configuration file /etc/raddb/sites-enabled/default group = root user = root including dictionary file /etc/raddb/dictionary main { prefix = "/usr" localstatedir = "/var" logdir = "/var/log/radius" libdir = "/usr/lib/freeradius" radacctdir = "/var/log/radius/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 5 max_requests = 1024 allow_core_dumps = no pidfile = "/var/run/radiusd/radiusd.pid" checkrad = "/usr/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = yes auth_badpass = no auth_goodpass = no } } client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = "testing123" nastype = "other" } client 10.0.1.0/24 { require_message_authenticator = no secret = "c3750test" shortname = "switch-man-lan" nastype = "cisco" } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } home_server localhost { ipaddr = 127.0.0.1 port = 1812 type = "auth" secret = "testing123" response_window = 20 max_outstanding = 65536 zombie_period = 40 status_check = "status-server" ping_check = "none" ping_interval = 30 check_interval = 30 num_answers_to_alive = 3 num_pings_to_alive = 3 revive_interval = 120 status_check_timeout = 4 } home_server_pool my_auth_failover { type = fail-over home_server = localhost } realm example.com { auth_pool = my_auth_failover } realm NINT { authhost = LOCAL accthost = LOCAL } realm ads.nint.org { authhost = LOCAL accthost = LOCAL } realm LOCAL { } radiusd: #### Instantiating modules #### instantiate { Module: Linked to module rlm_exec Module: Instantiating exec exec { wait = yes input_pairs = "request" shell_escape = yes } Module: Linked to module rlm_expr Module: Instantiating expr Module: Linked to module rlm_expiration Module: Instantiating expiration expiration { reply-message = "Password Has Expired " } Module: Linked to module rlm_logintime Module: Instantiating logintime logintime { reply-message = "You are calling outside your allowed timespan " minimum-timeout = 60 } } radiusd: #### Loading Virtual Servers #### server inner-tunnel { modules { Module: Checking authenticate {...} for more modules to load Module: Linked to module rlm_pap Module: Instantiating pap pap { encryption_scheme = "auto" auto_header = yes } Module: Linked to module rlm_chap Module: Instantiating chap Module: Linked to module rlm_mschap Module: Instantiating mschap mschap { use_mppe = no require_encryption = yes require_strong = no with_ntdomain_hack = yes ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --domain=NINT --username=%{Stripped-User-Name:-%{ mschap:User-Name}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}" } Module: Linked to module rlm_ldap Module: Instantiating ldap ldap { server = "********************" port = 3268 password = "***************" identity = "bckup@************" net_timeout = 1 timeout = 4 timelimit = 3 tls_mode = no start_tls = no tls_require_cert = "allow" tls { start_tls = no require_cert = "allow" } basedn = "dc=ads,dc=nint,dc=org" filter = "(sAMAccountname=%{mschap:User-Name:-%{User-Name}})" base_filter = "(objectclass=radiusprofile)" auto_header = no access_attr_used_for_allow = yes groupname_attribute = "cn" groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=Gro upOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" groupmembership_attribute = "memberOf" dictionary_mapping = "/etc/raddb/ldap.attrmap" ldap_debug = 0 ldap_connections_number = 5 compare_check_items = no do_xlat = yes set_auth_type = yes } rlm_ldap: Registering ldap_groupcmp for Ldap-Group rlm_ldap: Registering ldap_xlat with xlat_name ldap rlm_ldap: reading ldap<->radius mappings from file /etc/raddb/ldap.attrmap rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network rlm_ldap: LDAP radiusClass mapped to RADIUS Class rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message conns: 0x28f9510 Module: Linked to module rlm_eap Module: Instantiating eap eap { default_eap_type = "peap" timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no } Module: Linked to sub-module rlm_eap_gtc Module: Instantiating eap-gtc gtc { challenge = "Password: " auth_type = "pap" } Module: Linked to sub-module rlm_eap_tls Module: Instantiating eap-tls tls { rsa_key_exchange = no dh_key_exchange = yes rsa_key_length = 512 dh_key_length = 512 verify_depth = 0 pem_file_type = yes private_key_file = "/etc/raddb/certs/ns2.pem" certificate_file = "/etc/raddb/certs/cnsradius01.ads.nint.org.pem" CA_file = "/etc/raddb/certs/NINTCA.pem" private_key_password = "cnsradius" dh_file = "/etc/raddb/certs/dh" random_file = "/etc/raddb/certs/random" fragment_size = 1024 include_length = yes check_crl = no cipher_list = "DEFAULT" make_cert_command = "/etc/raddb/certs/bootstrap" } Module: Linked to sub-module rlm_eap_ttls Module: Instantiating eap-ttls ttls { default_eap_type = "gtc" copy_request_to_tunnel = yes use_tunneled_reply = yes virtual_server = "inner-tunnel" } Module: Linked to sub-module rlm_eap_peap Module: Instantiating eap-peap peap { default_eap_type = "mschapv2" copy_request_to_tunnel = no use_tunneled_reply = yes proxy_tunneled_request_as_eap = yes virtual_server = "inner-tunnel" } Module: Linked to sub-module rlm_eap_mschapv2 Module: Instantiating eap-mschapv2 mschapv2 { with_ntdomain_hack = no } Module: Checking authorize {...} for more modules to load Module: Linked to module rlm_preprocess Module: Instantiating preprocess preprocess { huntgroups = "/etc/raddb/huntgroups" hints = "/etc/raddb/hints" with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } Module: Linked to module rlm_realm Module: Instantiating suffix realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } Module: Instantiating ntdomain realm ntdomain { format = "prefix" delimiter = "\" ignore_default = no ignore_null = no } Module: Linked to module rlm_files Module: Instantiating files files { usersfile = "/etc/raddb/users" acctusersfile = "/etc/raddb/acct_users" preproxy_usersfile = "/etc/raddb/preproxy_users" compat = "no" } Module: Checking preacct {...} for more modules to load Module: Linked to module rlm_acct_unique Module: Instantiating acct_unique acct_unique { key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" } Module: Checking accounting {...} for more modules to load Module: Linked to module rlm_detail Module: Instantiating detail detail { detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" header = "%t" detailperm = 384 dirperm = 493 locking = no log_packet_header = no } Module: Linked to module rlm_unix Module: Instantiating unix unix { radwtmp = "/var/log/radius/radwtmp" } Module: Linked to module rlm_radutmp Module: Instantiating radutmp radutmp { filename = "/var/log/radius/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes perm = 384 callerid = yes } Module: Linked to module rlm_attr_filter Module: Instantiating attr_filter.accounting_response attr_filter attr_filter.accounting_response { attrsfile = "/etc/raddb/attrs.accounting_response" key = "%{User-Name}" } Module: Checking session {...} for more modules to load Module: Checking post-proxy {...} for more modules to load Module: Checking post-auth {...} for more modules to load Module: Instantiating attr_filter.access_reject attr_filter attr_filter.access_reject { attrsfile = "/etc/raddb/attrs.access_reject" key = "%{User-Name}" } } } server { modules { Module: Checking authenticate {...} for more modules to load Module: Checking authorize {...} for more modules to load Module: Linked to module rlm_perl Module: Instantiating perl perl { module = "/etc/raddb/perl_tolower.pm" func_authorize = "authorize" func_authenticate = "authenticate" func_accounting = "accounting" func_preacct = "preacct" func_checksimul = "checksimul" func_detach = "detach" func_xlat = "xlat" func_pre_proxy = "pre_proxy" func_post_proxy = "post_proxy" func_post_auth = "post_auth" } perl { max_clones = 32 start_clones = 32 min_spare_clones = 0 max_spare_clones = 32 cleanup_delay = 5 max_request_per_clone = 0 } Module: Checking preacct {...} for more modules to load Module: Checking accounting {...} for more modules to load Module: Checking session {...} for more modules to load Module: Checking post-proxy {...} for more modules to load Module: Checking post-auth {...} for more modules to load } } radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = * port = 0 } listen { type = "acct" ipaddr = * port = 0 } main { snmp = no smux_password = "" snmp_write_access = no } Listening on authentication address * port 1812 Listening on accounting address * port 1813 Listening on proxy address * port 1814 Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 38149, id=225, length=59 User-Name = "RadUser" User-Password = "R@diust3st" NAS-IP-Address = 10.0.0.247 NAS-Port = 10 +- entering group authorize ++[preprocess] returns ok perl_pool: item 0x29512a0 asigned new request. Handled so far: 1 found interpetator at address 0x29512a0 rlm_perl: RAD_REQUEST: User-Name = RadUser rlm_perl: RAD_REQUEST: User-Password = R@diust3st rlm_perl: RAD_REQUEST: NAS-Port = 10 rlm_perl: RAD_REQUEST: NAS-IP-Address = 10.0.0.247 rlm_perl: Added pair User-Name = raduser rlm_perl: Added pair User-Password = R@diust3st rlm_perl: Added pair NAS-Port = 10 rlm_perl: Added pair NAS-IP-Address = 10.0.0.247 perl_pool total/active/spare [32/0/32] Unreserve perl at address 0x29512a0 ++[perl] returns updated ++[chap] returns noop ++[mschap] returns noop rlm_realm: No '@' in User-Name = "raduser", looking up realm NULL rlm_realm: No such realm "NULL" ++[suffix] returns noop rlm_eap: No EAP-Message, not doing EAP ++[eap] returns noop rlm_ldap: Entering ldap_groupcmp() expand: dc=ads,dc=nint,dc=org -> dc=ads,dc=nint,dc=org expand: (sAMAccountname=%{mschap:User-Name:-%{User-Name}}) -> (sAMAccountname=raduser) rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: attempting LDAP reconnection rlm_ldap: (re)connect to ************:3268, authentication 0 rlm_ldap: bind as bckup@*********/*********** to ******************:3268 rlm_ldap: waiting for bind result ... rlm_ldap: Bind was successful rlm_ldap: performing search in dc=ads,dc=nint,dc=org, with filter (sAMAccountname=raduser) rlm_ldap: ldap_release_conn: Release Id: 0 expand: (|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn}))) -> (|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=))) rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in dc=ads,dc=nint,dc=org, with filter (&(cn=RCNS-Group)(|(&(objectClass=GroupOfNames)(member=))(&(objectClass=GroupOfUniqueNames)(uniquemember=)))) rlm_ldap: object not found or got ambiguous search result rlm_ldap: ldap_release_conn: Release Id: 0 rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in CN=RadUser,OU=CNS,OU=SupportGrp,DC=ads,DC=nint,DC=org, with filter (objectclass=*) rlm_ldap: performing search in CN=RCNS-Group,OU=CNS,OU=SupportGrp,DC=ads,DC=nint,DC=org, with filter (cn=RCNS-Group) rlm_ldap::ldap_groupcmp: User found in group RCNS-Group rlm_ldap: ldap_release_conn: Release Id: 0 users: Matched entry DEFAULT at line 204 ++[files] returns ok rlm_ldap: - authorize rlm_ldap: performing user authorization for raduser expand: (sAMAccountname=%{mschap:User-Name:-%{User-Name}}) -> (sAMAccountname=raduser) expand: dc=ads,dc=nint,dc=org -> dc=ads,dc=nint,dc=org rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in dc=ads,dc=nint,dc=org, with filter (sAMAccountname=raduser) rlm_ldap: looking for check items in directory... rlm_ldap: looking for reply items in directory... WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? rlm_ldap: Setting Auth-Type = LDAP rlm_ldap: user raduser authorized to use remote access rlm_ldap: ldap_release_conn: Release Id: 0 ++[ldap] returns ok ++[expiration] returns noop ++[logintime] returns noop rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. ++[pap] returns noop rad_check_password: Found Auth-Type LDAP auth: type "LDAP" +- entering group LDAP rlm_ldap: - authenticate rlm_ldap: login attempt by "raduser" with password "R@diust3st" rlm_ldap: user DN: CN=RadUser,OU=CNS,OU=SupportGrp,DC=ads,DC=nint,DC=org rlm_ldap: (re)connect to ****************:3268, authentication 1 rlm_ldap: bind as CN=RadUser,OU=CNS,OU=SupportGrp,DC=***,DC=*****,DC=****/R@diust3st to ************:3268 rlm_ldap: waiting for bind result ... rlm_ldap: Bind was successful rlm_ldap: user raduser authenticated succesfully ++[ldap] returns ok Login OK: [raduser] (from client localhost port 10) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 225 to 127.0.0.1 port 38149 Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Type:0 = VLAN Tunnel-Private-Group-Id:0 = "254" Finished request 0. Going to the next request