Hello,
I run a two-node replicated setup with director + dovecot and replication between the two nodes. The setup is a couple of years old and has been working properly until recently, so I suspect some type of regression.
I'm having an issue with replication and merging of newly created mailboxes. Old mailboxes work properly.
When creating a new mailbox, the two nodes will not replicate and sync the new mailbox. I have to manually "merge" the mailbox via a "doveadm sync -1f..." command, after which all works properly. This has not been the case in the past, so I'm trying to debug the issue.
When syncing manually, I get the following error:
# doveadm -v sync -df -u 'testaccount@mydomain.ext' doveadm(testaccount@mydomain.ext)<38041><wl3tAQ5LTWKZlAAAxdOQ8Q>: Warning: Mailbox changes caused a desync. You may want to run dsync again: Remote lost mailbox GUID 6bfcbb2f92484d624b890000c5d390f1 (maybe it was just deleted?)
I have to sync once with a one-way merge using sync -1f and after the sync works properly.
My setup is running Dovecot CE 2:2.3.18-4+debian11 from the dovecot.org repository installed on debian bullseye. The replicaiton is dove via TCP plaintext connection.
Below I'm attaching some debug logs, for both sync -1f and sync -f.
Is this a normal behavior or is this a bug ?
Kind regards, Dave
---- CUT ---- # doveadm -v sync -df -u 'testaccount@mydomain.ext'
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm 2022-04-06 10:12:17 Debug: Loading modules from directory: /usr/lib/dovecot/modules 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/lib02_lazy_expunge_plugin.so 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2022-04-06 10:12:17 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so 2022-04-06 10:12:17 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): Started passdb lookup 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb: Connecting 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (pid=181,uid=0): Client connected (fd=9) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): auth PASS input: user=testaccount@mydomain.ext 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): Finished passdb lookup (user=testaccount@mydomain.ext ) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): Started userdb lookup 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): auth USER input: testaccount@mydomain.ext home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): Finished userdb lookup (username=testaccount@mydomain.ext home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: Added userdb setting: mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><>: Debug: Added userdb setting: plugin/sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: No acl_shared_dict setting - shared mailbox listing is disabled 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota root: name=user backend=dict args=:file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=EXPUNGED ignored 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota grace: root=user bytes=0 (10%) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: quota-dict: user=testaccount@mydomain.ext, uri=file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage, noenforcing=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): dict created (uri=file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage, base_dir=/var/run/dovecot) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: maildir++: root=/var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir, index=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/idx, indexpvt=, control=, inbox=/var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir, alt= 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: initializing backend with data: vfile:/etc/dovecot/dovecot.acl 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: acl username = testaccount@mydomain.ext 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: owner = 1 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl vfile: Global ACL file: /etc/dovecot/dovecot.acl 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: brain M: Namespace has location maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/dovecot-acl http://mydomain.ext/testaccount/Maildir/dovecot-acl not found 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox '' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl not found 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl not found 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl not found 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl not found 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext): Debug: Namespace : Using permissions from /var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir: mode=0700 gid=default 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Local mailbox tree: INBOX guid=08b6a62792484d624b890000c5d390f1 uid_validity=1649232018 uid_next=2 subs=no last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Drafts guid=6bfcbb2f92484d624b890000c5d390f1 uid_validity=1649232022 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Junk guid=6afcbb2f92484d624b890000c5d390f1 uid_validity=1649232021 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Sent guid=69fcbb2f92484d624b890000c5d390f1 uid_validity=1649232020 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Trash guid=68fcbb2f92484d624b890000c5d390f1 uid_validity=1649232019 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: INBOX guid=4d70ba2389484d628fa91300660b22f9 uid_validity=1649232013 uid_next=1 subs=no last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Junk guid=4c70ba2389484d628fa91300660b22f9 uid_validity=1649232012 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Drafts guid=4b70ba2389484d628fa91300660b22f9 uid_validity=1649232011 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Sent guid=4a70ba2389484d628fa91300660b22f9 uid_validity=1649232010 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Trash guid=4970ba2389484d628fa91300660b22f9 uid_validity=1649232009 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox Drafts: local=6bfcbb2f92484d624b890000c5d390f1/0/1, remote=4b70ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox INBOX: local=08b6a62792484d624b890000c5d390f1/0/1, remote=4d70ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox Junk: local=6afcbb2f92484d624b890000c5d390f1/0/1, remote=4c70ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox Sent: local=69fcbb2f92484d624b890000c5d390f1/0/1, remote=4a70ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox Trash: local=68fcbb2f92484d624b890000c5d390f1/0/1, remote=4970ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Rotated transaction log /var/vmail-local/mydomain.ext/testaccount/idx/.Drafts/dovecot.index.log http://mydomain.ext/testaccount/idx/.Drafts/dovecot.index.log (seq=11, reset=yes) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Rotated transaction log /var/vmail-local/mydomain.ext/testaccount/idx/.INBOX/dovecot.index.log http://mydomain.ext/testaccount/idx/.INBOX/dovecot.index.log (seq=11, reset=yes) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Rotated transaction log /var/vmail-local/mydomain.ext/testaccount/idx/.Junk/dovecot.index.log http://mydomain.ext/testaccount/idx/.Junk/dovecot.index.log (seq=11, reset=yes) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Rotated transaction log /var/vmail-local/mydomain.ext/testaccount/idx/.Sent/dovecot.index.log http://mydomain.ext/testaccount/idx/.Sent/dovecot.index.log (seq=11, reset=yes) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Rotated transaction log /var/vmail-local/mydomain.ext/testaccount/idx/.Trash/dovecot.index.log http://mydomain.ext/testaccount/idx/.Trash/dovecot.index.log (seq=11, reset=yes) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Change during sync: Remote lost mailbox GUID 4b70ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Change during sync: Remote lost mailbox GUID 4d70ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Change during sync: Remote lost mailbox GUID 4c70ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Change during sync: Remote lost mailbox GUID 4a70ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Change during sync: Remote lost mailbox GUID 4970ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Warning: Mailbox changes caused a desync. You may want to run dsync again: Remote lost mailbox GUID 4b70ba2389484d628fa91300660b22f9 (maybe it was just deleted?) 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount@mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): dict destroyed 2022-04-06 10:12:17 doveadm(38324): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (pid=181,uid=0): Disconnected: Connection closed (fd=9) ------------------------- CUT -------------------------------------
Here's the sync with merge: ------------------- CUT ---------------------------------- # doveadm -v sync -1df -u 'testaccount@mydomain.ext' Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm 2022-04-06 10:13:25 Debug: Loading modules from directory: /usr/lib/dovecot/modules 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/lib01_acl_plugin.so 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/lib02_lazy_expunge_plugin.so 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so 2022-04-06 10:13:25 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so 2022-04-06 10:13:25 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): Started passdb lookup 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb: Connecting 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (pid=181,uid=0): Client connected (fd=9) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): auth PASS input: user=testaccount@mydomain.ext 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: auth-master: passdb lookup(testaccount@mydomain.ext): Finished passdb lookup (user=testaccount@mydomain.ext ) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): Started userdb lookup 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): auth USER input: testaccount@mydomain.ext home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount@mydomain.ext): Finished userdb lookup (username=testaccount@mydomain.ext home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: Added userdb setting: mail=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><>: Debug: Added userdb setting: plugin/sieve=/var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: No acl_shared_dict setting - shared mailbox listing is disabled 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota root: name=user backend=dict args=:file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=EXPUNGED ignored 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota grace: root=user bytes=0 (10%) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: quota-dict: user=testaccount@mydomain.ext, uri=file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage, noenforcing=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): dict created (uri=file:/var/vmail/mydomain.ext/testaccount/.quotausage http://mydomain.ext/testaccount/.quotausage, base_dir=/var/run/dovecot) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: maildir++: root=/var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir, index=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/idx, indexpvt=, control=, inbox=/var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir, alt= 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: initializing backend with data: vfile:/etc/dovecot/dovecot.acl 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: acl username = testaccount@mydomain.ext 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: owner = 1 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: Global ACL file: /etc/dovecot/dovecot.acl 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: brain M: Namespace has location maildir:/var/vmail/mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/testaccount/idx http://mydomain.ext/testaccount/Maildir:INDEX=/var/vmail-local/mydomain.ext/... 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/dovecot-acl http://mydomain.ext/testaccount/Maildir/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox '' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext): Debug: Namespace : Using permissions from /var/vmail/mydomain.ext/testaccount/Maildir http://mydomain.ext/testaccount/Maildir: mode=0700 gid=default 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Local mailbox tree: INBOX guid=4d70ba2389484d628fa91300660b22f9 uid_validity=1649232013 uid_next=2 subs=no last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Drafts guid=4b70ba2389484d628fa91300660b22f9 uid_validity=1649232011 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Junk guid=4c70ba2389484d628fa91300660b22f9 uid_validity=1649232012 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Sent guid=4a70ba2389484d628fa91300660b22f9 uid_validity=1649232010 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Local mailbox tree: Trash guid=4970ba2389484d628fa91300660b22f9 uid_validity=1649232009 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: INBOX guid=08b6a62792484d624b890000c5d390f1 uid_validity=1649232018 uid_next=1 subs=no last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Junk guid=6afcbb2f92484d624b890000c5d390f1 uid_validity=1649232021 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Drafts guid=6bfcbb2f92484d624b890000c5d390f1 uid_validity=1649232022 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Sent guid=69fcbb2f92484d624b890000c5d390f1 uid_validity=1649232020 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Remote mailbox tree: Trash guid=68fcbb2f92484d624b890000c5d390f1 uid_validity=1649232019 uid_next=1 subs=yes last_change=0 last_subs=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Mailbox Drafts: local=4b70ba2389484d628fa91300660b22f9/0/1, remote=6bfcbb2f92484d624b890000c5d390f1/0/1: GUIDs conflict - will be merged later 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Mailbox INBOX: local=4d70ba2389484d628fa91300660b22f9/0/1, remote=08b6a62792484d624b890000c5d390f1/0/1: GUIDs conflict - will be merged later 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Mailbox Junk: local=4c70ba2389484d628fa91300660b22f9/0/1, remote=6afcbb2f92484d624b890000c5d390f1/0/1: GUIDs conflict - will be merged later 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Mailbox Sent: local=4a70ba2389484d628fa91300660b22f9/0/1, remote=69fcbb2f92484d624b890000c5d390f1/0/1: GUIDs conflict - will be merged later 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: brain M: Mailbox Trash: local=4970ba2389484d628fa91300660b22f9/0/1, remote=68fcbb2f92484d624b890000c5d390f1/0/1: GUIDs conflict - will be merged later 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Drafts/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: Pigeonhole version 0.5.18 (0bc28b32) initializing 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts. 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Performing auto-detection 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Use home (/var/vmail/mydomain.ext/testaccount http://mydomain.ext/testaccount) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Using active Sieve script path: /var/vmail/mydomain.ext/testaccount/.sieve http://mydomain.ext/testaccount/.sieve 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Using script storage path: /var/vmail/mydomain.ext/testaccount/sieve http://mydomain.ext/testaccount/sieve 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Using permissions from /var/vmail/mydomain.ext/testaccount/sieve http://mydomain.ext/testaccount/sieve: mode=0700 gid=-1 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Created storage directory /var/vmail/mydomain.ext/testaccount/sieve/tmp http://mydomain.ext/testaccount/sieve/tmp 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/ 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: sync: Synchronization active 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/dovecot-acl http://mydomain.ext/testaccount/Maildir/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Adding field date.received to cache for the first time (uid=1) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Adding field date.save to cache for the first time (uid=1) 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Purging (new file_seq=1649232805): creating cache 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Purging finished, file_seq changed 1649232018 -> 1649232805, size=676 -> 172, max_uid=0 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Junk/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Sent/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: file /var/vmail/mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl http://mydomain.ext/testaccount/Maildir/.Trash/dovecot-acl not found 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount@mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): dict destroyed 2022-04-06 10:13:25 doveadm(38465): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (pid=181,uid=0): Disconnected: Connection closed (fd=9) ------------------------ CUT --------------------------------------