LDAP Authentication Not Working

I have ejabberd 2.1.6 installed on CentOS 5.6. It works fine using internal authentication. I am trying to set up LDAP authentication to Active Directory. When the ejabberd service starts, it binds correctly to the LDAP server (2 bind request/response pairs are received), but when a user tries to authenticate, nothing is passed to the LDAP server. The user is returned a not authorized error. If I run a packet capture on the LDAP server, I see the initial bind request/response, but nothing else. The authentication attempt is never sent on to the server.

ejabberd.cnf (Redacted, but all LDAP paths, username, and passwords match):

override_global.
override_local.
override_acls.
{loglevel, 5}.
{hosts, ["domain.com"]}.
{listen,
[
  {5222, ejabberd_c2s, [
                        {certfile, "/etc/ejabberd/ejabberd.pem"}, starttls,
                        {access, c2s},
                        {shaper, c2s_shaper},
                        {max_stanza_size, 65536}
                       ]},
  {5269, ejabberd_s2s_in, [
                           {shaper, s2s_shaper},
                           {max_stanza_size, 131072}
                          ]},
  {5280, ejabberd_http, [
                         captcha,
                         http_bind,
                         http_poll,
                         web_admin
                        ]}
]}.
{auth_method, ldap}.
{ldap_servers, ["dc1.domain.com"]}.
{ldap_encrypt, none}.
{ldap_port, 389}.
{ldap_rootdn, "cn=Jabber Admin,cn=Users,dc=domain,dc=com"}.
{ldap_password, "<REMOVED>"}.
{ldap_base, "ou=Users,ou=Company,dc=domain,dc=com"}.
{ldap_uids, [{"sAMAccountName"}]}.
{ldap_filter, "{memberOf=*}"}.
{shaper, normal, {maxrate, 1000}}.
{shaper, fast, {maxrate, 50000}}.
{max_fsm_queue, 1000}.
{acl, admin, {user, "admin", "domain.com"}}.
{acl, admin, {user, "administrator", "domain.com"}}.
{acl, admin, {user, "rich", "domain.com"}}.
{acl, local, {user_regexp, ""}}.
{access, max_user_sessions, [{10, all}]}.
{access, max_user_offline_messages, [{5000, admin}, {100, all}]}.
{access, local, [{allow, local}]}.
{access, c2s, [{deny, blocked},
               {allow, all}]}.
{access, c2s_shaper, [{none, admin},
                      {normal, all}]}.
{access, s2s_shaper, [{fast, all}]}.
{access, announce, [{allow, admin}]}.
{access, configure, [{allow, admin}]}.
{access, muc_admin, [{allow, admin}]}.
{access, muc_create, [{allow, local}]}.
{access, muc, [{allow, all}]}.
{access, pubsub_createnode, [{allow, local}]}.
{access, register, [{deny, all}]}.
{language, "en"}.
{modules,
[
  {mod_adhoc,    []},
  {mod_announce, [{access, announce}]}, % recommends mod_adhoc
  {mod_caps,     []},
  {mod_configure,[]}, % requires mod_adhoc
  {mod_disco,    []},
  {mod_irc,      []},
  {mod_http_bind, []},
  {mod_last,     []},
  {mod_muc,      [
                  {access, muc},
                  {access_create, muc_create},
                  {access_persistent, muc_create},
                  {access_admin, muc_admin}
                 ]},
  {mod_offline,  [{access_max_user_messages, max_user_offline_messages}]},
  {mod_ping,     []},
  {mod_privacy,  []},
  {mod_private,  []},
  {mod_pubsub,   [
                  {access_createnode, pubsub_createnode},
                  {ignore_pep_from_offline, true}, % reduces resource comsumption, but XEP incompliant
                  %%{ignore_pep_from_offline, false},  % XEP compliant, but increases resource comsumption
                  {last_item_cache, false},
                  {plugins, ["flat", "hometree", "pep"]}  % pep requires mod_caps
                 ]},
  {mod_register, [
                  {welcome_message, {"Welcome!",
                                     "Hi.\nWelcome to this XMPP server."}},
                  {ip_access, [{allow, "127.0.0.0/8"},
                               {deny, "0.0.0.0/0"}]},

                  {access, register}
                 ]},
  {mod_roster,   []},
  {mod_shared_roster,[]},
  {mod_stats,    []},
  {mod_time,     []},
  {mod_vcard,    []},
  {mod_version,  []},
  {mod_vcard_ldap,
   [{matches, infinity},
    {ldap_filter, "(&(memberOf=CN=All Users,OU=Groups,OU=Company,DC=domain,DC=com))"},
    {ldap_vcard_map,
     [{"NICKNAME", "%u", []},
      {"GIVEN", "%s", ["givenName"]},
      {"MIDDLE", "%s", ["initials"]},
      {"FAMILY", "%s", ["sn"]},
      {"FN", "%s", ["displayName"]},
      {"EMAIL", "%s", ["mail"]},
      {"ORGNAME", "%s", ["company"]},
      {"ORGUNIT", "%s", ["department"]},
      {"CTRY", "%s", ["c"]},
      {"LOCALITY", "%s", ["l"]},
      {"STREET", "%s", ["streetAddress"]},
      {"REGION", "%s", ["st"]},
      {"PCODE", "%s", ["postalCode"]},
      {"TITLE", "%s", ["title"]},
      {"URL", "%s", ["wWWHomePage"]},
      {"DESC", "%s", ["description"]},
      {"TEL", "%s", ["telephoneNumber"]}]},
    {ldap_search_fields,
     [{"User", "%u"},
      {"Name", "givenName"},
      {"Family Name", "sn"},
      {"Email", "mail"},
      {"Company", "company"},
      {"Department", "department"},
      {"Role", "title"},
      {"Description", "description"},
      {"Phone", "telephoneNumber"}]},
    {ldap_search_reported,
     [{"Full Name", "FN"},
      {"Nickname", "NICKNAME"},
      {"Email", "EMAIL"}]}
  ]}
]}.

