Re: occasional "Warning: lost track of 460840 pulled message(s)"

[Uwe Kleine-König]

Hello Oswald,
On 9/8/21 10:15 AM, Oswald Buddenhagen wrote:

On Tue, Sep 07, 2021 at 09:40:52PM +0200, Uwe Kleine-König wrote:

strace looks as follows:

there doesn't appear to be anything particularly remarkable about that
log. it simply downloads messages ...

Maybe it's the server's fault if it scrambled all UIDs?

i see no evidence of that so far.

    Sep 07 16:55:45 taurus syncmail-work[212854]: slave: 4386047 messages, 513211 recent     Sep 07 16:55:52 taurus syncmail-work[212854]: master: 523665 messages, 2 recent

the notable thing here is that you have *a lot* more messages on the
client than there are on the server. given your symmetrical
configuration, mbsync should try to upload them all in the next run, and
if it loses track again, it would keep ballooning up.

I don't know what these numbers mean. Is the goal of the symmetrical sync that the numbers for slave and master match? The first number is the absolute number of mails and the second?

to get meaningful logs, you should create a tiny (~5 messages) mailbox
for testing and record how the situation develops over, say, three runs
with only that box.

I have a few smaller mailboxes, too, e.g.:


        Sep 02 18:38:11 taurus syncmail-work[5211]: Loading master...
        Sep 02 18:38:11 taurus syncmail-work[5211]: Loading slave...
        Sep 02 18:38:11 taurus syncmail-work[5211]: slave: 762 messages, 74 
recent
        Sep 02 18:38:11 taurus syncmail-work[5211]: master: 762 messages, 0 
recent
        Sep 02 18:38:11 taurus syncmail-work[5211]: Synchronizing...
        --

        Sep 02 18:46:47 taurus syncmail-work[5473]: Loading master...
        Sep 02 18:46:47 taurus syncmail-work[5473]: Loading slave...
        Sep 02 18:46:47 taurus syncmail-work[5473]: slave: 762 messages, 74 
recent
        Sep 02 18:46:47 taurus syncmail-work[5473]: master: 762 messages, 0 
recent
        Sep 02 18:46:47 taurus syncmail-work[5473]: Synchronizing...
        --

        Sep 02 18:53:23 taurus syncmail-work[5917]: Loading master...
        Sep 02 18:53:23 taurus syncmail-work[5917]: Loading slave...
        Sep 02 18:53:23 taurus syncmail-work[5917]: slave: 762 messages, 74 
recent
        Sep 02 18:53:23 taurus syncmail-work[5917]: master: 762 messages, 0 
recent
        Sep 02 18:53:23 taurus syncmail-work[5917]: Synchronizing...
        --

        Sep 02 18:59:36 taurus syncmail-work[6147]: Loading master...
        Sep 02 18:59:36 taurus syncmail-work[6147]: Loading slave...
        Sep 02 18:59:36 taurus syncmail-work[6147]: slave: 762 messages, 74 
recent
        Sep 02 18:59:36 taurus syncmail-work[6147]: master: 762 messages, 0 
recent
        Sep 02 18:59:36 taurus syncmail-work[6147]: Synchronizing...
        --

        Sep 04 15:34:31 taurus syncmail-work[62797]: Loading master...
        Sep 04 15:34:31 taurus syncmail-work[62797]: Loading slave...
        Sep 04 15:34:31 taurus syncmail-work[62797]: slave: 762 messages, 74 
recent
        Sep 04 15:34:31 taurus syncmail-work[62797]: master: 762 messages, 0 
recent
        Sep 04 15:34:31 taurus syncmail-work[62797]: Synchronizing...
        --

        Sep 04 15:42:52 taurus syncmail-work[63132]: Loading master...
        Sep 04 15:42:52 taurus syncmail-work[63132]: Loading slave...
        Sep 04 15:42:52 taurus syncmail-work[63132]: slave: 762 messages, 74 
recent
        Sep 04 15:42:52 taurus syncmail-work[63132]: master: 762 messages, 0 
recent
        Sep 04 15:42:52 taurus syncmail-work[63132]: Synchronizing...
        --

        Sep 04 15:49:40 taurus syncmail-work[63368]: Loading master...
        Sep 04 15:49:40 taurus syncmail-work[63368]: Loading slave...
        Sep 04 15:49:40 taurus syncmail-work[63368]: slave: 762 messages, 74 
recent
        Sep 04 15:49:40 taurus syncmail-work[63368]: master: 762 messages, 0 
