Bug 319226

Created attachment 79628 [details]
IMHO relevant part of xsession-errors.txt during the bug happened.

Again we have:

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.

(see bug #318281)

and

AkonadiAgentServer(1029)/libakonadi Akonadi::ResourceBase::itemRetrieved: Item does not provide part "HEAD"

(see already mentioned bug #318290)

Created attachment 79629 [details]
akonadiserver error, dunno if all of it is related to the bug, no timestamps in there

Payload file "/home/martin/.local/share/akonadi/file_db_data/848168_r0" is missing, trying to recover.

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. 
Error during executing query "UPDATE PimItemTable SET atime = :0 WHERE ( ( PimItemTable.id = :1 ) )" :  "Deadlock found when trying to get lock; try restarting transaction QMYSQL3: Unable to execute statement" 
Error during executing query "UPDATE PimItemTable SET atime = :0 WHERE ( ( PimItemTable.id = :1 ) )" :  "Deadlock found when trying to get lock; try restarting transaction QMYSQL3: Unable to execute statement" 
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. 

Since these might be communication related, I add dbus version:

martin@merkaba:~> apt-show-versions | grep dbus
dbus/sid uptodate 1.6.8-1
dbus-x11/sid uptodate 1.6.8-1
libdbus-1-3/sid uptodate 1.6.8-1
libdbus-1-dev/sid uptodate 1.6.8-1
libdbus-c++-1-0/sid uptodate 0.9.0-6
libdbus-glib-1-2/sid uptodate 0.100.2-1
libdbusmenu-glib4/sid uptodate 0.6.2-1
libdbusmenu-qt2/sid uptodate 0.9.0-1
libkdepimdbusinterfaces4/experimental uptodate 4:4.10.2-2
libnet-dbus-perl/sid uptodate 1.0.0-2
libqt4-dbus/sid uptodate 4:4.8.2+dfsg-11
libqtdbus4/sid uptodate 4:4.8.2+dfsg-11
python-dbus/sid uptodate 1.1.1-1
python-dbus-dev/sid uptodate 1.1.1-1
python-qt4-dbus/sid uptodate 4.9.3-4
qdbus/sid uptodate 4:4.8.2+dfsg-11

martin@merkaba:~/.local/share/akonadi/db_data> cat mysql.err
130502 11:10:29 [Note] Plugin 'FEDERATED' is disabled.
130502 11:10:29 InnoDB: The InnoDB memory heap is disabled
130502 11:10:29 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130502 11:10:29 InnoDB: Compressed tables use zlib 1.2.7
130502 11:10:29 InnoDB: Using Linux native AIO
130502 11:10:29 InnoDB: Initializing buffer pool, size = 500.0M
130502 11:10:29 InnoDB: Completed initialization of buffer pool
130502 11:10:29 InnoDB: highest supported file format is Barracuda.
130502 11:10:29  InnoDB: Waiting for the background threads to start
130502 11:10:30 InnoDB: 5.5.30 started; log sequence number 3544836826
130502 11:10:30 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.30-1.1'  socket: '/home/martin/.local/share/akonadi/socket-merkaba/mysql.socket'  port: 0  (Debian)
130502 11:49:01 [Warning] Aborted connection 31 to db: 'unconnected' user: 'root' host: '' (Got an error reading communication packets)

Created attachment 79630 [details]
filter rules in use. 41 filter rules

I placed the manual mark as spam and mark as ham filters at the end, cause they are set to stop processing and filter on all mails, but not on incoming ones, and on manual filtering processing stopped there. Ah, I see, cause I had on manual filtering activated.

Dunno how to solve this. I can paste KMail-1 filter rules export for them.

Created attachment 79637 [details]
view of the mailing list archive

Yes, it looses data. This is the view of the mailing list archive and my Dovecot POP3 server agrees:

martin@mondschein:~/Maildir> grep -ir "Imminent"  
cur/1367464040.Vfe03I311cM429424.mondschein:2,S:Subject: Re: Imminent Debian GNU/Hurd release
cur/1367460024.Vfe03I30eeM704123.mondschein:2,S:Subject: Re: Imminent Debian GNU/Hurd release
cur/1367479100.Vfe03I320aM970019.mondschein:2,S:Subject: Re: Imminent Debian GNU/Hurd release
cur/1367465205.Vfe03I311fM204110.mondschein:2,S:Subject: Re: Imminent Debian GNU/Hurd release
cur/1367452572.Vfe03I2fffM29074.mondschein:2,S:Subject: Imminent Debian GNU/Hurd release
cur/1367472831.Vfe03I3175M261909.mondschein:2,S:Subject: Re: Imminent Debian GNU/Hurd release

Created attachment 79638 [details]
This is what I see in KMail2 as of 4.10.2

Created attachment 79639 [details]
akonadiconsole also sees those broken mails, part 1

Created attachment 79640 [details]
akonadiconsole also sees those broken mails, part 2

A possible way to reproduce it, could be to press Ctrl-J for manual filtering several times quickly in a row when Akonadi is busy with other things and KMail didn´t react to the first press of Ctrl-J immediately. 

I think the debian-hurd 1-byte mails came up like this. I made a new filter for the debian-hurd mails and pressed Ctrl-J while Akonadi was under load after POP3 retrieval. I am not sure I even pressed twice, but I got the popup that it was not able to move the mail.

In any case, on a failed move attempt I expect the mail to be still in inbox. In other words, I expect the mail move to be atomic. Either it succeeded and the mail is in the target folder, or it didn´t and it is still in the source folder.

To clarify those both find -size 1c results. The first was before the POP3 retrieval. The second was after it. Three new one byte files. I saw one notification of a failed move attempt. Maybe they has been more than one quickly in a row.

Would be good to have these notifications being logged. I didn´t see them in any log.

Created attachment 79641 [details]
filter rules in use. 41 filter rules

I placed the manual mark as spam and mark as ham filters at the end, cause they are set to stop processing and filter on all mails, but not on incoming ones, and on manual filtering processing stopped there. Ah, I see, cause I had on manual filtering activated. Dunno how to solve this. I can paste KMail-1 filter rules export for them.

The content of attachment 79630 [details] has been deleted by
    Tom Albers <toma@kde.org>
who provided the following reason:

Per request sysadmin ticket #86

The token used to delete this attachment was generated at 2013-05-02 18:35:18 CEST.

Unlike I first thought none of these mails where in old KMail-1 maildir. Its all new mails:

martin@merkaba:/mnt/home-zeit/martin-Mail-2013-05-01> find -size 1c
martin@merkaba:/mnt/home-zeit/martin-Mail-2013-05-01> find -name "1367483178.R30.merkaba:2,S"
martin@merkaba:/mnt/home-zeit/martin-Mail-2013-05-01> find -name "1367483178.R30.merkaba:2*" 
martin@merkaba:/mnt/home-zeit/martin-Mail-2013-05-01> find -name "1367483178.R30*"          
martin@merkaba:/mnt/home-zeit/martin-Mail-2013-05-01>

While I was able to recover mails by diffing Message-Ids on server and locally, KMail created further broken mails on another POP3 retrieval:

martin@merkaba:~/.local/share/local-mail> find -size 1c                                                                       
./.Lichtvoll.directory/.Amiga.directory/[…]/new/1367505273.R463.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R227.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367505281.R162.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R178.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R426.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R133.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R832.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367505281.R263.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R551.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R571.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R707.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R733.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R626.merkaba
./.Lichtvoll.directory/.Linux.directory/kernel-ml/new/1367515616.R528.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R16.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R424.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R689.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R514.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R237.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R754.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R380.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R557.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R580.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R311.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R564.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R944.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R635.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R653.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R479.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R579.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R632.merkaba
./.Lichtvoll.directory/.Linux.directory/fsdevel-ml/new/1367515616.R644.merkaba
./.Lichtvoll.directory/.Computer.directory/mesa-dev-ml/new/1367515616.R593.merkaba
./.trash.directory/Spam/new/1367515616.R127.merkaba

(I fixed those in debian-hurd by my manual approach)

I suspect this could be an issue with piping mails through the crm114 spam filter. This used to work just nice with KMail-1. The KMail-1 contain no 1-byte sized file (see previous comment).

Thus I remove the crm114 spam filter rules for now and continue testing.

If that doesn´t help either, I think I go back. Fixing up mails manually by comparing message-ids is more work than I want to cope with regularily.

I think, it was the CRM114 filter rules.

I did not have any further one-byte sized files after remove these CRM114 spam filter rules.

My theory is it, that it sometimes produces 1-byte sized files. A first safety check I´d recommend that it would it doesn´t accept any mail with less than 200 bytes or so as a valid result, takes the unpiped original in that case and issues a big fat warning! I would even go as far as not accepting anything that is below the original size of the unpiped mail as a result, but there might be virus filter setups where the piped mail is smaller than the unpiped one (mail less the virus that the virus filter stripped of it).

I found a grave mistake in one of my crm114 spam filter rules, which may explain these one-byte-sized files. I did some testing and it seems it doesn´t cause that harm, but well, maybe it still does:

It may have been this grave misconfiguration causing all the havoc. If so, please accept my apology!

I will take time to compare my crm114 rules with Sinclair, and with my old one and think of safe ways to test with new filter rules.


From a posting from me from this thread:
http://lists.kde.org/?l=kdepim-users&m=136750887020427&w=2

> For comparison of rules with O. Sinclair, a another CRM114 user on kdepim-
> users, I pasted them. During that I found a grave error in one of those
> rules:
> 
> [Filter #39]
> Applicability=0
> AutomaticName=false
> ConfigureShortcut=true
> ConfigureToolbar=true
> Enabled=true
> Icon=mail-mark-notjunk
> StopProcessingHere=true
> ToolbarName=crm114: Als Gut einstufen
> accounts-set=akonadi_pop3_resource_0,akonadi_maildir_resource_0
> action-args-0=H
> action-args-1=crm -u ~/.crm114 mailreaver.crm --good
> action-args-2=rm -u ~/.crm114 mailreaver.crm
                          ^ ^ ^
> 
> GOSH! That rm -u should be a "crm", a copy and paste error. I think I
> noticed an error like this and fixed it.
> 
> That might explain what I am seeing.
> 
> 
> action-name-0=unset status
> action-name-1=execute
> action-name-2=filter app
> actions=3
> apply-on=manual-filtering
> identifier=XOzgjB9dqty8V2Zn
> name=crm114: Als Gut einstufen
> operator=all
> rules=0
> 
> 
> This may explain the issues I have experienced, although …
> 
> … still that filter was after all mailing list based filters and the
> one-byte sized files where sorted into mailing lists by previous filters
> which have StopProcessingHere.
> 
> I will look at newer revisions of my filter rules.
> 
> 
> And well, I also had one-byte sized files with imported filter rules from
> KDEPIM-1, which were not having this "rm" in it. Just checked it.
> 
> But still:
> 
> merkaba:/tmp> echo "test" > test
> merkaba:/tmp> LANG=C rm -u test
> rm: invalid option -- 'u'
> Try 'rm --help' for more information.
> merkaba:/tmp#1> cat test
> test
> merkaba:/tmp>
> 
> 
> So if Akonadi pipes the mail through rm -u, it should get back "rm: invalid
> option -- 'u'
> Try 'rm --help' for more information."
> 
> or something like that.
> 
> Well, that could somehow have lead to a one byte sized file.

I tried just this misconfigured filter rule a ton of time with Ctrl-J and triggering via filter actions menu on two test mails. These are still there.

I thought they would be gone. Maybe Akonadi doesn´t accept the pipe result, if the command returns an error code?

I don´t even see the rm to be called, but may be to quick to notice.

While thats no prove that the rule did not cause any havoc, I have an idea on how to test crm114 filter rules for one-byte sized files (with crm	114 rules enabled) safely:

1) create a pop3 test account

2) stuff a lots of mails to this mail account via a for loop and mail command.

3) retrieve mails only from that test account.

