Guest User!

You are not Sophos Staff.

[7.270] Special characters in user name w/ RADIUS, auth fails [NOTOURBUG]

Issue:
UPDATED: With IAS and having users with "special characters" in their user names - back end fails as well as auto-creation on security subsystem fails.

REVISED EDIT #3:
IAS issue confirmed.
AD Authentication method does not have the problem.

However - when using the authentication order:
1. RADIUS
2. AD Authentication.
Then the AUTH will fail, because of the first RADIUS reject.
The second request through AD is "ignored" since the RADIUS/IAS has precedense in the AUTH list.


Workaround(s):
* Do not use special characters in user-names when using RADIUS/IAS Windows Server 2003.
* Or use AD Authentication method instead of RADIUS.

 
 

Test-environment:[LIST=1]
  • Create the following test-users in AD:

    • Username:testu
      Password: Password1
    • Username: tøstæ
      Password: Password1

  • Create RADIUS authentication setup according to the KB article, "RADIS Authentication V7 - Howto":
    http://portal.knowledgebase.net/display/2/kb/article.asp?aid=254953
    *** Note: You must enable"Automatic user creation" in Users->Authentication->Global Settings if this is not already enabled.
  • Enable debugging via SSH:
    killall -USR2 aua.bin
  • Enable AD Authentication (for an alternative test) as well.
[/LIST]Note: Both usernames are valid Active Directory user names, altough the latter username is not recommended.
 
 

Test procedure:

  • Log on to the End-user portal with "testu".
  • Verify that the user is properly created in Users->Users. It's username will be listed there.
  • Log on to the End-user portal with "tøstæ".
  • Logon to the portal should fail.
  • No user is created under "Users->Users" management page.
