#700 Endless message download loop

[Edwin]

Last week I set up davmail for a fresh Exchange account. After sending a mail with a bigger attachment, I started getting what looked like connection problems.

Checking the logs, the problems appear to focus around this one message.

After opening the "Sent" box, this happens:

2019-01-28 11:33:46,320 DEBUG [ImapConnection-50449] davmail.exchange.MessageLoadThread  - Load large message 7762KB uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24 in a separate thread
2019-01-28 11:33:48,444 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 128 KBytes from /ews/exchange.asmx
2019-01-28 11:33:49,928 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 256 KBytes from /ews/exchange.asmx
2019-01-28 11:33:51,100 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 385 KBytes from /ews/exchange.asmx
2019-01-28 11:33:52,224 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 513 KBytes from /ews/exchange.asmx
2019-01-28 11:33:53,396 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 641 KBytes from /ews/exchange.asmx
2019-01-28 11:33:54,552 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 769 KBytes from /ews/exchange.asmx
2019-01-28 11:33:55,677 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 897 KBytes from /ews/exchange.asmx
2019-01-28 11:33:56,332 DEBUG [ImapConnection-50449] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:33:57,130 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 1025 KBytes from /ews/exchange.asmx
2019-01-28 11:33:58,145 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 1154 KBytes from /ews/exchange.asmx
2019-01-28 11:33:59,269 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 1282 KBytes from /ews/exchange.asmx
2019-01-28 11:34:00,440 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 1410 KBytes from /ews/exchange.asmx

This keeps going on for about a minute then some other stuff happens and a little further I get this:

2019-01-28 11:35:28,615 DEBUG [ImapConnection-50454] davmail.exchange.MessageLoadThread  - Load large message 7762KB uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24 in a separate thread
2019-01-28 11:35:28,912 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 10772 KBytes from /ews/exchange.asmx
2019-01-28 11:35:31,161 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 10900 KBytes from /ews/exchange.asmx
2019-01-28 11:35:32,489 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 11028 KBytes from /ews/exchange.asmx
2019-01-28 11:35:33,895 DEBUG [ImapConnection-50454-LoadMessage] davmail  - Downloaded 128 KBytes from /ews/exchange.asmx
2019-01-28 11:35:34,536 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 11157 KBytes from /ews/exchange.asmx
2019-01-28 11:35:36,410 DEBUG [ImapConnection-50449] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:35:36,551 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 11285 KBytes from /ews/exchange.asmx
2019-01-28 11:35:36,675 DEBUG [ImapConnection-50454-LoadMessage] davmail  - Downloaded 256 KBytes from /ews/exchange.asmx
2019-01-28 11:35:38,627 DEBUG [ImapConnection-50454] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:35:38,831 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 11413 KBytes from /ews/exchange.asmx
2019-01-28 11:35:38,925 DEBUG [ImapConnection-50454-LoadMessage] davmail  - Downloaded 385 KBytes from /ews/exchange.asmx

This looks highly suspicious as it looks like a second download of the same message is started. The first one appears to end normally:

2019-01-28 11:36:31,031 DEBUG [ImapConnection-50449-LoadMessage] davmail  - Downloaded 14107 KBytes from /ews/exchange.asmx
2019-01-28 11:36:31,515 DEBUG [ImapConnection-50449-LoadMessage] davmail.exchange.ExchangeSession  - Downloaded full message content for IMAP UID 24 (10861573 bytes)
2019-01-28 11:36:31,515 DEBUG [ImapConnection-50449] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:36:31,593 DEBUG [ImapConnection-50449] davmail  - >  RFC822.SIZE 10861573 BODY[] {10861573}
2019-01-28 11:36:31,593 WARN  [ImapConnection-50449] davmail.imap.ImapConnection  - Client closed connection
2019-01-28 11:36:31,593 INFO  [ImapConnection-50449] davmail.connection  - DISCONNECT - 0:0:0:0:0:0:0:1:50449 

Even after that, further rereads of the sent box appear to keep spawning new downloads and 15 minutes later things have gone quite mad:

2019-01-28 11:50:05,326 DEBUG [ImapConnection-50498] davmail.exchange.MessageLoadThread  - Load large message 7762KB uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24 in a separate thread
2019-01-28 11:50:05,403 DEBUG [ImapConnection-50488-LoadMessage] davmail  - Downloaded 3334 KBytes from /ews/exchange.asmx
2019-01-28 11:50:09,684 DEBUG [ImapConnection-50480-LoadMessage] davmail  - Downloaded 3591 KBytes from /ews/exchange.asmx
2019-01-28 11:50:09,841 DEBUG [ImapConnection-50480] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:10,231 DEBUG [ImapConnection-50487] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:10,356 DEBUG [ImapConnection-50488] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:12,324 DEBUG [ImapConnection-50487-LoadMessage] davmail  - Downloaded 3206 KBytes from /ews/exchange.asmx
2019-01-28 11:50:13,027 DEBUG [ImapConnection-50496-LoadMessage] davmail  - Downloaded 128 KBytes from /ews/exchange.asmx
2019-01-28 11:50:13,590 DEBUG [ImapConnection-50488-LoadMessage] davmail  - Downloaded 3462 KBytes from /ews/exchange.asmx
2019-01-28 11:50:13,808 DEBUG [ImapConnection-50498-LoadMessage] davmail  - Downloaded 128 KBytes from /ews/exchange.asmx
2019-01-28 11:50:14,355 DEBUG [ImapConnection-50495] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:14,808 DEBUG [ImapConnection-50495-LoadMessage] davmail  - Downloaded 128 KBytes from /ews/exchange.asmx
2019-01-28 11:50:15,339 DEBUG [ImapConnection-50496] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:15,339 DEBUG [ImapConnection-50498] davmail.exchange.MessageLoadThread  - Still loading uid AAAAAJpPbg4HhuBFoJPhyFTwMUwBAEqVsQTnYg5LoiZOsb9NZ4gAAAAAINIAAA== imapUid 24
2019-01-28 11:50:16,261 DEBUG [ImapConnection-50480-LoadMessage] davmail  - Downloaded 3719 KBytes from /ews/exchange.asmx

