Dovecot sync problem in multiserver configuration after upgrading to Debian 12

Hi,
after upgrading to Debian 12 and ISPConfig 3.2.11 in the multiserver configuration when I open a new email inbox it is not synchronized with Dovecot sync between the two servers, while all the others already present synchronize in real time perfectly.

I tried and tried, even sending separate emails to the two servers, but when I open a new email account, these remain only on the server that received them and are not replicated on the other.

Any ideas on how I can resolve this?

Thanks a lot

 

First off check the output of the "doveadm replicator status" command.
Th0m has a guide for the debugging here:
https://forum.howtoforge.com/threads/dsync-faq.86543/

Make sure to check the logs on both servers first and may consider triggering a manual sync and see what happens

 

Thank you pyte.

At that time,

Code:

doveadm replicator status

is the command that tells me that there are "Waiting 'failed' requests" email boxes and by applying the '*' parameter i.e.

Code:

doveadm replicator status '*'

I see that the unsynchronized email boxes correspond to the latest ones created (while those created before the update to Debian 12 and ISPConfig 3.2.11 work normally).

If I try to manually activate the synchronization of the last test email inbox I created I get this output:

Code:

# doveadm -D sync -u [email protected]
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually intentional, so just ignore this message)
Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_sieve_plugin.so
Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-16 17:06:56 Debug: Loading modules from directory: /usr/lib/dovecot/modules
2023-09-16 17:06:56 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
2023-09-16 17:06:56 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
2023-09-16 17:06:56 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
2023-09-16 17:06:56 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
2023-09-16 17:06:56 Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
2023-09-16 17:06:56 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so
2023-09-16 17:06:56 Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
2023-09-16 17:06:56 Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
2023-09-16 17:06:56 Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
doveadm sync [-1fPRU] [-l <secs>] [-r <rawlog path>] [-m <mailbox>] [-g <mailbox guid>] [-n <namespace> | -N] [-x <exclude>] [-a <all mailbox>] [-s <state>] [-T <secs>] [-t <start date>] [-e <end date>] [-O <sync flag>] [-I <max size>] -d|<dest>

I don't understand much, do you have any ideas?

Thanks a lot

 

I guess you forgot the "-d" at the end which is why the command only show some debug output and the usage line.

 

Oooops sorry, here's the full output:

Code:

# doveadm -D sync -u [email protected] -d
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually intentional, so just ignore this message)
Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_sieve_plugin.so
Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-16 21:56:11 Debug: Loading modules from directory: /usr/lib/dovecot/modules
2023-09-16 21:56:11 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
2023-09-16 21:56:11 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
2023-09-16 21:56:11 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
2023-09-16 21:56:11 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
2023-09-16 21:56:11 Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
2023-09-16 21:56:11 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so
2023-09-16 21:56:11 Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
2023-09-16 21:56:11 Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
2023-09-16 21:56:11 Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: auth-master: userdb lookup([email protected]): Started userdb lookup
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb: Connecting
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=892,uid=0): Client connected (fd=9)
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: auth-master: userdb lookup([email protected]): auth USER input: [email protected] home=/var/vmail/webek.it/xyz mail=maildir:/var/vmail/webek.it/xyz/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/webek.it/xyz/.sieve
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: auth-master: userdb lookup([email protected]): Finished userdb lookup ([email protected] home=/var/vmail/webek.it/xyz mail=maildir:/var/vmail/webek.it/xyz/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/webek.it/xyz/.sieve)
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: Added userdb setting: mail=maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B
2023-09-16 21:56:11 doveadm([email protected])<201239><>: Debug: Added userdb setting: plugin/sieve=/var/vmail/webek.it/xyz/.sieve
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/webek.it/xyz
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Quota root: name=user backend=dict args=:file:/var/vmail/webek.it/xyz/.quotausage
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Quota grace: root=user bytes=0 (10%)
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: quota-dict: [email protected], uri=file:/var/vmail/webek.it/xyz/.quotausage, noenforcing=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): dict created (uri=file:/var/vmail/webek.it/xyz/.quotausage, base_dir=/run/dovecot)
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: open(/proc/self/io) failed: Permission denied
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: maildir++: root=/var/vmail/webek.it/xyz/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/webek.it/xyz/Maildir, alt=
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
2023-09-16 21:56:11 doveadm([email protected]): Debug: brain M: Namespace  has location maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-16 21:56:11 doveadm([email protected]): Debug: Mailbox INBOX: Mailbox opened
2023-09-16 21:56:11 doveadm([email protected]): Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:11 doveadm([email protected]): Debug: Namespace : Using permissions from /var/vmail/webek.it/xyz/Maildir: mode=0700 gid=default
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Local mailbox tree: Junk guid=10b79322d326fe64e4840100ae757343 uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Local mailbox tree: Trash guid=129cff30d226fe6459200000274c230b uid_validity=1694377684 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Local mailbox tree: Drafts guid=12b79322d326fe64e4840100ae757343 uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Local mailbox tree: Sent guid=13b79322d326fe64e4840100ae757343 uid_validity=1694377686 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Local mailbox tree: INBOX guid=109cff30d226fe6459200000274c230b uid_validity=1694377682 uid_next=2 subs=no last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Remote mailbox tree: Drafts guid=119cff30d226fe6459200000274c230b uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Remote mailbox tree: Trash guid=11b79322d326fe64e4840100ae757343 uid_validity=1694377684 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Remote mailbox tree: Junk guid=10b79322d326fe64e4840100ae757343 uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Remote mailbox tree: Sent guid=13b79322d326fe64e4840100ae757343 uid_validity=1694377686 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Remote mailbox tree: INBOX guid=109cff30d226fe6459200000274c230b uid_validity=1694377682 uid_next=2 subs=no last_change=0 last_subs=0
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Mailbox Drafts: local=12b79322d326fe64e4840100ae757343/0/1, remote=119cff30d226fe6459200000274c230b/0/1: GUIDs conflict - will be merged later
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Mailbox INBOX: local=109cff30d226fe6459200000274c230b/0/1, remote=109cff30d226fe6459200000274c230b/0/1: Mailboxes are equal
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Mailbox Junk: local=10b79322d326fe64e4840100ae757343/0/1, remote=10b79322d326fe64e4840100ae757343/0/1: Mailboxes are equal
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Mailbox Sent: local=13b79322d326fe64e4840100ae757343/0/1, remote=13b79322d326fe64e4840100ae757343/0/1: Mailboxes are equal
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: brain M: Mailbox Trash: local=129cff30d226fe6459200000274c230b/0/1, remote=11b79322d326fe64e4840100ae757343/0/1: GUIDs conflict - will be merged later
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Mailbox Trash: Mailbox opened
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Mailbox Trash: Mailbox opened
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:11 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-16 21:56:41 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Error: Failed to lock mailbox Drafts for dsyncing: file_create_locked(/var/vmail/webek.it/xyz/Maildir/.Drafts/.dovecot-box-sync.lock) failed: fcntl(/var/vmail/webek.it/xyz/Maildir/.Drafts/.dovecot-box-sync.lock, write-lock, F_SETLKW) locking failed: Timed out after 30 seconds (WRITE lock held by pid 200514)
2023-09-16 21:56:41 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:41 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: User session is finished
2023-09-16 21:56:41 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-16 21:56:41 doveadm([email protected])<201239><Qc17IFsIBmUXEgMArnVzQw>: Debug: dict(file): dict destroyed
2023-09-16 21:56:41 doveadm(201239): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=892,uid=0): Disconnected: Connection closed (fd=9)

Thanks a lot

 

Reading the full output, it has line

So find out what process is pid 200514

Code:

ps -ef | grep 200514

then figure out what that process is doing with files in Maildir/.Drafts.

 

Thanks Taleman.

Well, since some time has passed, that process no longer exists and today's output does not report any errors, but the synchronization of the new boxes still doesn't work:

Code:

