#90 Connection loss for IMAP2IMAP sync on large mailboxes

[Stephan Gerth]

When syncing from IMAP to IMAP (both dovecot instances) it can occur for large mailboxes, that no communication is to one of the servers is going on for over 30 minutes. This triggers a timeout resulting in the following message breaking the synchronization:

IMAP error: unexpected BYE response: Disconnected for inactivity.

[Oswald Buddenhagen]

at which point does that happen? while one side is still FETCHing the message list? for half an hour?!

[Stephan Gerth]

No, this happens somewhere in the middle (on the 43rd folder of 48 to be specific which happens to be quite large). I watched some numbers this time while running the synchronization:

• fetching from the source seems to be faster than pushing to the target
• mbsync seems to cache the whole(?) mailbox folder (memory usage went to max. 10G)
• when it tries to push the remaining mails to the target while the source mails have been already cached, the source connection is not seeing any activity

During the last point the connection is dropped by the source dovecot due to inactivity after 30mins (seems to be the CLIENT_IDLE_TIMEOUT_MSECS according to dovecot documentation) while mails are being pushed to the target.

[Oswald Buddenhagen]

that's just not how isync works.
you can watch it by adding -Dd. -Dn (or just -D) will produce even more output, but based on the info so far i expect that to be somewhat useless due to the sheer volume of repetetive content.

how large is "quite large"? at normal speeds, such a duration would translate to millions of messages.

[Stephan Gerth]

Regarding the working of isync this was just guessing from what I've observed, sorry!

The mailbox folder in question has about 108k emails, so that's far from millions of messages. I've tried to speed-up the target server by putting the target mailbox on a ramdisk. This lets the synchronization finish before the timeout hits which solves it in my case. However, for larger mailboxes or slower servers the issue would surely occur again.

How is the general mechanism working when target server takes longer than the source server timeout to synchronize on of the mailbox folders?

[Oswald Buddenhagen]

there is no such mechanism; i just didn't anticipate this situation.

assuming you are using the default BufferLimit, the timeout cannot possibly occur while messages are being transferred. (*)
so it must be during message enumeration. but that should be also on the order of 10 MB with your mailbox size, so i dunno.

have you tried the -Dd log? if you can't make sense of it, you can mail it to me privately.

EDIT: (*) well, actually, if the target server is using a legacy fs that does fsync inefficiently, then a backlog of many small messages could conceivably cause such a problem, and the use of a ramdisk would indeed completely sidestep the issue. using FSync no would then also be an option.

[Stephan Gerth]

I've tried with the -Dd option: The output makes sense so far:

A lot of interleaved messages of such as this snippet (within the large mailbox folder already):

F: [ 120772] Callback enter fetch_msg, sts=0, flags=, date=1789297202, size=110049
N: [ 228630] Enter store_msg, flags=, date=1789297202, size=110071, to_trash=no
N: [ 228630] Leave store_msg
F: [ 120772] Callback leave fetch_msg
F: [ 120773] Callback enter fetch_msg, sts=0, flags=, date=1789279202, size=122022
N: [ 228631] Enter store_msg, flags=, date=1789279202, size=122044, to_trash=no
N: [ 228631] Leave store_msg
F: [ 120773] Callback leave fetch_msg
F: [ 120774] Callback enter fetch_msg, sts=0, flags=, date=1789331286, size=73887
N: [ 228632] Enter store_msg, flags=, date=1789331286, size=73909, to_trash=no
N: [ 228632] Leave store_msg
F: [ 120774] Callback leave fetch_msg
F: [ 120775] Callback enter fetch_msg, sts=0, flags=, date=1789331286, size=41964
N: [ 228633] Enter store_msg, flags=, date=1789331286, size=41986, to_trash=no
N: [ 228633] Leave store_msg

at some point the communication happens only with the target, ca. 125k lines of

N: [ 136629] Callback enter store_msg, sts=0, uid=15841
N: [ 136629] Callback leave store_msg
N: [ 136630] Callback enter store_msg, sts=0, uid=15842
N: [ 136630] Callback leave store_msg
N: [ 136631] Callback enter store_msg, sts=0, uid=15843
N: [ 136631] Callback leave store_msg
[...]
N: [ 199431] Callback leave store_msg
N: [ 199432] Callback enter store_msg, sts=0, uid=78644
N: [ 199432] Callback leave store_msg

which is then stopped because of the source timeout with this message:

F: Callback enter bad store
F: Enter cancel_store
F: Leave cancel_store
N: [ 228647] Enter cancel_cmds

So it has fetched all the messages but takes too long to save them back to the target. Setting FSYNC no did not make any difference. Speaking of BufferLimit: I had not changed it. Would it make sense to set it to some smaller value than the default value so that it cannot fetch the whole mailbox folder or am I wrong on that?

[Oswald Buddenhagen]

Setting FSYNC no did not make any difference.

weird.
have a look at iotop on the target server with the two settings.
also check the mount options of the volume. it's kinda unexpected that the process is disk-bound to such a degree.

Would it make sense to set it to some smaller value than the default value so that it cannot fetch the whole mailbox folder [...]?

yes. you could actually use something ridiculously small (even 1) to avoid that multiple STOREs are queued up at all.

[Stephan Gerth]

I had a look at iotop and I could see that the write rate was 1,5x compared the Fsync yes setting. So it seems to make a difference but does not increase write rate enough. Setting BufferLimit 1 pushes message storage further to the end in the log file (-Dd) but it still fetches all messages so that the connection to the source server runs into the timeout (while it is working on storing all mails into the target mailbox folder (about 120k lines only enter/leave store_msg lines).

[Oswald Buddenhagen]

the fs load result is surprising. what are the actual numbers? network bw, disk bw, fs type & mount options, etc.

that effect of bufferlimit sounds just wrong. please mail me the log.

[Stephan Gerth]

I think the disk setup is not the actual problem since the network connection could always be the main bottleneck (imagine syncing over a 50MBit internet connection).

But I think I figured out why the BufferLimit has no effect (lines refer latest git 42cfa1): Line sync.c:1468 checks via get_memory_usage if BufferLimit has been already reached or overrun and handles that. However, according to the logs all calls to get_memory_usage returned no usage at all:

N: Called get_memory_usage, ret=0

This explains then the unchanged behaviour regardless of the actual BufferLimit setting. I'm a bit lost on where to check next why the calculation in drv_imap.c:3671 returns always 0. Putting some debug message on all places where buffer_mem members are increased and decreased do show some numbers actually.

I have not sent a log now as it seems some more debug info in that log would be useful, question is now which info would be helpful.

[Oswald Buddenhagen]

the only legitimate way how that can happen is that the IMAP commands were actually all already sent out, and the queuing is happening on the target server. -Ddn should confirm that.

the way to work around that would be limiting PipelineDepth to something reasonable, say 50.

[Stephan Gerth]

I've sent you a log of a -Ddn run with BufferLimit 1, PipelineDepth 1 on the target and FSync no to the maintainer address.

[Oswald Buddenhagen]

ok, thanks, something is obviously going wrong.
first it queues 22 fetches (which is incompatible with a pipeline depth of 1), then it queries the buffer size for all remaining messages (which is zero, because no appends have been scheduled), then it queues all remaining fetches. then the first fetches are completing, upon which it correctly schedules the first append, and the next one only once the first one completes (this is how pipelinedepth 1 should work). one notable observation is that the fetches complete in interleaved batches of 4, which i have never seen before, but it's allowed and isync handles it fine.

[Stephan Gerth]

FWIW: Source server is Dovecot 2.3.13 (Debian 11), target server is Dovecot 2.4.1-4 (Debian 13).