Dict Redis error: Unsupported operation (dict does not support this feature)

23 Aug 2022


      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 = 
dovecot-sysreport-mail1.default.cz-1661201665.tar.gz

Tomas Dolezal

tags

participants (1)