isync-devel

IMAP Timeouts During Local Operations—Correct Behaviour?

[Sabahattin G. <lis...@me...>]

Hi.

I’m trying to stuff a new maildir folder containing 1m+ messages (gatewayed from news) onto my IMAP server. Notwithstanding the usual *slowness* of that server (Apple IMAP, so maybe not the best choice), it’s usual for a timeout of 30 seconds to work in normal operation, getting neatly around stalls that occur for seemingly random reasons despite the fact that I’m well-connected from a fixed connection. (Insert rant about NAT and firewalls and other evil middleboxes here.) But while initially synchronising the mailbox, even before the synchronising stage has identified all the far-side messages to be appended, and before the first append has taken place, the 30 sec timeout repeatedly occurs with every subsequent invocation of mbsync from launchd.

So my question is this: is it expected behaviour that timeouts occur because of long local operations, and is it *correct* or desirable behaviour? Isn’t the “right thing” here to have a dedicated idle timeout, which would take effect while isync is doing purely local computation?

I am successfully working around this situation by using a separate config file for the duration of the initial upload which I am running interactively (and yes, the server really *is* slow). Once that’s done, I should be able to revert to my usual configuration, and if my understanding of the loading/sync process is right, subsequent incremental additions should be relatively fast because isync only needs information from the directory listing, won’t need to rename large numbers of files, and won’t spend a long time calculating the pending operations to be done.

This will all probably turn out to be a terrible idea and I really should just find other ways to examine the mailbox and slim it down. But I’d love to know what you think.

Cheers,
Sabahattin

Re: IMAP Timeouts During Local Operations—Correct Behaviour?

[Oswald B. <osw...@gm...>]

On Tue, Dec 03, 2024 at 04:12:09PM +0000, Sabahattin Gucukoglu via isync-devel wrote:
>So my question is this: is it expected behaviour that timeouts occur
>because of long local operations,
>
yes, sort of.

>and is it *correct* or desirable behaviour?
>
certainly not desirable.

>Isn’t the “right thing” here to have a dedicated idle timeout, which
>would take effect while isync is doing purely local computation?
>
is that timeout reported by isync or the server? what's the end of the
log with -Dn?

if it's the server, then it's quite some work to fix - the maildir
driver would have to be made asynchronous (possibly threaded).

>I am successfully working around this situation by using a separate
>config file for the duration of the initial upload [...]
>
how is it different?

my first idea would be to limit the operations to the minimum, in your
case that should be --push-new if i understand your case correctly.

secondly, if the problem is local i/o and you're pushing, then copying
the box to a ram drive might be a solution. (make sure to move the state
file into place when switching back to the proper box.)

did you try to identify what the time is actually spent on? i'd first
try htop and iotop, and then for finer results valgrind/cachegrind and
strace -tt, resp.

Re: IMAP Timeouts During Local Operations—Correct Behaviour?

[Sabahattin G. <lis...@me...>]

On 4 Dec 2024, at 09:31, Oswald Buddenhagen via isync-devel <isy...@li...> wrote:
> On Tue, Dec 03, 2024 at 04:12:09PM +0000, Sabahattin Gucukoglu via isync-devel wrote:
>> So my question is this: is it expected behaviour that timeouts occur
>> because of long local operations,
>> 
> yes, sort of.
> 
>> and is it *correct* or desirable behaviour?
>> 
> certainly not desirable.

Agreed. It’s just not intuitive IMO and is not what one would expect from a control intended to detect unreachability. Yes, it’s sort of obvious that it happens at all because by the time a response is expected that much time has passed. But of course the delay is being imposed by mbsync and not the server.

>> Isn’t the “right thing” here to have a dedicated idle timeout, which
>> would take effect while isync is doing purely local computation?
>> 
> is that timeout reported by isync or the server? what's the end of the
> log with -Dn?

Reported by mbsync. Here are the log lines starting with the opening of the problem mailbox:
Opening far side box GRC...
>>> 32 SELECT "GRC"
Opening near side box GRC...
* 0 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1692709377]
* OK [UIDNEXT 1]
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen \Recent $MailFlagBit0 $MailFlagBit1 $MailFlagBit2 $Forwarded Redirected $NotJunk NotJunk)
* OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \Recent $MailFlagBit0 $MailFlagBit1 $MailFlagBit2 $Forwarded Redirected $NotJunk NotJunk $iCloudCleanup \*)]
32 OK [READ-WRITE] SELECT completed (took 2 ms)
Loading far side box...
far side: 0 messages, 0 recent
Warning: lost track of 1018382 pushed message(s)
Loading near side box...
near side: 1018382 messages, 1018382 recent
Synchronizing...
>>> 33 APPEND "GRC" "04-Dec-2024 18:25:24 +0000" {7001}
Socket error on imap.mail.me.com (17.42.251.69:993): timeout.

That APPEND is the very first message in the mailbox. With even more debugging I see that every other near-far transaction is pending right before the timeout occurs. That “lost track” warning seems to be about uncommitted messages from the last failed attempt, but as you see not a single APPEND was actually successful, so it’s fine. I initially wasn’t really willing to download all the source messages again, so that was fortunate. But as it happens running mbsync interactively with a 300 second timeout (see below) was still giving me lots of “Server too busy” warnings from the IMAP server anyway, so I was willing to start again fresh from source for science.

>> I am successfully working around this situation by using a separate
>> config file for the duration of the initial upload [...]
>> 
> how is it different?

Sorry. Increase timeout from 30 to 300s. It is now running in background; it’s too slow and painful to watch interactively, so I’m hoping it’ll complete over the course of a few days. It is however making the IMAP server very grumpy and I seem to be pushing some limit or other because it sometimes just refuses to store a message, or disconnects me. I can’t wait to finish setting up my self-hosted mail again after years.

> my first idea would be to limit the operations to the minimum, in your
> case that should be --push-new if i understand your case correctly.

Yes, I’ll look into this, thanks, although it now seems to be on the rails.

> secondly, if the problem is local i/o and you're pushing, then copying
> the box to a ram drive might be a solution. (make sure to move the state
> file into place when switching back to the proper box.)
> 
> did you try to identify what the time is actually spent on? i'd first
> try htop and iotop, and then for finer results valgrind/cachegrind and
> strace -tt, resp.

Interesting idea re the ramdisk! I will probably try that next if I need to, though I’m hoping the 30s timeout will be acceptable again after the initial transfer.

This is macOS so I’ll need to look at the equivalents, however a quick look at ActivityMonitor doesn’t show substantial disk I/O at all, less than 10 K/s, so we’re probably being held back by latency here.

Thanks for the help.

Cheers,
Sabahattin