# doveadm -D sync -u [email protected] -d
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually intentional, so just ignore this message)
Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_sieve_plugin.so
Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-18 12:35:34 Debug: Loading modules from directory: /usr/lib/dovecot/modules
2023-09-18 12:35:34 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
2023-09-18 12:35:34 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
2023-09-18 12:35:34 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
2023-09-18 12:35:34 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
2023-09-18 12:35:34 Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
2023-09-18 12:35:34 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so
2023-09-18 12:35:34 Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
2023-09-18 12:35:34 Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
2023-09-18 12:35:34 Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: auth-master: userdb lookup([email protected]): Started userdb lookup
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb: Connecting
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=96082,uid=0): Client connected (fd=9)
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: auth-master: userdb lookup([email protected]): auth USER input: [email protected] home=/var/vmail/webek.it/xyz mail=maildir:/var/vmail/webek.it/xyz/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/webek.it/xyz/.sieve
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: auth-master: userdb lookup([email protected]): Finished userdb lookup ([email protected] home=/var/vmail/webek.it/xyz mail=maildir:/var/vmail/webek.it/xyz/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/webek.it/xyz/.sieve)
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: Added userdb setting: mail=maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B
2023-09-18 12:35:34 doveadm([email protected])<380895><>: Debug: Added userdb setting: plugin/sieve=/var/vmail/webek.it/xyz/.sieve
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/webek.it/xyz
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Quota root: name=user backend=dict args=:file:/var/vmail/webek.it/xyz/.quotausage
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Quota grace: root=user bytes=0 (10%)
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: quota-dict: [email protected], uri=file:/var/vmail/webek.it/xyz/.quotausage, noenforcing=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): dict created (uri=file:/var/vmail/webek.it/xyz/.quotausage, base_dir=/run/dovecot)
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: open(/proc/self/io) failed: Permission denied
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: maildir++: root=/var/vmail/webek.it/xyz/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/webek.it/xyz/Maildir, alt=
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
2023-09-18 12:35:34 doveadm([email protected]): Debug: brain M: Namespace  has location maildir:/var/vmail/webek.it/xyz/Maildir
2023-09-18 12:35:34 doveadm([email protected]): Debug: Mailbox INBOX: Mailbox opened
2023-09-18 12:35:34 doveadm([email protected]): Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:34 doveadm([email protected]): Debug: Namespace : Using permissions from /var/vmail/webek.it/xyz/Maildir: mode=0700 gid=default
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Local mailbox tree: Junk guid=10b79322d326fe64e4840100ae757343 uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Local mailbox tree: Trash guid=11b79322d326fe64e4840100ae757343 uid_validity=1694377684 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Local mailbox tree: Drafts guid=119cff30d226fe6459200000274c230b uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Local mailbox tree: Sent guid=149cff30d226fe6459200000274c230b uid_validity=1694377686 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Local mailbox tree: INBOX guid=109cff30d226fe6459200000274c230b uid_validity=1694377682 uid_next=4 subs=no last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Remote mailbox tree: Drafts guid=119cff30d226fe6459200000274c230b uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Remote mailbox tree: Trash guid=129cff30d226fe6459200000274c230b uid_validity=1694377684 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Remote mailbox tree: Junk guid=10b79322d326fe64e4840100ae757343 uid_validity=1694377685 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Remote mailbox tree: Sent guid=13b79322d326fe64e4840100ae757343 uid_validity=1694377686 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Remote mailbox tree: INBOX guid=109cff30d226fe6459200000274c230b uid_validity=1694377682 uid_next=4 subs=no last_change=0 last_subs=0
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Mailbox Drafts: local=119cff30d226fe6459200000274c230b/0/1, remote=119cff30d226fe6459200000274c230b/0/1: Mailboxes are equal
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Mailbox INBOX: local=109cff30d226fe6459200000274c230b/0/1, remote=109cff30d226fe6459200000274c230b/0/1: Mailboxes are equal
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Mailbox Junk: local=10b79322d326fe64e4840100ae757343/0/1, remote=10b79322d326fe64e4840100ae757343/0/1: Mailboxes are equal
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Mailbox Sent: local=149cff30d226fe6459200000274c230b/0/1, remote=13b79322d326fe64e4840100ae757343/0/1: GUIDs conflict - will be merged later
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Mailbox Trash: local=11b79322d326fe64e4840100ae757343/0/1, remote=129cff30d226fe6459200000274c230b/0/1: GUIDs conflict - will be merged later
2023-09-18 12:35:34 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Sent: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Sent: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Trash: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Trash: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox INBOX: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Junk: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Sent: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 13b79322d326fe64e4840100ae757343 (maybe it was just deleted?)
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: Mailbox Trash: Mailbox opened
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 129cff30d226fe6459200000274c230b (maybe it was just deleted?)
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Warning: Mailbox changes caused a desync. You may want to run dsync again: Remote lost mailbox GUID 13b79322d326fe64e4840100ae757343 (maybe it was just deleted?)
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: User session is finished
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-18 12:35:35 doveadm([email protected])<380895><f1m4LPYnCGXfzwUArnVzQw>: Debug: dict(file): dict destroyed
2023-09-18 12:35:35 doveadm(380895): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=96082,uid=0): Disconnected: Connection closed (fd=9)