recent
        Sep 04 15:49:40 taurus syncmail-work[63368]: Synchronizing...
        --

        Sep 04 15:55:40 taurus syncmail-work[63489]: Loading master...
        Sep 04 15:55:40 taurus syncmail-work[63489]: Loading slave...
        Sep 04 15:55:40 taurus syncmail-work[63489]: slave: 762 messages, 74 
recent
        Sep 04 15:55:40 taurus syncmail-work[63489]: master: 762 messages, 0 
recent
        Sep 04 15:55:40 taurus syncmail-work[63489]: Synchronizing...
        --

        Sep 04 16:01:40 taurus syncmail-work[63590]: Loading master...
        Sep 04 16:01:40 taurus syncmail-work[63590]: Loading slave...
        Sep 04 16:01:40 taurus syncmail-work[63590]: slave: 762 messages, 74 
recent
        Sep 04 16:01:40 taurus syncmail-work[63590]: master: 762 messages, 0 
recent
        Sep 04 16:01:40 taurus syncmail-work[63590]: Synchronizing...
        --

        Sep 04 16:07:39 taurus syncmail-work[63656]: Loading master...
        Sep 04 16:07:39 taurus syncmail-work[63656]: Loading slave...
        Sep 04 16:07:39 taurus syncmail-work[63656]: slave: 762 messages, 74 
recent
        Sep 04 16:07:39 taurus syncmail-work[63656]: master: 762 messages, 0 
recent
        Sep 04 16:07:39 taurus syncmail-work[63656]: Synchronizing...
        --

        Sep 04 16:13:40 taurus syncmail-work[63735]: Loading master...
        Sep 04 16:13:40 taurus syncmail-work[63735]: Loading slave...
        Sep 04 16:13:40 taurus syncmail-work[63735]: slave: 762 messages, 74 
recent
        Sep 04 16:13:40 taurus syncmail-work[63735]: master: 762 messages, 0 
recent
        Sep 04 16:13:40 taurus syncmail-work[63735]: Synchronizing...
        --

        Sep 04 16:19:36 taurus syncmail-work[63820]: Loading master...
        Sep 04 16:19:36 taurus syncmail-work[63820]: Loading slave...
        Sep 04 16:19:36 taurus syncmail-work[63820]: slave: 762 messages, 74 
recent
        Sep 04 16:19:36 taurus syncmail-work[63820]: master: 762 messages, 0 
recent
        Sep 04 16:19:36 taurus syncmail-work[63820]: Synchronizing...
        --

        Sep 04 16:25:39 taurus syncmail-work[63910]: Loading master...
        Sep 04 16:25:39 taurus syncmail-work[63910]: Loading slave...
        Sep 04 16:25:39 taurus syncmail-work[63910]: slave: 762 messages, 74 
recent
        Sep 04 16:25:39 taurus syncmail-work[63910]: master: 762 messages, 0 
recent
        Sep 04 16:25:39 taurus syncmail-work[63910]: Synchronizing...
        --

        Sep 04 16:31:47 taurus syncmail-work[63995]: Loading master...
        Sep 04 16:31:47 taurus syncmail-work[63995]: Loading slave...
        Sep 04 16:31:47 taurus syncmail-work[63995]: slave: 762 messages, 74 
recent
        Sep 04 16:31:47 taurus syncmail-work[63995]: master: 762 messages, 0 
recent
        Sep 04 16:31:47 taurus syncmail-work[63995]: Synchronizing...
        --

        Sep 04 16:38:42 taurus syncmail-work[64076]: Loading master...
        Sep 04 16:38:42 taurus syncmail-work[64076]: Loading slave...
        Sep 04 16:38:42 taurus syncmail-work[64076]: slave: 762 messages, 74 
recent
        Sep 04 16:38:42 taurus syncmail-work[64076]: master: 762 messages, 0 
recent
        Sep 04 16:38:42 taurus syncmail-work[64076]: Synchronizing...
        --

        Sep 04 16:44:36 taurus syncmail-work[64177]: Loading master...
        Sep 04 16:44:36 taurus syncmail-work[64177]: Loading slave...
        Sep 04 16:44:36 taurus syncmail-work[64177]: slave: 762 messages, 74 
recent
        Sep 04 16:44:36 taurus syncmail-work[64177]: master: 762 messages, 0 
recent
        Sep 04 16:44:36 taurus syncmail-work[64177]: Synchronizing...
        --
        ...

i.e. the numbers don't change.




        [...]

        [...]


