LDAP search error vs. "503 5.1.1 User does not exist"

UCS - Univention Corporate Server
, , ,
#1

Hallo,
ein Problem, welches inzwischen JEDES Mal am Tag (??) nach einen Kopano Update auftritt, hat mich heute wieder auf Trab gehalten.
Seit geraumer Zeit habe ich in /var/log/kopano/server.log folgende Einträge wiederkehrend:

(Timestamp): [error  ] LDAP search error: Can't contact LDAP server. Will unbind, reconnect and retry.
(Timestamp): [error  ] Previous message logged 100 times

Dies wurde hier im Forum schon einmal diskutiert, allerdings ohne Ergebnis - auch, da dies scheinbar keine Auswirkungen auf die Funktionalität zu haben scheint.

Da ich nun jedoch das direkte Kopano Repo aktiviert habe, trifft mich regelmäßig ein Problem, welches damit zusammenhängen könnte. Aus /var/log/mail.log:

(Timestamp) ucs fetchmail[7580]: 812 messages (811 seen) for USER_X@mydomain.tld at smarthost.domain.tld.
(Timestamp) ucs postfix/smtpd[7752]: connect from localhost[127.0.0.1]
(Timestamp) ucs postfix/smtpd[7752]: D5A61602E2: client=localhost[127.0.0.1]
(Timestamp) ucs postfix/cleanup[7755]: D5A61602E2: message-id=<201705140637.v4E6btEB022608@externalmx.domain.tld>
(Timestamp) ucs postfix/qmgr[19223]: D5A61602E2: from=<externalsender@domain.tld>, size=279830, nrcpt=1 (queue active)
(Timestamp) ucs fetchmail[7580]: reading message USER_X@mydomain.tld@smarthost.domain.tld:812 of 812 (2567 header octets) (276976 body octets) not flushed
(Timestamp) ucs postfix/smtpd[7752]: disconnect from localhost[127.0.0.1]
(Timestamp) ucs postfix/smtpd[7760]: connect from localhost[127.0.0.1]
(Timestamp) ucs postfix/smtpd[7760]: D30C2613DF: client=localhost[127.0.0.1], orig_queue_id=D5A61602E2, orig_client=localhost[127.0.0.1]
(Timestamp) ucs postfix/cleanup[7755]: D30C2613DF: message-id=<201705140637.v4E6btEB022608@externalmx.domain.tld>
(Timestamp) ucs postfix/qmgr[19223]: D30C2613DF: from=<externalsender@domain.tld>, size=280586, nrcpt=1 (queue active)
(Timestamp) ucs postfix/smtpd[7760]: disconnect from localhost[127.0.0.1]
(Timestamp) ucs amavis[1155]: (01155-10) Passed CLEAN {RelayedInternal}, LOCAL [127.0.0.1]:55765 [66.228.35.203] <externalsender@domain.tld> -> <USER_X@mydomain.tld>, Queue-ID: D5A61602E2, Message-ID: <201705140637.v4E6btEB022608@externalmx.domain.tld>, mail_id: MwRCoiKSKp_J, Hits: 0.874, size: 279829, queued_as: D30C2613DF, 1792 ms
(Timestamp) ucs postfix/smtp[7756]: D5A61602E2: to=<USER_X@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.1, delays=2.2/0.01/0/1.8, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as D30C2613DF)
(Timestamp) ucs postfix/qmgr[19223]: D5A61602E2: removed
(Timestamp) ucs postfix/lmtp[7761]: D30C2613DF: to=<USER_X@mydomain.tld>, relay=127.0.0.1[127.0.0.1]:2003, delay=0.16, delays=0.05/0.01/0.09/0.01, dsn=5.1.1, status=bounced (host 127.0.0.1[127.0.0.1] said: 503 5.1.1 User does not exist (in reply to RCPT TO command))
(Timestamp) ucs postfix/cleanup[7755]: EFF64613FD: message-id=<20170514063848.EFF64613FD@ucs.mydomain.local>
(Timestamp) ucs postfix/bounce[7765]: D30C2613DF: sender non-delivery notification: EFF64613FD
(Timestamp) ucs postfix/qmgr[19223]: EFF64613FD: from=<>, size=5586, nrcpt=1 (queue active)
(Timestamp) ucs postfix/qmgr[19223]: D30C2613DF: removed
(Timestamp) ucs postfix/smtp[7766]: EFF64613FD: to=<externalsender@domain.tld>, relay=smarthost.domain.tld[xxx.xxx.xxx.xxx]:25, delay=1.2, delays=0/0.02/0.75/0.47, dsn=2.0.0, status=sent (250 OK)
(Timestamp) ucs postfix/qmgr[19223]: EFF64613FD: removed
(Timestamp) ucs postfix/smtpd[7752]: connect from ucs.mydomain.local[192.168.100.3]
(Timestamp) ucs postfix/smtpd[7752]: disconnect from ucs.mydomain.local[192.168.100.3]