I think I will try this way.


I found another mistake with the mark as good rule: It should not be called on manual filtering, only by being called from filter action menu or icon.

While this should not cause one-byte sized files, it might have contributed to several filters being called quickly one after another and possible race conditions relating that.


martin@merkaba:~> while true; do ps aux | grep rm | egrep -v "(grep|btrfs|dirmngr)" ; sleep 0.01 ; done
martin    6208  0.0  0.0   4180   576 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentD29042.tmp
martin    6209  0.0  0.0  89148  1480 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6263  0.0  0.0   4180   580 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentL29042.tmp
martin    6264  0.0  0.0  89144  1468 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6311  0.0  0.0   4180   580 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentF29042.tmp
martin    6312  0.0  0.0  89016  1416 ?        R    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6311  0.0  0.0   4180   580 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentF29042.tmp
martin    6312  0.0  0.0  89148  1476 ?        R    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6361  0.0  0.0   4180   580 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentj29042.tmp
martin    6362  0.0  0.0  89152  1480 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6416  0.0  0.0   4180   576 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentg29042.tmp
martin    6417  0.0  0.0  89152  1480 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6464  0.0  0.0   4180   576 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agenta29042.tmp
martin    6465  0.0  0.0  89152  1480 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6515  0.0  0.0   4180   576 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agents29042.tmp
martin    6516  0.0  0.0  89020  1408 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6515  0.0  0.0   4180   576 ?        S    13:11   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agents29042.tmp
martin    6516  0.0  0.0  89152  1472 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6533  0.0  0.0  89152   648 ?        S    13:11   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    6534  0.0  0.0   4180   576 ?        S    13:11   0:00 sh -c .\/mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131157_862193_C8DEACBE --spam=reaver_cache/empty/ 
martin    6535  0.0  0.0  93208  1420 ?        R    13:11   0:00 /usr/bin/crm ./mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131157_862193_C8DEACBE --spam=reaver_cache/empty/
martin    7390  0.0  0.0   4180   576 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentQ29042.tmp
martin    7392  0.0  0.0  89152  1428 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7390  0.0  0.0   4180   576 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentQ29042.tmp
martin    7392  0.0  0.0  89152  1488 ?        R    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7445  0.0  0.0   4180   576 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agenta29042.tmp
martin    7447  0.0  0.0  89152  1480 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7445  0.0  0.0   4180   576 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agenta29042.tmp
martin    7447  0.0  0.0      0     0 ?        R    13:12   0:00 [crm]
martin    7496  0.0  0.0   4180   580 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agente29042.tmp
martin    7498  0.0  0.0  89148  1420 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7548  0.0  0.0   4180   580 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentA29042.tmp
martin    7549  0.0  0.0  89016  1292 ?        R    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7548  0.0  0.0   4180   580 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentA29042.tmp
martin    7549  0.0  0.0  89148  1472 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7566  0.0  0.0  89148   652 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7567  0.0  0.0   4180   580 ?        S    13:12   0:00 sh -c .\/mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131206_383516_C8DEACBE --spam=reaver_cache/empty/ 
martin    7568  0.0  0.0 122148  4948 ?        R    13:12   0:00 /usr/bin/crm ./mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131206_383516_C8DEACBE --spam=reaver_cache/empty/
martin    7603  0.0  0.0   4180   580 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentb29042.tmp
martin    7604  0.0  0.0  89016  1408 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7603  0.0  0.0   4180   580 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agentb29042.tmp
martin    7604  0.0  0.0  89148  1472 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7621  0.0  0.0  89148   652 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good
martin    7622  0.0  0.0   4180   576 ?        S    13:12   0:00 sh -c .\/mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131206_586995_C8DEACBE --spam=reaver_cache/empty/ 
martin    7623  0.0  0.0  93208  1444 ?        R    13:12   0:00 /usr/bin/crm ./mailtrainer.crm --fileprefix= --good=reaver_cache/known_good/20130504_131206_586995_C8DEACBE --spam=reaver_cache/empty/
martin    7653  0.0  0.0   4180   576 ?        S    13:12   0:00 /bin/sh -c (crm -u ~/.crm114 mailreaver.crm --good) </tmp/kde-martin/akonadi_mailfilter_agents29042.tmp
martin    7655  0.0  0.0  89148  1472 ?        S    13:12   0:00 crm -u /home/martin/.crm114 mailreaver.crm --good

