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@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@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Performing passdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): lookup: user=test@test.tld file=/etc/dovecot/mail-users Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test@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@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@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Finished passdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: auth(test@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Auth request finished Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Performing userdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): lookup: user=test@test.tld file=/etc/dovecot/mail-users Aug 22 22:16:40 mail1 dovecot[1012]: auth: Debug: passwd-file(test@test.tld,1.2.3.4,<KhIoINrmh8tecCPV>): Finished userdb lookup Aug 22 22:16:40 mail1 dovecot[1012]: imap-login: Login: user=<test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Loading modules from directory: /usr/lib64/dovecot Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@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@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@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@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@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: redis: Connecting Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: conn 127.0.0.1:6379: Client connected (fd=17) Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Starting transaction Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Setting 'shared/last-login/test@test.tld/imap/1.2.3.4' to '1661199400' Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Quota root: name=User quota backend=count args= Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Quota grace: root=User quota bytes=0 (10%) Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@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@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@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Dict transaction finished Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Waiting for dict to finish pending operations Aug 22 22:16:40 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: conn 127.0.0.1:6379: Disconnected: Connection closed (fd=17) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Trash.Test: Mailbox opened because: DELETE Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Iterating prefix priv/70555f26b6e803632f0d0000c2736b7f/ Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: redis: Connecting Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: conn 127.0.0.1:6379: Client connected (fd=18) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Starting transaction Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Unsetting 'priv/70555f26b6e803632f0d0000c2736b7f/comment' Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Iteration finished: Unsupported operation (dict does not support this feature) Aug 22 22:36:12 mail1 dovecot[1012]: imap(test@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: dict(redis)<test@test.tld>: Dict transaction finished Aug 22 22:36:22 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Junk: Mailbox opened because: SELECT Aug 22 22:36:22 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:36:22 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox Trash.Test: Mailbox opened because: quota count Aug 22 22:36:22 mail1 dovecot[1012]: imap(test@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:38:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:40:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:42:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:44:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:46:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:48:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:50:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:52:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:54:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:56:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 22:58:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 23:00:26 mail1 dovecot[1012]: imap(test@test.tld)<3355><KhIoINrmh8tecCPV>: Debug: Mailbox INBOX: Mailbox opened because: quota count Aug 22 23:02:26 mail1 dovecot[1012]: imap(test@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@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