Which looks like there are now 6 parallel downloads going on.

All this goes with rapidly growing memory consumption. About 500 MB after 20 minutes, which is where I left it. After restarting both DavMail and Thunderbird it looks like TBs cache now has the message and it doesn't try to read it anymore.

[Mickael Guessant]

Can you please check you have:
davmail.enableKeepAlive=true
in your DavMail settings to try to avoid Thunderbird timeout ?

[Edwin]

That option was still off. I don't see any evidence of timeouts in the logs though, but I don't know if that is logged.

[Edwin]

Now with Keep Alive an I sent another larger mail (3MB, so not that big, but the connection to the Exchange server is still pretty slow) and the same thing happened.

Note that after restarting both Thunderbird and Davmail I just let it download without touching anything. This made it finish properly. I did end up with two copies of the mail in my sent box.

It seems that Davmail runs into problems if other things happen while the message is being downloaded. So it should not be hard to reproduce if testing is done on an exchange server with a very slow connection.

[Mickael Guessant]

If your Exchange connection is slow, the first step is to disable Thunderbird save in sent setting and enable it in DavMail:
davmail.smtpSaveInSent=true

Thus at least you will send the message only once.

[Edwin]

Just wanted to add that it happened in the inbox today as well. The "workaround" is easy enough though. Simply don't touch Thunderbird until it completes downloading the message. As long as it does not send another task in the direction of davmail while it is downloading, everything completes normally and the local cache will prevent any further problems.

[Edwin]

I'd just like to mention that this problem still exists in 5.2.0. Davmail is still starting multiple downloads of the same message on slow connections.

[John SMITH]

I have the same problem with 5.3.1. and Kmail and a connection around 200 kB/s. It gets better with another connection around 1 or 2 MB/s.

(I am talking of the download loop / multiplication and the eventual duplicates in INBOX. For the duplicates in "Sent", I was told that Exchange servers were copying sent emails automatically in "Sent", thus we have to disable this in our clients.)

[Edwin]

Had a wonderful day yesterday with 5.3.1 as well. After getting back in the office with four > 10 MB messages in my mailbox I had a hell of a time getting them in. It's basically a process of selecting an unused folder in Thunderbird. Then letting everything download with the occasional restart of davmail and tb when it blows up. Took me six or seven restarts and several hours before everything was finally in. Something is seriously bugged in davmail.

[Mickael Guessant]

I understand your frustration: several hours for a few messages is just unusable.

However it's basically a client side timeout issue and very difficult to fix on DavMail side. If you manage to make Thunderbird wait for message download completion it won't try afain immediately and end up trying to download the same message multiple times.

Make sure you enable keepalive to at least maintain an activity on the connection.

@KMail user: you may have another issue, in order to support for some IMAP clients (e.g. mutt) DavMail has to download message bodies on SELECT to get exact message. You can override this with "Use Exchange message size in IMAP"

[Edwin]

It's a bit easy to put this on TB since it doesn't do any of these things on regular imap connections. And it also doesn't explain why davmail starts multiple threads with downloads of the same message. This last one appears to be triggered when other activity occurs. Like Thunderbird updating the message list. This helped me reduce the problem by putting an unused map active in TB when it downloads large messages.

Keep alive was always on, so that isn't a problem.

[Mickael Guessant]

DavMail will never trigger a message download on its own, all message downloads are the result of client command.

We have a few challenges related to the Exchange (or Office 365) backend and the fact that DavMail is not a standalone IMAP server:

• We don't have exact message size until we get full MIME body from the server
  => we have to get full message content before sending it down to the client
  => this means the IMAP client doesn't receive any content during the initial download from Exchange phase (this would not be the case with a normal IMAP server)
  => as a workaround to this, the "keep alive" mechanism sends (non IMAP compliant) spaces to the client to help maintain the connection open

• any change to message flags changes its IMAP uid on Exchange
  => this is not compliant with IMAP RFC
  => DavMail tries to workaround this by detecting changed IMAP uids and restoring original uid. This works only on a single connection

As far as I understand, the issue on a slow connection is the following use case:

• Thunderbird lists folder messages => OK even on slow connections
• Thunderbird tries to fetch a small message => OK
• Thunderbird tries to fetch a large message => DavMail creates a separate message download thread, and periodically sends ' ' characters on the connection
• Thunderbird hits some kind of read timeout on the connection, opens another connection and tries to fetch the message again
  => DavMail is not aware of this and the original message download thread is still running => There must be a way to detect this but I haven't found it yet.
  => On the new connection DavMail receives a new FETCH command, creates a new separate thread to download message
• Eventually Thunderbird hits read timeout again, opens another connection and tries to fetch the message again

We could implement a mechanism to block the duplicate FETCH command, but this would not help much as the initial connection is closed on Thunderbird side.

I see at least two issues there:

• there must be a way to detect initial client side timeout, if Thunderbird closes the connection we should be aware of it on DavMail side, to at least cancel folder download thread
• there must be a way to change Thunderbird read timeout to avoid this behaviour completely

Fixing the second one is definitely on Thunderbird side, fixing the first one would at least avoid the "multiple parallel download of the same message" effect, but would not help Thunderbird actually succeed.

Until we find a fix for this, the only available workaround is to move DavMail on the other side of the slow connection, i.e. host it somewhere closer to Exchange/Office 365, e.g. GCP, Azure or AWS.