/var/log/kopano/server.log hat währenddessen folgende Einträge:

(Timestamp): [warning] Authentication by plugin failed for user "USER_X": Trying to authenticate failed: No user type attribute value defined; username = USER_X
(Timestamp): [warning] Failed to authenticate user "USER_X" from "file:///var/run/kopano/server.sock" using program "apache2"

und

(Timestamp): [warning] Unable to perform search for string "USER_Y@domain.tld" on user database: No user type attribute value defined`

und

(Timestamp): [warning] Log connection was reset
(Timestamp): [crit   ] K-3904: Unable to setup ssl context: Can't find or read certificate in key file
(Timestamp): [error  ] Unable to reload plugin configuration file.
(Timestamp): [crit   ] Config error: Option 'ldap_group_type_attribute_value' cannot be empty!
(Timestamp): [crit   ] Config error: Option 'ldap_user_type_attribute_value' cannot be empty!
(Timestamp): [crit   ] Config error: Option 'ldap_group_type_attribute_value' cannot be empty!
(Timestamp): [crit   ] Config error: Option 'ldap_user_type_attribute_value' cannot be empty!
(Timestamp): [warning] Log connection was reset
(Timestamp): [crit   ] K-3904: Unable to setup ssl context: Can't find or read certificate in key file
(Timestamp): [warning] Authentication by plugin failed for user "USER_Z": Trying to authenticate failed: No user type attribute value defined; username = USER_Z
(Timestamp): [warning] Failed to authenticate user "USER_Z" from "file:///var/run/kopano/server.sock" using program "apache2"

Somit werden alles Mails vom Smarthost gebounced, aber erst am Tag NACH dem Kopano Update. Ich tippe auf einen Cronjob, welcher die User-Tabelle mit Samba abgleicht, hier in die Tiefe zu gehen überfordert meine Kenntnisse der Zusammenhänge zwischen UCS, Samba und Kopano deutlich.

Hat vielleicht jemand einen Tipp?

VG,
TP

#2

Hallo TP,

nein das die zwei Logmeldungen etwas miteinander zu tun haben würde ich ausschließen. Kopano nutzt OpenLDAP auf Univention, ein Cron Job zum Abgleich mit Samba wäre mir persönlich nicht bekannt.

Welche Version von Kopano wird denn verwendet, die “unable to reload plugin configuration” Fehlermeldung sieht wie etwas aus, was mit Zarafa 7.1.11 gefixt wurde.

#3

Hallo,

dieses Problem auf welches @ahrnke geantwortet hat, hört sich ähnlich an. Allerdings habe ich “/usr/lib/univention-server/server_password_change.d/70kopano” schon gecheckt, und es scheint richtig zu sein:

# restart kopano-server to apply new password
	service kopano-server restart

Allerdings glaube ich inzwischen an ein generelles Problem im UCS, da auch die WebGUI währen dieser Zeit keine Anmeldung mehr akzeptiert. Ein Neustart per SSH als root ist nötig geworden. Danach läuft alles wieder einwandfrei.

Die vermeintlich hilfreichen Logs starten leider alle erst wieder am Sonntag um 6:30 Uhr. Vermutlich von 0:00 Uhr bis zum Neustart bestand das Problem. In /var/log/univention/listener.log ist Folgendes zu lesen:

16.07.17 06:39:14.650  DEBUG_INIT
16.07.17 06:39:14.681  LISTENER    ( ERROR   ) : failed to connect to any notifier
16.07.17 06:39:14.681  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
16.07.17 06:39:44.682  LISTENER    ( WARN    ) : chosen server: ucs.domain.local:7389
UNIVENTION_DEBUG_BEGIN  : uldap.__open host=ucs.domain.local port=7389 base=dc=domain,dc=local
UNIVENTION_DEBUG_END    : uldap.__open host=ucs.domain.local port=7389 base=dc=domain,dc=local
16.07.17 08:34:12.475  LISTENER    ( ERROR   ) : connection to notifier was closed
16.07.17 08:34:12.475  LISTENER    ( ERROR   ) : failed to recv result
16.07.17 08:34:12.476  LISTENER    ( ERROR   ) : listener: 1
16.07.17 08:34:17.870  DEBUG_INIT
16.07.17 08:34:17.902  LISTENER    ( ERROR   ) : failed to connect to any notifier
16.07.17 08:34:17.902  LISTENER    ( WARN    ) : can not connect any server, retrying in 30 seconds
16.07.17 08:34:23.522  LISTENER    ( WARN    ) : received signal 15
16.07.17 08:36:30.454  DEBUG_INIT
UNIVENTION_DEBUG_BEGIN  : uldap.__open host=ucs.domain.local port=7389 base=dc=domain,dc=local
UNIVENTION_DEBUG_END    : uldap.__open host=ucs.domain.local port=7389 base=dc=domain,dc=local

Die Während des Problems auftauchenden Bounces sind effektiv ein großes Problem.

info@domain.tld: host 127.0.0.1[127.0.0.1] said: 503 5.1.1 User does not
exist (in reply to RCPT TO command)

Welche Logs wären denn aufschlussreich - ich kann trotz intensiver Suche nichts Aufregendes entdecken…?

VG,
TP

#4

Hallo,

welche Aktionen wurden denn ausgeführt, um das System wieder lauffähig zu bekommen? Wie sieht das /var/log/univention/server_password_change.log zu dem betreffenden Zeitraum aus? Wenn ein rotieren der Logfiles stattgefunden hat, sind die Dateien mit den Endungen .1 usw noch interessant.

#5

Hallo,

danke für die schnelle Rückmeldung! /var/log/univention/server_password_change.log(mit logrotate “1” zusammengefasst) zeigt nichts Aufregendes:

Starting server password change (Mon Jul 10 01:04:45 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Tue Jul 11 01:02:37 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Wed Jul 12 01:02:12 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Thu Jul 13 01:02:56 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Fri Jul 14 01:06:13 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Sat Jul 15 01:01:14 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Sun Jul 16 01:09:45 CEST 2017)
No server password change scheduled for today, terminating without a change
Starting server password change (Mon Jul 17 01:03:14 CEST 2017)
No server password change scheduled for today, terminating without a change

Ein simpler Neustart reicht aus. Ich vermute, beim Starten werden die Benutzer wieder korrekt abgeglichen. Ob ein vorheriges UCS oder Kopano Update dazu beiträgt, kann ich nicht sagen, da dessen Installation oft eine Woche zurückliegt. Eher gehe ich von einem fixen Zeitpunkt alle paar Wochen aus.

VG,
TP

#6

Dann scheint der passwordchange nicht der schuldige zu sein, es fand kein Passwortwechsel statt. Die Logfile Ausschnite im ersten Post lassen darauf schließen, dass der kopano-server Dienst neugestartet wurde (Zertifikat und config files lesen). Gibt es andere Cronjobs oder Software, die die Dienste neustarten, wie zum Beispiel Backupsoftware? Ohne jetzt genau auf das System zu schauen ist das aber nur gestochere im Dunkeln.

#7

Hallo,
ich konnte das Problem mit UCS 4.1-x nie besser eingrenzen, da es nur sporadisch auftrat.

Jedenfalls scheint es mit UCS 4.2-x behoben zu sein!

MBG,
TP

1 Like
Mastodon