Re: Dovecot Sieve weigert sich hartnäckig

Tim-Ole Golz toag at izsr.de
Mo Jul 29 08:50:39 CEST 2024


Moin, Markus,

> danke für den Test!

*ich* habe zu danken :)

> Danke auch dafür. Könntest Du bitte mal noch:
> 
> - die Ausgabe von 'postconf -n'

alias_database = hash:/etc/aliases, hash:/etc/sympa/aliases.sympa.postfix
alias_maps = hash:/etc/aliases, hash:/etc/sympa/aliases.sympa.postfix, hash:/etc/mail/sympa/aliases
append_dot_mydomain = no
biff = no
compatibility_level = 2
home_mailbox = Maildir/
inet_interfaces = all
local_header_rewrite_clients = static:all
mailbox_size_limit = 0
message_size_limit = 40240000
mydestination = sieve-geht.nicht mail.sieve-geht.nicht webmail.sieve-geht.nicht localhost.sieve-geht.nicht localhost
myhostname = mail.sieve-geht.nicht
mynetworks = 127.0.0.0/8, 192.168.123.0/24
myorigin = /etc/mailname
queue_directory = /var/spool/postfix
readme_directory = no
recipient_delimiter = +
relayhost = 1.2.3.4
remote_header_rewrite_domain =
sender_canonical_maps = hash:/etc/postfix/sender_canonical
smtp_tls_cert_file = /etc/letsencrypt/live/mail.sieve-geht.nicht/fullchain.pem
smtp_tls_key_file = /etc/letsencrypt/live/mail.sieve-geht.nicht/privkey.pem
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtp_use_tls = yes
smtpd_banner = $myhostname ESMTP $mail_name
smtpd_recipient_restrictions = permit_sasl_authenticated, check_sender_access hash:/etc/postfix/sender_access reject_non_fqdn_helo_hostname, reject_invalid_helo_hostname, reject_non_fqdn_sender, reject_non_fqdn_recipient, reject_unknown_sender_domain, reject_unknown_recipient_domain, reject_unverified_recipient, reject_unauth_destination, reject_unlisted_recipient reject_unauthenticated_sender_login_mismatch check_client_access hash:/etc/postfix/check_client_access permit
smtpd_relay_restrictions = check_sender_access hash:/etc/postfix/sender_access check_client_access hash:/etc/postfix/check_client_access permit_sasl_authenticated reject_non_fqdn_helo_hostname, reject_invalid_helo_hostname, reject_non_fqdn_sender reject_non_fqdn_recipient reject_unknown_sender_domain reject_unknown_recipient_domain reject_unverified_recipient reject_unauth_destination reject_unlisted_recipient reject_unauthenticated_sender_login_mismatch defer_unauth_destination permit
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot
smtpd_tls_cert_file = /etc/letsencrypt/live/mail.sieve-geht.nicht/fullchain.pem
smtpd_tls_key_file = /etc/letsencrypt/live/mail.sieve-geht.nicht/privkey.pem
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes
smtputf8_enable = no
soft_bounce = no
transport_maps = hash:/etc/postfix/transport
virtual_maps = hash:/etc/postfix/virtual
virtual_transport = virtual

> - das komplette Postfix- _und_ Dovecot-Log des Vorgangs der Einlieferung einer (Test-)Mail

=> „heini.meier“ loggt sich ein:

