GNOME Bugzilla – Bug 767564
Junk check fails due to empty cache file
Last modified: 2016-08-18 06:23:35 UTC
I very often get the following message when receiving emails with Evolution: Execution of filter 'Junk check' failed: Empty cache file: /home/user/.cache/evolution/mail/1465406006.2249.4@user/folders/INBOX/cur/24/8183 Execution of filter 'Junk check' failed: Empty cache file: /home/user/.cache/evolution/mail/1465406006.2249.4@user/folders/INBOX/cur/25/8197 I read about bug 737468 which seems to be related, but that bug is already resolved as fixed. As i am using version 3.20.3 on Debian Sid, i don't think that this bug is already fixed. I activated filters which move incoming mails to specific IMAP folders and "Check incoming messages for junk" which i consider a normal use case.
Thanks for a bug report. I thought of bug #761096 too, but maybe the problem is the execution order of the filters, as the "Check incoming messages for junk" is also a filter. Do you have configured a real Trash folder for that particular IMAP account? I guess you do, or the server supports a MOVE operation/IMAP extension. I noticed that some servers do not claim any error when the client (IMAPx in the evolution in this case) asks for a content of a message which doesn't exist in the folder. The server returns no content instead, which is transformed into the "Empty cache file" error. In case the filter execution order is as: 1) Move the message; 2) Run junk check on the message; then the second filter fails to read the message from the server. If you can easily reproduce the error, then run the evolution from a command line as follow: $ CAMEL_DEBUG=imapx:io,imapx:conman evolution &>log.txt then, once you'll see the error in the UI, examine the end of the log.txt file. I think even the "Empty cache file" error text can be seen there, but I'm not sure. Eventually search for a preceding MOVE or COPY commands (in upper-case).
i just catched such an issue with debug logging enabled: Execution of filter 'Junk check' failed: Empty cache file: /home/chris/.cache/evolution/mail/1465406006.2249.4@chris/folders/INBOX/cur/2a/8397 i hope i captured the correct log messages. You can find them in the attached file "".
Created attachment 329870 [details] empty cache file debug log
Thanks for the update. Either the move had been done earlier in the log, or it's some sort of thread interleaving issue. I see it downloaded the message headers with one connection, then the other connection was about to download the message body, but the server returned an empty stream. I do not see this from the log, do you use Quick Resync for this account? I would try to disable it in the account Properties, if you do. Just to try out.
*** Bug 769737 has been marked as a duplicate of this bug. ***
*** Bug 768673 has been marked as a duplicate of this bug. ***
I've got an updated log from Lindsay, as discussed on the evolution-list, and it shows basically two connections being involved doing these things, with roughly this interleaving: A - created A - LIST and LSUB on Inbox and its subfolders A - LIST and LSUB on other namespaces A - LIST and LSUB on the Inbox only (without subfolders) A - STATUS on Inbox A - SELECT Inbox (successfully) A - check of new messages on Inbox - none found A - check of changed messages on Inbox A - NOOP A - check of new messages in Inbox - none found A - check of changed messages in Inbox A - LIST and LSUB on Inbox and its subfolders A - LIST and LSUB on other namespaces B - while the A was doing the LIST, the second connection had been created A - LIST and LSUB on the Inbox only (without subfolders) B - finished STATUS of Inbox meanwhile B - SELECT Inbox (successfully) B - check for new messages in Inbox - one \Recent found B - fetch headers and flags of the new messages (successfully) B - check changes of old messages A - read the new message content - "fails" with empty response What I see odd on this log is the second triple of the "LIST and LSUB" commands on the connect A, but they may not influence this behaviour. The rest of the log looks pretty fine, from my point of view. I suspect that the server has some connection-state cache and when one connection knows about a newly received message, then another may not always know about it, at least not until the client side of that connection asks for an update. The log was made from a Courier server, which doesn't mean much, because other users claim the same issue with different server, like a Gmail server, but it helps me with debugging (I have a Courier test instance).
Sam Varshavchik <mrsam@courier-mta.com> of Double Precision is the developer of courier-imap and is very forthcoming with information on all parts of the Courier suite - if it matters. The full message I receive on failure is typically of the following form: Unable to retrieve message. Empty cache file: /home/fmouse/.cache/evolution/mail/1388626224.50386.24@pudina/folders/INBOX/cur/10/197743 The zero-length cache file doesn't exist, in each case, until an attempt is made to read the message. This is probably SOP, but I'm not familiar with Evolution internals so I thought I'd mention it. I'll look into logging the IMAP dialog if that might help.
(In reply to Milan Crha from comment #7) > I suspect that the server has some connection-state cache and when one > connection knows about a newly received message, then another may not always > know about it, at least not until the client side of that connection asks > for an update. I just verified it, by opening two connections to the server, opening the destination folder in one of them, then copying a message to that folder from the other connection. Asking for the message flags also returned no data. Simply invoking NOOP and then issuing the same FETCH command makes it work. Thus it's something on the server side and the fact that the server doesn't like quick connection "switching" (I do not know how to better name it, even it's not 'switching' in the usual meaning). (In reply to fmouse from comment #8) > Sam Varshavchik of Double Precision is the developer > of courier-imap and is very forthcoming with information on all parts of the > Courier suite - if it matters. Nice. Let him know about this bug report and my reproducer steps: 1) open terminal A and connect to the IMAP server, issue commands: A login user password A select Inbox.sub 2) open terminal B and connect to the IMAP server, issue commands: B login user password B select inbox.sub2 // this is different folder than the connect A has 3) issue in terminal A: A copy 1 inbox.sub2 * say it says the new UID of the copied message 1 is 2 4) issue in terminal B: B UID FETCH 2 (RFC822.SIZE RFC822.HEADER FLAGS) * nothing is returned (the server returns immediately: "B OK FETCH completed." without any data (I know this doesn't return message body, but it's only a detail) 5) issue in terminal B: B NOOP B UID FETCH 2 (RFC822.SIZE RFC822.HEADER FLAGS) Only now the headers are properly received. The NOOP also claimed here: * 2 EXISTS * 0 RECENT B OK NOOP completed From this I suspect the connection state on the server side was not updated after the copy, until the NOOP was issued. I do not know whether it's a bug on the server side, maybe not. > I'll look into logging the IMAP dialog if that might help. That's okay for now, the previous log is perfectly fine.
I made some changes in the evolution-data-server which may address the issue, I hope. The message fetching can be re-tried if it "fails" with an empty stream, or the folder can be NOOP-ed when it's already selected in case it changed from another thread/connection before trying to select it. Created commit 6e44372 in eds master (3.21.90+)
Created attachment 333188 [details] debug patch for 3.20.5 This is the same patch as the committed one, with added debug prints, which I used to create a Fedora 24/3.20.5 debug build [1]. I made also Fedora 23 build [2] with it, but the patch doesn't apply cleanly to 3.18.5. It's enough to run evolution on a terminal, where will be printed when the issue was/could be hit. No need to turn on any special debugging. If there is anyone being able to give it a try (I do not know how to build test packages for other than Fedora, I'm sorry), and report the findings, then it'll be great. [1] http://koji.fedoraproject.org/koji/taskinfo?taskID=15232020 [2] http://koji.fedoraproject.org/koji/taskinfo?taskID=15232097
*** Bug 769011 has been marked as a duplicate of this bug. ***
*** Bug 763735 has been marked as a duplicate of this bug. ***
*** Bug 720942 has been marked as a duplicate of this bug. ***
Great ! I have 2 questions. Will the patch be ported to Evolution 3.20 (Fedora 24) ? I didn't managed to get a log, the problem didn't happen when needed of course, so can you confirm that is not needed anymore https://bugzilla.gnome.org/show_bug.cgi?id=769412#c4 Thanks !
(In reply to jeremy9856 from comment #15) > Great ! I have 2 questions. Will the patch be ported to Evolution 3.20 > (Fedora 24) ? I didn't managed to get a log, the problem didn't happen when > needed of course, so can you confirm that is not needed anymore > https://bugzilla.gnome.org/show_bug.cgi?id=769412#c4 The imapx log is not needed any more. The Fedora 24 (for the eds 3.20.5) has currently the above test buil, which has its own debugging prints. If you can run that for some time, then it'll be helpful. I plan to create a regular Fedora 24 update once it's confirmed through the test build that the fix really works. Do not forget to enable more (than one) concurrent connections. :)
I can run the test build but what do I have to install ? I found this package but is it the one ? http://koji.fedoraproject.org/koji/taskinfo?taskID=15232022 evolution-data-server-3.20.5-1.1.fc24.x86_64.rpm Do I need this one too or some others packages ? evolution-data-server-debuginfo-3.20.5-1.1.fc24.x86_64.rpm In order to have the debug output, do the test build have to be launched from a terminal or can be launched normally with the icon ? Thanks !
If it's as simple as effectively pinging the server with a NOOP to get it into the proper state, then I'd expect that you should have a commit for Redhat soon. Is it possible that the fix could be pushed to Ubuntu? They maintain a catch-all closed developers list at <ubuntu-devel-discuss@lists.ubuntu.com>. I'd like to get a fixed version installed here without having to rebuild Evolution from source, or even the Evolution dataserver shared lib suite. The last time I did that was when I ran Gentoo Linux, and it took a _long_ time. I emailed Sam Varshavchik, the courier-imap developer, about this, but I suspect this falls back on Evolution to address the problem since other folks have indicated that the problem occurs with other IMAP servers as well, including Google's gmail IMAP server.
(In reply to jeremy9856 from comment #17) > I can run the test build but what do I have to install ? I found this > package but is it the one ? Yes, it's the correct one. Though I do not know what exactly you mean that "you found", when I gave a link for the parent task above. > Do I need this one too or some others packages ? It depends what packages you've already installed, as you should update all of them. Simply running: # dnf install ./evolution-data-server-3.20.5-1.1.fc24.x86_64.rpm will either succeed, or it'll tell you what packages should be updated together with it. > In order to have the debug output, do the test build have to be launched > from a terminal or can be launched normally with the icon ? The debuginfo package is not needed to get the logs, though are printed on the terminal, where you run the evolution, thus yes, yto see the added logging you should run the evolution from a terminal. (In reply to fmouse from comment #18) > Is it possible that the fix could be pushed to Ubuntu? Ask them, not here, this is Evolution upstream, unrelated to any distribution. It's only a coincidence that I can create test packages for Fedora and I offer them. > I emailed Sam Varshavchik, the courier-imap developer, about this, but I > suspect this falls back on Evolution to address the problem since other > folks have indicated that the problem occurs with other IMAP servers as > well, including Google's gmail IMAP server. Correct, the (final) fix (not a workaround) from the comment #10 is already in the evolution-data-server sources and in the 3.21.90 release. The behaviour I see with the courier server is weird to me, but it's only because of my basically no knowledge of the server internals. The issue can be reproduced both with other servers and completely out of the Evolution, as indicated in the comment #9.
(In reply to Milan Crha from comment #19) > Yes, it's the correct one. Though I do not know what exactly you mean that > "you found", when I gave a link for the parent task above. I meant I found the package thanks to the link you provided ;) I expected your link to point directly on a package download page. Also I'm french so excuse me if I should have used an other word :) Thank you for the clarifications !
(In reply to jeremy9856 from comment #20) > I meant I found the package thanks to the link you provided ;) I expected > your link to point directly on a package download page. Also I'm french so > excuse me if I should have used an other word :) Ah, I see. I've no problem with your English, it's perfectly fine. It only confused me a bit, thus I rather asked. I made the build for two architectures, just in case some users may use one and other the other architecture. Thus the link was to the build, not to the package itself. I agree that the koji interface can be confusing when one sees it for the first time and/or doesn't use it often.
Sometimes I see this in the terminal with the test build > camel_imapx_server_ensure_selected_sync: [imapx:A] Selected mailbox 'INBOX' changed, do NOOP instead There is no error message in evolution. Does this confirm that the patch work ?
(In reply to jeremy9856 from comment #22) > Sometimes I see this in the terminal with the test build > > > camel_imapx_server_ensure_selected_sync: [imapx:A] Selected mailbox 'INBOX' changed, do NOOP instead > > There is no error message in evolution. Does this confirm that the patch > work ? Correct, it's one of the added debug prints, which can mean that the bug would be triggered, but as you do not see an error message in the UI, then it worked just fine.
Great ! Do you think we can have the fix in the next version of evolution-data-server ?
It's already part of the 3.21.90 release, as stated in comment #10 (the last line there deciphers as that). There is not planned any other stable branch release (3.20 and lower), but the distribution maintainers can pick the patch and include it in the distribution. I will build updates for the Fedora 24. Thanks for the confirmation and the help on this bug report.
Perfect ! I use Fedora 24 so I will still enjoy the fix. Thank you very much !
Good. The update for Fedora 24 is filled here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-56d7735695