Created attachment 79699 [details]
text log of reproducting the problem

Yay! I got a reproducer with CRM114 filter rules corrected to use "crm -u" instead of the dangerious "rm -u" in case of mark as good.

Steps:

1) Create 5000 mails on your pop server in a *test* account. (See attached text file)

2) Have those 5 CRM114 filter rules in place.

3) Configure test account in KMail and download all these.

4) While the detect spam rule is active and sorts these mail to "unsure" (here it did so), mark some mails as good.

5) MySQL gets stuck for minutes (see bug #319208).

6) Stop Akonadi server.

7) Wait till its stopped properly.

8) Start again. KMail complains about a lot of mails that cannot be deleted via notification popups.

9) Voila, I have the following new broken mail files in maildir:

./.trash.directory/Unsicher/new/1367668711.R735.merkaba
./.trash.directory/Unsicher/new/1367668711.R721.merkaba
./.trash.directory/Unsicher/new/1367668711.R39.merkaba
./.trash.directory/Unsicher/new/1367668698.R276.merkaba


All the details attached.

I will attach the exact filter rules that were in use for the reproducer.

For now enough time spent on it, but I think I will try to reproduce it again to see whether the reproducer is reliable.

Created attachment 79700 [details]
complete reproducer rules, although I think the mailinglist rules do not matter here

