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