Mattermost-server: LDAP stops working after ESR upgrade

[torgeirl]

Summary

LDAP stops working when upgrading server from last to current ESR version.

Steps to reproduce

1. Configure 4.10 (last ESR) server with LDAP
2. Upgrade server to 5.9 (current ESR)
3. Try to log in.

Observed behavior (that appears unintentional)

The user dialog indicate the username or password is wrong/unrecognized (forgot to take a screenshot), while the logs states the user hasn't logged on before (they had):

msg: "Unable to find an existing account matching your credentials. This team may require an invite from the team owner to join."
level: "error"
user_id: "" (empty)
method: "POST"
err_where: "GetUserForLogin"
http_code: 400
err_details: "" (empty)

My session on the mobile app continued to work after the upgrade so I assume the issue had to do with LDAP changes since 4.10?

[amyblais]

Hi @torgeirl, would you be open to posting your LDAP settings and your full Mattermost logs?

I also recommend taking a look at our customer support system here as our customer support team is more familiar with enterprise features and also provides faster support for urgent issues. You can open a support ticket via https://mattermost.zendesk.com/hc/en-us/requests/new if you want to.

[torgeirl]

would you be open to posting your LDAP settings and your full Mattermost logs?

Yes, but I'll need to do some redactions:

    "LdapSettings": {
        "Enable": true,
        "EnableSync": false,
        "LdapServer": "<LDAP server URL",
        "LdapPort": 636,
        "ConnectionSecurity": "TLS",
        "BaseDN": "<LDAP object with employees>",
        "BindUsername": "",
        "BindPassword": "",
        "UserFilter": "",
        "FirstNameAttribute": "givenName",
        "LastNameAttribute": "sn",
        "EmailAttribute": "mail",
        "UsernameAttribute": "uid",
        "NicknameAttribute": "",
        "IdAttribute": "uid",
        "PositionAttribute": "",
        "SyncIntervalMinutes": 60,
        "SkipCertificateVerification": false,
        "QueryTimeout": 60,
        "MaxPageSize": 0,
        "LoginFieldName": "<Custom field text>",
        "LoginButtonColor": "",
        "LoginButtonBorderColor": "",
        "LoginButtonTextColor": ""
    }

Full log for the Mattermost server from daemon start to first failed login attempt:

