thr3ads.net - dovecot - Dict Redis error: Unsupported operation (dict does not support this feature) [Aug 2022]

If this information is useful, please help other people find it:
Share via:
Tomas Dolezal
2022-Aug-22 21:24 UTC
Dict Redis error: Unsupported operation (dict does not support this feature)

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

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