Without tree internal mailing lists and another private item.

Created attachment 79701 [details]
just the crm114 reproducer rules

The mark as spam and mark as good should not be applied on manual filtering, but for the case of this POP3 retrieval test case, I think this does not matter.

So or so it shouldn´t produce empty files.

Created attachment 79702 [details]
crm114 testsetup

With empty training files included. I think it does not matter for reproducing if crm114 is trained already or not.

Just place the .crm114 directory in directly in your home directory.

I use:

merkaba:~> apt-show-versions | egrep "(crm114|libtre5)"
crm114/sid uptodate 20100106-3
libtre5/sid uptodate 0.8.0-3

Likely works with older versions as well.

Newer versions may or may not work.


For SUSE this could work:

http://software.opensuse.org/package/crm114

There is a 20100106 version of it available.

(In reply to comment #17)
> Created attachment 79699 [details]
> text log of reproducting the problem
> 
> Yay! I got a reproducer with CRM114 filter rules corrected to use "crm -u"
> instead of the dangerious "rm -u" in case of mark as good.
> 
> Steps:
[…]
> 8) Start again. KMail complains about a lot of mails that cannot be deleted
> via notification popups.

I think this is unrelated seems to be a race condition like in bug #319238.

I can give you access to a POP3 account with 5000 or more mails in it if need be.

