Bug 327894

Daniel,

Thanks for update.
Could you advice which packages I need for proper bug-report?

Thank you.
Arthur


Daniel Vrátil[1] changed bug 327894[2] 


*What*
*Removed*
*Added*
CC
  
dvratil@redhat.com, kdepim-bugs@kde.org, vkrause@kde.org 
Component
message list 
IMAP resource 
Version
4.11.3 
4.11 
Assignee
kdepim-bugs@kde.org 
chrigi_1@fastmail.fm 
Product
kmail2 
Akonadi 

--------------------
     *  You reported the bug. 



--------
[1] mailto:dvratil@redhat.com
[2] https://bugs.kde.org/show_bug.cgi?id=327894

We will need some debug info to be able to do anything about this.
Please see http://techbase.kde.org/Projects/PIM/Akonadi/Debug_IMAP#How_To_Create_Useful_Bugreports_for_the_Akonadi_IMAP_Resource

Created attachment 84133 [details]
attachment-3432-0.html

enclosed some log info.

I am trying to get more (when I understand how to get it)

this is info from:
~$ export KIMAP_LOGFILE=/tmp/imap.log
~$ akonadictl restart

Then I deleted some files, the second to last line popped up.
Then I synced kmail. After a while the last line popped up.

I  could not figure out how to get to the log files. Maybe this info is already helpfull.

Issue is still not resolved.




roland@delorean.net[1] changed bug 327894[2] 


*What*
*Removed*
*Added*
CC
  
roland@delorean.net 

--------------------
     *  You reported the bug. 



--------
[1] mailto:roland@delorean.net
[2] https://bugs.kde.org/show_bug.cgi?id=327894

Created attachment 84134 [details]
attachment-3432-1.dat

Created attachment 84135 [details]
nepomuk_info

What is the mail server you are connecting to?

I have the same problem with an account on a server with postfix 2.9.6. But I do not see this problem with an account on a zimbra server. It might be a new incompatibility between kmail and postfix.

We will need the imap logs. .dat file is empty, and nepomuk info is not useful to debug this.

With:
$ export KIMAP_LOGFILE=/tmp/imap.log
$ akonadictl restart

you should get the imap logs in /tmp/, and those should be useful.
(~/.xsession-errors is also useful if all imap* things are turned on in kdebugdialog)

Created attachment 84146 [details]
attachment-16231-0.html

OK, sorry for the confusion. 
Here is the info.
Attached the log files.

Below the output generated by the terminal. It was so much more, maybe it contains 
something usefull.


Keep up the good work!

Arthur



