[Kde-pim] ItemSync assert still happens

Mon Oct 27 10:42:18 GMT 2014

On Wednesday 22 October 2014 11.03:18 David Faure wrote:
> The assert "Calling items retrieval methods although no item retrieval is in
> progress" still happens regularly to me, even after the ItemSync error
> handling fix that went in recently. This time it seems purely related to
> losing the connection (due to using suspend, then resume, and switching
> wifi networks).
> 
> It used to work, so I suspect commits a13c4655ea5 and 73dd22e5f (hi
> Christian :).
> 

I doubt these commits are the problem, but feel free to educate me ;-)

IMO the problem is that neither the resourcebase interface nor the imap 
resource task mechanism can actually deal with cancelled tasks. If a task is 
cancelled (i.e. due to disconnect), while the collectionfetchjob in 
ResourceBase::synchronizeCollection is in progress, resourcebase will happly 
continue to execute the task after it has already been aborted.

Similar situation can arise in the imap-resource code where I had to issue new 
fetchjobs because resourcebase failed to provide up-to-date versions of the 
collections.

A similar situation can arise if an imap resourcetask calls cancelTask twice. 
Once because i.e. the connection was dropped and it's cancelled by 
ResourceTask, and once because an operation was ongoing while the connection 
was dropped. Cancelling a task twice will result in a similar crash.

I have some patches that could mitigate the problems, but I didn't yet get to 
backport them and push them for review.