Thanks,
Martin

Another update on this.

I run without CRM114 spam filter rules.

First on Ext4 to make sure its not BTRFS.

Now on BTRFS.

For weeks already.

All is safe. :)

Still "just" 33 broken mails that I didn´t fix up yet by copying mail files with correct message ids over.

martin@merkaba:~/.local/share/local-mail> find -size 1c | wc -l 
33

I hope to be able to get back to this and try to find the cause of this data loss with a test user setup soon.

Okay, new findings:

I tested this with a clean kmail 4.10 / akonadi setup and it worked okay for some days, no 1-byte sized files. Then I copied over my whole main mail account with several GB of mails and tested with CRM114 and all filter rules enabled and it just worked okay.

Then I tried moving my whole setup to the test user but this failed due to:

[Bug 325699] New: Akonadi stores absolute path to maildir resource maildir in database, making it difficult to create a test setup

Today I thought I try the crm114 rules that worked just nice with my test setup, and only those five crm114 rules where two of them are just for manual marking mail as spam or good, on my production setup after I upgraded it to KMail SC 4.11. It worked for the first bunchs of downloads but then I got:

martin@merkaba:~/.kde/share/config> find ~/.local/share/local-mail -size 1c | wc -l
92

Thats 59 new broken mails that KMail displayed without body at first and on next startup also with unknown subject. 33 are still broken from the initial occuring of this issue. I didn´t yet fix them manually by comparing Message-Ids from a backup from the server Maildir at this time.