Parents
  • Additional debug log - using both AD authentication and RADIUS authentication:
    (Domain names and IP's have been changed for safety reasons)

    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="handle_client: portal,tøstæ,Password1,192.***.***.***" 
    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="handle_client: f[:P]ortal u:tøstæ c:192.***.***.*** t:-" 
    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="authentication for facility portal. Force re-auth" 
    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="Summary u:tøstæ f[:P]ortal -> cache miss" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Child forked" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Calling do_auth as child" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: trying method local" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Entering do_auth_local. facility = portal, username = tøstæ" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: authentication failed with method local, trying next method" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: trying method adirectory" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Entering do_auth_adirectory" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Entering do_auth_directory: server=192.777.888.999 port=389 ssl=0 bind_dn=CN=__RADIUS,OU=Service Accounts,OU=Users,OU=Resources,DC=mydomain,DC=local base_dn=DC=mydomain,DC=local" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth_directory: getting base_dn..." 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth_directory() authenticating user" 
    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="Master: spawned authentication child." 
    2008:08:10-16:25:07 (none) aua[32383]: id="3007" severity="debug" sys="System" sub="auth" name="Master: waiting for new connection." 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="ldapFilter: (&(objectClass=user)(objectcategory=Person)(sAMAccountName=tøstæ))" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth_directory() - dump ldapUserObject: 
    2008:08:10-16:25:07 (none) aua[5100]: $VAR1 = bless( { 
    2008:08:10-16:25:07 (none) aua[5100]: 'changes' => [], 
    2008:08:10-16:25:07 (none) aua[5100]: 'changetype' => 'modify', 
    2008:08:10-16:25:07 (none) aua[5100]: 'asn' => { 
    2008:08:10-16:25:07 (none) aua[5100]: 'objectName' => 'CN=Tøst Usær,OU=Users,OU=Users,OU=Resources,DC=mydomain,DC=local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'attributes' => [ 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'type' => 'displayName', 
    2008:08:10-16:25:07 (none) aua[5100]: 'vals' => [ 
    2008:08:10-16:25:07 (none) aua[5100]: 'Tøst Usær' 
    2008:08:10-16:25:07 (none) aua[5100]: ] 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'type' => 'memberOf', 
    2008:08:10-16:25:07 (none) aua[5100]: 'vals' => [ 
    2008:08:10-16:25:07 (none) aua[5100]: 'CN=portal,OU=Groups,OU=Resources,DC=mydomain,DC=local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'CN=ssl,OU=Groups,OU=Resources,DC=mydomain,DC=local' 
    2008:08:10-16:25:07 (none) aua[5100]: ] 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'type' => 'sAMAccountName', 
    2008:08:10-16:25:07 (none) aua[5100]: 'vals' => [ 
    2008:08:10-16:25:07 (none) aua[5100]: 'tøstæ' 
    2008:08:10-16:25:07 (none) aua[5100]: ] 
    2008:08:10-16:25:07 (none) aua[5100]: } 
    2008:08:10-16:25:07 (none) aua[5100]: ] 
    2008:08:10-16:25:07 (none) aua[5100]: } 
    2008:08:10-16:25:07 (none) aua[5100]: }, 'Net::LDAP::Entry' ); 
    2008:08:10-16:25:07 (none) aua[5100]: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth_directory() trying to bind to user 'CN=Tøst Usær,OU=Users,OU=Users,OU=Resources,DC=mydomain,DC=local'" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth_directory() bind LDAP server - informational message:$VAR1 = bless( { 
    2008:08:10-16:25:07 (none) aua[5100]: 'parent' => bless( { 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_version' => 3, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_debug' => 0, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_socket' => bless( \*Symbol::GEN18, 'IO::Socket::INET' ), 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_onerror' => sub { "DUMMY" }, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_host' => '192.777.888.999:389', 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_uri' => 'ldap://192.777.888.999:389', 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_resp' => {}, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_mesg' => {}, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_async' => 0, 
    2008:08:10-16:25:07 (none) aua[5100]: 'net_ldap_refcnt' => 1 
    2008:08:10-16:25:07 (none) aua[5100]: }, 'Net::LDAP' ), 
    2008:08:10-16:25:07 (none) aua[5100]: 'errorMessage' => '', 
    2008:08:10-16:25:07 (none) aua[5100]: 'ctrl_hash' => undef, 
    2008:08:10-16:25:07 (none) aua[5100]: 'resultCode' => 0, 
    2008:08:10-16:25:07 (none) aua[5100]: 'callback' => undef, 
    2008:08:10-16:25:07 (none) aua[5100]: 'mesgid' => 6, 
    2008:08:10-16:25:07 (none) aua[5100]: 'matchedDN' => '', 
    2008:08:10-16:25:07 (none) aua[5100]: 'controls' => undef 
    2008:08:10-16:25:07 (none) aua[5100]: }, 'Net::LDAP::Bind' ); 
    2008:08:10-16:25:07 (none) aua[5100]: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="comparing 'sAMAccountName': old username tøstæ, changed to tøstæ" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="group: CN=portal,OU=Groups,OU=Resources,DC=mydomain,DC=local" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="group hash: $VAR1 = [ 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'portal', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'cn' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'Groups', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'ou' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'Resources', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'ou' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'mydomain', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'dc' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'dc' 
    2008:08:10-16:25:07 (none) aua[5100]: } 
    2008:08:10-16:25:07 (none) aua[5100]: ]; 
    2008:08:10-16:25:07 (none) aua[5100]: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="group: CN=ssl,OU=Groups,OU=Resources,DC=mydomain,DC=local" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="group hash: $VAR1 = [ 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'ssl', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'cn' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'Groups', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'ou' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'Resources', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'ou' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'mydomain', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'dc' 
    2008:08:10-16:25:07 (none) aua[5100]: }, 
    2008:08:10-16:25:07 (none) aua[5100]: { 
    2008:08:10-16:25:07 (none) aua[5100]: 'value' => 'local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'key' => 'dc' 
    2008:08:10-16:25:07 (none) aua[5100]: } 
    2008:08:10-16:25:07 (none) aua[5100]: ]; 
    2008:08:10-16:25:07 (none) aua[5100]: " 
  • DEBUG log cont:

    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="out_groups: $VAR1 = [ 
    2008:08:10-16:25:07 (none) aua[5100]: 'cn=portal,ou=groups,ou=resources,dc=mydomain,dc=local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'portal', 
    2008:08:10-16:25:07 (none) aua[5100]: 'cn=ssl,ou=groups,ou=resources,dc=mydomain,dc=local', 
    2008:08:10-16:25:07 (none) aua[5100]: 'ssl' 
    2008:08:10-16:25:07 (none) aua[5100]: ]; 
    2008:08:10-16:25:07 (none) aua[5100]: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="server_groups: cn=portal,ou=groups,ou=resources,dc=mydomain,dc=local,portal,cn=ssl,ou=groups,ou=resources,dc=mydomain,dc=local,ssl" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: authentication succeeded with method adirectory, checking authorization now" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="User tøstæ is not allowed for facility portal, method adirectory" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: authentication failed with method adirectory, trying next method" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: trying method radius" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Sending request to RADIUS server (User tøstæ, NAS-Identifier portal)" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Received response" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="U:tøstæ F[:P]ortal R[:D]ENIED C:radius" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: authentication failed with method radius, trying next method" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: skipping method edirectory (not configured)" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: skipping method ldap (not configured)" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth: skipping method tacacs (not configured)" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="do_auth returns result 0" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="User tøstæ is not authenticated or authorized for facility portal, all methods tried" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3005" severity="warn" sys="System" sub="auth" name="Authentication failed" srcip="192.***.***.***" user="tøstæ" caller="portal" reason="DENIED" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Groups: $VAR1 = []; 
    2008:08:10-16:25:07 (none) aua[5100]: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Method: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Result: 0" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Ref: ''" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Groups: " 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Comment: Radius authentication failed" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="Updating blocklist" 
    2008:08:10-16:25:07 (none) aua[5100]: id="3007" severity="debug" sys="System" sub="auth" name="result: 
    2008:08:10-16:25:07 (none) aua[5100]: DENIED" 
  • Actually - I have to modify my statement a little bit.
    Seems like it may be the 2003 RADIUS that have a problem with the username. Maybe.
    Here's the IAS log:

    192.***.***.555,testu1,08/10/2008,16:23:26,IAS,MY-RADIUS-SERVER,32,portal,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\testu1,4127,1,4149,FW-PORTAL Authentication,25,311 1 192.666.***.666 07/10/2008 00:02:49 76,4130,MYDOMAIN.LOCAL/Resources/Users/Users/Test User,4136,1,4142,0
    192.***.***.555,testu1,08/10/2008,16:23:26,IAS,MY-RADIUS-SERVER,25,311 1 192.666.***.666 07/10/2008 00:02:49 76,4130,MYDOMAIN.LOCAL/Resources/Users/Users/Test User,4294967206,14,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\testu1,4127,1,4149,FW-PORTAL Authentication,7,1,6,2,4294967207,2,4136,2,4142,0
    192.***.***.555,tøstæ,08/10/2008,16:25:07,IAS,MY-RADIUS-SERVER,32,portal,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\tøstæ,4130,MYDOMAIN\tøstæ,4127,1,25,311 1 192.666.***.666 07/10/2008 00:02:49 77,4136,1,4142,0
    192.***.***.555,tøstæ,08/10/2008,16:25:07,IAS,MY-RADIUS-SERVER,25,311 1 192.666.***.666 07/10/2008 00:02:49 77,4127,1,4130,MYDOMAIN\tøstæ,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\tøstæ,4136,3,4142,16

    Note that:
    "4136,1" means "authentication request".
    "4136,2" means Success
    "4136,3" means Reject
    Reference: http://technet.microsoft.com/en-us/library/cc785145.aspx
