Rocket.chat: LDAP login issues

Created on 19 Jul 2017 · 2Comments · Source: RocketChat/Rocket.Chat

Rocket.Chat Version: 0.57.2
Running Instances: 1
DB Replicaset OpLog: disabled
Node Version: 4.8.2

I had an instance of RC version 0.44.0 running with LDAP working. There were some issues where users would register an account using non-LDAP credentials which would fail, but the email address would still be in the database so that when attempted to login using their AD credentials it would fail. I could work around this by manually deleting their user account and having them re-register using their AD credentials.

I made the mistake of messing around with the LDAP Sync and LDAP fallback settings and somehow screwed things up such that some people can't log in at all now. Thinking that it might be a bug in that version given the number of other LDAP-related issues on here, I updated to version 0.57.2 yesterday.

LDAP Enable: True
Login Fallback: False

Domain Base: dc=xx,dc=xxxx
Domain Search Filter: memberOf=CN=Employees,OU=SecurityGroups,DC=xx,DC=xxxx
Enable LDAP user group filter: False
Domain Search User ID: sAMAccountName
Domain Search Object Class: user
Domain Search Object Category:
Username Field: sAMAccountName
Unique Identifier Field:
Sync Data: True
Sync User Avatar: True
User Data Field Map: {"cn":"name","mail":"email"}
Default Domain: dc=xx,dc=xxxx
Merge existing users: True
Import LDAP users: False

I have a user who is unable to log in and receives the error "User not found or incorrect password".

The error log is as follows:

```
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m LDAP connected
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Bind.info#033[39m Binding admin user
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.info#033[39m Searching user
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.debug#033[39m searchOptions { filter: '(&(objectclass=user)(memberOf=CN=Employees,OU=SecurityGroups,DC=dw,DC=local)(sAMAccountName=))',
Jul 19 10:37:07 builder2 node[14321]: scope: 'sub' }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.debug#033[39m domain_base dc=xx,dc=xxxx
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.info#033[39m Search result count 1
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.debug#033[39m Search result [
Jul 19 10:37:07 builder2 node[14321]: {
Jul 19 10:37:07 builder2 node[14321]: "messageID": 2,
Jul 19 10:37:07 builder2 node[14321]: "protocolOp": "SearchEntry",
Jul 19 10:37:07 builder2 node[14321]: "objectName": "CN=,CN=Users,DC=xx,DC=xxxx",
Jul 19 10:37:07 builder2 node[14321]: "attributes": [
Jul 19 10:37:07 builder2 node[14321]: {
Jul 19 10:37:07 builder2 node[14321]: "type": "objectClass",
Jul 19 10:37:07 builder2 node[14321]: "vals": [
Jul 19 10:37:07 builder2 node[14321]: "top",
Jul 19 10:37:07 builder2 node[14321]: "person",
Jul 19 10:37:07 builder2 node[14321]: "organizationalPerson",
Jul 19 10:37:07 builder2 node[14321]: "user"
Jul 19 10:37:07 builder2 node[14321]: ]
Jul 19 10:37:07 builder2 node[14321]: },
Jul 19 10:37:07 builder2 node[14321]: {
Jul 19 10:37:07 builder2 node[14321]: "type": "cn",
Jul 19 10:37:07 builder2 node[14321]: "vals": [
Jul 19 10:37:07 builder2 node[14321]: ""
Jul 19 10:37:07 builder2 node[14321]: ]
...
lots more AD stuff
...
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Auth.info#033[39m Authenticating CN=,CN=Users,DC=xx,DC=xxxx
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Auth.info#033[39m Authenticated CN=,CN=Users,DC=xx,DC=xxxx
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m Disconecting
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ info#033[39m Querying user
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ debug#033[39m userQuery { 'services.ldap.id': '416e74686f6e79426f6f72736d61' }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ debug#033[39m userQuery { username: '' }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ info#033[39m User does not exist, creating
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m user.name changed to:
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m New user data { username: '',
Jul 19 10:37:07 builder2 node[14321]: email: '' }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m joinDefaultChannels -> userId: sfXzKiZk8n8tnNafQ , arguments: { '0': undefined }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ info#033[39m Syncing user data
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m user { email: '',
Jul 19 10:37:07 builder2 node[14321]: _id: 'sfXzKiZk8n8tnNafQ' }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m ldapUser SearchEntry {
...
lots of AD stuff
...
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m user.name changed to:
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ debug#033[39m setting {
Jul 19 10:37:07 builder2 node[14321]: "name": " ",
Jul 19 10:37:07 builder2 node[14321]: "emails": [
Jul 19 10:37:07 builder2 node[14321]: {
Jul 19 10:37:07 builder2 node[14321]: "address": "",
Jul 19 10:37:07 builder2 node[14321]: "verified": true
Jul 19 10:37:07 builder2 node[14321]: }
Jul 19 10:37:07 builder2 node[14321]: ],
Jul 19 10:37:07 builder2 node[14321]: "services.ldap.id": "416e74686f6e79426f6f72736d61",
Jul 19 10:37:07 builder2 node[14321]: "services.ldap.idAttribute": "sAMAccountName",
Jul 19 10:37:07 builder2 node[14321]: "ldap": true
Jul 19 10:37:07 builder2 node[14321]: }
Jul 19 10:37:07 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ info#033[39m Syncing user avatar
Jul 19 10:37:08 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m spotlight -> userId: mNm6Y3nZdYu5RcGZB , arguments: { '0': '',
...
Jul 19 10:37:12 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m UserPresence:online -> userId: jxtKH7yiRJAXKmGZN , arguments: {}
Jul 19 10:37:13 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m UserPresence:online -> userId: pwY8MzAEtrLDdnLDH , arguments: {}
Jul 19 10:37:13 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m UserPresence:online -> userId: null , arguments: {}
Jul 19 10:37:15 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mMeteor ➔ method#033[39m saveSetting -> userId: Jg43vSMigYzquLyGQ , arguments: { '0': 'Log_Level', '1': '1', '2': null }
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ info#033[39m Init LDAP login
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m Init setup
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m Connecting ldap://:389
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m LDAP connected
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Bind.info#033[39m Binding admin user
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.info#033[39m Searching user
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Search.info#033[39m Search result count 1
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Auth.info#033[39m Authenticating CN=,CN=Users,DC=xx,DC=xxxx
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Auth.info#033[39m Authenticated CN=,CN=Users,DC=xx,DC=xxxx
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAP ➔ Connection.info#033[39m Disconecting
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ info#033[39m Querying user
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPHandler ➔ info#033[39m Logging user
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ info#033[39m Syncing user data
Jul 19 10:37:36 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[34mLDAPSync ➔ info#033[39m Syncing user avatar
Jul 19 10:38:50 builder2 node[14321]: rocketchat_logger rocketchat_logger.js:377 #033[31mLDAP ➔ Connection.error#033[39m connection { [Error: read ECONNRESET] code: 'ECONNRESET', errno: 'ECONNRESET', syscall: 'read' }
Jul 19 10:43:33 builder2 node[14321]: at Object.Future.wait (/var/www/Rocket.Chat/programs/server/node_modules/fibers/future.js:449:15)
Jul 19 10:43:33 builder2 node[14321]: at Mail._syncSendMail (packages/meteor.js:213:24)
Jul 19 10:43:33 builder2 node[14321]: at smtpSend (packages/email.js:110:13)
Jul 19 10:43:33 builder2 node[14321]: at Object.Email.send (packages/email.js:168:5)
Jul 19 10:43:33 builder2 node[14321]: at Object.Email.send (packages/rocketchat_monitoring.js:3496:28)
Jul 19 10:43:33 builder2 node[14321]: at /var/www/Rocket.Chat/programs/server/packages/rocketchat_lib.js:1664:14
Jul 19 10:43:33 builder2 node[14321]: at [object Object]._.extend.withValue (packages/meteor.js:1122:17)
Jul 19 10:43:33 builder2 node[14321]: at packages/meteor.js:445:45
Jul 19 10:43:33 builder2 node[14321]: at runWithEnvironment (packages/meteor.js:1176:24)
Jul 19 10:43:33 builder2 node[14321]: - - - - -
Jul 19 10:43:33 builder2 node[14321]: at Error (native)
Jul 19 10:43:33 builder2 node[14321]: at TLSSocket. (_tls_wrap.js:1022:38)
Jul 19 10:43:33 builder2 node[14321]: at emitNone (events.js:67:13)
Jul 19 10:43:33 builder2 node[14321]: at TLSSocket.emit (events.js:166:7)
Jul 19 10:43:33 builder2 node[14321]: at TLSSocket._init.ssl.onclienthello.ssl.oncertcb.TLSSocket._finishInit (_tls_wrap.js:586:8)
Jul 19 10:43:33 builder2 node[14321]: at TLSWrap.ssl.onclienthello.ssl.oncertcb.ssl.onnewsession.ssl.onhandshakedone (_tls_wrap.js:428:38)

````

In the mongodb I can see the user is created, the username is correct and the email address is correct.

I tried deleting the user in the RC application, verified the user entry was removed from the users collection in mongodb and had the user try again. They received the same error "User not found or incorrect password"

I tried disabling Sync and Merge:

Sync Data: False
Merge existing users: False

then deleted the user account, verified it was gone in the database, and had the user attempt to log in again. Same error was received and the user account was created again, but he's still unable to log in.

Any ideas?

need more info

Source