Greetings,
Seems that I had catched a proof that it is defently bug in dsync.
On Thu, 18 Apr 2024 16:59:23 +0200, Kirill A. Korinsky wrote:
Anyway, I'll be back.
As usual after I sent an update here, the issue is comeback.
mx1# doveadm fetch "uid guid" -u kirill@korins.ky mailbox virtual.All | tail -n 30
uid: 147696 guid: 1713451338.M678759P24080.mx2.catap.net,S=5182,W=5299
uid: 147699 guid: 1713452322.M905815P78454.mx2.catap.net,S=6036,W=6143
uid: 147700 guid: 1713452365.M594673P95241.mx1.catap.net,S=3958,W=4066
uid: 147701 guid: 1713452405.M535379P78454.mx2.catap.net,S=3351,W=3431
uid: 147705 guid: 1713453074.M691924P5954.mx1.catap.net,S=6333,W=6437
uid: 147706 guid: 1713453359.M591908P38204.mx1.catap.net,S=54792,W=56096
uid: 147707 guid: 1713453469.M178617P70020.mx2.catap.net,S=2406,W=2453
uid: 147708 guid: 1713452587.M931589P64530.mx1.catap.net,S=5044,W=5161
uid: 147709 guid: 1713453576.M23051P30161.mx1.catap.net,S=2044,W=2090
uid: 147710 guid: 1713452952.M729802P32094.mx1.catap.net,S=4873,W=5017 mx1#
vs
mx2# doveadm fetch "uid guid" -u kirill@korins.ky mailbox virtual.All | tail -n 30
uid: 147696 guid: 1713451338.M678759P24080.mx2.catap.net,S=5182,W=5299
uid: 147699 guid: 1713452365.M594673P95241.mx1.catap.net,S=3958,W=4066
uid: 147701 guid: 1713452322.M905815P78454.mx2.catap.net,S=6036,W=6143
uid: 147702 guid: 1713452405.M535379P78454.mx2.catap.net,S=3351,W=3431
uid: 147707 guid: 1713452587.M931589P64530.mx1.catap.net,S=5044,W=5161
uid: 147708 guid: 1713452952.M729802P32094.mx1.catap.net,S=4873,W=5017
uid: 147709 guid: 1713453074.M691924P5954.mx1.catap.net,S=6333,W=6437
uid: 147710 guid: 1713453359.M591908P38204.mx1.catap.net,S=54792,W=56096
uid: 147711 guid: 1713453469.M178617P70020.mx2.catap.net,S=2406,W=2453
uid: 147712 guid: 1713453576.M23051P30161.mx1.catap.net,S=2044,W=2090 mx2#
as you may notice differences at begining of output:
mx1: uid: 147696 guid: 1713451338.M678759P24080.mx2.catap.net,S=5182,W=5299
uid: 147699 guid: 1713452322.M905815P78454.mx2.catap.net,S=6036,W=6143
uid: 147700 guid: 1713452365.M594673P95241.mx1.catap.net,S=3958,W=4066
mx2: uid: 147696 guid: 1713451338.M678759P24080.mx2.catap.net,S=5182,W=5299
uid: 147699 guid: 1713452365.M594673P95241.mx1.catap.net,S=3958,W=4066
uid: 147701 guid: 1713452322.M905815P78454.mx2.catap.net,S=6036,W=6143
and here the collistion in email with id 147699 which is different on different servers.
Funny things that 1713452365.M594673P95241.mx1.catap.net,S=3958,W=4066 is my email to the mail list.
Let see the logs for 16:58 and 16:59 on both servers.
mx1:
Apr 18 16:58:36 mx1 dovecot: imap-login: Login: user=<k@catap.net>, method=PLAIN, rip=90.187.54.213, lip=162.55.82.72, mpid=33482, TLS, session=<THygNGAWw+pauzbV> Apr 18 16:58:42 mx1 dovecot: imap(k@catap.net)<33482><THygNGAWw+pauzbV>: Disconnected: Logged out in=529 out=100334 deleted=0 expunged=0 trashed=0 hdr_count=5 hdr_bytes=16964 body_count=3 body_bytes=77607 Apr 18 16:59:24 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp connected address=90.187.54.213 host=sa31.catap.net Apr 18 16:59:24 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp tls ciphers=TLSv1.3:TLS_AES_256_GCM_SHA384:256 Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp authentication user=kirill@korins.ky result=ok Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp message msgid=12820125 size=3979 nrcpt=3 proto=ESMTP Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp envelope evpid=128201259a418712 from=<kirill@korins.ky> to=<aki.tuomi@open-xchange.com> Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp envelope evpid=12820125e2eb8c1d from=<kirill@korins.ky> to=<dovecot@dovecot.org> Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp envelope evpid=12820125cea959e4 from=<kirill@korins.ky> to=<kirill@korins.ky> Apr 18 16:59:25 mx1 dovecot: lmtp(95241): Connect from local Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp disconnected reason=quit Apr 18 16:59:25 mx1 dovecot: lmtp(kirill@korins.ky)<95241><D3z9Ik01IWYJdAEAeeMcAQ>: sieve: msgid=<7824635f3b544cfe@mx1.catap.net>: stored mail into mailbox 'INBOX' Apr 18 16:59:25 mx1 dovecot: lmtp(95241): Disconnect from local: Logged out (state=READY) Apr 18 16:59:25 mx1 smtpd[99113]: 782463605f75696d mda delivery evpid=12820125cea959e4 from=<kirill@korins.ky> to=<kirill@korins.ky> rcpt=<kirill@korins.ky> user=vmail delay=0s result=Ok stat=Delivered Apr 18 16:59:25 mx1 smtpd[99113]: 782463663f7915e7 mta connecting address=smtp://87.191.57.186:25 host=87.191.57.186 Apr 18 16:59:25 mx1 smtpd[99113]: 782463663f7915e7 mta connected Apr 18 16:59:26 mx1 smtpd[99113]: 78246367e5a94426 mta connecting address=smtp://94.237.105.223:25 host=talvi.dovecot.org Apr 18 16:59:26 mx1 smtpd[99113]: 78246367e5a94426 mta connected Apr 18 16:59:26 mx1 smtpd[99113]: 782463663f7915e7 mta tls ciphers=TLSv1.3:TLS_AES_256_GCM_SHA384:256 Apr 18 16:59:26 mx1 smtpd[99113]: 782463663f7915e7 mta cert-check result="unverified" fingerprint="SHA256:0b2c6253f1cd8789fcc6c62500d5e4c95f5bdba55b7f65f5b403ed2ff60a4f2f" Apr 18 16:59:26 mx1 smtpd[99113]: 78246367e5a94426 mta tls ciphers=TLSv1.3:TLS_AES_256_GCM_SHA384:256 Apr 18 16:59:26 mx1 smtpd[99113]: 78246367e5a94426 mta cert-check result="unverified" fingerprint="SHA256:e0395990333b76652ad46427b4ba754b924fa3a494e4c6848e3a3d97dabd993e" Apr 18 16:59:27 mx1 smtpd[99113]: 78246367e5a94426 mta delivery evpid=12820125e2eb8c1d from=<kirill@korins.ky> to=<dovecot@dovecot.org> rcpt=<-> source="162.55.82.72" relay="94.237.105.223 (talvi.dovecot.org)" delay=2s result="Ok" stat="250 2.0.0 Ok: queued as 052525E5DA" Apr 18 16:59:29 mx1 smtpd[99113]: 782463663f7915e7 mta delivery evpid=128201259a418712 from=<kirill@korins.ky> to=<aki.tuomi@open-xchange.com> rcpt=<-> source="162.55.82.72" relay="87.191.57.186 (87.191.57.186)" delay=4s result="Ok" stat="250 2.0.0 Ok: queued as B73CA60088" Apr 18 16:59:37 mx1 smtpd[99113]: 78246367e5a94426 mta disconnected reason=quit messages=1 Apr 18 16:59:39 mx1 smtpd[99113]: 782463663f7915e7 mta disconnected reason=quit messages=1 Apr 18 16:59:57 mx1 dovecot: imap-login: Login: user=<k@catap.net>, method=PLAIN, rip=90.187.54.213, lip=162.55.82.72, mpid=69504, TLS, session=</WN3OWAWxOpauzbV> Apr 18 16:59:57 mx1 dovecot: imap-login: Login: user=<k@catap.net>, method=PLAIN, rip=90.187.54.213, lip=162.55.82.72, mpid=93901, TLS, session=<0wV/OWAWxepauzbV> Apr 18 16:59:59 mx1 dovecot: imap-login: Login: user=<k@kcry.pt>, method=PLAIN, rip=90.187.54.213, lip=162.55.82.72, mpid=24491, TLS, session=<dGmVOWAWxupauzbV> Apr 18 16:59:59 mx1 dovecot: imap(k@kcry.pt)<24491><dGmVOWAWxupauzbV>: Disconnected: Logged out in=205 out=2801 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1064 body_count=0 body_bytes=0 Apr 18 16:59:59 mx1 dovecot: imap(k@catap.net)<93901><0wV/OWAWxepauzbV>: Disconnected: Logged out in=161 out=33462 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=1 body_bytes=32436 Apr 18 16:59:59 mx1 dovecot: imap(k@catap.net)<69504></WN3OWAWxOpauzbV>: Disconnected: Logged out in=251 out=7760 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=4239 body_count=0 body_bytes=0
mx2:
Apr 18 16:58:34 mx2 dovecot: imap(kirill@korins.ky)<22911><gixTEGAWhupauzbV>: Disconnected: Logged out in=383 out=7513 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(kirill@korins.ky)<24960><3jWvEGAWjupauzbV>: Disconnected: Logged out in=305 out=1496 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(kirill@korins.ky)<65049><6Xf9LmAWwepauzbV>: Disconnected: Logged out in=5277 out=606180 deleted=0 expunged=0 trashed=0 hdr_count=50 hdr_bytes=119949 body_count=52 body_bytes=460135 Apr 18 16:58:35 mx2 dovecot: imap(k@kcry.pt)<47696><+wdTEGAWiOpauzbV>: Disconnected: Logged out in=319 out=2153 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(k@kcry.pt)<67677><JqCWEGAWjOpauzbV>: Disconnected: Logged out in=438 out=1590 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(k@catap.de)<3774><qhhTEGAWh+pauzbV>: Disconnected: Logged out in=319 out=2165 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(k@catap.de)<44176><18uKEGAWi+pauzbV>: Disconnected: Logged out in=293 out=1364 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(k@catap.net)<91286><lipTEGAWiepauzbV>: Disconnected: Logged out in=319 out=1978 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:35 mx2 dovecot: imap(k@catap.net)<23132><V9AIMmAWwupauzbV>: Disconnected: Logged out in=3770 out=1127766 deleted=0 expunged=0 trashed=0 hdr_count=45 hdr_bytes=71991 body_count=41 body_bytes=1034586 Apr 18 16:58:35 mx2 dovecot: imap(k@catap.net)<48420><O4+iEGAWjepauzbV>: Disconnected: Logged out in=350 out=1455 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Apr 18 16:58:39 mx2 smtpd[33019]: b64b5ed1b2fb95ef smtp connected address=192.30.252.204 host=out-21.smtp.github.com Apr 18 16:58:42 mx2 smtpd[33019]: b64b5ed1b2fb95ef smtp tls ciphers=TLSv1.3:TLS_AES_256_GCM_SHA384:256 Apr 18 16:58:42 mx2 smtpd[33019]: b64b5ed1b2fb95ef smtp message msgid=c41b05ef size=6145 nrcpt=1 proto=ESMTP Apr 18 16:58:42 mx2 smtpd[33019]: b64b5ed1b2fb95ef smtp envelope evpid=c41b05ef1a389587 from=<noreply@github.com> to=<kirill@korins.ky> Apr 18 16:58:42 mx2 dovecot: lmtp(78454): Connect from local Apr 18 16:58:42 mx2 dovecot: lmtp(kirill@korins.ky)<78454><fjKINSI1IWZ2MgEAU0lCkg>: sieve: msgid=<scalatest/scalatest/pull/2318/c2064119667@github.com>: stored mail into mailbox 'INBOX' Apr 18 16:58:42 mx2 dovecot: lmtp(78454): Disconnect from local: Logged out (state=READY) Apr 18 16:58:42 mx2 smtpd[33019]: b64b5ed2ba72fc20 mda delivery evpid=c41b05ef1a389587 from=<noreply@github.com> to=<kirill@korins.ky> rcpt=<kirill@korins.ky> user=vmail delay=0s result=Ok stat=Delivered Apr 18 16:58:42 mx2 smtpd[33019]: b64b5ed1b2fb95ef smtp disconnected reason=quit
All of this allows to reconstruct the workflow which leads to an issue:
- mx2 had a new mail.
- mx2 registered that mail as 147699 inside virtual folder.
- by some reason this email wasn't replicated to mx1 for at least 30-40 seconds. Maybe it runs full-scan on all users, I have no idea.
- mx1 had a new mail as well.
- mx1 resitered that mail as 147699 inside virtual folder.
- mx1's mail was replicated to mx2 as 147700
- mx2's mail was replicated back to mx1 as 147701
-- wbr, Kirill