August 2022 - dovecot

namespace directives from userdb not being applied
by Brendan Braybrook 24 Aug '22

24 Aug '22

hi all, i'm having a strange issue. i have a few dovecot instances running: 1- debian 10 with debian's dovecot-core 1:2.3.4.1-5+deb10u5 2- debian 10 with debian's dovecot-core 1:2.3.4.1-5+deb10u6 3- debian 11 with dovecot's dovecot-core 2:2.3.19.1-2+debian11 for all these, i've just been testing with a static userdb (ignore if the login user was different; they all had the same userdb data.. various different passdb configs were tried (none do any userdb prefetching): userdb { driver = static args = mail=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ home=/mail/mailstore03/492/177/b(a)b.com/ namespace=inbox,share namespace/inbox/separator=/ namespace/share/separator=/ namespace/share/prefix=boop/ } instance #2 and #3 don't seem to pass all the namespace directives i'm passing through to the imap process. (i originally found it happening with a lua userdb script then noticed it with a dict userdb, but the simpler static userdb still shows it happening so i don't think it's related to the different userdb mechanisms themselves) debug looks like: auth: Debug: master userdb out: USER 3466461185 b(a)b.com mail=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ home=/mail/mailstore03/492/177/b(a)b.com/ namespace=inbox,share namespace/inbox/separator=/ namespace/share/separator=/ namespace/share/prefix=boop/ auth_mech=PLAIN auth_token=bcdb366d56f4fceee83775a1b28ca89ccdf881fd script-login(b(a)b.com)<56895><>: Debug: Added userdb setting: mail=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ script-login(b(a)b.com)<56895><>: Debug: Added userdb setting: namespace=inbox,share script-login(b(a)b.com)<56895><>: Debug: Added userdb setting: namespace/inbox/separator=/ script-login(b(a)b.com)<56895><>: Debug: Added userdb setting: namespace/share/prefix=boop/ script-login(b(a)b.com)<56895><>: Debug: Added userdb setting: namespace/share/separator=/ imap(b(a)b.com)<56894><9mFyornjaMcKyAUI>: Debug: Added userdb setting: mail=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ imap(b(a)b.com)<56894><9mFyornjaMcKyAUI>: Debug: Added userdb setting: namespace=inbox,share imap(b(a)b.com)<56894><9mFyornjaMcKyAUI>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ imap(b(a)b.com)<56894><9mFyornjaMcKyAUI>: Debug: Namespace : type=private, prefix=, sep=, inbox=no, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ the script-login task notes that these userdb settings are being added: namespace=inbox,share namespace/inbox/separator=/ namespace/share/prefix=boop/ namespace/share/separator=/ but the imap task only notes one: namespace=inbox,share both of these two instances end up getting an error because the imap task didn't pick up the prefix: Error: namespace configuration error: Duplicate namespace prefix: "" instance #1 behaves differently. it's script-login task debug is the same, but the imap debug notes: imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: Added userdb setting: mail=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: Added userdb setting: namespace=inbox,share imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: Added userdb setting: namespace/inbox/separator=/ imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: tc_empty_notify_plugin init imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: Namespace inbox: type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ imap(bigip-imap(a)nagios.tucows.com)<2146><s3ctO7njd6cKBS39>: Debug: Namespace : type=private, prefix=, sep=, inbox=no, hidden=no, list=yes, subscriptions=yes location=maildir:/mail/mailstore03/492/177/b@b.com/:INDEX=/mail/index03/492/177/b@b.com/ on this one, the imap task notes that it added ALL the namespace directives, and consequently doesn't have any namespace prefix collisions. the difference between 1:2.3.4.1-5+deb10u5 and 1:2.3.4.1-5+deb10u6 doesn't seem that great, and the bug tracker for it doesn't indicate anything around userdb would be patched (https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=970386) but the problem still seems to exist in 2.3.19 - can anyone else see the same thing happening with the current builds? thanks! -brendan