> Here's the debug output - with extra debug output of mine.
> 
> 10:10:29 akonadi_imap_resource_1(20257) ImapResourceBase::retrieveItems:
> 10:10:29 akonadi_imap_resource_1(20257) ResourceTask::~ResourceTask:
> ResourceTask(0x2b6cbc0) releasing session KIMAP::Session(0x2604e50)
> 10:10:29 akonadi_imap_resource_1(20257)
> ImapResourceBase::onItemRetrievalCollectionFetchDone: 10:10:29
> akonadi_imap_resource_1(20257)
> ImapResourceBase::onItemRetrievalCollectionFetchDone: 10:10:29
> akonadi_imap_resource_1(20257) ImapResourceBase::startTask: 10:10:29
> akonadi_imap_resource_1(20257) ResourceTask::start: Starting task
> RetrieveItemsTask(0x2b7ab80) 10:10:29 akonadi_imap_resource_1(20257)
> SessionPool::requestSession: pending requests: (299) 10:10:29
> akonadi_imap_resource_1(20257) SessionPool::processPendingRequests: session
> ready: 299 KIMAP::Session(0x2604e50) 10:10:29
> akonadi_imap_resource_1(20257) ResourceTask::onSessionRequested: task
> RetrieveItemsTask(0x2b7ab80) session request says 299 0 "" 10:10:29
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> RetrieveItemsTask::startRetrievalTasks: Starting retrieval for 
> "INBOX/teamleads" 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs
> (kimap) RetrieveItemsTask::onFinalSelectDone: Starting message retrieval.
> Elapsed(ms):  322 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs
> (kimap) RetrieveItemsTask::onFinalSelectDone: MessageCount:  5181 Local
> message count:  5181 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs
> (kimap) RetrieveItemsTask::onFinalSelectDone: UidNext:  5184 Local UidNext:
>  5177 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> RetrieveItemsTask::onFinalSelectDone: HighestModSeq:  5657 Local
> HighestModSeq:  5640 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs
> (kimap) RetrieveItemsTask::onFinalSelectDone: Fetching new messages:
> UidNext:  5184  Old UidNext:  5177 10:10:29
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ResourceBase::setTotalItems: 5181 10:10:29
> akonadi_imap_resource_1(20257)/libakonadi Akonadi::ItemSync::setTotalItems:
> 5181 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> BatchFetcher::fetchNextBatch: Fetching  1  intervals 10:10:29
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ItemSync::setFullSyncItems: Received:  2 In total:  2  Wanted: 
> 5181 10:10:29 akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ItemSync::setFullSyncItems: Received:  2 In total:  4  Wanted: 
> 5181 10:10:29 akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ItemSync::setFullSyncItems: Received:  3 In total:  7  Wanted: 
> 5181 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> RetrieveItemsTask::listFlagsForImapSet: Listing flags  1 5176 10:10:29
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> RetrieveItemsTask::listFlagsForImapSet: Starting flag retrieval.
> Elapsed(ms):  653 10:10:29 akonadi_imap_resource_1(20257)/kdepimlibs
> (kimap) BatchFetcher::fetchNextBatch: Fetching  1  intervals 10:10:30
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ItemSync::setFullSyncItems: Received:  314 In total:  321  Wanted:
>  5181 10:10:30 akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ProtocolHelper::streamPayloadToFile: Wrote 8430 bytes to 
> "/home/dfaure/.local/share/akonadi/file_db_data/5335304_r19" 10:10:30
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ProtocolHelper::streamPayloadToFile: Wrote 8934 bytes to 
> "/home/dfaure/.local/share/akonadi/file_db_data/5335310_r19" 10:10:30
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ItemSync::setFullSyncItems: Received:  686 In total:  1007 
> Wanted:  5181 10:10:30 akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ProtocolHelper::streamPayloadToFile: Wrote 10067 bytes to 
> "/home/dfaure/.local/share/akonadi/file_db_data/5335928_r12" 10:10:30
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ProtocolHelper::streamPayloadToFile: Wrote 8224 bytes to 
> "/home/dfaure/.local/share/akonadi/file_db_data/5336167_r8" 10:10:30
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ProtocolHelper::streamPayloadToFile: Wrote 9548 bytes to 
> "/home/dfaure/.local/share/akonadi/file_db_data/5336378_r6" < here I used
> suspend, went to the office, resumed, connected to the another wifi network
> > 10:33:26 akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> BatchFetcher::fetchNextBatch: Fetching  1  intervals 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionPrivate::onSocketTimeout: Socket timeout! 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionThread::doCloseSocket: close 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionThread::slotSocketDisconnected: 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionPrivate::socketDisconnected: 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionPrivate::socketDisconnected: state= 3 10:34:06
> akonadi_imap_resource_1(20257) ResourceTask::cancelTask:
> RetrieveItemsTask(0x2b7ab80) "Connection lost" 10:34:06
> akonadi_imap_resource_1(20257) ResourceState::cancelTask: 10:34:06
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionPrivate::socketDisconnected: emit connectionLost 10:34:06
> akonadi_imap_resource_1(20257) BatchFetcher::onHeadersFetchDone: Fetch job
> failed  "Connection to server lost." 10:34:06
> akonadi_imap_resource_1(20257) RetrieveItemsTask::onFlagsFetchDone: ""
> 10:34:06 akonadi_imap_resource_1(20257) ResourceTask::cancelTask:
> RetrieveItemsTask(0x2b7ab80) "" 10:34:06 akonadi_imap_resource_1(20257)
> ResourceState::cancelTask: 10:34:06 akonadi_imap_resource_1(20257)
> ImapResourceBase::retrieveItems: 10:34:07 akonadi_imap_resource_1(20257)
> ImapResourceBase::onItemRetrievalCollectionFetchDone: 10:34:07
> akonadi_imap_resource_1(20257)
> ImapResourceBase::onItemRetrievalCollectionFetchDone: 10:34:07
> akonadi_imap_resource_1(20257) ImapResourceBase::startTask: 10:34:07
> akonadi_imap_resource_1(20257) ResourceTask::start: Starting task
> RetrieveItemsTask(0x2b7aa90) 10:34:07 akonadi_imap_resource_1(20257)
> SessionPool::requestSession: pending requests: (300) 10:34:07
> akonadi_imap_resource_1(20257) SessionPool::processPendingRequests: create
> new session by calling requestPassword 10:34:07
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::LoginJob::LoginJob: KIMAP::LoginJob(0x26981a0) 10:34:07
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionThread::reconnect: connectToHost "mail.kdab.com" 993 10:34:17
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::LoginJob::connectionLost: Connection to server lost  7 10:34:17
> akonadi_imap_resource_1(20257) SessionPool::cancelSessionCreation: Killing
> 10:34:17 akonadi_imap_resource_1(20257) SessionPool::cancelSessionCreation:
> sessionRequestDone(error) for first pending request 300 8 "Could not
> connect to the IMAP-server mail.kdab.com. Connection to server lost."
> 10:34:17 akonadi_imap_resource_1(20257) ResourceTask::onSessionRequested:
> task RetrieveItemsTask(0x2b7aa90) session request says 300 8 "Could not
> connect to the IMAP-server mail.kdab.com. Connection to server lost."
> 10:34:17 akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::SessionThread::doCloseSocket: close 10:34:17
> akonadi_imap_resource_1(20257) ResourceTask::onSessionRequested: Cancelling
> this request. Probably there is no more session available. 10:34:17
> akonadi_imap_resource_1(20257) ResourceState::cancelTask: 10:34:17
> akonadi_imap_resource_1(20257) SessionPool::cancelSessionCreation: emit
> connectDone 8 "Could not connect to the IMAP-server mail.kdab.com. Could
> not connect to the IMAP-server mail.kdab.com.
> Connection to server lost." (now at end of method)
> 10:34:17 akonadi_imap_resource_1(20257) ImapResourceBase::doSetOnline:
> online= false 10:34:17 akonadi_imap_resource_1(20257) ResourceTask::kill:
> 10:34:17 akonadi_imap_resource_1(20257) ResourceTask::cancelTask:
> RetrieveItemsTask(0x2b7aa90) "killed" 10:34:17
> akonadi_imap_resource_1(20257) ResourceState::cancelTask: 10:34:17
> akonadi_imap_resource_1(20257) SessionPool::cancelPasswordRequests: NEW
> CODE PATH (commit a13c4655ea) 10:34:17 akonadi_imap_resource_1(20257)
> ImapIdleManager::~ImapIdleManager: STOP IDLE 10:34:17
> akonadi_imap_resource_1(20257)/kdepimlibs (kimap)
> KIMAP::LoginJob::~LoginJob: KIMAP::LoginJob(0x26981a0) 10:34:17
> akonadi_imap_resource_1(20257) ImapResourceBase::retrieveItems: 10:34:18
> akonadi_imap_resource_1(20257)
> ImapResourceBase::onItemRetrievalCollectionFetchDone: 10:34:18
> akonadi_imap_resource_1(20257)/libakonadi
> Akonadi::ResourceBasePrivate::createItemSyncInstanceIfMissing: Calling
> items retrieval methods although no item retrieval is in progress 0 ASSERT
> failure in createItemSyncInstance: "Calling items retrieval methods
> although no item retrieval is in progress", file
> /d/kde/src/4/kde/kdepimlibs/akonadi/resourcebase.cpp, line 180

_______________________________________________
KDE PIM mailing list kde-pim at kde.org
https://mail.kde.org/mailman/listinfo/kde-pim
KDE PIM home page at http://pim.kde.org/