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 kir...@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 kir...@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=kir...@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=<kir...@korins.ky> to=<aki.tu...@open-xchange.com>
Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp envelope
evpid=12820125e2eb8c1d from=<kir...@korins.ky> to=<dovecot@dovecot.org>
Apr 18 16:59:25 mx1 smtpd[99113]: 7824635eb33a7cc5 smtp envelope
evpid=12820125cea959e4 from=<kir...@korins.ky> to=<kir...@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(kir...@korins.ky)<95241><D3z9Ik01IWYJdAEAeeMcAQ>: sieve:
msgid=<7824635f3b544...@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=<kir...@korins.ky> to=<kir...@korins.ky>
rcpt=<kir...@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=<kir...@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=<kir...@korins.ky> to=<aki.tu...@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(kir...@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(kir...@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(kir...@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=<nore...@github.com> to=<kir...@korins.ky>
Apr 18 16:58:42 mx2 dovecot: lmtp(78454): Connect from local
Apr 18 16:58:42 mx2 dovecot:
lmtp(kir...@korins.ky)<78454><fjKINSI1IWZ2MgEAU0lCkg>: sieve:
msgid=<scalatest/scalatest/pull/2318/c2064119...@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=<nore...@github.com> to=<kir...@korins.ky>
rcpt=<kir...@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:
1. mx2 had a new mail.
2. mx2 registered that mail as 147699 inside virtual folder.
3. 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.
4. mx1 had a new mail as well.
5. mx1 resitered that mail as 147699 inside virtual folder.
6. mx1's mail was replicated to mx2 as 147700
7. mx2's mail was replicated back to mx1 as 147701
--
wbr, Kirill
_______________________________________________
dovecot mailing list -- dovecot@dovecot.org
To unsubscribe send an email to dovecot-le...@dovecot.org
