May 2024 - dovecot - dovecot.org

temporary auth errors
by Jaco Kroon 02 May '24

02 May '24

Hi All, Looking for some advise. We ran into a situation yesterday where our SQL cluster (mariadb-galera) stopped serving requests due to some DDL queries locking the wsrep provider. We're addressing this separately, so just background as to the cause of the problem. As far as I know both POP3 and IMAP protocols only have two possible responses when a user tries to authenticate, either ACK (yes, you're fine let's proceed) and NACK (no, something with authentication failed, and either you've got credential issues, or something is wrong with the backend). An ACK results in granting the user access. A NACK results in the user having to retry. This is all good and well, but the *typical* response by a MUA is to re-prompt the user for credentials, to which the response is usually to retry random passwords until it works again (confirmed with Outlook and Thunderbird). What I'm hoping is that dovecot has some way to in case of such "authentication backend" problem scenarios to ignore protocol and politeness and simply disconnect the client, ie, just shut the connection without saying anything, this could even be with a small delay (I'd say 1 second or so, just to avoid tight auth retry loops, up to 4 or 5 seconds IMHO would be fine). The hope is that this will result in the mail client treating this like a connection error rather than an authentication error, and hopefully not prompt for new credentials, but simply an alert of the "there has been a problem communicating with your mail server please retry or contact your service provider" kind of error messages. For reference, the errors in dovecot logs looks like: May 1 04:42:25 uriel dovecot[352]: auth-worker(11615): Warning: sqlpool(mysql): Query failed, retrying: WSREP has not yet prepared node for application use May 1 04:42:25 uriel dovecot[352]: auth-worker(11615): Error: conn unix:auth-worker (pid=11453,uid=76): auth-worker<68>: sql(user(a)domain,a.b.c.d,<XXXX>): Password query failed: WSREP has not yet prepared node for application use May 1 04:42:27 uriel dovecot[352]: pop3-login: Disconnected: Aborted login by logging out (auth service reported temporary failure): user=<user@domain>, method=PLAIN, rip=a.b.c.d, lip=e.f.g.h, TLS, session=<XXXX> Kind regards, Jaco

2 3

Re: Failing to archive many messages
by Francis Augusto Medeiros-Logeay 01 May '24

01 May '24

