- dovecot - dovecot.org

RE: temporary auth errors
by Michael Slusarz 02 May '24

02 May '24

> On 05/02/2024 7:48 AM MDT Marc via dovecot <dovecot(a)dovecot.org> wrote: > > > auth_failure_delay = 2 secs ? > > > > That will still simply wait before *rejecting* the login, compared to > > *dropping the connection*. > > > > We are thus looking for three different behaviours: > > > > 1. If backend confrims auth, ACK auth + proceed (grant access) to email. > > > > 2. If backend confirm "no such user" or "invalid creds", wait for > > auth_failure_delay and then *reject* the login. > > > > 3. If the backend fails (ie, can neither confirm nor deny), simply drop > > the connection. > > > > I hope this is more clear. > > > > Yes that is more clear, but no idea (seems a little out of scope to support by design) In complicated, localized authentication scenarios, Lua auth is likely the best answer. https://doc.dovecot.org/configuration_manual/authentication/lua_based_authe… michael

1 0

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

Re: Time moved forwards
by Param 30 Apr '24

30 Apr '24

There is already ntpd configured and working properly.

1 0

Time moved forwards
by Param 30 Apr '24

30 Apr '24

Is there any solution for this? I am on FreeBSD 13.3 with dovecot-2.3.21_4 built from ports and have noticed warnings: Apr 26 08:42:29 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.181936 seconds - adjusting timeouts. Apr 26 08:43:39 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.146834 seconds - adjusting timeouts. Apr 26 08:48:40 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.489300 seconds - adjusting timeouts. The more emails coming in, the more often warning. dovecot --version 2.3.21 (47349e2482) FreeBSD 13.3-RELEASE

3 2

doveadm backup empties the remote host? SERIOUSLY???
by Nils 29 Apr '24

29 Apr '24

Sure it's my own fault - no discussion about that, but seriously? How dangerously unintuitive it that? I found it when I was searching for a good practice to migrate a mail server with rsync and I mistakably assumed it works in the same direction as rsync. Luckily i have a backup from all mails except today's. Please, someone tell me what's the best procedure to migrate dovecot.

5 9

doveadm backup has problems with some accounts
by roger.meier＠4synergy.com 29 Apr '24

29 Apr '24

I try to setup for our mailserver (in a dc) a job backup to a secondary server (in our office) with "doveadm backup" via the -R option. (rsync , rsnapshot and so on tooks too long at the moment) For the most user accounts all work as expected, but for three users it always fails First run: /usr/bin/doveadm -Dv backup -Ru user1 tcp:mua01.domain.intra:12345 > Dec 01 08:54:21 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions > Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Warning: Deleting mailbox 'Archiv.Allgemein unsortiert': UID=1 GUID=1350559209.P2052Q54.lin-mail1.intra is missing locally > Dec 01 08:54:22 doveadm(user1)<70126><qfzHDjyfaWXuEQEAy5X8iQ>: Debug: brain M: Import Archiv.Allgemein unsortiert: Import change type=save GUID=1350559209.P2052Q54.mail1.intra UID=1 > hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found > Dec 01 08:54:22 doveadm(70126): Debug: brain M: Import Archiv.Allgemein unsortiert: Saved UIDs: > Dec 01 08:54:22 doveadm(70126): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9) So it aborts on the lines above and a incomplete maildir is on the local server. so the next doveadm try say's that he can't delete INBOX , etc. > Dec 01 09:03:33 doveadm(user1)<70169><TzH+MmKhaWUZEgEAy5X8iQ>: Error: Mailbox INBOX sync: mailbox_delete failed: INBOX can't be deleted. This a very old account on our server which was migrated over different iterations of our dovecot mailserver. The user behind the account uses outlook over years. Is the space here a problem? Another user with a similiar issue has the following error message at the end: > Dec 01 09:22:14 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Debug: Mailbox INBOX: Mailbox opened because: copy caching decisions > Dec 01 09:22:56 doveadm(user2)<70354><RU12FsWlaWXSEgEAy5X8iQ>: Error: read(mua01.domain.intra) failed: EOF (last sent=mailbox, last recv=mailbox) > Dec 01 09:22:56 doveadm(70354): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9) I see that the user has a very big inbox? when i check in the source server in the "cur" folder of the INBOX it count's around 269372 mails. Is this perhaps the issue for this message? And on the last user it looks like: Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Warning: Deleting mailbox 'Entwürfe': UID=1265 GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 is missing locally Dec 01 09:25:19 doveadm(user3)<70376><UoiQAHWmaWXoEgEAy5X8iQ>: Debug: brain M: Import Entwürfe: Import change type=save GUID=1521832311.M6830P7652.mail-mx1.intra,S=1764,W=1809 UID=1265 hdr_hash= result=Reverting local change by deleting mailbox - No more local mails found Dec 01 09:25:19 doveadm(70376): Debug: brain M: Import Entwürfe: Saved UIDs: Dec 01 09:25:19 doveadm(70376): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=661,uid=0): Disconnected: Connection closed (fd=9) The "Entwürfe" folder directly cannot be the issue? On the filesystem the folder has the name ".Entw&APw-rfe" and also other users has similar folders in their mailboxes. The source server has dovecot version 2.2.36 (centos 7.9.2009) and the current destination server dovecot version 2.3.16 (ubuntu 22.04 lts)

2 3