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=
Apr 18 16:58:42 mx1 dovecot: imap(k@catap.net)<33482>: 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>: 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>: 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