Interesting parts of ejabberd.log:

=INFO REPORT==== 2011-05-17 16:37:57 ===
I(<0.270.0>:eldap:967) : LDAP connection on dc1.domain.com:389

=INFO REPORT==== 2011-05-17 16:37:57 ===
I(<0.281.0>:eldap:967) : LDAP connection on dc1.domain.com:389

=INFO REPORT==== 2011-05-17 16:37:57 ===
D(<0.281.0>:eldap:1010) : Bind Request Message:{'LDAPMessage',1,
                                                {bindRequest,
                                                 {'BindRequest',3,
                                                  "cn=Jabber Admin,cn=Users,dc=domain,dc=com",
                                                  {simple,"<REMOVED>"}}},
                                                asn1_NOVALUE}

=INFO REPORT==== 2011-05-17 16:37:57 ===
D(<0.270.0>:eldap:1010) : Bind Request Message:{'LDAPMessage',1,
                                                {bindRequest,
                                                 {'BindRequest',3,
                                                  "cn=Jabber Admin,cn=Users,dc=domain,dc=com",
                                                  {simple,"<REMOVED>"}}},
                                                asn1_NOVALUE}

=INFO REPORT==== 2011-05-17 16:37:57 ===
D(<0.281.0>:eldap:858) : {'LDAPMessage',1,
                             {bindResponse,
                                 {'BindResponse',success,[],[],asn1_NOVALUE,
                                     asn1_NOVALUE}},
                             asn1_NOVALUE}

=INFO REPORT==== 2011-05-17 16:37:57 ===
D(<0.270.0>:eldap:858) : {'LDAPMessage',1,
                             {bindResponse,
                                 {'BindResponse',success,[],[],asn1_NOVALUE,
                                     asn1_NOVALUE}},
                             asn1_NOVALUE}

[...]

