Bug 343114

In order to find out about why KMail sometimes seems to loose Akonadi I tried what Dan suggested in:

http://lists.kde.org/?l=kde-pim&m=141501040507170&w=2

Re: [Kde-pim] KMail seems to loose connection to Akonadi at times

I did it for my work setup. Where I use a huge IMAP account hosted by Exchange. Exchange seems to not reply in time on some requests or even drop connections, but I´d expect an IMAP client to recover from that condition. I recently switched the account to "download all messages for offline use" after finding out it Akonadi caches about 7 GiB of in in file_db_data anyway (see bug #338402).



Reproducible: Sometimes

Steps to Reproduce:
It just happens after a while. I started KMail as follows for the debugging Dan suggested:

ms@merkaba:~> export AKONADI_SESSION_LOGFILE=/var/tmp/akonadi.log
ms@merkaba:~> akonadictl stop
Akonadi is not running. 
ms@merkaba:~#4> ps aux | grep mysql
martin   23674  2.7  3.4 2766408 566452 ?      Sl   Jan20  19:55 /usr/sbin/mysqld --defaults-file=/home/martin/.local/share/akonadi/mysql.conf --datadir=/home/martin/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-martin.eQY0MM/mysql.socket
ms       27067  9.9  0.7 2297324 124212 ?      Sl   09:18  15:09 /usr/sbin/mysqld --defaults-file=/home/ms/.local/share/akonadi/mysql.conf --datadir=/home/ms/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-ms.g6IkT6/mysql.socket
ms       31987  0.0  0.0  12676  1684 pts/24   S+   11:49   0:00 grep mysql
ms@merkaba:~> kill 27067
ms@merkaba:~> kill 27067
ms@merkaba:~> kill 27067
ms@merkaba:~> kill 27067
ms@merkaba:~> kill 27067
ms@merkaba:~> kill 27067
kill: kill 27067 failed: kein passender Prozess gefunden
ms@merkaba:~#1> kmail

Actual Results:  
I get this on console output:




ms@merkaba:~> kmail2(31990) MessageList::Core::ModelPrivate::viewItemJobStepInternalForJobPass1Fill: Circular In-Reply-To reference loop detected in the message tree 
kmail2(31990) MessageList::Core::ModelPrivate::findMessageParent: Circular In-Reply-To reference loop detected in the message tree



ms@merkaba:~> continuing 
request for item 1669405 "902" failed: "Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken." 
ItemRetrieverException :  Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
posting retrieval request for item 1669405  there are  1  queues and  0  items in mine 
request for item 1669405 still pending - waiting 
processing retrieval request for item 1669405  parts: ("RFC822")  of resource: "akonadi_imap_resource_0" 


ms@merkaba:~> continuing 
request for item 1669405 "902" failed: "Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken." 
ItemRetrieverException :  Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
posting retrieval request for item 1668979  there are  1  queues and  0  items in mine 
request for item 1668979 still pending - waiting 
processing retrieval request for item 1668979  parts: ("RFC822")  of resource: "akonadi_imap_resource_0"


It goes on like this. KMail even displays it in the status line at the bottom of the window. In KMail I see:

- It won´t display a single mail anymore. If just displays the blue background loading contents of current folder message instead of the mail.

- Folder switching still works.

- KMail often shows "Synchronizing folder ext4-ml" with 97% and gets stuck there. Its always 97%.


Expected Results:  
Expected results:

- Akonadi IMAP resource gives up on the time out IMAP request after some time. That said, I don´t understand why it doesn´t succeed after some times, Exchange isn´t that unresponsive either. I may drop a connection, but re-requesting it should eventually give a result.

- KMail would at least locally stored mails for offline usage if it can´t get a response from the IMAP server in time.

- KMail would display other mails stored on the IMAP server, which means that Akonadi IMAP wouldn´t block further IMAP requests, just cause one of them times out. I.e. it would process some amount of requests in parallel.

I have KMail stuck here now and asked on #akonadi on freenode about which parts of the Akonadi session log would be required for further diagnosing of the issue. I certainly won´t upload it all as it contains a ton of confidential information including folder names but also *complete* mails.

At least according to

tail -f akonadi.log.32040.akonadi_imap_resource_0

There does not seem more data after:

ms@merkaba:/var/tmp> tail -f akonadi.log.32040.akonadi_imap_resource_0
S: 1472987 FETCH (UID 1472987 REV 0 REMOTEID "59" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4079 FLAGS ())
S: 1472986 FETCH (UID 1472986 REV 0 REMOTEID "58" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4389 FLAGS ())
S: 1472985 FETCH (UID 1472985 REV 0 REMOTEID "57" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4407 FLAGS ())
S: 1472984 FETCH (UID 1472984 REV 0 REMOTEID "56" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4200 FLAGS ())
S: 1472983 FETCH (UID 1472983 REV 0 REMOTEID "55" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4000 FLAGS ())
S: 1472982 FETCH (UID 1472982 REV 0 REMOTEID "54" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4025 FLAGS ())
S: 1472981 FETCH (UID 1472981 REV 0 REMOTEID "53" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4001 FLAGS ())
S: 1472980 FETCH (UID 1472980 REV 0 REMOTEID "52" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 3988 FLAGS ())
S: 1472979 FETCH (UID 1472979 REV 0 REMOTEID "51" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 3982 FLAGS ())
S: 1472978 FETCH (UID 1472978 REV 0 REMOTEID "50" MIMETYPE "message/rfc822" COLLECTIONID 356 SIZE 4734 FLAGS ())


Also Akonadiconsole is not able to retrieve any payloads anymore. Lets see what I can enable there:

Okay, in the job tracker I see "UID FETCH" some number. One running, rest is waiting.

Akonadi IMAP resource in resource tracker is waiting on FetchItem.

When I click mails in KMail I also see "UID FETCH" as watiing in job tracker.

Well to me it seems Akonadi IMAP resource is stuck.

I am using Akonadi git with MySQL optimization, and Akonadi IMAP resource from 4.14.2 debian packages.

The IMAP resource also doesn´t respond to a "Restart" or "Abort" request in Akonadiconsole.


the Akonadi IMAP resource really seems stuck and Akonadi may serve the folder switching from metadata in the MySQL database instead.

Okay, I will end this.

I will xz the logs:

ms@merkaba:/var/tmp> du -sh akonadi* | sort -rh | head -10
102M    akonadi.log.31990.KMail Kernel ETM
27M     akonadi.log.32040.akonadi_imap_resource_0
1,7M    akonadi.log.32036.akonadi_baloo_indexer
724K    akonadi.log.31990.kmail2-1339195199
168K    akonadi.log.32046.MailFilter Kernel ETM
168K    akonadi.log.32035.Archive Mail Kernel ETM
124K    akonadi.log.32046.akonadi_mailfilter_agent
56K     akonadi.log.32041.akonadi_imap_resource_1
24K     akonadi.log.32048.akonadi_newmailnotifier_agent
20K     akonadi.log.32049.KNotes Session

But as said, tell me what you need, I won´t send it all due to confidentiality issues.

tail -f "akonadi.log.31990.KMail Kernel ETM" also does not give any more results. Seems all stuck. Last in there is:

S: 1667763 FETCH (UID 1667763 REV 0 MIMETYPE "message/rfc822" COLLECTIONID 415 SIZE 4651 FLAGS (\SEEN) ANCESTORS ((415 "/basket-devel-ml") (296 "/KDE") (276 "imap://[…]") (0 "")) PLD:ENVELOPE[1] {235}
("Sat, 26 Oct 2013 22:12:18 +0200" "[Basket-devel] Non-ASCII text storage\r" (("Some name" NIL "some mail user name" "some domain")) NIL NIL ((NIL NIL "basket-devel" "lists.sourceforge.net")) NIL NIL NIL "<526C2222.1070603@gmail.com>" NIL))
S: OK FETCH completed
C: 120 FETCH 1:* COLLECTIONID 411  IGNOREERRORS ANCESTORS INF EXTERNALPAYLOAD (UID COLLECTIONID FLAGS SIZE TAGS PLD:ENVELOPE ATR:entityannotations)

Even if I click mails in KMail, nothing more comes. Actually I am in the basket folder now. So this may be the last it got.

Okay, interesting, when I switch folders in KMail I get somemore. Okay for switching folders I get more output there. But not more in "akonadi.log.32040.akonadi_imap_resource_0".

Okay, and now, after more of half an hour digging into thinks I got a kwallet requester asking for my IMAP password again. But I didn´t close the KDE session or lock the screen. And the progress bar in KMail with Synchronizing ext4-ml at 97% disappeared.

Still I keep getting these:

ms@merkaba:~> continuing 
request for item 2039976 "6" failed: "Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken." 
ItemRetrieverException :  Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
processing retrieval request for item 1363436  parts: ("RFC822")  of resource: "akonadi_imap_resource_0" 
continuing 
request for item 1363436 still pending - waiting 
continuing 
request for item 2520302 still pending - waiting 
posting retrieval request for item 2039977  there are  1  queues and  1  items in mine 
request for item 2039977 still pending - waiting 

ms@merkaba:~>  list is empty 
continuing 
request for item 1363436 "9" failed: "Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken." 
processing retrieval request for item 2520302  parts: ("RFC822")  of resource: "akonadi_imap_resource_0" 
ItemRetrieverException :  Unable to retrieve item from resource: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
continuing 
request for item 2520302 still pending - waiting 
continuing 
request for item 2039977 still pending - waiting 
posting retrieval request for item 1363439  there are  1  queues and  1  items in mine 
request for item 1363439 still pending - waiting 
kmail2(31990) MessageList::Core::ModelPrivate::findMessageParent: Circular reference loop detected in the message tree 
processing retrieval request for item 2039977  parts: ("RFC822")  of resource: "akonadi_imap_resource_0" 
continuing 
continuing 
request for item 2520302 "49727" failed: "Unable to retrieve item from resource: <html>Der Auftrag wurde abgebrochen</html>" 
continuing 
request for item 1363439 still pending - waiting 
request for item 2039977 still pending - waiting 
ItemRetrieverException :  Unable to retrieve item from resource: <html>Der Auftrag wurde abgebrochen</html>
posting retrieval request for item 2520302  there are  1  queues and  1  items in mine 
request for item 2520302 still pending - waiting 
kmail2(31990) MessageList::Core::ModelPrivate::viewItemJobStepInternalForJobPass1Fill: Circular In-Reply-To reference loop detected in the message tree 
kmail2(31990) MessageList::Core::ModelPrivate::findMessageParent: Circular In-Reply-To reference loop detected in the message tree