Following up on a request/suggestion from @pgr I’ve done the following test:
There isn’t much “extended information”. There is only a
Failed to load resource: the server responded with a status of 401 (Unauthorized)
Login failed
Screenshot attached.
I had done this test before. Same result.
I was looking at the logs on the LDAP server side
SuiteCRM requests come like this:
[26/Jan/2024:12:59:41.190646024 +0000] conn=64347 fd=253 slot=253 connection from 1.1.1.1(crm-server-ip) to 2.2.2.2(idm-server-ip)
[26/Jan/2024:12:59:41.191192457 +0000] conn=64347 op=0 EXT oid="1.3.6.1.4.1.1466.20037" name="start_tls_plugin"
[26/Jan/2024:12:59:41.191280241 +0000] conn=64347 op=0 RESULT err=0 tag=120 nentries=0 wtime=0.000358914 optime=0.000129024 etime=0.000486443
[26/Jan/2024:12:59:41.228051635 +0000] conn=64347 TLS1.3 128-bit AES-GCM
[26/Jan/2024:12:59:41.228532725 +0000] conn=64347 op=1 BIND dn="uid=bind-dn,cn=sysaccounts,cn=etc,dc=domain,dc=tld" method=128 version=3
[26/Jan/2024:12:59:41.229479533 +0000] conn=64347 op=1 RESULT err=0 tag=97 nentries=0 wtime=0.021358633 optime=0.000938740 etime=0.022294725 dn="uid=bind-dn,cn=sysaccounts,cn=etc,dc=domain,dc=tld"
[26/Jan/2024:12:59:41.246339682 +0000] conn=64347 op=2 SRCH base="cn=accounts,dc=domain,dc=tld" scope=2 filter="(memberOf=cn=sales,cn=groups,cn=accounts,dc=domain,dc=tld)" attrs="* aci"
[26/Jan/2024:12:59:41.250503876 +0000] conn=64347 op=2 RESULT err=0 tag=101 nentries=2 wtime=0.000254305 optime=0.004170018 etime=0.004419211
[26/Jan/2024:12:59:41.311098525 +0000] conn=64347 op=3 BIND dn="uid=bind-dn,cn=sysaccounts,cn=etc,dc=domain,dc=tld" method=128 version=3
[26/Jan/2024:12:59:41.312039818 +0000] conn=64347 op=3 RESULT err=0 tag=97 nentries=0 wtime=0.000173717 optime=0.000960047 etime=0.001130890 dn="uid=bind-dn,cn=sysaccounts,cn=etc,dc=domain,dc=tld"
[26/Jan/2024:12:59:41.328356714 +0000] conn=64347 op=4 SRCH base="dc=domain,dc=tld" scope=2 filter="(uid=my-user)" attrs="* aci"
[26/Jan/2024:12:59:41.332848612 +0000] conn=64347 op=4 RESULT err=0 tag=101 nentries=1 wtime=0.000294621 optime=0.004498508 etime=0.004789213
[26/Jan/2024:12:59:41.351576404 +0000] conn=64347 op=5 UNBIND
[26/Jan/2024:12:59:41.351629711 +0000] conn=64347 op=5 fd=253 closed error - U1
So the number one question here is where does this attrs="* aci" part being parsed from. This is failing because the request isn’t properly formed.
What about Network tab?
Any nice, detailed, Symfony exception there?
Your LDAP logs are also interesting! 
Network tab gives this:
Until the request is properly formed, it will always fail.
I have commenting the ### LDAP AUTO CREATE CONFIG
but the issue is the same.
Edit:
On the headers I have
URL https://suitecrm.app/login
Status: 401 Unauthorised
Source: Network
Address: suitecrm-server-ip:443
Initiator: poly fills.7539f468be309dcf.js:1:32939
If I put the mouse over this, I get:
dunno if this is of any help but well
No, that’s the front-end stack, might be useful for front-end bugs, but this is back-end.
The code appears to be this:
I see that it logs a lot if you increase your suitecrm.log log level to info, that might provide more clues. This can be changed from the UI: Admin / System settings, or from a text entry in public/legacy/config_override.php:
$sugar_config['logger']['level'] = 'info';
The messages will appear in public/legacy/suitecrm.log
I can’t change anything via UI since I’m locked out since I ran the update.
I just have to finish a task here and I’ll add that to config override and increase the logging level in order to see if I get other feedback,
But I am starting to doubt that as I don’t believe the log will show how the request was being properly formed before, and is wrong now.
Which leaves us with the part where apparently the SuiteCRM developers did breaking changes that screwed up this, but are absolutely clueless about what changes were done, and how it came to affect LDAP. Clueless is a keyword.
Anyway, be back soon with the results.
Whenever I attempt to login, this is the output I get on suitecrm.log
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Found language file: en_us.lang.php
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Found custom language file: en_us.lang.php
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query Execution Time:0.0011050701141357
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query Execution Time:0.0012409687042236
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' AND deleted = 0
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query Execution Time:0.00098991394042969
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '67d4e908-187c-5bfe-0080-64440daa0029'
Fri Jan 26 16:01:53 2024 [1070][-none-][INFO] Query Execution Time:0.0011289119720459
EDIT: by the way that ID belongs to the system user (user_id = 1), just checked on the database at table outbound_email.
I have no idea why is it making this query.
Sorry, my bad, we want debug level, not info
I want to see the messages that have ldapauth, at least that will give me an idea of where we are in the code
The email messages are mysterious but for now I would say they’re harmless, probably just some part of the init process of the app, loading the current user and some other related info.
with debug enabled you get this (I had actually tried it already but the output was so irrelevant I didn’t care to put it here)
==> public/legacy/suitecrm.log <==
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] current_language is: en_us
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheAPC
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheFile
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheMemcache
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheMemcached
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheMemory
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Using cache backend SugarCacheMemory, since 999 is less than 1000
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheRedis
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheWincache
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCacheZend
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Found cache backend SugarCachesMash
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Found language file: en_us.lang.php
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Found custom language file: en_us.lang.php
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query Execution Time:0.0010459423065186
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query:SELECT category, name, value FROM config
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query Execution Time:0.0010290145874023
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query:SELECT id FROM outbound_email WHERE type = 'system' AND deleted = 0
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query Execution Time:0.00092887878417969
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query:SELECT * FROM outbound_email WHERE id = '67d4e908-187c-5bfe-0080-64440daa0029'
Fri Jan 26 16:26:51 2024 [2598][-none-][INFO] Query Execution Time:0.0010130405426025
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Hook called: ::after_entry_point
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Including module specific hook file for custom/modules
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Including Ext hook file for custom/application
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Hook called: ::server_round_trip
Fri Jan 26 16:26:51 2024 [2598][-none-][DEBUG] Calling MySQLi::disconnect()
There’s no ldapauth, but if you have other level that want me to give a try, let’s have it.
I’d swap the FreeIPA server for any other LDAP server, and see what the difference is, if any.
That’s frustrating…
I really expected to see more, I can’t explain how SuiteCRM is attempting any LDAP authentication without passing through that code I linked above, which has several lines logging stuff…
I bet you would, cause you don’t know better. So you think IPA is an LDAP server, but it’s not.
Also it’s borderline insulting blaming the external system for the f*** ups of so called devs here.
But worry not, mine is just one system, I’ll wait patiently for you to suggest Microsoft AD users to also use something else. ffs
It’s anybody’s guess where the bug is. To find it, I’d try it out with a different LDAP server than the one that’s a part of the FreeIPA server, as a test, to see how it works differently, if it does. This gives the community valuable troubleshooting information.
It’s anybody’s guess where the bug is
Version 8.4.1 had the EXACT SAME CONFIGURATION, WORKING
People reporting problems here use different implementations, I am using Red Hat IDM (not freeipa, that’s the open-source version for you to learn something), there’s people using Microsoft Active Directory.
Want to guess where the problem is, so different implementations that were previously working and now are not after an update of SuiteCRM? Would you like a drawing to help you guess where the problem is?
Click on “Files Changed”.
Perhaps someone with very high familiarity with the 8.x code could review and determine if a code change could cause LDAP authentication failure in 8.5.0?
I already did that work of going through ALL the commits in the upgrades. Nothing jumped at me regarding LDAP or authentication.
This is something harder to find. I would bet on some quirk from a 3rd-party package that got updated.
The LDAP authentication failure did not appear in version 8.5.0
It appeared originally at version 8.4.2 and I was the first person to report the issue that I know of.
Due to the lack of involvement, the issue persisted from 8.4.2 to 8.5.0.
So maybe looking a bit further may help someone to find the issue.
And again, if someone suggests feasible, reasonable, tests to make, I will make them, as I have been doing so far.
OK thanks for that @maverickws
Here’s the updated code from 8.4.1 to 8.4.2 it’s only 11 commits, 84 files, 7 contributors!
Pro Tip: The way to find which commit caused this issue (if indeed it’s an issue in the 8.4.2 code), is called git bisect. It’s a real git command used to pinpoint the cause of issues.
How to Use Git Bisect! https://www.youtube.com/watch?v=D7JJnLFOn4A