3 4

Dovecot ACLs and XOAUTH2
by Felix Auringer 23 Aug '22

23 Aug '22

Hi, we're trying to set up an IMAP server using Dovecot as part of a new email system in a middle-sized company (around 150 employees). We have a keycloak identity server that is used for all logins and we would also like to use it for the new email system so that the non-technical employees (the majority) will have no issues using it. It's very nice that XOAUTH2 is already included in Dovecot, it works very well with our Roundcube web client. However, it seems that other clients like Thunderbird or Android Apps like FairEmail are not easy to set up as they have their XOAUTH providers hardcoded somewhere (https://bugzilla.mozilla.org/show_bug.cgi?id=1602166) Are you aware of any solution to integrate a dovecot server using XOAUTH2 into local clients (like Thunderbird)? We are currently trying to do it with passwords that can be set in Keycloak only for the purpose of email that can then be used to receive a valid token via a direct access grant but it's not a really nice solution as it introduces an additional password. Additionally, we would like to have all permission-related information saved in our identity server. For email, this includes shared mailboxes that a user is allowed to access. The ACL plugin that is used for shared mailboxes currently reads the permissions from disk which is not really feasible if the user base is large and setting these permissions should happen automatically. We are thinking the best way to do this is to encode the user's permissions in the token that dovecot receives in the login process. But as the token is only available in the authentication process and it does not seem to be intended to return such information from the password database (https://doc.dovecot.org/configuration_manual/authentication/password_databa…) we are unsure on how to process these information from the token. We did not find any plugin hooks in the authentication processes and the normal plugin hooks do not have access to information from the token anymore. What do you think is the best way to do this? We would be okay modifying some dovecot source code and contributing it back if desired. Best regards, Felix Auringer --- Gesellschaft für interkulturelles Zusammenleben gGmbH (GIZ) Felix Auringer IT Reformationsplatz 2 13597 Berlin Tel: 030/513 0100 00; Fax: 030/513 0100 09 www.giz.berlin; felix.auringer(a)giz.berlin Amtsgericht Charlottenburg HRB 200872 B Geschäftsführerin: Dr. Britta Marschke

2 6

Dict Redis error: Unsupported operation (dict does not support this feature)
by Tomas Dolezal 23 Aug '22

23 Aug '22

Hi all, when we try to delete any folder from Trash folder, for exmaple Trash.Test, Thunderbird and RoundCube IMAP clients show this error: DELETE: Internal error occurred. Refer to server log for more information. [2022-08-22 23:03:00] (0.001 + 0.000 secs). And deleted folder is still in Trash. This error is in the maillog: Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Error: Mailbox Trash.Test: dict_iterate(priv/70555f26b6e803632f0d0000c2736b7f/) failed: Unsupported operation (dict does not support this feature) We use Redis as Dovecot dict and the command "redis-cli monitor" shows queries MULTI and DISCARD. I have tried to find any simillar problem at Google but without success. The error message "Unsupported operation (dict does not support this feature)" has not found. And in the source dict-fail.c there are many situations with this error string. Anybody can help me? Thanks, Tom. $ cat /var/log/maillog Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: client in: AUTH#0111#011PLAIN#011service=imap#011secured=tls#011session=KhIoINrmh8tecCPV#011lip=4.5.6.7#011rip=1.2.3.4#011lport=143#011rport=52103#011real_lip=1.2.3.4#011real_rip=4.5.6.7#011real_rport=58392#011local_name=mail1.default.cz#011resp=<hidden> Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Performing passdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): lookup: user=test(a)test.tld file=/etc/dovecot/mail-users Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): allow_real_nets: Matching for network 1.2.3.4 Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): allow_real_nets: Matching for network 4.5.6.7 Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Finished passdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: auth(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Auth request finished Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Performing userdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): lookup: user=test(a)test.tld file=/etc/dovecot/mail-users Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test(a)test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Finished userdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: imap-login: Login: user=<test(a)test.tld>, method=PLAIN, rip=1.2.3.4, lip=4.5.6.7, mpid=3355, TLS, session=<KhIoINrmh8tecCPV> Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Loading modules from directory: /usr/lib64/dovecot Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib10_last_login_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib20_quota_clone_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib30_imap_zlib_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib95_imap_sieve_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Effective uid=8, gid=12, home=/var/maildir/test.tld/test Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: redis: Connecting Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: conn 127.0.0.1:6379: Waiting for connect (fd=17) to finish for max 0 msecs Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: conn 127.0.0.1:6379: Client connected (fd=17) Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Starting transaction Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Setting 'shared/last-login/test(a)test.tld/imap/1.2.3.4' to '1661199400' Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Quota root: name=User quota backend=count args= Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Quota grace: root=User quota bytes=0 (10%) Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir:UTF-8 Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: maildir++: root=/var/maildir/test.tld/test/Maildir, index=, indexpvt=, control=, inbox=/var/maildir/test.tld/test/Maildir, alt= Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Dict transaction finished Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Waiting for dict to finish pending operations Aug 22 22:16:40 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: conn 127.0.0.1:6379: Disconnected: Connection closed (fd=17) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Trash.Test: Mailbox opened because: DELETE Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Namespace : Using permissions from /var/maildir/test.tld/test/Maildir: mode=0700 gid=default Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Iterating prefix priv/70555f26b6e803632f0d0000c2736b7f/ Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: redis: Connecting Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: conn 127.0.0.1:6379: Waiting for connect (fd=18) to finish for max 0 msecs Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: conn 127.0.0.1:6379: Client connected (fd=18) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Starting transaction Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Unsetting 'priv/70555f26b6e803632f0d0000c2736b7f/comment' Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Iteration finished: Unsupported operation (dict does not support this feature) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Error: Mailbox Trash.Test: dict_iterate(priv/70555f26b6e803632f0d0000c2736b7f/) failed: Unsupported operation (dict does not support this feature) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test(a)test.tld>: Dict transaction finished Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: Mailbox opened because: SELECT Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Trash.Test: Mailbox opened because: quota count Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field flags from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field mime.parts from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.BCC from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.CC from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.CONTENT-TYPE from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.DATE from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.FROM from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.IN-REPLY-TO from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.MESSAGE-ID from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.NEWSGROUPS from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.PRIORITY from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.REFERENCES from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.REPLY-TO from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.SUBJECT from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.TO from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.X-PRIORITY from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.X-SPAM-FLAG from mail cache Aug 22 22:36:22 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: UID 51504: Looked up field hdr.X-SPAM-STATUS from mail cache Aug 22 22:36:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:38:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:40:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:42:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:44:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:46:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:48:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:50:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:52:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:54:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:56:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:58:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 23:00:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 23:02:26 mail1 dovecot[1012]: imap(test(a)test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count $ uname -a Linux mail1.default.cz 4.18.0-408.el8.x86_64 #1 SMP Mon Jul 18 17:42:52 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux $ cat /etc/centos-release CentOS Stream release 8 $ dnf list installed dovecot redis: Installed Packages dovecot.x86_64 1:2.3.16-3.el8 @appstream redis.x86_64 5.0.3-5.module_el8.4.0+955+7126e393 @appstream $ mount /dev/mapper/system-root on / type xfs (rw,noatime,nodiratime,attr2,inode64,logbufs=8,logbsize=32k,noquota) $ dovecot -n # 2.3.16 (7e2e900c1a): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.16 (09c29328) # OS: Linux 4.18.0-408.el8.x86_64 x86_64 CentOS Stream release 8 # Hostname: mail1.default.cz auth_debug = yes auth_mechanisms = plain login auth_verbose = yes disable_plaintext_auth = no first_valid_uid = 8 hostname = mail1.default.cz lmtp_rcpt_check_quota = yes lmtp_save_to_detail_mailbox = yes login_trusted_networks = 1.2.3.4 mail_attribute_dict = redis:host=127.0.0.1:port=6379:prefix=dovecot/ mail_debug = yes mail_gid = mail mail_location = maildir:~/Maildir:UTF-8 mail_server_admin = mailto:admin@test.tld mail_uid = mail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext vnd.dovecot.debug imapsieve vnd.dovecot.imapsieve namespace inbox { inbox = yes location = mailbox Archive { auto = no special_use = \Archive } mailbox Archives { auto = no special_use = \Archive } mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { auto = subscribe autoexpunge = 30 days special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox Trash { auto = subscribe autoexpunge = 30 days special_use = \Trash } prefix = } passdb { args = scheme=CRYPT username_format=%u /etc/dovecot/mail-users driver = passwd-file } plugin { imapsieve_url = sieve://mail.vizus.cz last_login_dict = redis:host=127.0.0.1:port=6379:prefix=dovecot/ last_login_key = # hidden, use -P to show it quota = count:User quota quota_clone_dict = redis:host=127.0.0.1:port=6379:prefix=dovecot/ quota_grace = 10%% quota_vsizes = yes sieve = file:~/sieve;active=~/user.sieve sieve_before = file:~/admin.sieve sieve_extensions = +vnd.dovecot.debug +copy sieve_plugins = sieve_imapsieve } postmaster_address = postmaster(a)test.tld protocols = imap pop3 lmtp sieve service anvil { client_limit = 2048 } service auth { client_limit = 2048 } service imap-login { process_limit = 1024 } service lmtp { unix_listener lmtp { group = postfix mode = 0600 user = postfix } } service pop3-login { process_limit = 256 } ssl_ca = </etc/pki/tls/cert.pem ssl_cert = </etc/pki/test.tld.pem ssl_client_cert = </etc/pki/test.tld.pem ssl_client_key = # hidden, use -P to show it ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_prefer_server_ciphers = yes ssl_require_crl = no userdb { args = username_format=%u /etc/dovecot/mail-users driver = passwd-file } protocol imap { imap_metadata = yes mail_plugins = quota quota_clone imap_quota last_login imap_zlib imap_sieve } protocol pop3 { mail_plugins = quota quota_clone last_login } protocol lmtp { mail_plugins = quota quota_clone last_login sieve } protocol !indexer-worker { mail_vsize_bg_after_count = 100 } dovecot-sysreport-mail1.default.cz-1661201665.tar.gz

1 0

Should one prevent reconnection before expunge?
by Jack Cecil 22 Aug '22

22 Aug '22

Hello. From my understanding the 'autoexpunge' feature activates on user disconnect. But could you help me understand the 'doveadm expunge' feature better? If a Maildir has 20 thousand messages and user is reading it over IMAP I have a suspicion it is not a good idea to be rewriting the dovecot cache at the same time. Should I temporarily prevent login (e.g. with passwd-file deny) and then kick them before the expunge? Thank you.

3 4

Get a list of currently active IMAP connections?
by Jaroslaw Rafa 22 Aug '22

22 Aug '22

Hello Dovecot community, I have a question: is it possible to programmatically get from Dovecot a list of currently active IMAP sessions (with IP addresses)? Via a plugin or something? Or just check if there is an IMAP session currently open from a particular IP address, with true/false type answer? I'm planning to implement a policy service for *Postfix* that will revive the old "POP before SMTP" authorization concept (only it will be "IMAP before SMTP" this time). This policy service will reject connections to mail submission ports (465, 587) - without even going to SMTP AUTH phase - unless the connecting IP address has currently an IMAP session open to Dovecot, to mitigate SMTP AUTH attacks. But for this I need some way to check from within this policy service if the particular IP address has a connection open or not. It could be of course obtained by scanning Dovecot logs, but this involves quite a large overhead. Therefore I'm looking for the way to get this information directly from Dovecot's current state. Can you advise me of any way to do this? Or maybe someone has already written such a piece of software and it is available somewhere on the Net? -- Regards, Jaroslaw Rafa raj(a)rafa.eu.org -- "In a million years, when kids go to school, they're gonna know: once there was a Hushpuppy, and she lived with her daddy in the Bathtub."

8 17

Adding new server (POP3 only)
by Antonino Esposito 21 Aug '22

21 Aug '22

Good morning, we're facing a spike in users activation and we've decided to add another server for POP3 only. Since our dovecot is currently backed by NFS, i'm under the impression we just need to add a new instance listening for POP3, backed by the same NFS. However, i'm afraid the existing POP3 users will download the messages once again, due to the fact the responding server will be on a different IP address, even if the hostname will be exactly the same. Am i right in this assumption? Have you any advice for me? Thanks Antonino

2 1

Fields not showing in openmetrics statistics
by Rybkin Vladimir 17 Aug '22

17 Aug '22

Hello I'm trying to configure stats with openmetrics Dovecot version: 2.3.19 I make the settings as follows: ``` # cat /home/beget/dovecot/conf/conf.d/90-openmetrics.conf | grep -v -E "^#" service stats { inet_listener http { port = 9900 } } event_exporter log { format = json format_args = time-rfc3339 transport = log } metric imap_commands { exporter = log filter = event=* } metric imap_command { filter = event=imap_command_finished fields = bytes_in bytes_out group_by = cmd_name tagged_reply_state } ``` The problem is that no matter what configuration I do, the fields parameter is not displayed in openmetrics ``` # curl http://192.168.20.252:9900/metrics | grep -v -E "^#\ " | grep imap_command % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 4891 100 4891 0 0 285k 0 --:--:-- --:--:-- --:--:-- 341k dovecot_imap_commands_total 388 dovecot_imap_commands_duration_seconds_total 24.225760 dovecot_imap_command_total{cmd_name="NAMESPACE"} 1 dovecot_imap_command_total{cmd_name="NAMESPACE",tagged_reply_state="OK"} 1 dovecot_imap_command_total{cmd_name="ID"} 4 dovecot_imap_command_total{cmd_name="ID",tagged_reply_state="OK"} 4 dovecot_imap_command_total{cmd_name="ENABLE"} 4 dovecot_imap_command_total{cmd_name="ENABLE",tagged_reply_state="OK"} 4 dovecot_imap_command_total{cmd_name="SELECT"} 3 dovecot_imap_command_total{cmd_name="SELECT",tagged_reply_state="OK"} 3 dovecot_imap_command_total{cmd_name="GETQUOTAROOT"} 3 dovecot_imap_command_total{cmd_name="GETQUOTAROOT",tagged_reply_state="OK"} 3 dovecot_imap_command_total{cmd_name="UID FETCH"} 19 dovecot_imap_command_total{cmd_name="UID FETCH",tagged_reply_state="OK"} 19 dovecot_imap_command_total{cmd_name="LIST"} 2 dovecot_imap_command_total{cmd_name="LIST",tagged_reply_state="OK"} 2 dovecot_imap_command_total{cmd_name="IDLE"} 1 dovecot_imap_command_total{cmd_name="IDLE",tagged_reply_state="OK"} 1 dovecot_imap_command_total{cmd_name="STATUS"} 2 dovecot_imap_command_total{cmd_name="STATUS",tagged_reply_state="OK"} 2 dovecot_imap_command_count 39 dovecot_imap_command_duration_seconds_total{cmd_name="NAMESPACE"} 0.000218 dovecot_imap_command_duration_seconds_total{cmd_name="NAMESPACE",tagged_reply_state="OK"} 0.000218 dovecot_imap_command_duration_seconds_total{cmd_name="ID"} 0.000900 dovecot_imap_command_duration_seconds_total{cmd_name="ID",tagged_reply_state="OK"} 0.000900 dovecot_imap_command_duration_seconds_total{cmd_name="ENABLE"} 0.000332 dovecot_imap_command_duration_seconds_total{cmd_name="ENABLE",tagged_reply_state="OK"} 0.000332 dovecot_imap_command_duration_seconds_total{cmd_name="SELECT"} 0.028734 dovecot_imap_command_duration_seconds_total{cmd_name="SELECT",tagged_reply_state="OK"} 0.028734 dovecot_imap_command_duration_seconds_total{cmd_name="GETQUOTAROOT"} 0.127621 dovecot_imap_command_duration_seconds_total{cmd_name="GETQUOTAROOT",tagged_reply_state="OK"} 0.127621 dovecot_imap_command_duration_seconds_total{cmd_name="UID FETCH"} 0.097117 dovecot_imap_command_duration_seconds_total{cmd_name="UID FETCH",tagged_reply_state="OK"} 0.097117 dovecot_imap_command_duration_seconds_total{cmd_name="LIST"} 0.003738 dovecot_imap_command_duration_seconds_total{cmd_name="LIST",tagged_reply_state="OK"} 0.003738 dovecot_imap_command_duration_seconds_total{cmd_name="IDLE"} 7.397259 dovecot_imap_command_duration_seconds_total{cmd_name="IDLE",tagged_reply_state="OK"} 7.397259 dovecot_imap_command_duration_seconds_total{cmd_name="STATUS"} 0.041169 dovecot_imap_command_duration_seconds_total{cmd_name="STATUS",tagged_reply_state="OK"} 0.041169 dovecot_imap_command_duration_seconds_sum 7.697088 ``` It is displayed through doveadm ``` # altdocker exec $(altdocker ps -aq -f name=dove) doveadm stats dump metric_name field count sum min max avg median stddev %95 imap_commands duration 449 1043812019 20 116763630 2324748.37 2382 12137052.43 608328 imap_command duration 49 145807071 72 46020784 2975654.51 3381 11041798.07 46017747 imap_command bytes_in 49 1419 0 179 28.96 37 28.93 55 imap_command bytes_out 49 1867985 0 424616 38122.14 167 74553.96 158613 imap_command_NAMESPACE duration 1 218 218 218 218.00 218 0.00 218 imap_command_NAMESPACE bytes_in 1 0 0 0 0.00 0 0.00 0 imap_command_NAMESPACE bytes_out 1 86 86 86 86.00 86 0.00 86 imap_command_NAMESPACE_OK duration 1 218 218 218 218.00 218 0.00 218 imap_command_NAMESPACE_OK bytes_in 1 0 0 0 0.00 0 0.00 0 imap_command_NAMESPACE_OK bytes_out 1 86 86 86 86.00 86 0.00 86 imap_command_ID duration 4 900 145 288 225.00 233 59.07 288 imap_command_ID bytes_in 4 168 42 42 42.00 42 0.00 42 imap_command_ID bytes_out 4 275 66 75 68.75 67 3.63 75 imap_command_ID_OK duration 4 900 145 288 225.00 233 59.07 288 imap_command_ID_OK bytes_in 4 168 42 42 42.00 42 0.00 42 imap_command_ID_OK bytes_out 4 275 66 75 68.75 67 3.63 75 imap_command_ENABLE duration 4 332 72 110 83.00 75 15.65 110 imap_command_ENABLE bytes_in 4 44 11 11 11.00 11 0.00 11 imap_command_ENABLE bytes_out 4 147 36 37 36.75 37 0.44 37 imap_command_ENABLE_OK duration 4 332 72 110 83.00 75 15.65 110 imap_command_ENABLE_OK bytes_in 4 44 11 11 11.00 11 0.00 11 imap_command_ENABLE_OK bytes_out 4 147 36 37 36.75 37 0.44 37 imap_command_SELECT duration 3 28734 4662 16200 9578.00 7872 4862.39 16200 imap_command_SELECT bytes_in 3 33 7 14 11.00 12 2.94 14 imap_command_SELECT bytes_out 3 1034 309 416 344.67 309 50.44 416 imap_command_SELECT_OK duration 3 28734 4662 16200 9578.00 7872 4862.39 16200 imap_command_SELECT_OK bytes_in 3 33 7 14 11.00 12 2.94 14 imap_command_SELECT_OK bytes_out 3 1034 309 416 344.67 309 50.44 416 imap_command_GETQUOTAROOT duration 6 171676 12353 74871 28612.67 17219 22308.42 74871 imap_command_GETQUOTAROOT bytes_in 6 66 7 14 11.00 12 2.94 14 imap_command_GETQUOTAROOT bytes_out 6 983 159 167 163.83 165 3.18 167 imap_command_GETQUOTAROOT_OK duration 6 171676 12353 74871 28612.67 17219 22308.42 74871 imap_command_GETQUOTAROOT_OK bytes_in 6 66 7 14 11.00 12 2.94 14 imap_command_GETQUOTAROOT_OK bytes_out 6 983 159 167 163.83 165 3.18 167 imap_command_UID_FETCH duration 20 97998 881 16915 4899.90 3304 4306.81 13912 imap_command_UID_FETCH bytes_in 20 922 13 179 46.10 37 34.76 103 imap_command_UID_FETCH bytes_out 20 1864818 40 424616 93240.90 100838 92111.34 174020 imap_command_UID_FETCH_OK duration 20 97998 881 16915 4899.90 3304 4306.81 13912 imap_command_UID_FETCH_OK bytes_in 20 922 13 179 46.10 37 34.76 103 imap_command_UID_FETCH_OK bytes_out 20 1864818 40 424616 93240.90 100838 92111.34 174020 imap_command_LIST duration 2 3738 1715 2023 1869.00 1869 154.00 2023 imap_command_LIST bytes_in 2 56 10 46 28.00 28 18.00 46 imap_command_LIST bytes_out 2 315 85 230 157.50 157 72.50 230 imap_command_LIST_OK duration 2 3738 1715 2023 1869.00 1869 154.00 2023 imap_command_LIST_OK bytes_in 2 56 10 46 28.00 28 18.00 46 imap_command_LIST_OK bytes_out 2 315 85 230 157.50 157 72.50 230 imap_command_IDLE duration 4 145454703 7397259 46020784 36363675.75 46018330 16723768.54 46020784 imap_command_IDLE bytes_in 4 32 8 8 8.00 8 0.00 8 imap_command_IDLE bytes_out 4 91 10 27 22.75 27 7.36 27 imap_command_IDLE_OK duration 4 145454703 7397259 46020784 36363675.75 46018330 16723768.54 46020784 imap_command_IDLE_OK bytes_in 4 32 8 8 8.00 8 0.00 8 imap_command_IDLE_OK bytes_out 4 91 10 27 22.75 27 7.36 27 imap_command_STATUS duration 2 41169 16692 24477 20584.50 20584 3892.50 24477 imap_command_STATUS bytes_in 2 92 45 47 46.00 46 1.00 47 imap_command_STATUS bytes_out 2 236 117 119 118.00 118 1.00 119 imap_command_STATUS_OK duration 2 41169 16692 24477 20584.50 20584 3892.50 24477 imap_command_STATUS_OK bytes_in 2 92 45 47 46.00 46 1.00 47 imap_command_STATUS_OK bytes_out 2 236 117 119 118.00 118 1.00 119 imap_command_NOOP duration 3 7603 1654 3177 2534.33 2772 644.07 3177 imap_command_NOOP bytes_in 3 6 2 2 2.00 2 0.00 2 imap_command_NOOP bytes_out 3 0 0 0 0.00 0 0.00 0 imap_command_NOOP_OK duration 3 7603 1654 3177 2534.33 2772 644.07 3177 imap_command_NOOP_OK bytes_in 3 6 2 2 2.00 2 0.00 2 imap_command_NOOP_OK bytes_out 3 0 0 0 0.00 0 0.00 0 ``` I can’t understand what I’m doing wrong so that field data is displayed in openmetrics.

1 0

Re: dovecot/config processes open, and consuming all memory
by Joseph Tam 17 Aug '22

17 Aug '22

From: Aki Tuomi <aki.tuomi(a)open-xchange.com> > The *default* configuration for service config is usually just fine. > Is there some reason you decided to modify it in first place? Are you asking me, or the OP? I guess the blunt answer is ignorance on my part. However, I pointed out that the docs about this setting is somewhat misleading -- it's used to limit any potential memory leaks for long-lived processes by ensuring it terminates periodically. I read this and thought to myself "this is a good thing to do", without realizing that it would have the opposite effect as lingering clients could delay service termination indefinitely. The side effect is many new processes are spawned to handle new clients, and eventually the maximum process limit is reached, and chaos ensues. So for services like imap-login and others that can have lingering clients, the only sensible values for service_limit is {0,1}. If you set service_limit>1, the asymptotic behaviour is like service_limit=1, and process_limit would have to be adjusted accordingly. The docs can explain this rather wordy and subtle explanation of service_limit, or service_limit can be constrained to values {0,1} so that others don't blunder along the same path I did. Joseph Tam <jtam.home(a)gmail.com>

2 1

Re: dovecot/config processes open, and consuming all memory
by Joseph Tam 16 Aug '22

16 Aug '22

> I'm having strange behavior in dovecot 2.3.16. > It's opening dozens of dovecot/config process and consuming all server > memory. Normally each process consumes between 700Mb and 1Gb of ram. > > Would anyone have an idea about this? > > service config { > vsz_limit = 2048M > idle_kill = 60s > service_count = 1024 > } Not sure it's related, but if you have service_count not 0 or 1, there is a strange interaction with other limits that could cause processes to hang around. My description of problem https://www.mail-archive.com/dovecot%40dovecot.org/msg85850.html Your situation is slgihtly different (service not imap_login, and idle_kill timeout should reduce lingering processes that caused my problem), but try setting service_limit to either 0 or 1 and see if your problem goes away, or gets worse. You can also see how many file descriptors are being held by the config process, and see the behaviour over time (e.g. monitor /proc/{pid}/fd/*); maybe that will give you a clue as to what the config process is doing. Joseph Tam <jtam.home(a)gmail.com>

3 5

Slow IMAP SORT
by Ewald Dieterich 16 Aug '22

16 Aug '22

The following IMAP SORT with 2 sort criteria is very slow on an mdbox mailbox with lots of mails (more than 10,000) and an empty cache: . SORT (ARRIVAL DATE) UTF-8 ALL Each mail is opened when the SORT is executed, which is slow, given the number of mails in the mailbox. Debug: Mailbox INBOX: UID 1003: Opened mail because: header stream <repeated for each mail> Repeating the SORT opens all mails again and again: Debug: Mailbox INBOX: UID 1003: Opened mail because: header stream <repeated for each mail> If I just sort by ARRIVAL, the SORT is fast and I don't see any "Opened mail because" messages in the debug log. . SORT (ARRIVAL) UTF-8 ALL If I just sort by DATE, the first SORT is slow. . SORT (DATE) UTF-8 ALL The debug log looks like this: Debug: Mailbox INBOX: UID 1003: Opened mail because: header Date (Mail has other cached fields, reset_id=1633683216) <repeated for each mail> This fills the cache and if I sort by DATE again, the SORT is fast and I don't get any more "Opened mail because" messages in the debug log. If I now repeat "SORT (ARRIVAL DATE)", the SORT is fast, the mails are not opened. If I clear the cache, "SORT (ARRIVAL DATE)" goes back to being slow, not filling the cache. This doesn't seem right. "SORT (ARRIVAL DATE)" should also fill the cache to execute repeated SORTS faster, right?

3 2