I can't solve the problem...

Thanks a lot

 

I opened a new test email inbox on another domain and immediately tried manual synchronization from the main server, here is the output:

Code:

# doveadm -D sync -u [email protected] -d
Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so: undefined symbol: quota_user_module (this is usually intentional, so just ignore this message)
Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_sieve_plugin.so
Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-19 13:06:49 Debug: Loading modules from directory: /usr/lib/dovecot/modules
2023-09-19 13:06:49 Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so
2023-09-19 13:06:49 Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
2023-09-19 13:06:49 Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
2023-09-19 13:06:49 Debug: Loading modules from directory: /usr/lib/dovecot/modules/doveadm
2023-09-19 13:06:49 Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_acl_plugin.so: undefined symbol: acl_user_module (this is usually intentional, so just ignore this message)
2023-09-19 13:06:49 Debug: Module loaded: /usr/lib/dovecot/modules/doveadm/lib10_doveadm_quota_plugin.so
2023-09-19 13:06:49 Debug: Skipping module doveadm_fts_lucene_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_lucene_plugin.so: undefined symbol: lucene_index_iter_deinit (this is usually intentional, so just ignore this message)
2023-09-19 13:06:49 Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/lib20_doveadm_fts_plugin.so: undefined symbol: fts_user_get_language_list (this is usually intentional, so just ignore this message)
2023-09-19 13:06:49 Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/lib/dovecot/modules/doveadm/libdoveadm_mail_crypt_plugin.so: undefined symbol: mail_crypt_box_get_pvt_digests (this is usually intentional, so just ignore this message)
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: auth-master: userdb lookup([email protected]): Started userdb lookup
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb: Connecting
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=85183,uid=0): Client connected (fd=9)
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: auth-master: userdb lookup([email protected]): auth USER input: [email protected] home=/var/vmail/conprof.it/prova mail=maildir:/var/vmail/conprof.it/prova/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/conprof.it/prova/.sieve
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: auth-master: userdb lookup([email protected]): Finished userdb lookup ([email protected] home=/var/vmail/conprof.it/prova mail=maildir:/var/vmail/conprof.it/prova/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/conprof.it/prova/.sieve)
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: Added userdb setting: mail=maildir:/var/vmail/conprof.it/prova/Maildir
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B
2023-09-19 13:06:49 doveadm([email protected])<499760><>: Debug: Added userdb setting: plugin/sieve=/var/vmail/conprof.it/prova/.sieve
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Effective uid=5000, gid=5000, home=/var/vmail/conprof.it/prova
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Quota root: name=user backend=dict args=:file:/var/vmail/conprof.it/prova/.quotausage
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Quota rule: root=user mailbox=* bytes=0 messages=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Quota grace: root=user bytes=0 (10%)
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: quota-dict: [email protected], uri=file:/var/vmail/conprof.it/prova/.quotausage, noenforcing=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): dict created (uri=file:/var/vmail/conprof.it/prova/.quotausage, base_dir=/run/dovecot)
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: open(/proc/self/io) failed: Permission denied
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Namespace inbox: type=private, prefix=, sep=., inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/vmail/conprof.it/prova/Maildir
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: maildir++: root=/var/vmail/conprof.it/prova/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/conprof.it/prova/Maildir, alt=
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
2023-09-19 13:06:49 doveadm([email protected]): Debug: brain M: Namespace  has location maildir:/var/vmail/conprof.it/prova/Maildir
2023-09-19 13:06:49 doveadm([email protected]): Debug: Mailbox INBOX: Mailbox opened
2023-09-19 13:06:49 doveadm([email protected]): Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:49 doveadm([email protected]): Debug: Namespace : Using permissions from /var/vmail/conprof.it/prova/Maildir: mode=0700 gid=default
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Local mailbox tree: Drafts guid=ea88eb255f800965f7400c00ae757343 uid_validity=1695121505 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Local mailbox tree: Trash guid=e988eb255f800965f7400c00ae757343 uid_validity=1695121504 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Local mailbox tree: Junk guid=e888eb255f800965f7400c00ae757343 uid_validity=1695121503 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Local mailbox tree: Sent guid=eb88eb255f800965f7400c00ae757343 uid_validity=1695121506 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Local mailbox tree: INBOX guid=ec88eb255f800965f7400c00ae757343 uid_validity=1695121507 uid_next=2 subs=no last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Remote mailbox tree: Junk guid=93d44f0f5e800965459f0700274c230b uid_validity=1695121505 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Remote mailbox tree: Trash guid=92d44f0f5e800965459f0700274c230b uid_validity=1695121504 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Remote mailbox tree: Drafts guid=91d44f0f5e800965459f0700274c230b uid_validity=1695121503 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Remote mailbox tree: Sent guid=94d44f0f5e800965459f0700274c230b uid_validity=1695121506 uid_next=1 subs=yes last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Remote mailbox tree: INBOX guid=90d44f0f5e800965459f0700274c230b uid_validity=1695121502 uid_next=1 subs=no last_change=0 last_subs=0
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Mailbox Drafts: local=ea88eb255f800965f7400c00ae757343/0/1, remote=91d44f0f5e800965459f0700274c230b/0/1: GUIDs conflict - will be merged later
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Mailbox INBOX: local=ec88eb255f800965f7400c00ae757343/0/1, remote=90d44f0f5e800965459f0700274c230b/0/1: GUIDs conflict - will be merged later
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Mailbox Junk: local=e888eb255f800965f7400c00ae757343/0/1, remote=93d44f0f5e800965459f0700274c230b/0/1: GUIDs conflict - will be merged later
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Mailbox Sent: local=eb88eb255f800965f7400c00ae757343/0/1, remote=94d44f0f5e800965459f0700274c230b/0/1: GUIDs conflict - will be merged later
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Mailbox Trash: local=e988eb255f800965f7400c00ae757343/0/1, remote=92d44f0f5e800965459f0700274c230b/0/1: GUIDs conflict - will be merged later
2023-09-19 13:06:49 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-19 13:06:53 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Drafts: Rotated transaction log /var/vmail/conprof.it/prova/Maildir/.Drafts/dovecot.index.log (seq=4, reset=yes)
2023-09-19 13:06:53 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:53 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox INBOX: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox INBOX: Rotated transaction log /var/vmail/conprof.it/prova/Maildir/dovecot.index.log (seq=4, reset=yes)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox INBOX: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Junk: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Junk: Rotated transaction log /var/vmail/conprof.it/prova/Maildir/.Junk/dovecot.index.log (seq=4, reset=yes)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Junk: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Sent: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Sent: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Trash: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Trash: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Drafts: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 91d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox INBOX: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 90d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Junk: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 93d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Sent: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 94d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: Mailbox Trash: Mailbox opened
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: brain M: Change during sync: Remote lost mailbox GUID 92d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Warning: Mailbox changes caused a desync. You may want to run dsync again: Remote lost mailbox GUID 91d44f0f5e800965459f0700274c230b (maybe it was just deleted?)
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: User session is finished
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): Waiting for dict to finish pending operations
2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Debug: dict(file): dict destroyed
2023-09-19 13:06:54 doveadm(499760): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=85183,uid=0): Disconnected: Connection closed (fd=9)