so these numbers doesn't seem to sync?!



uwe@taurus:~/Maildir-work/.lists.linux-arm-kernel$ find -type f | wc -l
4909721

u...@dude.ptx:~/Maildir/.lists.linux-arm-kernel$ find -type f | wc -l
523933

so this seems to match the numbers that mbsync found ...

Does this give a clue what could be the problem?

Best regards
Uwe

uwe@taurus:~$ journalctl --user -u syncmail-work --since 2021-09-01 | grep -A 5 ptxlists/distrokit Sep 02 18:38:11 taurus syncmail-work[5211]: Opening master box ptxlists/distrokit... Sep 02 18:38:11 taurus syncmail-work[5211]: Opening slave box ptxlists/distrokit... Sep 02 18:46:46 taurus syncmail-work[5473]: Opening master box ptxlists/distrokit... Sep 02 18:46:46 taurus syncmail-work[5473]: Opening slave box ptxlists/distrokit... Sep 02 18:53:23 taurus syncmail-work[5917]: Opening master box ptxlists/distrokit... Sep 02 18:53:23 taurus syncmail-work[5917]: Opening slave box ptxlists/distrokit... Sep 02 18:59:36 taurus syncmail-work[6147]: Opening master box ptxlists/distrokit... Sep 02 18:59:36 taurus syncmail-work[6147]: Opening slave box ptxlists/distrokit... Sep 04 15:34:31 taurus syncmail-work[62797]: Opening master box ptxlists/distrokit... Sep 04 15:34:31 taurus syncmail-work[62797]: Opening slave box ptxlists/distrokit... Sep 04 15:42:52 taurus syncmail-work[63132]: Opening master box ptxlists/distrokit... Sep 04 15:42:52 taurus syncmail-work[63132]: Opening slave box ptxlists/distrokit... Sep 04 15:49:40 taurus syncmail-work[63368]: Opening master box ptxlists/distrokit... Sep 04 15:49:40 taurus syncmail-work[63368]: Opening slave box ptxlists/distrokit... Sep 04 15:55:40 taurus syncmail-work[63489]: Opening master box ptxlists/distrokit... Sep 04 15:55:40 taurus syncmail-work[63489]: Opening slave box ptxlists/distrokit... Sep 04 16:01:40 taurus syncmail-work[63590]: Opening master box ptxlists/distrokit... Sep 04 16:01:40 taurus syncmail-work[63590]: Opening slave box ptxlists/distrokit... Sep 04 16:07:39 taurus syncmail-work[63656]: Opening master box ptxlists/distrokit... Sep 04 16:07:39 taurus syncmail-work[63656]: Opening slave box ptxlists/distrokit... Sep 04 16:13:40 taurus syncmail-work[63735]: Opening master box ptxlists/distrokit... Sep 04 16:13:40 taurus syncmail-work[63735]: Opening slave box ptxlists/distrokit... Sep 04 16:19:36 taurus syncmail-work[63820]: Opening master box ptxlists/distrokit... Sep 04 16:19:36 taurus syncmail-work[63820]: Opening slave box ptxlists/distrokit... Sep 04 16:25:39 taurus syncmail-work[63910]: Opening master box ptxlists/distrokit... Sep 04 16:25:39 taurus syncmail-work[63910]: Opening slave box ptxlists/distrokit... Sep 04 16:31:47 taurus syncmail-work[63995]: Opening master box ptxlists/distrokit... Sep 04 16:31:47 taurus syncmail-work[63995]: Opening slave box ptxlists/distrokit... Sep 04 16:38:42 taurus syncmail-work[64076]: Opening master box ptxlists/distrokit... Sep 04 16:38:42 taurus syncmail-work[64076]: Opening slave box ptxlists/distrokit... Sep 04 16:44:35 taurus syncmail-work[64177]: Opening master box ptxlists/distrokit... Sep 04 16:44:35 taurus syncmail-work[64177]: Opening slave box ptxlists/distrokit... On the other hand, if I look how the numbers behave for my linux-arm-kernel mailbox: uwe@taurus:~$ journalctl --user -u syncmail-work --since 2021-09-01 | grep -A 5 lists/linux-arm | grep recent Sep 05 16:08:51 taurus syncmail-work[72676]: master: 523305 messages, 0 recent Sep 05 16:14:43 taurus syncmail-work[72925]: slave: 4385689 messages, 512906 recent Sep 05 16:14:49 taurus syncmail-work[72925]: master: 523305 messages, 0 recent Sep 05 16:20:43 taurus syncmail-work[73243]: slave: 4385689 messages, 512906 recent Sep 05 16:20:50 taurus syncmail-work[73243]: master: 523305 messages, 0 recent Sep 05 16:26:42 taurus syncmail-work[73444]: slave: 4385689 messages, 512906 recent Sep 05 16:26:58 taurus syncmail-work[73444]: master: 523307 messages, 2 recent Sep 05 16:32:43 taurus syncmail-work[73575]: slave: 4385691 messages, 512908 recent Sep 05 16:32:59 taurus syncmail-work[73575]: master: 523309 messages, 2 recent Sep 05 16:38:43 taurus syncmail-work[73789]: slave: 4385693 messages, 512910 recent Sep 05 16:38:59 taurus syncmail-work[73789]: master: 523311 messages, 2 recent Sep 05 16:45:43 taurus syncmail-work[73955]: slave: 4385695 messages, 512912 recent Sep 05 16:45:59 taurus syncmail-work[73955]: master: 523312 messages, 1 recent Sep 05 16:52:43 taurus syncmail-work[74087]: slave: 4385696 messages, 512913 recent Sep 05 16:52:59 taurus syncmail-work[74087]: master: 523313 messages, 1 recent Sep 05 16:59:30 taurus syncmail-work[74275]: slave: 4385697 messages, 512914 recent Sep 05 16:59:37 taurus syncmail-work[74275]: master: 523313 messages, 0 recent Sep 05 17:05:43 taurus syncmail-work[74378]: slave: 4385697 messages, 512914 recent Sep 05 17:05:49 taurus syncmail-work[74378]: master: 523313 messages, 0 recent Sep 05 17:11:40 taurus syncmail-work[74553]: slave: 4385697 messages, 512914 recent Sep 05 17:12:07 taurus syncmail-work[74553]: master: 523313 messages, 0 recent Sep 05 17:18:40 taurus syncmail-work[74747]: slave: 4385697 messages, 512914 recent Sep 05 17:18:46 taurus syncmail-work[74747]: master: 523313 messages, 0 recent Sep 05 17:24:40 taurus syncmail-work[74857]: slave: 4385697 messages, 512914 recent Sep 05 17:24:46 taurus syncmail-work[74857]: master: 523313 messages, 0 recent Sep 05 17:30:40 taurus syncmail-work[75089]: slave: 4385697 messages, 512914 recent Sep 05 17:30:47 taurus syncmail-work[75089]: master: 523313 messages, 0 recent Sep 05 17:36:41 taurus syncmail-work[75242]: slave: 4385697 messages, 512914 recent Sep 05 17:36:48 taurus syncmail-work[75242]: master: 523313 messages, 0 recent Sep 05 17:42:40 taurus syncmail-work[75371]: slave: 4385697 messages, 512914 recent Sep 05 17:42:46 taurus syncmail-work[75371]: master: 523313 messages, 0 recent Sep 05 17:48:44 taurus syncmail-work[75510]: slave: 4385697 messages, 512884 recent Sep 05 17:48:50 taurus syncmail-work[75510]: master: 523313 messages, 0 recent Sep 05 17:55:43 taurus syncmail-work[75704]: slave: 4385697 messages, 512884 recent Sep 05 17:55:50 taurus syncmail-work[75704]: master: 523313 messages, 0 recent Sep 05 18:01:41 taurus syncmail-work[75787]: slave: 4385697 messages, 512884 recent Sep 05 18:01:48 taurus syncmail-work[75787]: master: 523313 messages, 0 recent Sep 05 18:07:41 taurus syncmail-work[75867]: slave: 4385697 messages, 512884 recent Sep 05 18:07:48 taurus syncmail-work[75867]: master: 523313 messages, 0 recent Sep 05 18:13:42 taurus syncmail-work[75943]: slave: 4385697 messages, 512884 recent Sep 07 16:55:45 taurus syncmail-work[212854]: slave: 4386047 messages, 513211 recent Sep 07 16:55:52 taurus syncmail-work[212854]: master: 523665 messages, 2 recent Sep 07 17:02:44 taurus syncmail-work[213028]: slave: 4386049 messages, 513213 recent Sep 07 17:03:02 taurus syncmail-work[213028]: master: 523670 messages, 523670 recent Having shell access to the remote Maildir, I counted the files here and there in the linux-arm-kernel folder:

OpenPGP_signature
Description: OpenPGP digital signature

_______________________________________________
isync-devel mailing list
isync-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/isync-devel