Page MenuHomePhorge

kolab-saslauthd fails on Almalinux 9 with status=2/INVALIDARGUMENT
Open, Needs TriagePublic

Description

I am running Kolab 16 on Almalinux 9.
kolab-saslauthd is kolab-saslauthd-0.9.0.7-1.5.el9.kolab_16.noarch
Without any further log message the kolab-saslauthd fails with just the following message in the journal log:
kolab-saslauthd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT

This disables all logins
Can I do to increase the log messages?

Details

Ticket Type
Task

Event Timeline

Spenneberg triaged this task as Needs Triage priority.Aug 2 2024, 9:32 AM
Spenneberg created this task.

the debug option is " -d " with an integer up to 9

Thanks a lot. Saslauthd fails every 3-14 days. Once I have more data, I will add it to the ticket.

I have increased the debug output to 5 so far. Currently it only logs failed authentications. I will increase it to 9 now. I was a bit hesitant because of the log size.

Ok. I have increased the debug output to 9. Unfortunately nothing is logged. kolab-saslauthd failed at 08:03:39 and is automatically restarted.

/var/log/messages:
Sep 10 08:03:39 xchg3 systemd[1]: kolab-saslauthd.service: Main process exited,
code=exited, status=2/INVALIDARGUMENT

In /var/log/kolab/pykolab.log nothing noticable is logged before the restart:
2024-09-10 08:03:38,930 pykolab.auth DEBUG [3565584] Binding with bind_dn: uid=k
olab-service,ou=Special Users,dc=spenneberg,dc=net and password: ***
2024-09-10 08:03:38,931 pykolab.auth DEBUG [3565584] * <ldap.ldapobject.Recon
nectLDAPObject object at 0x7f045fca4280> ldap://localhost:389 - ReconnectLDAPObj
ect.simple_bind
2024-09-10 08:03:38,931 pykolab.auth DEBUG [3565584] (('uid=kolab-service,ou=Sp
ecial Users,dc=spenneberg,dc=net',
2024-09-10 08:03:38,931 pykolab.auth DEBUG [3565584] 'XXXXXXXX',
2024-09-10 08:03:38,931 pykolab.auth DEBUG [3565584] None,
2024-09-10 08:03:38,932 pykolab.auth DEBUG [3565584] None),
2024-09-10 08:03:38,932 pykolab.auth DEBUG [3565584] {})
2024-09-10 08:03:38,933 pykolab.auth DEBUG [3565584]
* <ldap.ldapobject.Recon
nectLDAPObject object at 0x7f045fca4280> ldap://localhost:389 - ReconnectLDAPObj
ect.result4
2024-09-10 08:03:38,933 pykolab.auth DEBUG [3565584] ((1, 1, -1, 0, 0, 0), {})
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.i
d AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key,
entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.i
d AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key,
entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.i
d AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key,
entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.i
d AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key,
entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,962 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.61s ago] ('spenneberg.net',)
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,964 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:38,969 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.62s ago] ('(&(|(mail=hendrik)(mail=hendrik@spenneberg.net)(alias=hendrik)(alias=hendrik@spenneberg.net)(uid=hendrik)(uid=hendrik@spenneberg.net))(objectclass=inetorgperson))',)
2024-09-10 08:03:38,969 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.62s ago] ('(&(|(mail=hendrik)(mail=hendrik@spenneberg.net)(alias=hendrik)(alias=hendrik@spenneberg.net)(uid=hendrik)(uid=hendrik@spenneberg.net))(objectclass=inetorgperson))',)
2024-09-10 08:03:38,969 pykolab.auth_cache DEBUG [3565584] Entry found: {'_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f045f110760>, 'value': 'uid=hendrik,ou=People,dc=spenneberg,dc=net', 'last_change': datetime.datetime(2024, 9, 10, 6, 10, 1, 40844), 'id': 2, 'domain': None, 'key': '(&(|(mail=hendrik)(mail=hendrik@spenneberg.net)(alias=hendrik)(alias=hendrik@spenneberg.net)(uid=hendrik)(uid=hendrik@spenneberg.net))(objectclass=inetorgperson))'}
2024-09-10 08:03:38,970 pykolab.auth_cache DEBUG [3565584] Returning: 'uid=hendrik,ou=People,dc=spenneberg,dc=net'
2024-09-10 08:03:38,970 pykolab.conf DEBUG [3565584] Die Option ldap/timeout existiert in der Konfigurationsdatei /etc/kolab/kolab.conf nicht, sie wird aus den Standardeinstellungen geholt
2024-09-10 08:03:38,970 pykolab.auth DEBUG [3565584] Binding with bind_dn: uid=hendrik,ou=People,dc=spenneberg,dc=net and password: **
2024-09-10 08:03:38,970 pykolab.auth DEBUG [3565584] * <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca4280> ldap://localhost:389 - ReconnectLDAPObject.simple_bind
2024-09-10 08:03:38,970 pykolab.auth DEBUG [3565584] (('uid=hendrik,ou=People,dc=spenneberg,dc=net', '+++++"', None, None), {})
2024-09-10 08:03:38,971 pykolab.auth DEBUG [3565584]
* <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca4280> ldap://localhost:389 - ReconnectLDAPObject.result4
2024-09-10 08:03:38,971 pykolab.auth DEBUG [3565584] ((2, 1, -1, 0, 0, 0), {})
2024-09-10 08:03:38,998 pykolab.auth INFO [3565584] Authentifizierung für 'hendrik' erfolgreich

2024-09-10 08:03:39,118 pykolab.auth DEBUG [3565584] Aufgerufen für Domäne None
2024-09-10 08:03:39,118 pykolab.auth DEBUG [3565584] Benutze Abschnitt os-s.de und Domäne os-s.de
2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Benutze Abschnitt os-s.de und Domäne os-s.de
2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Verbinde zu Authentifizierungsbackend für Domäne os-s.de

Any further hints?

Any further ideas how to debug this? What error causes INVALIDARGUMENT? Or is this a sign for an uncaught error?

perhaps Domain based issue?
see end of your logs.

permissions, connection, configuration?
api (wap), associateddomain, aci, postfix (main and ldap cf)

Crash is after:
2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Verbinde zu Authentifizierungsbackend für Domäne os-s.de

Actually the logs continue. Apparently my copy buffer did not copy the complete log. I guess the failed login of hr1 is the last thing of the old process. Then the saslauthd is restarted reading its configuration files:

2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Abschnitt kolab hat auth_mechanism: 'ldap'
2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Starte LDAP...
2024-09-10 08:03:39,119 pykolab.auth DEBUG [3565584] Zum LDAP verbinden…
2024-09-10 08:03:39,120 pykolab.auth DEBUG [3565584] Versuche LDAP URI ldap://localhost:389 zu benutzen
2024-09-10 08:03:39,120 pykolab.auth DEBUG [3565584] * <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.set_option
2024-09-10 08:03:39,120 pykolab.auth DEBUG [3565584] ((17, 3), {})
2024-09-10 08:03:39,121 pykolab.auth DEBUG [3565584]
* <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.set_option
2024-09-10 08:03:39,121 pykolab.auth DEBUG [3565584] ((17, 3), {})
2024-09-10 08:03:39,121 pykolab.auth DEBUG [3565584] Versuche Benutzer hr1 in Bereich os-s.de zu authentisieren
024-09-10 08:03:39,122 pykolab.auth DEBUG [3565584] Binding with bind_dn: uid=kolab-service,ou=Special Users,dc=spenneberg,dc=net and password: ***
2024-09-10 08:03:39,122 pykolab.auth DEBUG [3565584] * <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.simple_bind
2024-09-10 08:03:39,122 pykolab.auth DEBUG [3565584] (('uid=kolab-service,ou=Special Users,dc=spenneberg,dc=net',
2024-09-10 08:03:39,123 pykolab.auth DEBUG [3565584] 'xxxxx',
2024-09-10 08:03:39,123 pykolab.auth DEBUG [3565584] None,
2024-09-10 08:03:39,123 pykolab.auth DEBUG [3565584] None),
2024-09-10 08:03:39,123 pykolab.auth DEBUG [3565584] {})
2024-09-10 08:03:39,124 pykolab.auth DEBUG [3565584]
* <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.result4
2024-09-10 08:03:39,124 pykolab.auth DEBUG [3565584] ((1, 1, -1, 0, 0, 0), {})
2024-09-10 08:03:39,164 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,165 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.81s ago] ('os-s.de',)
2024-09-10 08:03:39,165 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.81s ago] ('os-s.de',)
2024-09-10 08:03:39,168 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,168 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,168 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('os-s.de',)
2024-09-10 08:03:39,168 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('os-s.de',)
2024-09-10 08:03:39,169 pykolab.auth_cache DEBUG [3565584] Entry found: {'_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f045f110730>, 'value': 'dc=spenneberg,dc=net', 'last_change': datetime.datetime(2024, 9, 10, 6, 36, 5, 697087), 'id': 7, 'domain': None, 'key': 'os-s.de'}
2024-09-10 08:03:39,170 pykolab.auth_cache DEBUG [3565584] Returning: 'dc=spenneberg,dc=net'
2024-09-10 08:03:39,172 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,172 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,172 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('(&(|(mail=hr1)(mail=hr1@os-s.de)(alias=hr1)(alias=hr1@os-s.de)(uid=hr1)(uid=hr1@os-s.de))(objectclass=inetorgperson))',)
2024-09-10 08:03:39,172 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('(&(|(mail=hr1)(mail=hr1@os-s.de)(alias=hr1)(alias=hr1@os-s.de)(uid=hr1)(uid=hr1@os-s.de))(objectclass=inetorgperson))',)
2024-09-10 08:03:39,174 sqlalchemy.engine.Engine INFO [3565584] SELECT entries.id AS entries_id, entries.domain AS entries_domain, entries."key" AS entries_key, entries.value AS entries_value, entries.last_change AS entries_last_change
FROM entries
WHERE entries."key" = ?
2024-09-10 08:03:39,174 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('(&(|(mail=hr1)(mail=hr1@os-s.de)(alias=hr1)(alias=hr1@os-s.de)(uid=hr1)(uid=hr1@os-s.de))(objectclass=inetorgperson))',)
2024-09-10 08:03:39,174 sqlalchemy.engine.Engine INFO [3565584] [cached since 29.82s ago] ('(&(|(mail=hr1)(mail=hr1@os-s.de)(alias=hr1)(alias=hr1@os-s.de)(uid=hr1)(uid=hr1@os-s.de))(objectclass=inetorgperson))',)
2024-09-10 08:03:39,175 pykolab.conf DEBUG [3565584] Die Option ldap/timeout existiert in der Konfigurationsdatei /etc/kolab/kolab.conf nicht, sie wird aus den Standardeinstellungen geholt
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] * <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.search_ext
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] (('dc=spenneberg,dc=net',
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] 2,
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] '(&(|(mail=hr1)(mail=hr1@os-s.de)(alias=hr1)(alias=hr1@os-s.de)(uid=hr1)(uid=hr1@os-s.de))(objectclass=inetorgperson))',
024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] ['entrydn'],
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] True,
2024-09-10 08:03:39,176 pykolab.auth DEBUG [3565584] None,
2024-09-10 08:03:39,177 pykolab.auth DEBUG [3565584] None,
2024-09-10 08:03:39,177 pykolab.auth DEBUG [3565584] 10.0,
2024-09-10 08:03:39,177 pykolab.auth DEBUG [3565584] 0),
2024-09-10 08:03:39,177 pykolab.auth DEBUG [3565584] {})
2024-09-10 08:03:39,177 pykolab.auth DEBUG [3565584]
* <ldap.ldapobject.ReconnectLDAPObject object at 0x7f045fca42e0> ldap://localhost:389 - ReconnectLDAPObject.result4
2024-09-10 08:03:39,178 pykolab.auth DEBUG [3565584] ((2, 1, -1, 0, 0, 0), {})
2024-09-10 08:03:39,180 pykolab.auth DEBUG [3565584] Länge der gefundenen Einträge: 0
2024-09-10 08:03:39,180 pykolab.auth INFO [3565584] Authentifizierung für 'hr1' fehlgeschlagen (kein Eintrag)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze loglevel auf 50 (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze imap_virtual_domains auf 'userid' (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze cyrus_annotations_retry_interval auf 1 (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze address_search_attrs auf ['mail', 'alias'] (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze mail_attributes auf ['mail', 'alias'] (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze mailserver_attribute auf 'mailhost' (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze kolab_domain_sync_interval auf 600 (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze kolab_default_locale auf 'en_US' (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze ldap_timeout auf 10 (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze ldap_unique_attribute auf 'nsuniqueid' (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze wallace_resource_calendar_expire_days auf 100 (aus den Standardeinstellungen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze config_file auf '/etc/kolab/kolab.conf' (aus den Standardwerten für Kommandozeilenoptionen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze debuglevel auf 0 (aus den Standardwerten für Kommandozeilenoptionen)
2024-09-10 08:03:44,735 pykolab.conf DEBUG [3565623] Setze answer_default auf False (aus den Standardwerten für Kommandozeilenoptionen)
2024-09-10 08:03:44,736 pykolab.conf DEBUG [3565623] Setze loglevel auf 'CRITICAL' (aus den Standardwerten für Kommandozeilenoptionen)
2024-09-10 08:03:44,736 pykolab.conf DEBUG [3565623] Setze logfile auf '/var/log/kolab/pykolab.log' (aus den Standardwerten für Kommandozeilenoptionen)

as long as I could see, it is still a Domain address issue!

while there are two domains in log files, one on ldap side as basedn and the other on users mailaddress.

https://docs.kolab.org/administrator-guide/configuring-the-kolab-server.html#configuration-considerations-for-multiple-domain-namespaces

Domain os-s.de , troubling, while searching on basedn: dc=spenneberg,dc=net
mailaddress with user@os-s.de not found! user not found, so did no auth!

Yes, the user hr1@os-s.de does not exist in the LDAP. It is not a vaild usser. Therefore no authentication is possible. But this should not be a cause for saslauthd to fail and terminate, am I correct?
The kolab-saslauthd terminates. I reconfigured systemd to automatically restart the daemon because otherwise the login would fail for valid users as well.

You asked for hints!
The crash should not happen, but there are still to much variables included.
I just analyzed, the information I had.

Catching this error with an irreproducible behavior, is like fortune telling.

Could you reproduce the crash with non existing user?
If reproduced, which part(s) causing the trouble?

  • user
  • domain
  • alias domain
  • multi domain

As written before, there are some more log files, where a correlated error could be thrown.