It is weird. At first, it seems that the logs are going fine. It goes like this for many minutes: May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.IN-REPLY-TO from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.MESSAGE-ID from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.SUBJECT from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.TO from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.X-PRIORITY from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.BCC from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.REPLY-TO from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.DISPOSITION-NOTIFICATION-TO from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Looked up field hdr.LIST-POST from mail cache May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: multi-script: Start execute sequence May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: Executing script from `/var/mail/vmail/mail/sieve/global/report-ham.svbin' May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: multi-script: Run script `/var/mail/vmail/mail/sieve/global/report-ham.svbin' May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: Started running script `/var/mail/vmail/mail/sieve/global/report-ham.svbin' May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: Finished running script `ok' (status=/var/mail/vmail/mail/sieve/global/report-ham.svbin, resource usage: no usage recorded) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: multi-script: Execute result May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing result (status=ok, commit=no) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Starting execution of actions May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing actions May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing pipe action May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: action pipe: running program: sa-learn-ham.sh May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Created May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Pass environment: USER=francis(a)mydomain.com May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Pass environment: HOME=/var/mail/vmail/med-lo.eu/francis May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Pass environment: HOST=fb58607074fd May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: Mailbox Archive: UID 25719: Opened mail because: mail stream May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finished executing pipe action (status=ok, keep=implicit) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finished executing actions (status=ok, keep=implicit) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finished executing result (no commit, status=ok, keep=yes) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: multi-script: Sequence active May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: multi-script: Finishing sequence (status=ok) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing result (status=ok, commit=yes) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Starting execution of actions May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing actions May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finished executing actions (status=ok, keep=implicit) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Execute implicit keep (failure=no) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Start storing into mailbox Archive May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Executing implicit keep action May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Execute storing into mailbox 'Archive' May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Updated existing mail in mailbox 'Archive' May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finished executing implicit keep action (status=ok) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finalizing actions May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Finalize pipe action (status=ok, action_status=ok, commit_status=ok, pre-commit=yes) May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: sieve: uid=25719: Commit pipe action May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Establishing connection May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh: Forked child process May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (416): Connected to program May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (416): Finished streaming payload to program May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (416): Finished input to program May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (416): Disconnected May 01 14:20:04 imap(francis(a)mydomain.com)<226><zNW3d2MX9uku45qA>: Debug: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (416): Waiting for program to finish after 6 msecs (timeout = 9994 msecs) The client stays just like «Moving 1 of 4000 messages». Then the logs start to go like this: May 01 14:43:09 imap: Error: ERROR: the Bayes learn function returned an error, please re-run with -D for more information at /usr/bin/sa-learn line 500. May 01 14:43:12 imap: Error: ERROR: the Bayes learn function returned an error, please re-run with -D for more information at /usr/bin/sa-learn line 500. ^C root@fb58607074fd:/# tail -f /var/log/dovecot.log | grep Error May 01 14:43:15 imap: Error: plugin: eval failed: interrupted at /usr/bin/sa-learn line 513. May 01 14:43:15 imap: Error: ERROR: the Bayes learn function returned an error, please re-run with -D for more information at /usr/bin/sa-learn line 500. May 01 14:43:15 imap(francis(a)mydomain.com)<295><TwG1fGMXCuou45qA>: Error: sieve: failed to pipe message to program `sa-learn-ham.sh': refer to server log for more information. [2024-05-01 14:43:15] May 01 14:43:15 imap(francis(a)mydomain.com)<295><TwG1fGMXCuou45qA>: Error: sieve: Execution of script /var/mail/vmail/mail/sieve/global/report-ham.sieve failed May 01 14:43:16 imap(francis(a)mydomain.com)<292><Ei2ofGMXBeou45qA>: Error: program exec:/var/mail/vmail/mail/sieve/global/scripts/sa-learn-ham.sh (2978): Forcibly terminated with signal 15 May 01 14:43:16 imap(francis(a)mydomain.com)<292><Ei2ofGMXBeou45qA>: Error: sieve: failed to pipe message to program `sa-learn-ham.sh': refer to server log for more information. [2024-05-01 14:43:16] May 01 14:43:16 imap(francis(a)mydomain.com)<292><Ei2ofGMXBeou45qA>: Error: sieve: Execution of script /var/mail/vmail/mail/sieve/global/report-ham.sieve failed May 01 14:43:17 imap: Error: plugin: eval failed: interrupted at /usr/bin/sa-learn line 513. May 01 14:43:17 imap: Error: ERROR: the Bayes learn function returned an error, please re-run with -D for more information at /usr/bin/sa-learn line 500. For many minutes, the mail client gets an error about reaching the max connections from ip, and the logs go on and on with the errors above. What could be the issue? Best, Francis -- Francis Augusto Medeiros-Logeay Oslo, Norway

1 0

ENV{"PATH"}. errors on my log
by Francis Augusto Medeiros-Logeay 01 May '24

01 May '24

Hi, I'm getting this error a lot on my logs: May 01 12:57:03 imap: Error: Use of uninitialized value $ENV{"PATH"} in split at /usr/lib/x86_64-linux-gnu/perl-base/File/Spec/Unix.pm line 136. I googled a bit and the only reference I found was related to the possibility of imapsieve scripts that could be generating this. I haven't found any perl script on my install, but I momentarily turned off spamassassin, but the logs continued. Any hint on how I can debug this? Turning the debug logs on dovecot didn't bring me any extra information of what the source of this could be. Best, Francis -- Francis Augusto Medeiros-Logeay Oslo, Norway

2 2

Failing to archive many messages
by Francis Augusto Medeiros-Logeay 01 May '24

01 May '24

Hi, When I archive one or two messages, the messages are correctly moved to the Archive. However, when I archive more messages - like 50 or more, dovecot seems to fail. The error I get is this one: Warning: Failed to do incremental sync for mailbox Archive, retry with a full sync (Modseq 17277 no longer in transaction log (highest=17323, last_common_uid=12216, nextuid=15767)) No messages end up being moved to the Archive folder. I tried to do this both from a mail client and from roundcube. What could be the problem here?

1 0

Dovecot, migrating mailboxes from old to new server and from old to new format?
by David Mehler 01 May '24

01 May '24

Hello, I've got a task to migrate a Dovecot mailstore, mailboxes, public folders, etc from an older server (it runs Dovecot 2.2.x) to a new server (running Dovecot 2.3.x). At the same time I'm needing to change mailbox storage formats, going from Mbox (on old server) to Maildir (on new server). I'm not sure if any of the mailboxes are compressed with zlib or encrypted, there's a lot of them, is there a way to find out compression or encryption and decompress/decrypt them prior to migration? Suggestions welcome. Thanks. Dave. -- Sent from Mozilla Thunderbird 91.13.1

2 1