ppq at tuta.io
2022-Apr-06 08:35 UTC
Problem with initial sync on new mailbox in a replicated setup
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 at mydomain.ext' doveadm(testaccount at 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 at 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 at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): Started passdb lookup 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb: Connecting 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): auth PASS input: user=testaccount at mydomain.ext 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): Finished passdb lookup (user=testaccount at mydomain.ext ) 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): Started userdb lookup 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): auth USER input: testaccount at 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/testaccount/idx> 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 at mydomain.ext)<38324><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): Finished userdb lookup (username=testaccount at 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/testaccount/idx> 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 at 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/testaccount/idx> 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B 2022-04-06 10:12:17 doveadm(testaccount at 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 at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: No acl_shared_dict setting - shared mailbox listing is disabled 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=EXPUNGED ignored 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Quota grace: root=user bytes=0 (10%) 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: quota-dict: user=testaccount at 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 at 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 at 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/testaccount/idx> 2022-04-06 10:12:17 doveadm(testaccount at 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>, alt2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: initializing backend with data: vfile:/etc/dovecot/dovecot.acl 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: acl username = testaccount at mydomain.ext 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl: owner = 1 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: acl vfile: Global ACL file: /etc/dovecot/dovecot.acl 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2022-04-06 10:12:17 doveadm(testaccount at 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/testaccount/idx> 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox '' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:12:17 doveadm(testaccount at 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 at 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 at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): Started passdb lookup 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb: Connecting 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): auth PASS input: user=testaccount at mydomain.ext 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: auth-master: passdb lookup(testaccount at mydomain.ext): Finished passdb lookup (user=testaccount at mydomain.ext ) 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): Started userdb lookup 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): auth USER input: testaccount at 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/testaccount/idx> 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 at mydomain.ext)<38465><>: Debug: auth-master: userdb lookup(testaccount at mydomain.ext): Finished userdb lookup (username=testaccount at 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/testaccount/idx> 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 at 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/testaccount/idx> 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B 2022-04-06 10:13:25 doveadm(testaccount at 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 at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: No acl_shared_dict setting - shared mailbox listing is disabled 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota rule: root=user mailbox=EXPUNGED ignored 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Quota grace: root=user bytes=0 (10%) 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: quota-dict: user=testaccount at 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 at 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 at 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/testaccount/idx> 2022-04-06 10:13:25 doveadm(testaccount at 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>, alt2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: initializing backend with data: vfile:/etc/dovecot/dovecot.acl 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: acl username = testaccount at mydomain.ext 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl: owner = 1 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: acl vfile: Global ACL file: /etc/dovecot/dovecot.acl 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping 2022-04-06 10:13:25 doveadm(testaccount at 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/testaccount/idx> 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox '' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext): Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext): Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Drafts: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Drafts' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: Pigeonhole version 0.5.18 (0bc28b32) initializing 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: Performing auto-detection 2022-04-06 10:13:25 doveadm(testaccount at 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 at 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 at 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 at 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 at 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 at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: sieve: file storage: sync: Synchronization active 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'INBOX' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: UID 1: Opened mail because: prefetch 2022-04-06 10:13:25 doveadm(testaccount at 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 at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox INBOX: Purging (new file_seq=1649232805): creating cache 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Junk: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Junk' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Sent: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Sent' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox Trash: Mailbox opened 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: Mailbox 'Trash' matches global ACL pattern '*' 2022-04-06 10:13:25 doveadm(testaccount at 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 at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at mydomain.ext)<38465><+7naC6VLTWJBlgAAxdOQ8Q>: Debug: dict(file): Waiting for dict to finish pending operations 2022-04-06 10:13:25 doveadm(testaccount at 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 --------------------------------------
Christian Mack
2022-Apr-07 13:49 UTC
Problem with initial sync on new mailbox in a replicated setup
Hello Am 06.04.22 um 10:35 schrieb ppq at tuta.io:> 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 at mydomain.ext' > doveadm(testaccount at 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 >[...]> 2022-04-06 10:12:17 doveadm(testaccount at 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 at 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 at 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 at 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 at mydomain.ext)<38324><WJH0HGFLTWK0lQAAxdOQ8Q>: Debug: brain M: Mailbox Trash: local=68fcbb2f92484d624b890000c5d390f1/0/1, remote=4970ba2389484d628fa91300660b22f9/0/1: GUIDs conflict - will be merged later[-cut-] Problem is, that those folders are already created on the target system by other means than replication. Therefore they exist already, but with different GUIDs. With that the replication can not create those folders on the target side and refuses to sync mails into the existing ones. That is, till you explicitly want to merge. You have to stop automatic creation on the target machine, before doing initial sync. Kind regards, Christian Mack -- Christian Mack Universit?t Konstanz Kommunikations-, Informations-, Medienzentrum (KIM) Abteilung IT-Dienste Forschung und Lehre 78457 Konstanz +49 7531 88-4416 -------------- next part -------------- A non-text attachment was scrubbed... Name: smime.p7s Type: application/pkcs7-signature Size: 5351 bytes Desc: S/MIME Cryptographic Signature URL: <https://dovecot.org/pipermail/dovecot/attachments/20220407/33455dfd/attachment.bin>