=INFO REPORT==== 2011-05-17 16:38:48 ===
I(<0.375.0>:ejabberd_listener:281) : (#Port<0.3580>) Accepted connection {{a,b,c,d},49428} -> {{192,168,100,250},5222}

=INFO REPORT==== 2011-05-17 16:38:48 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "<?xml version='1.0' ?>"

=INFO REPORT==== 2011-05-17 16:38:48 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "<stream:stream to='domain.com' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>"

=INFO REPORT==== 2011-05-17 16:38:48 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = [60,63,120,109,108,32,
                                                       118,101,114,115,105,
                                                       111,110,61,39,49,46,48,
                                                       39,63,62,60,115,116,
                                                       114,101,97,109,58,115,
                                                       116,114,101,97,109,32,
                                                       120,109,108,110,115,61,
                                                       39,106,97,98,98,101,
                                                       114,58,99,108,105,101,
                                                       110,116,39,32,120,109,
                                                       108,110,115,58,115,116,
                                                       114,101,97,109,61,39,
                                                       104,116,116,112,58,47,
                                                       47,101,116,104,101,114,
                                                       120,46,106,97,98,98,
                                                       101,114,46,111,114,103,
                                                       47,115,116,114,101,97,
                                                       109,115,39,32,105,100,
                                                       61,39,"2640158898",39,
                                                       32,102,114,111,109,61,
                                                       39,"domain.com",39,
                                                       [" version='","1.0",
                                                        "'"],
                                                       [" xml:lang='","en",
                                                        "'"],
                                                       62]

=INFO REPORT==== 2011-05-17 16:38:48 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = <<"<stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism></mechanisms><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='8P/XuMtKq0lNk50DLBC8v+TXoAU='/><register xmlns='http://jabber.org/features/iq-register'/></stream:features>">>

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>"

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,0,1305664728968745}, Size=51
M=25.5, I=107.629

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = []

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,236.89857953753682,
                                    1305664729076386}, Size=0
M=0.0, I=21.095

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = []

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,118.44928976876841,
                                    1305664729097507}, Size=0
M=0.0, I=59.233

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = []

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,59.224644884384205,
                                    1305664729156750}, Size=0
M=0.0, I=71.164

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "<stream:stream to='domain.com' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>"

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,29.612322442192102,
                                    1305664729227923}, Size=117
M=59.37917767787472, I=141.489

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = [60,63,120,109,108,32,
                                                       118,101,114,115,105,
                                                       111,110,61,39,49,46,48,
                                                       39,63,62,60,115,116,
                                                       114,101,97,109,58,115,
                                                       116,114,101,97,109,32,
                                                       120,109,108,110,115,61,
                                                       39,106,97,98,98,101,
                                                       114,58,99,108,105,101,
                                                       110,116,39,32,120,109,
                                                       108,110,115,58,115,116,
                                                       114,101,97,109,61,39,
                                                       104,116,116,112,58,47,
                                                       47,101,116,104,101,114,
                                                       120,46,106,97,98,98,
                                                       101,114,46,111,114,103,
                                                       47,115,116,114,101,97,
                                                       109,115,39,32,105,100,
                                                       61,39,"1396320492",39,
                                                       32,102,114,111,109,61,
                                                       39,"domain.com",39,
                                                       [" version='","1.0",
                                                        "'"],
                                                       [" xml:lang='","en",
                                                        "'"],
                                                       62]

=INFO REPORT==== 2011-05-17 16:38:49 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = <<"<stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism></mechanisms><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='8P/XuMtKq0lNk50DLBC8v+TXoAU='/><register xmlns='http://jabber.org/features/iq-register'/></stream:features>">>

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "<auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN' xmlns:ga='http://www.google.com/talk/protocol/auth' ga:client-uses-full-bind-result='true'><REMOVED></auth>"

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,0,1305664729369718}, Size=191
M=95.5, I=4412.399

=INFO REPORT==== 2011-05-17 16:38:53 ===
I(<0.379.0>:ejabberd_c2s:657) : ({socket_state,tls,{tlssock,#Port<0.3580>,#Port<0.3602>},<0.378.0>}) Failed authentication for rich@domain.com

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = <<"<failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/></failure>">>

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.378.0>:ejabberd_receiver:320) : Received XML on stream = "</stream:stream>"

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.378.0>:shaper:61) : State: {maxrate,1000,21.643491133647537,
                                    1305664733782130}, Size=16
M=8.087521095562497, I=71.652

=INFO REPORT==== 2011-05-17 16:38:53 ===
D(<0.379.0>:ejabberd_c2s:1508) : Send XML on stream = "</stream:stream>"

Any help will be most appreciated.

Thanks,
Rich Williams

I noticed your ldap_filter

I noticed your ldap_filter has curly brackets around the LDAP search filter instead of parenthesis.

Try changing to the following and see if it works:

{ldap_filter, "(memberOf=*)"}.

*facepalm*

The simplest things are sometimes the hardest to spot. Thanks. That was it.

Syndicate content