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

Tomas Dolezal tomas.dolezal at vizus.cz
Mon Aug 22 21:24:25 UTC 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 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 args=
Aug 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, alt=
Aug 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

More information about the dovecot mailing list