{"level":"info","ts":1558328547.8153248,"caller":"utils/i18n.go:83","msg":"Loaded system translations for 'en' from '/opt/mattermost/i18n/en.json'"}
{"level":"info","ts":1558328547.8155055,"caller":"app/server_app_adapters.go:58","msg":"Server is initializing..."}
{"level":"info","ts":1558328547.8178933,"caller":"sqlstore/supplier.go:215","msg":"Pinging SQL master database"}
{"level":"warn","ts":1558328548.337643,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 4.10.0 appears to be out of date"}
{"level":"warn","ts":1558328548.3377955,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.0.0"}
{"level":"warn","ts":1558328548.4898362,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.0.0"}
{"level":"warn","ts":1558328548.4902983,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.0.0 appears to be out of date"}
{"level":"warn","ts":1558328548.490345,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.1.0"}
{"level":"warn","ts":1558328548.4914074,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.1.0"}
{"level":"warn","ts":1558328548.4918916,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.1.0 appears to be out of date"}
{"level":"warn","ts":1558328548.491982,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.2.0"}
{"level":"warn","ts":1558328548.4963946,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.2.0"}
{"level":"warn","ts":1558328548.496864,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.2.0 appears to be out of date"}
{"level":"warn","ts":1558328548.496921,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.3.0"}
{"level":"warn","ts":1558328548.4978652,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.3.0"}
{"level":"warn","ts":1558328548.4986267,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.3.0 appears to be out of date"}
{"level":"warn","ts":1558328548.4987087,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.4.0"}
{"level":"warn","ts":1558328548.5184128,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.4.0"}
{"level":"warn","ts":1558328548.518895,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.4.0 appears to be out of date"}
{"level":"warn","ts":1558328548.5189385,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.5.0"}
{"level":"warn","ts":1558328548.5216024,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.5.0"}
{"level":"warn","ts":1558328548.5220718,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.5.0 appears to be out of date"}
{"level":"warn","ts":1558328548.5221205,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.6.0"}
{"level":"warn","ts":1558328548.5647538,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.6.0"}
{"level":"warn","ts":1558328548.5652766,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.6.0 appears to be out of date"}
{"level":"warn","ts":1558328548.5653272,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.7.0"}
{"level":"warn","ts":1558328548.580765,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.7.0"}
{"level":"warn","ts":1558328548.581298,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.7.0 appears to be out of date"}
{"level":"warn","ts":1558328548.5813744,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.8.0"}
{"level":"warn","ts":1558328548.603934,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.8.0"}
{"level":"warn","ts":1558328548.6043735,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.8.0 appears to be out of date"}
{"level":"warn","ts":1558328548.604433,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.9.0"}
{"level":"warn","ts":1558328548.6113844,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.9.0"}
{"level":"info","ts":1558328548.9359748,"caller":"filesstore/localstore.go:33","msg":"Able to write files to local storage."}
{"level":"info","ts":1558328548.9412012,"caller":"app/license.go:42","msg":"License key valid unlocking enterprise features."}
{"level":"info","ts":1558328548.9436839,"caller":"app/migrations.go:101","msg":"Migrating emojis config to database."}
{"level":"info","ts":1558328548.9583645,"caller":"app/plugin.go:130","msg":"Starting up plugins"}
{"level":"info","ts":1558328550.884737,"caller":"app/server.go:192","msg":"Current version is 5.9.0 (5.9.1/Wed Apr 24 08:47:10 UTC 2019/c201065b4f25d4794ae86c077efb60c6f934fbc8/f658a7c8a74d60f9d9374e5bb9ead82b4351514e)"}
{"level":"info","ts":1558328550.8848035,"caller":"app/server.go:193","msg":"Enterprise Enabled: true"}
{"level":"info","ts":1558328550.8848279,"caller":"app/server.go:195","msg":"Current working directory is /opt/mattermost"}
{"level":"info","ts":1558328550.8849475,"caller":"app/server.go:196","msg":"Loaded config file from /opt/mattermost/config/config.json"}
{"level":"info","ts":1558328550.9620898,"caller":"sqlstore/post_store.go:1287","msg":"Post.Message supports at most 16383 characters (65535 bytes)"}
{"level":"info","ts":1558328550.9705033,"caller":"jobs/workers.go:68","msg":"Starting workers"}
{"level":"info","ts":1558328550.9706352,"caller":"app/server.go:400","msg":"Starting Server..."}
{"level":"info","ts":1558328550.9713457,"caller":"app/server.go:460","msg":"Server is listening on [::]:8065"}
{"level":"info","ts":1558328550.9716473,"caller":"jobs/schedulers.go:72","msg":"Starting schedulers."}
{"level":"info","ts":1558328550.9864066,"caller":"app/web_hub.go:75","msg":"Starting 8 websocket hubs"}
{"level":"error","ts":1558328581.4350247,"caller":"web/context.go:52","msg":"Unable to find an existing account matching your credentials. This team may require an invite from the team owner to join.","path":"/api/v4/users/login","request_id":"<request ID>","ip_addr":"<IP address>","user_id":"","method":"POST","err_where":"GetUserForLogin","http_code":400,"err_details":""}

[amyblais]

Hi @torgeirl, I've posted this issue for our team to look at, I'll let you know their feedback,

[torgeirl]

Hi @amyblais. Does the issue on upgrade instructions from v4.10 ESR to v5.9 ESR getting marked as completed indicate that this issue also is solved, or is the team still working on a fix for this?

[amyblais]

Hi @torgeirl, letting you know that our developers are working on testing this,

[torgeirl]

Hi @amyblais, any further development on this issue? 4.10's end of support is now only weeks away (July 15).

[amyblais]

I'll ask our devs on the status of this. In the meanwhile, would you be able to try upgrading to v5.0 first and then to v5.9? We added upgrade instructions for 4.10 > 5.9: https://docs.mattermost.com/administration/extended-support-release.html#what-are-the-current-supported-esr-versions.

[torgeirl]

Hi @amyblais. Tried it now. LDAP works after upgrading v4.10 to v5.0, then stops working after upgrading v5.0 to v5.9. Logs:

{"level":"info","ts":1562840544.20585,"caller":"utils/i18n.go:83","msg":"Loaded system translations for 'en' from '/opt/mattermost/i18n/en.json'"}
{"level":"info","ts":1562840544.2060497,"caller":"app/server_app_adapters.go:58","msg":"Server is initializing..."}
{"level":"info","ts":1562840544.2095935,"caller":"sqlstore/supplier.go:215","msg":"Pinging SQL master database"}
{"level":"warn","ts":1562840544.3872988,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.0.0 appears to be out of date"}
{"level":"warn","ts":1562840544.3874133,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.1.0"}
{"level":"warn","ts":1562840544.3906436,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.1.0"}
{"level":"warn","ts":1562840544.3913417,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.1.0 appears to be out of date"}
{"level":"warn","ts":1562840544.391394,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.2.0"}
{"level":"warn","ts":1562840544.4132185,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.2.0"}
{"level":"warn","ts":1562840544.4139884,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.2.0 appears to be out of date"}
{"level":"warn","ts":1562840544.4140687,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.3.0"}
{"level":"warn","ts":1562840544.415968,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.3.0"}
{"level":"warn","ts":1562840544.4166446,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.3.0 appears to be out of date"}
{"level":"warn","ts":1562840544.4166884,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.4.0"}
{"level":"warn","ts":1562840544.4301727,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.4.0"}
{"level":"warn","ts":1562840544.4308596,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.4.0 appears to be out of date"}
{"level":"warn","ts":1562840544.4309058,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.5.0"}
{"level":"warn","ts":1562840544.432584,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.5.0"}
{"level":"warn","ts":1562840544.4332738,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.5.0 appears to be out of date"}
{"level":"warn","ts":1562840544.4333274,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.6.0"}
{"level":"warn","ts":1562840544.5082934,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.6.0"}
{"level":"warn","ts":1562840544.5090356,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.6.0 appears to be out of date"}
{"level":"warn","ts":1562840544.5090826,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.7.0"}
{"level":"warn","ts":1562840544.5108058,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.7.0"}
{"level":"warn","ts":1562840544.5114872,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.7.0 appears to be out of date"}
{"level":"warn","ts":1562840544.5115614,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.8.0"}
{"level":"warn","ts":1562840544.536316,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.8.0"}
{"level":"warn","ts":1562840544.5370495,"caller":"sqlstore/upgrade.go:133","msg":"The database schema version of 5.8.0 appears to be out of date"}
{"level":"warn","ts":1562840544.5371003,"caller":"sqlstore/upgrade.go:134","msg":"Attempting to upgrade the database schema version to 5.9.0"}
{"level":"warn","ts":1562840544.5387478,"caller":"sqlstore/upgrade.go:128","msg":"The database schema has been upgraded to version 5.9.0"}
{"level":"info","ts":1562840544.7336202,"caller":"filesstore/localstore.go:33","msg":"Able to write files to local storage."}
{"level":"info","ts":1562840544.738422,"caller":"app/license.go:42","msg":"License key valid unlocking enterprise features."}
{"level":"info","ts":1562840544.7432528,"caller":"app/plugin.go:130","msg":"Starting up plugins"}
{"level":"info","ts":1562840546.7518654,"caller":"app/server.go:192","msg":"Current version is 5.9.0 (5.9.2/Thu Jun 20 17:04:32 UTC 2019/9a9c8aff3c08089c6ae3ece282941608105732ef/f658a7c8a74d60f9d9374e5bb9ead82b4351514e)"}
{"level":"info","ts":1562840546.7519264,"caller":"app/server.go:193","msg":"Enterprise Enabled: true"}
{"level":"info","ts":1562840546.7519495,"caller":"app/server.go:195","msg":"Current working directory is /opt/mattermost"}
{"level":"info","ts":1562840546.7534733,"caller":"app/server.go:196","msg":"Loaded config file from /opt/mattermost/config/config.json"}
{"level":"info","ts":1562840546.8077378,"caller":"sqlstore/post_store.go:1287","msg":"Post.Message supports at most 16383 characters (65535 bytes)"}
{"level":"info","ts":1562840546.813946,"caller":"jobs/workers.go:68","msg":"Starting workers"}
{"level":"info","ts":1562840546.8140702,"caller":"app/server.go:400","msg":"Starting Server..."}
{"level":"info","ts":1562840546.8149312,"caller":"app/server.go:460","msg":"Server is listening on [::]:8065"}
{"level":"info","ts":1562840546.817815,"caller":"jobs/schedulers.go:72","msg":"Starting schedulers."}
{"level":"info","ts":1562840546.8303359,"caller":"app/web_hub.go:75","msg":"Starting 8 websocket hubs"}
{"level":"error","ts":1562840571.9737442,"caller":"web/context.go:52","msg":"Unable to find an existing account matching your credentials. This team may require an invite from the team owner to join.","path":"/api/v4/users/login","request_id":"<request ID>","ip_addr":"<IP address>","user_id":"","method":"POST","err_where":"GetUserForLogin","http_code":400,"err_details":""}

[icelander]

Hi @torgeirl,

I attempted to reproduce this in a test environment with LDAP when upgrading to Mattermost 5.9 and was unable to reproduce this error. Here are some things to check:

• Use this script to verify that the user can be found in the LDAP server
• Double check that the uid field in LDAP matches the value in the AuthData field for that user. If it doesn't use the idmigrate CLI command to migrate the values

If these don't work, open a support ticket by emailing [email protected] so we can look into this further.

[mkraft]

No errors for me either during my upgrade test.

[torgeirl]

@icelander, @mkraft: I tested some more, and it seems to me that my issue is cause by Mattermost no longer allowing the connection to our LDAP server to be run unbounded (empty BindUsername and BindPassword). Is this an intended change?

[mkraft]

@torgeirl There was a change to a Golang LDAP package that Mattermost uses that broke unauthenticated binds to LDAP. It was fixed in v5.10.

[torgeirl]

@mkraft: can't read the PR notes (unavailable to me), but good it's fixed although that doesn't help ESR (v5.9) unfortunately. :disappointed:

Note that the binding error doesn't get printed in logs ("err_details":""), which I assume is an implementation oversight.

[mkraft]

@torgeirl There is an item queued today to determine whether this can be released as a patch to v5.9. I will let you know the outcome (likely later today).

[torgeirl]

@mkraft: that would be nice, thanks! :crossed_fingers:

[mkraft]

@torgeirl We will be issuing a patch to v5.9 to fix this.

[amyblais]

@torgeirl v5.9.3 patch is now available: https://docs.mattermost.com/administration/version-archive.html.

[torgeirl]

@amyblais: upgraded now, without any other issues. :tada: Thanks, @mkraft!