Thus for me KMail / Akonadi still looses mails. ;-(((

This time I fixed it by removing approximately 122 UIDs from akonadi_pop3_resource_0rc and having it redownload those from the POP3 server.

I have two ideas, but actually I do not really like to try even one of them:

1) Maybe since I migrated some severe database related consistency issues have been fixed and now I still have a database with these issues. Thus I could try to restart from scratch once again.

2) Maybe this just happens when several POP3 resources are configured. My test setup just consisted of one.

3) Once bug #325699 is fully fixed I could again try to build up a test setup with a second user and then if it works okay, just swap test and production setups. This needs 325699 to be fixed.

Created attachment 82883 [details]
I used these rules which worked just fine in clean one POP3 resource test setup

Software versions in use:

martin@merkaba:~> apt-show-versions | egrep "akonadi|kdepim|kmail|kdelibs|libqtgui|crm114|mysql"
akonadi-backend-mysql:all/experimental 1.10.2-1 uptodate
akonadi-backend-sqlite:amd64/sid 1.9.2-2+b1 uptodate
akonadi-server:amd64/experimental 1.10.2-1 uptodate
akonadiconsole:amd64/experimental 4:4.11.2-1 uptodate
crm114:amd64/sid 20100106-3 uptodate
kdelibs-bin:amd64/experimental 4:4.11.2-1 uptodate
kdelibs5-data:all/experimental 4:4.11.2-1 uptodate
kdelibs5-plugins:amd64/experimental 4:4.11.2-1 uptodate
kdepim:all/experimental 4:4.11.2-1 uptodate
kdepim-kresources:amd64/experimental 4:4.11.2-1 uptodate
kdepim-runtime:amd64/experimental 4:4.11.2-2 uptodate
kdepimlibs-kio-plugins:amd64/experimental 4:4.11.2-2 uptodate
kmail:amd64/experimental 4:4.11.2-1 uptodate
libakonadi-calendar4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-contact4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-kabc4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-kcal4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-kde4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-kmime4:amd64/experimental 4:4.11.2-2 uptodate
libakonadi-notes4:amd64/experimental 4:4.11.2-2 uptodate
libakonadiprotocolinternals1:amd64/experimental 1.10.2-1 uptodate
libdbd-mysql-perl:amd64/sid 4.024-1 uptodate
libkdepim4:amd64/experimental 4:4.11.2-1 uptodate
libkdepimdbusinterfaces4:amd64/experimental 4:4.11.2-1 uptodate
libmysqlclient-dev:amd64/sid 5.5.33+dfsg-1 uptodate
libmysqlclient18:amd64/sid 5.5.33+dfsg-1 uptodate
libqt4-sql-mysql:amd64/sid 4:4.8.5+git121-g2a9ea11+dfsg1-2 uptodate
libqtgui4:amd64/sid 4:4.8.5+git121-g2a9ea11+dfsg1-2 uptodate
mysql-client:all/sid 5.5.33+dfsg-1 uptodate
mysql-client-5.5:amd64/sid 5.5.33+dfsg-1 uptodate
mysql-common:all/sid 5.5.33+dfsg-1 uptodate
mysql-server-core-5.5:amd64/sid 5.5.33+dfsg-1 uptodate
python-mysqldb:amd64/sid 1.2.3-2 uptodate