Reply
  • Actually - I have to modify my statement a little bit.
    Seems like it may be the 2003 RADIUS that have a problem with the username. Maybe.
    Here's the IAS log:

    192.***.***.555,testu1,08/10/2008,16:23:26,IAS,MY-RADIUS-SERVER,32,portal,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\testu1,4127,1,4149,FW-PORTAL Authentication,25,311 1 192.666.***.666 07/10/2008 00:02:49 76,4130,MYDOMAIN.LOCAL/Resources/Users/Users/Test User,4136,1,4142,0
    192.***.***.555,testu1,08/10/2008,16:23:26,IAS,MY-RADIUS-SERVER,25,311 1 192.666.***.666 07/10/2008 00:02:49 76,4130,MYDOMAIN.LOCAL/Resources/Users/Users/Test User,4294967206,14,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\testu1,4127,1,4149,FW-PORTAL Authentication,7,1,6,2,4294967207,2,4136,2,4142,0
    192.***.***.555,tøstæ,08/10/2008,16:25:07,IAS,MY-RADIUS-SERVER,32,portal,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\tøstæ,4130,MYDOMAIN\tøstæ,4127,1,25,311 1 192.666.***.666 07/10/2008 00:02:49 77,4136,1,4142,0
    192.***.***.555,tøstæ,08/10/2008,16:25:07,IAS,MY-RADIUS-SERVER,25,311 1 192.666.***.666 07/10/2008 00:02:49 77,4127,1,4130,MYDOMAIN\tøstæ,4108,192.***.***.555,4116,0,4128,fw,4155,1,4154,FW-PORTAL Connection Request,4129,MYDOMAIN\tøstæ,4136,3,4142,16

    Note that:
    "4136,1" means "authentication request".
    "4136,2" means Success
    "4136,3" means Reject
    Reference: http://technet.microsoft.com/en-us/library/cc785145.aspx
Children