akonadi.collectionattributetable                   OK
akonadi.collectionmimetyperelation                 OK
akonadi.collectionpimitemrelation                  OK
akonadi.collectiontable                            OK
akonadi.flagtable                                  OK
akonadi.mimetypetable                              OK
akonadi.parttable                                  OK
akonadi.pimitemflagrelation                        OK
akonadi.pimitemtable                               OK
akonadi.resourcetable                              OK
akonadi.schemaversiontable                         OK
mysql.columns_priv                                 OK
mysql.db                                           OK
mysql.event                                        OK
mysql.func                                         OK
mysql.general_log                                  OK
mysql.help_category                                OK
mysql.help_keyword                                 OK
mysql.help_relation                                OK
mysql.help_topic                                   OK
mysql.host                                         OK
mysql.ndb_binlog_index                             OK
mysql.plugin                                       OK
mysql.proc                                         OK
mysql.procs_priv                                   OK
mysql.proxies_priv                                 OK
mysql.servers                                      OK
mysql.slow_log                                     OK
mysql.tables_priv                                  OK
mysql.time_zone                                    OK
mysql.time_zone_leap_second                        OK
mysql.time_zone_name                               OK
mysql.time_zone_transition                         OK
mysql.time_zone_transition_type                    OK
mysql.user                                         OK
Connecting to deprecated signal 
QDBusConnectionInterface::serviceOwnerChanged(QString,QString,QString)
search paths:  ("/usr/lib/lightdm/lightdm", "/usr/local/sbin", "/usr/local/bin", "/usr/sbin", 
"/usr/bin", "/sbin", "/bin", "/usr/games", "/usr/local/games") 
search paths:  ("/home/arthur/.kde/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", 
"/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/lib/qt4/plugins", "/usr/bin", 
"/usr/lib/kde4/plugins", "/home/arthur/.kde/lib/kde4/", "/usr/lib/kde4/") 
search paths:  ("/home/arthur/.kde/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", 
"/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/lib/qt4/plugins", "/usr/bin", 
"/usr/lib/kde4/plugins", "/home/arthur/.kde/lib/kde4/", "/usr/lib/kde4/") 
search paths:  ("/home/arthur/.kde/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", 
"/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/lib/qt4/plugins", "/usr/bin", 
"/usr/lib/kde4/plugins", "/home/arthur/.kde/lib/kde4/", "/usr/lib/kde4/") 
AkonadiAgentServer(9091)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_ical_resource_0"
AkonadiAgentServer(9091)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
search paths:  ("/home/arthur/.kde/lib/kde4/plugins/", "/usr/lib/kde4/plugins/", 
"/usr/lib/x86_64-linux-gnu/qt4/plugins", "/usr/lib/qt4/plugins", "/usr/bin", 
"/usr/lib/kde4/plugins", "/home/arthur/.kde/lib/kde4/", "/usr/lib/kde4/") 
AkonadiAgentServer(9088)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_akonotes_resource_0"
akonadi_maildispatcher_agent(9094)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
AkonadiAgentServer(9088)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
AkonadiAgentServer(9093)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_maildir_resource_0"
AkonadiAgentServer(9090)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_contacts_resource_0"
akonadi_maildispatcher_agent(9094)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
AkonadiAgentServer(9093)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
AkonadiAgentServer(9090)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
akonadi_maildispatcher_agent(9094)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_imap_resource_0(9092)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_imap_resource_0(9092)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_maildispatcher_agent(9094)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_maildispatcher_agent(9094)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_imap_resource_0(9092)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing old cached entry due to collision.
akonadi_imap_resource_0(9092)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_newmailnotifier_agent(9097)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing old cached entry due to collision.
akonadi_imap_resource_0(9092)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_maildispatcher_agent(9094)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_maildispatcher_agent"
akonadi_newmailnotifier_agent(9097)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_maildispatcher_agent(9094)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
akonadi_imap_resource_0(9092)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_imap_resource_0"
akonadi_imap_resource_0(9092)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
akonadi_newmailnotifier_agent(9097)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_archivemail_agent(9089)/libakonadi Akonadi::SessionPrivate::init: 
"akonadi_archivemail_agent"
akonadi_archivemail_agent(9089)/libakonadi Akonadi::SessionPrivate::reconnect: 
connectToServer "/tmp/akonadi-arthur.6NPnuB/akonadiserver.socket"
akonadi_nepomuk_feeder(9096)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_newmailnotifier_agent(9097)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.
akonadi_nepomuk_feeder(9096)/KSharedDataCache KSharedDataCache::insert: 
Overwriting existing cached entry due to collision.

Created attachment 84147 [details]
attachment-16231-1.dat

Created attachment 84148 [details]
imap.log.9092.2

Created attachment 84149 [details]
.xsession-errors

I could resolve the problem for my setup by replacing the IMAP server. I was working with uw-imapd before, but this server can not handle multiple simultaneous connections. The kmail log files showed, that kmail and/or akonadi open two IMAP connections. Because of the uw-imapd limitation, the second one was read-only. This was the reason why kmail was not able to delete the messages I moved to trash. After replacing uw-imapd with dovecot-imap, everything works perfect.

May be, this information helps you tracking down the problem in your environment.