Jul 29 08:27:28 imap-login: Info: Login: user=<heini.meier>, method=PLAIN, rip=::1, lip=::1, mpid=8551, secured, session=<bKeH9Fwe8MYAAAAAAAAAAAAAAAAAAAAB>
Jul 29 08:27:28 imap(heini.meier)<8551><bKeH9Fwe8MYAAAAAAAAAAAAAAAAAAAAB>: Debug: Effective uid=10241, gid=10251, home=/home/heini.meier
Jul 29 08:27:28 imap(heini.meier)<8551><bKeH9Fwe8MYAAAAAAAAAAAAAAAAAAAAB>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir
Jul 29 08:27:28 imap(heini.meier)<8551><bKeH9Fwe8MYAAAAAAAAAAAAAAAAAAAAB>: Debug: maildir++: root=/home/heini.meier/Maildir, index=, indexpvt=, control=, inbox=/home/heini.meier/Maildir, alt=
Jul 29 08:27:28 imap(heini.meier)<8551><bKeH9Fwe8MYAAAAAAAAAAAAAAAAAAAAB>: Info: Logged out in=82 out=611 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 29 08:27:28 imap-login: Info: Login: user=<heini.meier>, method=PLAIN, rip=::1, lip=::1, mpid=8553, secured, session=<iCiJ9Fwe9sYAAAAAAAAAAAAAAAAAAAAB>
Jul 29 08:27:28 imap(heini.meier)<8553><iCiJ9Fwe9sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Effective uid=10241, gid=10251, home=/home/heini.meier
Jul 29 08:27:28 imap(heini.meier)<8553><iCiJ9Fwe9sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir
Jul 29 08:27:28 imap(heini.meier)<8553><iCiJ9Fwe9sYAAAAAAAAAAAAAAAAAAAAB>: Debug: maildir++: root=/home/heini.meier/Maildir, index=, indexpvt=, control=, inbox=/home/heini.meier/Maildir, alt=
Jul 29 08:27:28 imap(heini.meier)<8553><iCiJ9Fwe9sYAAAAAAAAAAAAAAAAAAAAB>: Info: Logged out in=44 out=527 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Jul 29 08:27:28 imap-login: Info: Login: user=<heini.meier>, method=PLAIN, rip=::1, lip=::1, mpid=8558, secured, session=<hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Effective uid=10241, gid=10251, home=/home/heini.meier
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: maildir++: root=/home/heini.meier/Maildir, index=, indexpvt=, control=, inbox=/home/heini.meier/Maildir, alt=
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Mailbox opened because: STATUS
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Mailbox opened because: SELECT
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Purging (new file_seq=1722175296): Drop old field flags (last_used=0)
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Purge dropped field flags (decision=temp, last_used=0)
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Purging finished, file_seq changed 1722175295 -> 1722175296, size=976 -> 700, max_uid=1
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: UID 2: Opened mail because: mail stream
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: UID 2: Opened mail because: 10/10 headers not cached (first=CC) (Mail not cached, highest cached seq=1 uid=1: reset_id=1722175296)
Jul 29 08:27:28 imap-login: Info: Login: user=<heini.meier>, method=PLAIN, rip=::1, lip=::1, mpid=8559, secured, session=</tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>
Jul 29 08:27:28 imap(heini.meier)<8558><hciL9Fwe/sYAAAAAAAAAAAAAAAAAAAAB>: Info: Logged out in=292 out=2028 deleted=0 expunged=0 trashed=0 hdr_count=2 hdr_bytes=476 body_count=0 body_bytes=0
Jul 29 08:27:28 imap(heini.meier)<8559></tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>: Debug: Effective uid=10241, gid=10251, home=/home/heini.meier
Jul 29 08:27:28 imap(heini.meier)<8559></tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir
Jul 29 08:27:28 imap(heini.meier)<8559></tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>: Debug: maildir++: root=/home/heini.meier/Maildir, index=, indexpvt=, control=, inbox=/home/heini.meier/Maildir, alt=
Jul 29 08:27:28 imap(heini.meier)<8559></tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>: Debug: Mailbox INBOX: Mailbox opened because: STATUS
Jul 29 08:27:28 imap(heini.meier)<8559></tyL9FweDMcAAAAAAAAAAAAAAAAAAAAB>: Info: Logged out in=82 out=614 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0

=> heini.meier ändert etwas an seinem Autoresponder:

Jul 29 08:34:35 managesieve-login: Info: Login: user=<heini.meier>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=8692, secured, session=<GizzDV0ebut/AAAB>
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: Effective uid=10241, gid=10251, home=/home/heini.meier
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: maildir++: root=/home/heini.meier/Maildir, index=, indexpvt=, control=, inbox=/home/heini.meier/Maildir, alt=
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: Pigeonhole version 0.5.13 (cdd19fe3) initializing
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: Using active Sieve script path: /home/heini.meier/.dovecot.sieve
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: Using script storage path: /home/heini.meier/sieve
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: Using permissions from /home/heini.meier/sieve: mode=0700 gid=-1
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: sync: Synchronization active
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script `managesieve' from `/home/heini.meier/sieve/managesieve.sieve'
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script for reading
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Closed script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': save: Started saving script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: Using Sieve script path: /home/heini.meier/sieve/tmp/managesieve_1722234875.M135875P8692.webmail.sieve
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script `managesieve' from `/home/heini.meier/sieve/tmp/managesieve_1722234875.M135875P8692.webmail.sieve'
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script for reading
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Closed script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': save: Finished saving script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Info: Disconnected: Logged out bytes=443/875
Jul 29 08:34:37 imap(merle.kirmse)<8690><ZgWHDV0e+8zAqHsL>: Debug: Mailbox Trash: Mailbox opened because: UID move