In particular this line seems not to find the corresponding box on the other server:

Code:

2023-09-19 13:06:54 doveadm([email protected])<499760><R4wTC8mACWUwoAcAJ0wjCw>: Warning: Mailbox changes caused a desync. You may want to run dsync again: Remote lost mailbox GUID 91d44f0f5e800965459f0700274c230b (maybe it was just deleted?)

Can anyone tell me how Dovecot recognizes the coupling of a specific email account between the two servers, i.e. it does it only on the basis of the email address and its position in the folders (/var/vmail/etc/) or does it use some other parameter?

Because the test email inbox, [email protected] in this case, is present on both servers and works perfectly on each of the two in the exact same position on each one's filesystem. But it doesn't sync!

Thanks a lot

 

Thanks Thom.

ISPConfig works well and therefore replicates the exact same information on the two servers, of course the fact that it actually created it is the first thing I checked.

I'll post the configuration on the two servers so you can see for yourself.

This is the situation on the ks06 server:

Code:

root@ks06 /var/vmail/conprof.it/prova # l
totale 36
drwx------  4 vmail vmail 4096 20 set 21.56 .
drwxrwx--- 24 vmail vmail 4096 19 set 13.05 ..
-rw-r--r--  1 vmail vmail  573 19 set 13.05 .ispconfig-before.sieve
-rw-r--r--  1 vmail vmail  527 19 set 13.05 .ispconfig-before.svbin
-rw-r--r--  1 vmail vmail  363 19 set 13.05 .ispconfig.sieve
-rw-r--r--  1 vmail vmail  376 19 set 13.05 .ispconfig.svbin
drwx------  9 vmail vmail 4096 20 set 21.56 Maildir
-rw-------  1 vmail vmail   43 19 set 13.15 .quotausage
drwx------  2 vmail vmail 4096 19 set 13.05 sieve