This is tentatively fixed in master, after a little more testing I will backport to 4.12.

András, did you backport? Could it be safe again to test with 4.12.2? As copying my complete Akonadi setup including database to a different user with a different path to home directory does not yet work, it is difficult for me to test without risking mail loss. What was the problem? Thanks, Martin

This one might be related: https://bugs.kde.org/show_bug.cgi?id=331486

Could this be related? I am currently checking out current git of Akonadi server and Akonadi KDEPIM libs and just found this commit in activity display on projects.kde.org.

Well, for me I didn´t see any issues anymore with disabled CRM114 spam filters… and its just 500-1000 mails filtered at maximum I think, yet the filtering involved moving mails again… after mail retrieval, with busy maildir resource (I reported minute long 100% hogging on one core)… 

Anyway, thanks for fixing that issue.

Revision ff9edf8c

ID: ff9edf8c0d96b179116558020d5a571a25142795
Added by Dan Vrátil about 11 hours ago

Fix potential severe data loss during copy and move operations

Move and copy operations on larger sets of items can take some time, because
we need to make sure that all items have full payload stored in Akonadi. This
is necessary especially with local resources, like maildir, which have cache
timeout set to 5 minutes (after that all their payload is removed from Akonadi
and is fetched from HDD on demand, because it's cheap, fast and does not
unnecessarily duplicate emails in maildir and in database). However fetching
large amount of items via ItemRetriever takes a lot of time, sometimes it can
take even more than 5 minutes. And in such case there is a very high chance,
that the CacheCleaner will just remove the newly cached payloads from Akonadi
again and so when ItemRetriever finishes, many items have empty payload in
Akonadi again. ItemRetriever nor handlers are aware of this howerver, so they
will just make copies or moves of empty items, causing data loss.

This patch introduces CacheCleanerInhibitor, a class which when it is created
will pause the timer in CacheCleaner and resume the timer again when it's
destroyed (so usually when it goes out of scope). Also, this patch adds the
inhibitor to all handlers that use ItemRetriever, so that the the situation
described above does not happen.

The current solution is not perfect because it pauses the entire CacheCleaner
while I think it would be better to be able to temporarily 'blacklist' only
specific collections or items. That would however require much more complex
code and changes, which makes it unsuitable for 1.12 release.

I tried moving 78 000 emails from one maildir to another and all emails were
moved correctly. Move itself has many other problems (CPU, IO, memory, KMail
responsivness, etc.) but that's out of scope of this fix.

CCBUG: 330895

View differences

Bug 319204 - Mailbodies are deleted by Kmails spam-bogofilter on the remote IMAP Server!

might be related. I added a comment the other way around, but not from this bug as far as I see.

I am currently in the process of summoning up the courage to try this. I have mail duplication set up on my postfix server so all mails to my main POP3 account is duplicated into a separate IMAP account on the server, so I can restore lost mails when I find *which* ones got lost, and thats the difficult part :). As its not visible afterwards anymore more, which mail it trashed and can only be revealed by message-id search, but that will also find deleted spam mails as missing.

Setting to waiting for information after I received bugzilla rights to do that.

Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least 15 days. Please provide the requested information as soon as possible and set the bug status as REPORTED. Due to regular bug tracker maintenance, if the bug is still in NEEDSINFO status with no change in 30 days, the bug will be closed as RESOLVED > WORKSFORME due to lack of needed information.

For more information about our bug triaging procedures please read the wiki located here: https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

If you have already provided the requested information, please set the bug status as REPORTED so that the KDE team knows that the bug is ready to be confirmed.

Thank you for helping us make KDE software even better for everyone!

Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least 30 days. The bug is now closed as RESOLVED > WORKSFORME due to lack of needed information.

For more information about our bug triaging procedures please read the wiki located here: https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

Thank you for helping us make KDE software even better for everyone!