Bug 334269

Summary:	Email retrieval comes to a full HALT after BatchFetcher::fetchNextBatch: fetchNextBatch called while fetch is in process error
Product:	[Frameworks and Libraries] Akonadi	Reporter:	Raymond Wooninck <tittiatcoke>
Component:	IMAP resource	Assignee:	Christian Mollekopf <chrigi_1>
Status:	RESOLVED FIXED
Severity:	crash	CC:	kdepim-bugs, lbeltrame, mollekopf, vkrause
Priority:	NOR
Version:	GIT (master)
Target Milestone:	---
Platform:	unspecified
OS:	Linux
Latest Commit:	http://commits.kde.org/kdepim-runtime/0de7f0faef78b570b3930ec34f0320de7f2f055b	Version Fixed In:

Description Raymond Wooninck 2014-05-03 07:41:16 UTC

With the latest commits regarding the IMAP resource last night (Friday May 2), the email retrieval for gmail is no longer working. 

I have the following experience:

1) Email retrieval is very slow. Much slower than before
2) The debug output shows that for each folder all emails are retrieved in batches until the moment that fetchNextBatch is called while a fetchBatch is still active. At this moment, the IMAP resource NO longer retrieves any emails and just comes to a full HALT.
3) You can stop the email retrieval at that moment, but with the next scheduled one, this again comes to a HALT after the same message. 

The debug output in the console is :

akonadi_imap_resource_13(23100)/kdepimlibs (kimap) BatchFetcher::fetchNextBatch: Fetching  57401  to  57500
akonadi_imap_resource_13(23100)/kdepimlibs (kimap) BatchFetcher::fetchNextBatch: Fetching  57501  to  57600
akonadi_imap_resource_13(23100)/kdepimlibs (kimap) BatchFetcher::fetchNextBatch: Fetching  57601  to  57700
akonadi_imap_resource_13(23100)/kdepimlibs (kimap) BatchFetcher::fetchNextBatch: Fetching  57701  to  57800
akonadi_imap_resource_13(23100) BatchFetcher::fetchNextBatch: fetchNextBatch called while fetch is in process 
akonadi_imap_resource_11(23099)/kdecore (KConfigSkeleton) KCoreConfigSkeleton::writeConfig:
akonadi_imap_resource_10(23098)/kdecore (KConfigSkeleton) KCoreConfigSkeleton::writeConfig:
akonadi_imap_resource_10(23098)/kdepimlibs (kimap) RetrieveItemsTask::startRetrievalTasks: Starting retrieval for  "INBOX.Spam"
akonadi_imap_resource_11(23099)/kdepimlibs (kimap) RetrieveItemsTask::startRetrievalTasks: Starting retrieval for  "INBOX.Trash"
akonadi_imap_resource_10(23098)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: Starting message retrieval. Elapsed(ms):  374
akonadi_imap_resource_10(23098)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: MessageCount:  0 Local message count:  0
akonadi_imap_resource_10(23098)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: UidNext:  1 Local UidNext:  1
akonadi_imap_resource_10(23098)/kdepimlibs (kimap) RetrieveItemsTask::onFinalSelectDone: HighestModSeq:  1 Local HighestModSeq:  1


Reproducible: Always

Steps to Reproduce:
1. Try to retrieve emails
2.
3.
Actual Results:  
Emails are not retrieved and IMAP resource comes to a HALT

Expected Results:  
Emails are retrieved normally

Comment 1 Raymond Wooninck 2014-05-03 12:48:21 UTC

For now I have resolved the situation with reverting commit a5cd38deac8f6bbdd46bdcf88a4dfaf581b27e5c . I know that this is not optimal and I might loose locally some email, but at least I am able to synchronize.

Comment 2 Christian Mollekopf 2014-05-04 19:29:40 UTC

Git commit c8763c863111afe99cda997bb9ca7e481d0e5142 by Christian Mollekopf.
Committed on 04/05/2014 at 19:29.
Pushed by cmollekopf into branch 'master'.

IMAP-Resource: Fixed stuck BatchFetcher