(In reply to comment #12)
> I could resolve the problem for my setup by replacing the IMAP server. I was
> working with uw-imapd before, but this server can not handle multiple
> simultaneous connections. The kmail log files showed, that kmail and/or
> akonadi open two IMAP connections. Because of the uw-imapd limitation, the
> second one was read-only. This was the reason why kmail was not able to
> delete the messages I moved to trash. After replacing uw-imapd with
> dovecot-imap, everything works perfect.
> 
> May be, this information helps you tracking down the problem in your
> environment.

The imap resource works with a session pool that has a fixed size of 2 (and a session corresponds to a tcp connection to the server). Typically one session is used for IDLE and the other for all other requests. If IDLE is not supported by the server two session are anyways allocated and used.

I'm not sure whether we anyways want to work with multiple session to emulate pipelining or if we should resize the session pool to 1 if IDLE is not supported (or even have a dedicated session for IDLE).

Maybe the following info will help:

- I can delete the mails. Yet, if I synchronise, these deleted mails are downloaded again. 
- My imap is roundcube (only one)
- I did not have that problem before. The beta of Saucy did not have this problem. The beta crashed (my mistake). Afterwards, I did a secure erase of the disk, so no info would influence my clean install. No upgrade of the firmware either (intel xeon sandy bridge, intel s1200btl board)

NB: merry christmas holidays

Art

I have a problem with exact same symptoms (messages sent to trash appear seconds later as ghosts, have to delete from separate MUA) but have not done quite as deep an investigation. In my case the server is Dovecot and multiple simultaneous connections from different clients works perfectly fine. I'm not sure any other client uses more than one session to the same server at a time except for bulk download.

The use of a separate thread for IDLE makes no sense to me, it sounds like whomever set that up didn't quite get the concept. The intended way to use IMAP IDLE, and the way basically everything else that works does it, is you connect, refresh mail, perform whatever user actions have been queued, then call IDLE and you stop. Whenever the connection closes, that means something changes so you repeat the process starting at connect, refresh everything, do queued user-initiated actions, call IDLE, wait. ad naseum.

Hello,

Some additional information.

My imap server is Gandi, using roundcube.

From their site nothing changed.
 
I am still having this issue and really have no clue how to solve it.

(In reply to comment #15)
> I have a problem with exact same symptoms (messages sent to trash appear
> seconds later as ghosts, have to delete from separate MUA) but have not done
> quite as deep an investigation. In my case the server is Dovecot and
> multiple simultaneous connections from different clients works perfectly
> fine. I'm not sure any other client uses more than one session to the same
> server at a time except for bulk download.
> 
> The use of a separate thread for IDLE makes no sense to me, it sounds like
> whomever set that up didn't quite get the concept. The intended way to use
> IMAP IDLE, and the way basically everything else that works does it, is you
> connect, refresh mail, perform whatever user actions have been queued, then
> call IDLE and you stop. Whenever the connection closes, that means something
> changes so you repeat the process starting at connect, refresh everything,
> do queued user-initiated actions, call IDLE, wait. ad naseum.

That doesn't resemble anything in RFC 2177. AFAIU IDLE works like this:
* the client opens a connection
* the client sends IDLE command
* the server can now send unsolicited responses for for arriving mail etc.
* the client stops the command using DONE

We're doing this in a separate session, which should work. Ideally we would be reconnecting every 29mins to keep the server from closing the connection, but currently we simply wait for the server to close the connection and then reopen a new one.

Anyways, this probably has nothing to do with the bug at hand.

Christian,

I am using it on a single machine, with only one user. (desk top)
Do you have the problem as desktop or as server?

If as desktop, how many accounts are defined? (maybe this could be the issue)

Reg.
Art

It's been quite some time since I looked at the RFC and perhaps got some parts crossed with what is done for mobile devices (phones) where any loss of the TCP session triggers a reconnect and fetch of new messages. In that context, the device wants to be as idle as possible for powersaving reasons so it doesn't want to have a live session with traffic as it has to wake up to some extent any time there is data to process. After the connect and fetch, the mobile device will idle the connection and expects no data transfer until the user initiates an action. If the server has something new, it just closes the session and the mobile device will then fetch new data upon reconnect. If the TCP session drops for any other reason, the device reconnects and attempts to fetch new data just the same. That is an elegantly simple solution which relies on a single connection for everything.

I observe the following symptoms:

- When I delete mails using the delete-key, they disappear from the IMAP-folder, but do not appear in the Trash (local folder).
- After syncing the IMAP folder the mails reappear.
- Moving mails by drag and drop works as expected, *even when moving to the Trash*. (Moving to other IMAP-folders works as well.)

The symptoms started when I upgraded from akonadi-server-1.10.3 to akonadi-server-1.11.0. I performed no other updates at that time.  (I'm running gentoo stable, KDE version is 4.11.5)

I have  the same problem with IMAP (server - Exchange 2003) and expiration. From time to time (sometimes several times per day) akonadi tries to delete messages that was expired and then re-download it with message "downloading missing mail bodies"

Okay, I can add another imapd to the pool: cyrus-imapd as of openSUSE 13.2.

I cannot delete any mails, neither with <delete> (move to trash), nor <shift><delete>, nor by d'n'd.
Same case for moving mail to other folders.

Setup: openSUSE 13.2/x86_64 on both server and client, cyrus-imapd-2.4.17, kdepim 4.14.{5,6,8,9}

Result always similar to:
akonadi_imap_resource_1(11917) RetrieveItemsTask::onFinalSelectDone: Detected 
inconsistency in local cache, we're missing some messages. Server:  13722  Local:  13721 
akonadi_imap_resource_1(11917) RetrieveItemsTask::onFinalSelectDone: 
Refetching complete mailbox. 

After refetching, the mail appears again in the source folder (disabled).
After clicking on the open letter symbol, the mail can be opened again.
The same happens, if I hit <shift><delete> apart from the trash folder copy.

I've tried everything serveral times, one would usually do with such issues:
 * restarting akonadi correctly (that is akonadictl stop, wait for all
   processes  finishing, akonadictl start
 * removing the akonadi cache with akonadiconsole
 * rebuilding the akonadi database from scratch (¹)
 * reconstructing the mailboxes on the cyrus server (reconstruct -GR ...)

The akonadi DB is living on a local SSD in a otherwise idle XFS filesystem.

Here's an excerpt of the offending operation from the log including some comments:

# client copies the mail 32602 to the trash folder (german version)
C: A000024 UID COPY 32602 "INBOX.M&APw-lleimer"
# server successfully created 9933 in trash
S: A000024 OK Completed [ COPYUID 1432637812 32602 9933  ]
# client flags mail as deleted
C: A000025 UID STORE 32602 +FLAGS (\Deleted)
# server flagged it as deleted, seen was set before
S: * 13712 FETCH ( FLAGS (\Deleted \Seen) UID 32602 )
S: A000025 OK Completed
# client investigates folder settings
C: A000026 GETANNOTATION "INBOX" "*" "value.shared"
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/duplicatedeliver ( value.shared false )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/sharedseen ( value.shared false )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/pop3newuidl ( value.shared true )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/lastpop ( value.shared   )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/lastupdate ( value.shared  9-Jun-2015 14:57:56 +0200 )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/size ( value.shared 2371801752 )
S: * ANNOTATION INBOX /vendor/cmu/cyrus-imapd/partition ( value.shared default )
S: A000026 OK Completed
C: A000027 GETACL "INBOX"
S: * ACL INBOX hp lrswipcda cyrus lrswipkxtecda
S: A000027 OK Completed
C: A000028 MYRIGHTS "INBOX"
S: * MYRIGHTS INBOX lrswipkxtecda
S: A000028 OK Completed
C: A000029 GETQUOTAROOT "INBOX"
S: * QUOTAROOT INBOX user.hp
S: * QUOTA user.hp ( STORAGE 54982759 100000000 )
S: A000029 OK Completed
# client investigates folder state
C: A000030 SELECT "INBOX" (CONDSTORE)
S: * OK Ok [ CLOSED  ]
S: * 13724 EXISTS
S: * 0 RECENT
S: * FLAGS ( \Answered \Flagged \Draft \Deleted \Seen $TODO $NOTJUNK $JUNK )
S: * OK Ok [ PERMANENTFLAGS ( \Answered \Flagged \Draft \Deleted \Seen $TODO $NOTJUNK $JUNK \* )  ]
S: * OK Ok [ UNSEEN 13670  ]
S: * OK Ok [ UIDVALIDITY 1430161627  ]
S: * OK Ok [ UIDNEXT 32615  ]
S: * OK Ok [ HIGHESTMODSEQ 1235  ]
S: * OK Ok [ URLMECH INTERNAL  ]
S: A000030 OK Completed [ READ-WRITE  ]

Server responded with 13724 mails in this folder. This is the problem, since
akonadi expects 13723 mails only:

akonadi_imap_resource_1(25099) RetrieveItemsTask::onFinalSelectDone: Detected inconsistency in local cache, we're missing some messages. Server:  13724  Local:  13723 

Resulting in a full refetch. Although missing in the log, be assured, that there were
13724 mails in that folder before this operation.

Is that result to be expected? Shouldn't it be 13723 on the server side, too?
Could this be some kind of server side race?

WARNING:

This issue boiled down as a PEBCAK for me: I disabled the option

    Compress folder automatically (removes messages flagged as deleted)

on the advanced tab of the IMAP account settings dialog for some (performance related) reasons and forgot about it. Unfortunately, this leads to the buggy behaviour described above. 

@ the developers:
Please show a serious version of a warning dialog every time the IMAP account settings dialog is about to close, if this option is disabled:

"Be aware, that, if you disable this option, you cannot move or delete any mails successfully anymore, and if you attempt to do so, your mails are COPIED to trash/other folder AND left in place. While at it, expect more silly behaviour from akonadi, since it is going to refetch all messages of the affected source folder immediately. IOW: if you disable this option, you're going to suffer!"

This bug has never been confirmed for a KDE PIM version that is based on KDE Frameworks (5.x). Those versions differ significantly from the old 4.x series. Therefore, I plan to close it in around two or three months. In the meantime, it is set to WAITINGFORINFO to give reporters the oportunity to check if it is still valid. As soon as someone confirms it for a recent version (at least 5.1, ideally even more recent), I'll gladly reopen it.

Please understand that we lack the manpower to triage bugs reported for versions almost two years beyond their end of life.

Just as announced in my last comment, I close this bug. If you encounter it again in a recent version (at least 5.1 aka 15.12; preferably much more recent), please open a new one unless it already exists. Thank you for all your input.