=> heini.meiers Datei /home/heini.meier/.dovecot.sieve sieht so aus:

require ["date","relational","vacation"];
# rule:[Abwesenheit ]
if allof (currentdate :zone "+0200" :value "ge" "date" "2024-07-27", currentdate :zone "+0200" :value "le" "date" "2024-07-30")
{
	vacation :days 1 :addresses "heini.meier at sieve-geht.nicht" :subject "Bin wech!" :from "\"heini.meier\" <heini.meier at sieve-geht.nicht>" "Barum? Darum!";
}

=> Mail von Aussen kommt rein, Postfix-Log:

Jul 29 08:38:18 webmail postfix/smtpd[8718]: connect from mailin.draussen[1.2.3.4]
Jul 29 08:38:18 webmail postfix/smtpd[8718]: CEF53400306: client=mailin.draussen[1.2.3.4]
Jul 29 08:38:18 webmail postfix/cleanup[8702]: CEF53400306: message-id=<07EDEC24-4D30-432E-965C-B7F453A0DB17 at foo.bar>
Jul 29 08:38:18 webmail postfix/qmgr[2162]: CEF53400306: from=<toag at foo.bar>, size=1636, nrcpt=1 (queue active)
Jul 29 08:38:18 webmail postfix/smtpd[8718]: disconnect from mailin.draussen[1.2.3.4] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jul 29 08:38:18 webmail postfix/local[8784]: CEF53400306: to=<heini.meier at sieve-geht.nicht>, relay=local, delay=0.04, delays=0.03/0.01/0/0, dsn=2.0.0, status=sent (delivered to maildir)
Jul 29 08:38:18 webmail postfix/qmgr[2162]: CEF53400306: removed

=> Debug-Dovecot-Log:

- nichts - …. tatsächlich! Das vorher so geschwätzige Dovecot-Log bleibt bei der Einlieferung der Autoresponder-Testmail so still wie ein Mönch im Schweigekloster. Ich habe die Mail um 8:38 Uhr geschickt, wenn ich gezielt nach heini.meier im Dovecot-Log suche, findet sich der letzte Eintrag von 8:34 Uhr:

Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script `managesieve' from `/home/heini.meier/sieve/tmp/managesieve_1722234875.M135875P8692.webmail.sieve'
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Opened script for reading
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': Closed script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Debug: sieve: file storage: script `managesieve': save: Finished saving script
Jul 29 08:34:35 managesieve(heini.meier)<8692><GizzDV0ebut/AAAB>: Info: Disconnected: Logged out bytes=443/875

= vermutlich muss ich das Debugging des Dovecot und/oder Sieve anders einstellen. Andererseits loggt er ja grundsätzlich die IMAP-Aktivitäten, siehe oben.

Autoresponder hat übrigens natürlich *nicht* funktioniert …. ich habe zwischenzeitlich in /etc/dovecot/conf.d/90-sieve.conf wieder die Zeilen reingenommen, mit denen es auf dem Referenzsystem ja funktioniert:

egrep -v '#|^ *$' /etc/dovecot/conf.d/90-sieve.conf

plugin {
  sieve = ~/.dovecot.sieve
  sieve_global_path = /var/lib/dovecot/sieve/default.sieve
  sieve_dir = ~/sieve
  sieve_global_dir = /var/lib/dovecot/sieve/
sieve_default = /var/lib/dovecot/sieve/default.sieve
sieve_global = /var/lib/dovecot/sieve/default.sieve
}

Mit den obigen Zeilen auskommentiert und

sieve = file:~/sieve;active=~/.dovecot.sieve

einkommentiert passiert genauso wenig :\

Bin echt ratlos; allmählich tippe ich auf irgend eine korrupte Library, die sich irgendwann mal zerschossen hat und die trotz (kurz zusammengefasst) 

apt remove —purge dovecot-managesieve* dovecot-sieve* && Reboot && apt autoremove && Reboot && apt update && apt upgrade && Reboot && apt install dovecot-managesieve* dovecot-sieve* && Reboot 

auch nicht wieder zum Leben erweckt werden kann. 

apt install -f und apt install vacation habe ich ebenfalls schon durch. Doveot kann ich nicht so einfach re-installieren, weil es sich um ein Produktivsystem handelt :\

Beste Grüße

Toag



Mehr Informationen über die Mailingliste Postfixbuch-users