This is the situation on the ks07 server:

Code:

root@ks07 /var/vmail/conprof.it/prova # l
totale 36
drwx------  4 vmail vmail 4096 19 set 13.05 .
drwxrwx--- 24 vmail vmail 4096 19 set 13.05 ..
-rw-r--r--  1 vmail vmail  573 19 set 13.05 .ispconfig-before.sieve
-rw-r--r--  1 vmail vmail  527 19 set 13.05 .ispconfig-before.svbin
-rw-r--r--  1 vmail vmail  363 19 set 13.05 .ispconfig.sieve
-rw-r--r--  1 vmail vmail  376 19 set 13.05 .ispconfig.svbin
drwx------  9 vmail vmail 4096 20 set 22.01 Maildir
-rw-------  1 vmail vmail   46 19 set 13.05 .quotausage
drwx------  2 vmail vmail 4096 19 set 13.05 sieve

And this is the report of doveadm replicator status '*' on ks06:

Code:

root@ks06 /var/vmail/conprof.it/prova # doveadm replicator status '*'
username                           priority fast sync full sync success sync failed
[email protected]                   none     00:03:21  09:05:00  -            y

and the same command in ks07:

Code:

root@ks07 /var/vmail/conprof.it/prova # doveadm replicator status '*'
username                           priority fast sync full sync success sync failed
[email protected]                   none     00:00:59  09:02:36  -            y

I can't understand what the problem is because all the other boxes present on the two servers, which however were already present before the update, continue to disappear...

Thanks a lot

 

Thanks Thom.
Unfortunately the /var/log/mail.err file has been empty since August 20th on both ks06 and ks07.

Before that date there were errors on August 13/14/15 because we were moving the service VMs to new servers with new IP addresses but nothing to do with the problem which had probably not yet arisen because on August 11 I opened the last new inbox for a client and it synced without any problems.

I don't have in-depth knowledge of dovecot sync, but it's as if dovecot was unable to find a sufficient correspondence between the two twin boxes on the two servers to consider them the same box and therefore synchronizable.

Based on this thought, I tried to manually copy the box between one server and another with rsync.

Here is the rsync output from ks07 which is the main server:

Code:

root@ks07 /var/vmail/conprof.it/prova # rsync -av --info=progress2 -e 'ssh -p 55555' /var/vmail/conprof.it/prova/ root@ks06://var/vmail/conprof.it/prova/
sending incremental file list
./
.ispconfig-before.sieve
            573   8%    0,00kB/s    0:00:00 (xfr#1, to-chk=47/49)
.ispconfig-before.svbin
          1.100  15%  514,65kB/s    0:00:00 (xfr#2, to-chk=46/49)
.ispconfig.sieve
          1.463  20%  434,57kB/s    0:00:00 (xfr#3, to-chk=45/49)
.ispconfig.svbin
          1.839  26%  412,11kB/s    0:00:00 (xfr#4, to-chk=44/49)
.quotausage
          1.885  26%  427,08kB/s    0:00:00 (xfr#5, to-chk=43/49)
Maildir/dovecot-uidlist
          1.984  28%  196,85kB/s    0:00:00 (xfr#6, to-chk=40/49)
Maildir/dovecot-uidvalidity
          1.992  28%   86,61kB/s    0:00:00 (xfr#7, to-chk=39/49)
Maildir/dovecot-uidvalidity.65098062
          1.992  28%   86,61kB/s    0:00:00 (xfr#8, to-chk=38/49)
Maildir/dovecot.index.cache
          2.688  38%  129,09kB/s    0:00:00 (xfr#9, to-chk=37/49)
Maildir/dovecot.index.log
          2.920  41%  143,25kB/s    0:00:00 (xfr#10, to-chk=36/49)
Maildir/dovecot.list.index
          3.632  51%  186,71kB/s    0:00:00 (xfr#11, to-chk=35/49)
Maildir/dovecot.list.index.log
          4.760  68%  255,55kB/s    0:00:00 (xfr#12, to-chk=34/49)
Maildir/maildirfolder
          4.760  68%  240,52kB/s    0:00:00 (xfr#13, to-chk=33/49)
Maildir/subscriptions
          4.783  68%  241,84kB/s    0:00:00 (xfr#14, to-chk=32/49)
Maildir/.Drafts/dovecot-uidlist
          4.834  69%  244,77kB/s    0:00:00 (xfr#15, to-chk=24/49)
Maildir/.Drafts/maildirfolder
          4.834  69%  244,77kB/s    0:00:00 (xfr#16, to-chk=22/49)
Maildir/.Drafts/cur/
Maildir/.Drafts/new/
Maildir/.Drafts/tmp/
Maildir/.Junk/dovecot-uidlist
          4.885  69%  247,70kB/s    0:00:00 (xfr#17, to-chk=18/49)
Maildir/.Junk/cur/
Maildir/.Junk/new/
Maildir/.Junk/tmp/
Maildir/.Sent/dovecot-uidlist
          4.936  70%  250,63kB/s    0:00:00 (xfr#18, to-chk=12/49)
Maildir/.Sent/dovecot.index.log
          5.168  73%  263,96kB/s    0:00:00 (xfr#19, to-chk=11/49)
Maildir/.Sent/cur/
Maildir/.Sent/new/
Maildir/.Sent/tmp/
Maildir/.Trash/dovecot-uidlist
          5.219  74%  266,89kB/s    0:00:00 (xfr#20, to-chk=6/49)
Maildir/.Trash/dovecot.index.log
          5.451  77%  280,22kB/s    0:00:00 (xfr#21, to-chk=5/49)
Maildir/.Trash/cur/
Maildir/.Trash/new/
Maildir/.Trash/tmp/
Maildir/cur/
Maildir/new/1695121502.M256891P499525.ks07,S=1209,W=1237
          6.660  95%  258,45kB/s    0:00:00 (xfr#22, to-chk=0/49)
sieve/
          6.660  95%  112,16kB/s    0:00:00 (xfr#22, to-chk=0/49)

sent 7.275 bytes  received 616 bytes  5.260,67 bytes/sec
total size is 6.996  speedup is 0,89

And here is the rsync output from ks06:

Code:

root@ks06 /var/vmail/conprof.it/prova # rsync -av --info=progress2 -e 'ssh -p 55555' /var/vmail/conprof.it/prova/ root@ks07://var/vmail/conprof.it/prova/
sending incremental file list
              0   0%    0,00kB/s    0:00:00 (xfr#0, to-chk=43/51)
Maildir/dovecot-uidvalidity.65098063
              0   0%    0,00kB/s    0:00:00 (xfr#1, to-chk=39/51)
Maildir/dovecot.list.index.log.2
          8.232  53%    0,00kB/s    0:00:00 (xfr#2, to-chk=34/51)
Maildir/.Drafts/dovecot-uidlist
          8.283  53%   49,80kB/s    0:00:00 (xfr#3, to-chk=24/51)
Maildir/.Drafts/dovecot.index.log
          8.539  55%  299,80kB/s    0:00:00 (xfr#4, to-chk=23/51)
Maildir/.Junk/dovecot-uidlist
          8.590  55%  349,61kB/s    0:00:00 (xfr#5, to-chk=18/51)
Maildir/.Junk/dovecot.index.log
          8.846  57%   17,64kB/s    0:00:00 (xfr#6, to-chk=0/51)

sent 10.596 bytes  received 175 bytes  7.180,67 bytes/sec
total size is 15.404  speedup is 1,43

After I also made the second copy (only with the first it didn't work) the automatic synchronization with Dovecot magically worked.

Now, manually synchronizing every new email inbox opened with rsync is a chore so I have to find what's blocking it and solve the problem.

Can you by chance guess, based on the rsync outputs from the two servers, what Dovecot sync was missing to start the synchronization?

Thanks a lot

 

Update: My previous guess was wrong.

I opened new email boxes and ran rsync on each of the two servers to make the new boxes identical and I noticed that where " doveadm replicator status '*' " continued to give the synchronization "failed" but in reality the synchronization of the Inbox folder, checking in the Roundcube of each of the servers, it happened regularly.
However, if I moved a message to Trash on one of the servers, on the other it disappeared from Inbox but did not appear in Trash.
So I tried to open an inbox manually from Roundcube and it opened automatically on the other server and then by moving a message from Inbox to this new folder the synchronization was perfect.

At this point I opened a new test email inbox and, without copying anything with rsync from either server, I simply deleted all the folders automatically created by ISPConfig from the Rouncube of each of the two servers and then recreated them only on one server and the synchronization of that email box started perfectly: even where " doveadm replicator status '*' " gave it ok.

In summary: the problem is certainly in the folders created automatically when opening a new email account because Dovecot sync cannot manage them on both servers.

Now, however, the permissions and owners (vmail:vmail) of automatically created folders are identical to those of a manually created folder as you can see below.

Automatically created Trash folder permissions:

Code:

root@ks07 /var/vmail/conprof.it/prova5/Maildir/.Trash # l
totale 32
drwx------  5 vmail vmail 4096 23 set 20.52 .
drwx------ 10 vmail vmail 4096 23 set 20.55 ..
drwx------  2 vmail vmail 4096 23 set 20.51 cur
-rw-------  1 vmail vmail  320 23 set 20.51 dovecot.index.cache
-rw-------  1 vmail vmail 1616 23 set 20.51 dovecot.index.log
-rw-------  1 vmail vmail   51 23 set 20.52 dovecot-uidlist
-rw-------  1 vmail vmail    0 23 set 20.49 maildirfolder
drwx------  2 vmail vmail 4096 23 set 20.49 new
drwx------  2 vmail vmail 4096 23 set 20.50 tmp

Hand-created prova folder permissions:

Code:

root@ks07 /var/vmail/conprof.it/prova5/Maildir/.prova # l
totale 32
drwx------  5 vmail vmail 4096 23 set 20.57 .
drwx------ 10 vmail vmail 4096 23 set 20.57 ..
drwx------  2 vmail vmail 4096 23 set 20.52 cur
-rw-------  1 vmail vmail 1604 23 set 20.52 dovecot.index.cache
-rw-------  1 vmail vmail 1948 23 set 20.53 dovecot.index.log
-rw-------  1 vmail vmail  100 23 set 20.52 dovecot-uidlist
-rw-------  1 vmail vmail    0 23 set 20.51 maildirfolder
drwx------  2 vmail vmail 4096 23 set 20.51 new
drwx------  2 vmail vmail 4096 23 set 20.52 tmp

What could be the cause of the problem?

Thanks a lot

 

I bring this old thread back to light because I haven't yet found the solution to the problem of dovecot synchronization after upgra to Debian 12, but thanks to ChatBOT GPT-4, I discovered that it is generated by the difference between the guids contained in the dovecot-uidlist files on the respective servers.

Example:

Code:

ks07 INBOX guid=7495c52fdf42466671780e00ae757343
ks06 INBOX guid=183e7200df424666b1cb1200274c230b

Putting the same value present in ks07 in the ks06 dovecot-uidlist file

Code:

3 V1715880671 N7 7495c52fdf42466671780e00ae757343

that is, by aligning the two files, dovecot synchronization resumes spontaneously.

Now my question becomes more precise: why does this problem arise when I open a new email box with ISPConfig, i.e. different guid values in the respective dovecot-uidlist files?

And above all, how can I solve the problem?

Thanks a lot

 

Hi Till,
I saw the bug issue discussed on the thread but there might be a simpler solution.

It would be sufficient for ISPConfig to open the folders of a new email account only on the main server, including INBOX, leaving Dovecot with the task of replicating them.

This is because when I open new folders from Roundcube, which therefore opens them on only one server, they are easily reproduced on the other (even if the replication does not seem to work) and the emails inserted in these new folders are also reproduced without problems.

Is there a way to manually prevent ISPConfig from automatically creating new email folders on the secondary server?

Thanks a lot

 

Thanks for the reply Thom.

I was asking what were the steps to follow to get lSPConfig on the secondary server to create the new email inbox (or modify an existing one) without creating the classic Drafts, Junk, Sent and Trash folders (and also INBOX itself if possible).

If it were possible for me to manually change the behavior of ISPConfig (only on the secondary server) this would solve the problem that occurs with dovecot 2.3.19.1 in Debian 12 because in recent months to make dovecot sync replication work on the new mailboxes I simply deleted the folders on the secondary server so that they would be played by dovecot with the correct guid.

Thanks a lot