The continuation request can be delivered while a fetch job is in progress
if we deliver too many messages (which is likely with the uid based fetches
where we can't predict the exact amount of fetched messages). In this
case we need to remember the continuation request, and automatically proceed.

This causes m_fetchedItemsInCurrentBatch to be off by the messages we delivered
too many, but that's not a problem as it means we just deliver too many messages
during every batch.

M  +11   -1    resources/imap/retrieveitemstask.cpp

http://commits.kde.org/kdepim-runtime/c8763c863111afe99cda997bb9ca7e481d0e5142

Comment 3 Raymond Wooninck 2014-05-04 20:04:12 UTC

I can confirm that with this commit the HALT situation is no longer occurring.

Comment 4 Christophe Marin 2014-05-04 20:36:16 UTC

Do the last changes switch the imap resource to read only while it's refetching ? 

I'm seeing this kind of messages (not directly related to this commit but also visible with it):

akonadi_imap_resource_0(11329) RetrieveItemsTask::onExpungeDone: Expunge failed:  "Expunge failed, server replied: A000009 NO mailbox selected READ-ONLY " 
akonadi_imap_resource_1(11332) RetrieveItemsTask::onExpungeDone: Expunge failed:  "Expunge failed, server replied: A000009 NO mailbox selected READ-ONLY " 
akonadi_imap_resource_0(11329) RetrieveItemsTask::onExpungeDone: Expunge failed:  "Expunge failed, server replied: A000015 NO mailbox selected READ-ONLY " 
akonadi_imap_resource_1(11332) RetrieveItemsTask::onExpungeDone: Expunge failed:  "Expunge failed, server replied: A000015 NO mailbox selected READ-ONLY "

which disappear if I reroll kdepim-runtime to a commit from before the last changes

(server capabilities:
IMAP4REV1
ACL
BINARY
CATENATE
CHILDREN
CONDSTORE
ENABLE
ESEARCH
ESORT
I18NLEVEL=1
ID
IDLE
LIST-EXTENDED
LIST-STATUS
LITERAL+
LOGIN-REFERRALS
MULTIAPPEND
NAMESPACE
QRESYNC
QUOTA
RIGHTS=EKTX
SASL-IR
SEARCHRES
SORT
THREAD=ORDEREDSUBJECT
UIDPLUS
UNSELECT
WITHIN
XLIST
)

Comment 5 Christian Mollekopf 2014-05-05 07:04:48 UTC

(In reply to comment #4)
> Do the last changes switch the imap resource to read only while it's
> refetching ? 
> 
> I'm seeing this kind of messages (not directly related to this commit but
> also visible with it):
> 
> akonadi_imap_resource_0(11329) RetrieveItemsTask::onExpungeDone: Expunge
> failed:  "Expunge failed, server replied: A000009 NO mailbox selected
> READ-ONLY " 
> akonadi_imap_resource_1(11332) RetrieveItemsTask::onExpungeDone: Expunge
> failed:  "Expunge failed, server replied: A000009 NO mailbox selected
> READ-ONLY " 
> akonadi_imap_resource_0(11329) RetrieveItemsTask::onExpungeDone: Expunge
> failed:  "Expunge failed, server replied: A000015 NO mailbox selected
> READ-ONLY " 
> akonadi_imap_resource_1(11332) RetrieveItemsTask::onExpungeDone: Expunge
> failed:  "Expunge failed, server replied: A000015 NO mailbox selected
> READ-ONLY "
> 
> which disappear if I reroll kdepim-runtime to a commit from before the last
> changes
> 
> (server capabilities:
> IMAP4REV1
> ACL
> BINARY
> CATENATE
> CHILDREN
> CONDSTORE
> ENABLE
> ESEARCH
> ESORT
> I18NLEVEL=1
> ID
> IDLE
> LIST-EXTENDED
> LIST-STATUS
> LITERAL+
> LOGIN-REFERRALS
> MULTIAPPEND
> NAMESPACE
> QRESYNC
> QUOTA
> RIGHTS=EKTX
> SASL-IR
> SEARCHRES
> SORT
> THREAD=ORDEREDSUBJECT
> UIDPLUS
> UNSELECT
> WITHIN
> XLIST
> )

We used to unconditionally expunge, even if we don't have the rights, and then silently ignore any errors. I changed that to only conditionally expunging if we have the necessary rights and then checking for errors.
I checked the akonadi rights though and not the actual IMAP ACL's and apparently the check doesn't work in all cases (I get those too for some shared folders).

Comment 6 Christian Mollekopf 2014-05-20 23:15:59 UTC

Git commit 0de7f0faef78b570b3930ec34f0320de7f2f055b by Christian Mollekopf.
Committed on 04/05/2014 at 19:29.
Pushed by cmollekopf into branch 'kolab/integration/4.13.0'.

IMAP-Resource: Fixed stuck BatchFetcher

The continuation request can be delivered while a fetch job is in progress
if we deliver too many messages (which is likely with the uid based fetches
where we can't predict the exact amount of fetched messages). In this
case we need to remember the continuation request, and automatically proceed.

This causes m_fetchedItemsInCurrentBatch to be off by the messages we delivered
too many, but that's not a problem as it means we just deliver too many messages
during every batch.

M  +11   -1    resources/imap/retrieveitemstask.cpp

http://commits.kde.org/kdepim-runtime/0de7f0faef78b570b3930ec34f0320de7f2f055b