#568 4.4.1 EWS creates excessive Exchange 2010 transaction log growth

[Ted Lohman]

DavMail 4.4.1 Bug (major)

Symptom: When using DavMail 4.4.1 Exchange Web Services with Thunderbird, some users cause excessive Exchange 2010 transaction log growth which results in address high replication queues for the Exchange mailbox database.

Cause: For certain users with at least one folder of more than 10,000 items, when DavMail first connects, a huge number of the below transaction are generated:

Line 541881: 2014-05-01 15:55:57,885 DEBUG [ImapConnection-46144-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 8400 fetchCount: 100 highest uid: 36220 lowest uid: 27815

These are repeated over and over in the DavMail log.

Effect: Exchange transaction logs grow massively. This causes the Exchange database replication to fall behind, putting recovery at risk if the primary database copy fails. If we wait long enough, eventually DavMail 4.4.1 gets through the search phase and the transaction logs stop growing and the replication catches up, but the Exchange production environment is at risk for a long period of time.

Exchange version was 2010 SP3 RU3 (14.3.169.1)

The issue will return if the Exchange mailbox is being used normally or if the mailbox is re-opened.
Other information: Reverting DavMail to 4.4.0 or earlier corrects this issue. Below are extracts from the 4.4.1 debug log and the 4.4.0 debug log. The attachement has full logs.

Log 4.4.1 shows

2014-05-08 14:53:33,413 DEBUG [ImapConnection-59879] davmail - > * lsub (\HasNoChildren) "/" "Sync Issues/Local Failures"
2014-05-08 14:53:33,413 DEBUG [ImapConnection-59879] davmail - > * lsub (\HasNoChildren) "/" "Sync Issues/Server Failures"
2014-05-08 14:53:33,413 DEBUG [ImapConnection-59879] davmail - > 2 OK lsub completed
2014-05-08 14:53:33,413 DEBUG [ImapConnection-59879] davmail - < 3 list "" "INBOX"
2014-05-08 14:53:33,475 DEBUG [ImapConnection-59879] davmail - > * list (\HasNoChildren) "/" "INBOX"
2014-05-08 14:53:33,475 DEBUG [ImapConnection-59879] davmail - > 3 OK list completed
2014-05-08 14:53:33,475 DEBUG [ImapConnection-59879] davmail - < 4 select "FIltered"
2014-05-08 14:53:33,569 DEBUG [ImapConnection-59879] davmail.imap.ImapConnection - *
2014-05-08 14:53:33,647 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 100 fetchCount: 100 highest uid: 4598 lowest uid: 4499
2014-05-08 14:53:33,710 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 200 fetchCount: 100 highest uid: 4598 lowest uid: 4399
2014-05-08 14:53:33,772 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 300 fetchCount: 100 highest uid: 4598 lowest uid: 4299
2014-05-08 14:53:33,835 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 400 fetchCount: 100 highest uid: 4598 lowest uid: 4199
2014-05-08 14:53:33,897 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 500 fetchCount: 100 highest uid: 4598 lowest uid: 4099
2014-05-08 14:53:33,944 DEBUG [ImapConnection-59879-LoadFolder] davmail.exchange.ExchangeSession - Search items current count: 600 fetchCount: 100 highest uid: 4598 lowest uid: 3999

Log 4.4.0 shows

2014-05-08 14:50:18,566 DEBUG [ImapConnection-59853] davmail - > * lsub (\HasNoChildren) "/" "Sync Issues/Local Failures"
2014-05-08 14:50:18,566 DEBUG [ImapConnection-59853] davmail - > * lsub (\HasNoChildren) "/" "Sync Issues/Server Failures"
2014-05-08 14:50:18,566 DEBUG [ImapConnection-59853] davmail - > 2 OK lsub completed
2014-05-08 14:50:18,582 DEBUG [ImapConnection-59852] davmail - < 4 select "FIltered"
2014-05-08 14:50:18,582 DEBUG [ImapConnection-59853] davmail - < 3 list "" "INBOX"
2014-05-08 14:50:18,629 DEBUG [ImapConnection-59853] davmail - > * list (\HasNoChildren) "/" "INBOX"
2014-05-08 14:50:18,629 DEBUG [ImapConnection-59853] davmail - > 3 OK list completed
2014-05-08 14:50:18,644 DEBUG [ImapConnection-59853] davmail - < 4 select "INBOX"
2014-05-08 14:50:18,644 DEBUG [ImapConnection-59852] davmail.imap.ImapConnection -
2014-05-08 14:50:18,676 DEBUG [ImapConnection-59853] davmail.imap.ImapConnection -
2014-05-08 14:50:21,144 DEBUG [davmail.imap.ImapServer] davmail - Connection from /127.0.0.1 on port 1143
2014-05-08 14:50:21,144 DEBUG [ImapConnection-59859] davmail.exchange.ExchangeSession - Test configuration status: 302
2014-05-08 14:50:21,144 DEBUG [ImapConnection-59859] davmail - > * OK [CAPABILITY IMAP4REV1 AUTH=LOGIN MOVE] IMAP4rev1 DavMail 4.4.0-2198 server ready
2014-05-08 14:50:21,160 DEBUG [ImapConnection-59859] davmail - < 1 authenticate login
2014-05-08 14:50:21,176 DEBUG [ImapConnection-59859] davmail - > + VXNlcm5hbWU6
2014-05-08 14:50:21,176 DEBUG [ImapConnection-59859] davmail - < d2luZ3RpcHRveXNcdXNlcjIwMTBk
2014-05-08 14:50:21,176 DEBUG [ImapConnection-59859] davmail - > + UGFzc3dvcmQ6
2014-05-08 14:50:21,191 DEBUG [ImapConnection-59859] davmail - < **
2014-05-08 14:50:21,191 DEBUG [ImapConnection-59859] davmail.exchange.ExchangeSession - Got session davmail.exchange.ews.EwsExchangeSession@35bd2a from cache
2014-05-08 14:50:21,269 DEBUG [ImapConnection-59859] davmail - > 1 OK Authenticated
2014-05-08 14:50:21,269 DEBUG [ImapConnection-59859] davmail - < 2 STATUS "Drafts" (UIDNEXT MESSAGES UNSEEN RECENT)
2014-05-08 14:50:21,347 DEBUG [ImapConnection-59859] davmail - > * STATUS "Drafts" (UIDNEXT 1 MESSAGES 0 UNSEEN 0 RECENT 0)
2014-05-08 14:50:21,347 DEBUG [ImapConnection-59859] davmail - > 2 OK STATUS completed
2014-05-08 14:50:21,426 DEBUG [ImapConnection-59852-LoadFolder] davmail.exchange.ExchangeSession - Message IMAP uid: 4598 uid: AAAAAGU1FuXN5PdIkHtBrNHLHNkBABHGd2k5XcNBpv/fwOilNIsAAAB8HTsAAA== ItemId: AAMkAGU3MWNkNjk5LTNkNmUtNDNiMy1iNDczLTk3MDE3MDY1MDQyMgBGAAAAAABlNRblzeT3SJB7QazRyxzZBwARxndpOV3DQab/38DopTSLAAAAe9KoAAARxndpOV3DQab/38DopTSLAAAAfB07AAA= ChangeKey: CQAAABYAAAARxndpOV3DQab/38DopTSLAAAAfDka
2014-05-08 14:50:21,426 DEBUG [ImapConnection-59852-LoadFolder] davmail.exchange.ExchangeSession - Message IMAP uid: 4597 uid: AAAAAGU1FuXN5PdIkHtBrNHLHNkBABHGd2k5XcNBpv/fwOilNIsAAAB8HToAAA== ItemId: AAMkAGU3MWNkNjk5LTNkNmUtNDNiMy1iNDczLTk3MDE3MDY1MDQyMgBGAAAAAABlNRblzeT3SJB7QazRyxzZBwARxndpOV3DQab/38DopTSLAAAAe9KoAAARxndpOV3DQab/38DopTSLAAAAfB06AAA= ChangeKey: CQAAABYAAAARxndpOV3DQab/38DopTSLAAAAfDkW

[Mickael Guessant]

Thanks for this detailed report, the issue is related to the new paging implementation that tries to fix another issue: concurrent changes on folder.

4.4.0 uses fixed pages algorithm:
- retrieve messages 0 to 99
- retrieve message 100 to 101
- ...
=> the same search request multiple times

The issue appears when new messages are added / deleted to the folder during search: DavMail receives multiple times the same message or miss some messages.

To avoid this, I changed the implementation to :
- retrieve messages 0 to 99 order by imapuid desc
- retrieve message 0 to 99 order by imapuid desc, start below lowest retrieved uid
- ...
=> a different search request each time

This may be the root cause of your issue.

Now we need to find a way that does not incure high server load but still fixes the missing/duplicate messages issue

I see at least two approaches:
- increase page size from 100 to 1000 => at least we will send ten times less search requests
- change algorithm back to fixed pages, but detect duplicates and/or sort messages by imapuid asc

[Ted Lohman]

Thank you for the quick response. I don't know enough about this issue to have an opinion of your two approaches. I am glad to test any fix and provide feedback. We have a very large Exchange environment so it is not hard for me to find someone with more than 10,000 items in a folder.

[Mickael Guessant]

A fix is available in latest svn revision:
- search with folderSizeLimit: single search request, order by imapUid descending
- unlimited search: paged search, order by imapUid ascending, detect duplicates

I also changed page size from 100 to 500 to limit request count

[Ted Lohman]

I'm sorry, I can't find the "svn revision". We have some people with Ubuntu/Linux and some with Microsoft Windows. Can you tell me how to test the fix?

[Mickael Guessant]

Please check with latest 4.5.0 release

[Ted Lohman]

We have now tested the 4.5.0 release in the lab and in our production environment with users with the large item count. The 4.5.0 release is working well and is not causing excessive transaction log growth.

Thank you for fixing the issue so quickly!