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