1119529 - Sending message succeeds but Error "error while running message filters on it.", when "Keep messages for this account on this computer" or "Select this folder for offline use" are disabled.

Status: RESOLVED FIXED

(MailNews Core :: Filters, defect)

Description

[Wayne Mery (:wsmwk)]

I replyto a message in Trash folder. In this case from an account with NO message filters defined, not even disabled ones.  I get "Your message has been sent and saved, but there was an error while running message filters on it."  Nothing in error console

2015-01-08 daily build

Comment 1

[Wayne Mery (:wsmwk)]

I was mistaken - two disabled filters. But I removed them and could still reproduce

Comment 2

[Kent James (:rkent)]

Can you try a filter log and see if you see anything?

Comment 3

[Wayne Mery (:wsmwk)]

Nothing

Comment 4

[[e-mail]]

POP or IMAP?

Comment 6

[Kent James (:rkent)]

Bug 1122738 mentions the Mail Redirect Add-on. Does anyone else seeing this use that?

Comment 7

[Walter Lapchynski]

I've disabled *all* Add-ons and this is not improved the situation.

Comment 8

[Walter Lapchynski]

I have only IMAP boxes, btw.

Comment 9

[Kent James (:rkent)]

The current version of the filter service, which is presumably generating the error, has english strings detailing the source of issues. What would you think of exposing those error strings in the error console? That does not have to be localized, right? There is a risk of a flood of errors I suppose.

Comment 10

[Walter Lapchynski]

Being able to see the root cause somehow would certainly be useful.

Comment 11

[Ian Neal]

I also see this on SeaMonkey using IMAP, also seems to cause "gnome-shell" to crash.
I have no filters set at all.

Comment 12

[Ben Bucksch (:BenB)]

Wayne, we (Neil and me) would like to fix this, but we need a reliable reproduction. Please find one, so that Neil can reproduce this at will, as often as he wants, and thus fix this.

Comment 13

[Walter Lapchynski]

Steps to reproduce:
 * Using 37.0 with an IMAP account, compose an email through any means (including forwarding and replying).

Actual results:
 * On send, an error dialog pops up: "Your message has been sent and saved, but there was an error while running message filters on it."
 * Turning off filters has no effect.
 * Disabling add-ons has no effect.
 * Nothing is registered in the Filter Log.
 * No relevant information is reported on the command line.

Expected results:
 * Mail should send with no error.

Comment 14

[Walter Lapchynski]

…also true with 38.0.

Comment 15

[Kent James (:rkent)]

I think that the way forward is going to be to do a try build with a patch that adds logging to the error console of the filter errors. Then we could at least see where the failure is occurring for Walter. Based on that experience, we could decide whether such a patch is going to be a good idea in the long run.

Comment 16

[Walter Lapchynski]

I concur entirely. Error logging would be easy. I tried to `gdb` my way to it, but segfaults keeping me from it.

Comment 17

[Wayne Mery (:wsmwk)]

(In reply to Kent James (:rkent) from comment #15)
> I think that the way forward is going to be to do a try build with a patch
> that adds logging to the error console of the filter errors.

I agree. There's nothing I can add to the description/steps that will make it reproducible for someone else. It's just a garden variety imap account and compose, which afaik is like all my others.

Comment 18

[Kent James (:rkent)]

Attachment: FilterError.png

I created a ScriptError object to add a message to the error console, coming from C++. This is an example of how the error looks in the error console.

Comment 19

[Kent James (:rkent)]

Attachment: WIP to show the errors

Comment 20

[Walter Lapchynski]

WIP meaning this is testable?

Comment 21

[Kent James (:rkent)]

WIP was done so that ISHIKAWA, Chiaki who is pursuing similar issues in bug 854172 can see what I am doing here.

The patch itself is on a try run. You should be able to download and test from that try run when done.

Try status: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=069bb01d03bc

Try results (when done): https://ftp-ssl.mozilla.org/pub/mozilla.org/thunderbird/try-builds/[e-mail]-069bb01d03bc

Comment 22

[Walter Lapchynski]

Using https://ftp-ssl.mozilla.org/pub/mozilla.org/thunderbird/try-builds/[e-mail]-069bb01d03bc/try-comm-central-linux/thunderbird-38.0a1.en-US.linux-i686.tar.bz2, I loaded my profile, went to the error console, cleared everything out, sent a message, opened the error console again. Nothing.

Comment 23

[Kent James (:rkent)]

It looks like the error must be occurring before ApplyFilter, so I extended the messages to include that code as well.

Please try https://ftp-ssl.mozilla.org/pub/mozilla.org/thunderbird/try-builds/[e-mail]-a38318aea387

Comment 24

[Walter Lapchynski]

I am happy to report success, though nothing very detailed: "Filter error: Could not get message header." I grabbed the tarball with debug symbols and didn't see anything else that could really help, so I hope that does it.

Comment 25

[Wayne Mery (:wsmwk)]

What I see in error console is "Error: Filter error: Could not get message header"

Comment 26

[Kent James (:rkent)]

Looking at this some more, the message is added to the db for the sent folder when the sent message is copied to the offline store. When the Sent folder is not enabled for offline use, then the message is never added to the db, and this error results. I can reproduce the error by disabling offline use for the Sent folder.

Comment 27

[Walter Lapchynski]

I can confirm that with the Sent folder enabled for offline use, there is no error and that when it is disabled, the error can be reproduced.

Comment 28

[Wayne Mery (:wsmwk)]

In my case it was with "Keep messages for this account on this computer" disabled, which has the same effect.

Comment 29

[mdavids]

(In reply to Walter Lapchynski from comment #27)
> I can confirm that with the Sent folder enabled for offline use, there is no
> error and that when it is disabled, the error can be reproduced.

Me too.

Comment 30

[Kent James (:rkent)]

Attachment: Console Error message

In my next version, I will add a more general console error method that will add filename and line number. Here is what an error will look like.

Comment 31

[Kent James (:rkent)]

Attachment: Part 1: Define and use a C++ interface to the error console

Comment 32

[Kent James (:rkent)]

Attachment: Part 2: Force imap sent folder available offline if outgoing filters are defined

Comment 33

[Kent James (:rkent)]

Comment on attachment 8563884 [details] [diff] [review]
Part 1: Define and use a C++ interface to the error console

Joshua and Magnus, you might want to give feedback on where I am headed with the error processing here. I'm tired of errors where the users says "But there is nothing in the error console". For filters, I am basically logging any error into the error console. This feature was important for locating the root cause of this bug, and I think it is something we should do more widely.

Comment 34

[Kent James (:rkent)]

This really must be fixed for Thunderbird 38, else we will need to back out bug 11039.

Comment 35

[[e-mail]]

Comment on attachment 8563886 [details] [diff] [review]
Part 2: Force imap sent folder available offline if outgoing filters are defined

>     nsresult rv = FilterSentMessage();
>+    // NS_ERROR_ABORT is an expected result when no filter is applied.
>     if (NS_FAILED(rv))
>+    {
>+      if (rv == NS_ERROR_ABORT)
>+        rv = NS_OK;
>       OnStopOperation(rv);
>-    return rv;
>+      return rv;
>+    }
>   }
> 
>   return MaybePerformSecondFCC(aStatus);
Why does finding that the sent folder is online block the second FCC?
(And given the rest of the patch, how likely is that going to happen?)

>+        if (filterType & nsMsgFilterType::PostOutgoing)
>+        {
>+          setOffline = true;
>+          break;
Actually you could just set the folder offline here and be done with it.

Comment 36

[Magnus Melin [:mkmelin]]

(In reply to Kent James (:rkent) from comment #26)
> Looking at this some more, the message is added to the db for the sent
> folder when the sent message is copied to the offline store. 

That do sound like something worth fixing. Did you have a link to where that happens?

Comment 37

[Ian Neal]

->MailNews

Comment 38

[Kent James (:rkent)]

(In reply to Magnus Melin from comment #36)
> (In reply to Kent James (:rkent) from comment #26)
> > Looking at this some more, the message is added to the db for the sent
> > folder when the sent message is copied to the offline store. 
> 
> That do sound like something worth fixing. Did you have a link to where that
> happens?

In what way do you mean it is worth fixing? Yes I can trace out where it occurs easily enough. One possibility is to add the message to the db even when the folder is not set for offline use. Is that what you mean? I considered that, and perhaps that would be the best fix, but it is also more difficult and riskier than the approach taken here.

(There are also other issues going on that I did not address, like I believe that the new message claims it has a pseudo key when in fact it was created as a response to an IMAP protocol request that did indeed have the correct key. But that just highlights the fragility of this part of the code, hence why I prefer the simpler approach here.)

Comment 39

[Kent James (:rkent)]

Attachment: Part 2 rev 2: Force imap sent folder available offline if outgoing filters are defined

Addressing review comments.

1) It was not really needed to call OnStopOperation when the filter was bypasses, I just did that to run the filter status messages. But probably better not to. I think in either case, the second FCC was not being bypassed, but that is clearer now.

Comment 40

[Magnus Melin [:mkmelin]]

(In reply to Kent James (:rkent) from comment #38)
> In what way do you mean it is worth fixing? Yes I can trace out where it
> occurs easily enough. One possibility is to add the message to the db even
> when the folder is not set for offline use. Is that what you mean? I
> considered that, and perhaps that would be the best fix, but it is also more
> difficult and riskier than the approach taken here.

Yes that sounds like a better fix. Who knows what other problems that is causing. Not to mention, you'll certainly have complaints about the Sent folder (which might be huge, and online for a reason) is getting downloaded and people can't understand why.

Comment 41

[Kent James (:rkent)]

Attachment: Part 2 option B, add to db without adding to message store

Here is an alternate approach, modifying the copy so that the sent item always gets added to the db, even when offline. I am less confident of the side effects of this. I've pushed a try run to see if it affects any tests.

Comment 42

[Kent James (:rkent)]

Comment on attachment 8564361 [details] [diff] [review]
Part 2 option B, add to db without adding to message store

Oops, I did no remove the parts from the other patch.

Comment 43

[Kent James (:rkent)]

Attachment: Part 2 option B, add to db without adding to message store

Comment 44

[Kent James (:rkent)]

Comment on attachment 8564366 [details] [diff] [review]
Part 2 option B, add to db without adding to message store

So I just uploaded the wrong patch previously, this is the correct patch.

Comment 45

[[e-mail]]

Comment on attachment 8564266 [details] [diff] [review]
Part 2 rev 2: Force imap sent folder available offline if outgoing filters are defined

>   if (NS_SUCCEEDED(aStatus) &&
>       !mPerformingSecondFCC && m_messageKey != nsMsgKey_None &&
>       (m_deliver_mode == nsMsgDeliverNow || m_deliver_mode == nsMsgSendUnsent))
>   {
>     nsresult rv = FilterSentMessage();
>-    if (NS_FAILED(rv))
>+    // NS_ERROR_ABORT is an expected result when no filter is applied.
>+    if (NS_FAILED(rv) && rv != NS_ERROR_ABORT)
>+    {
>       OnStopOperation(rv);
>-    return rv;
>+      return rv;
>+    }
>   }
> 
>   return MaybePerformSecondFCC(aStatus);
Oh, I see now, OnStopOperation calls MaybePerformSecondFCC anyway, but this is still wrong because we need to return if FilterSentMessage() succeeded, because that means that the filter service will call us back via OnStopOperation when the filter completes.

Case 1: no filtering (not saving a message to sent items). Outer conditional applies.
Case 2: filtering initiated successfully. Filter status will be passed to OnStopOperation, which then calls MaybePerformSecondFCC, so neither manually call OnStopOperation nor fall through to call MaybePerformSecondFCC!
Case 3: filtering failed to initiate. Call OnStopOperation manually to alert user; because that will call MaybePerformSecondFCC, don't fall through.
Case 4: filtering aborted because there is no message header to filter. Either call OnStopOperation(NS_OK) or (preferably?) fall through, but not both.

Comment 46

[Magnus Melin [:mkmelin]]

Comment on attachment 8563884 [details] [diff] [review]
Part 1: Define and use a C++ interface to the error console

Review of attachment 8563884 [details] [diff] [review]:
-----------------------------------------------------------------

::: mailnews/base/search/src/nsMsgFilterService.cpp
@@ +496,5 @@
>      return m_searchHits.IsEmpty() ? RunNextFilter() : ApplyFilter();
>  
>    mFinalResult = status;
> +  if (NS_FAILED(status))
> +    MSG_LOG_TO_CONSOLE("Search Failed");

nit: failed

::: mailnews/base/util/nsMsgUtils.h
@@ +586,5 @@
> +void MsgLogToConsole(const nsAString& aText, const nsAString &aFilename, uint32_t aLine);
> +
> +// macro with filename and line number
> +#define MSG_LOG_TO_CONSOLE(_text) MsgLogToConsole(_text, NS_LITERAL_STRING(__FILE__), __LINE__)
> + 

nit: whitespace
might be nice if the rv was also logged, especially once those are all enums you'd get more hints to what the problem was

Comment 47

[Kent James (:rkent)]

Neil, I also need you to comment on the alternative patch, https://bugzilla.mozilla.org/attachment.cgi?id=8564366  Magnus objected to the approach in https://bugzilla.mozilla.org/attachment.cgi?id=8564266 so this alternate approach would be preferred if we are comfortable with this approach.

Comment 48

[[e-mail]]

Comment on attachment 8564366 [details] [diff] [review]
Part 2 option B, add to db without adding to message store

>+    nsCOMPtr<nsISeekableStream> seekable;
Why move this?

>+    if (aStoreOffline)
This variable is only used once. Furthermore, its computation does not depend on any local variables. This means you could just compute it here instead of passing it as a parameter.

>     SetFlag(nsMsgFolderFlags::OfflineEvents);
Is this true in the !aStoreOffline case?

>+      if (offlineStore)
[A bit confusing without the aid of diff -w]

>+            if (offlineStore)
>+              rv = offlineStore->Write(newLine, numBytesInLine, &bytesWritten);
>+
>             NS_Free(newLine);
>+            NS_ENSURE_SUCCESS(rv, rv);
Mismatch between the set and read of rv.
Is it worth breaking after the header when we're not storing this offline?

>         SetFlag(nsMsgFolderFlags::OfflineEvents);
There it is again!

Comment 49

[Joshua Cranmer [:jcranmer]]

Comment on attachment 8563884 [details] [diff] [review]
Part 1: Define and use a C++ interface to the error console

Review of attachment 8563884 [details] [diff] [review]:
-----------------------------------------------------------------

I really, really dislike the nsMsgSend changes. What makes these changes particularly egregious is that you're inviting developers to come up with, in some cases, vague strings to describe effectively impossible changes (e.g., AppendElement, quite frankly, shouldn't be capable of failing; the only reason it has a return code is because XPIDL is too stupid to be able to express the notion of infallible methods). For the other strings, you're inviting throwing messages into the error console that have absolutely 0 context. For example, suppose you saw this in the error console:
Could not get message header

What does that mean? Who could not get the message header? Which one could you not? Your comments imply that you intend to use this sort of error reporting more widely, which only exacerbates the issue.

Comment 50

[Kent James (:rkent)]

So is is the concept of reporting C++ errors to the error console, including unexpected errors, that you dislike? Or is it more narrowly the issue of "inviting developers to come up with, in some cases, vague strings to describe effectively impossible changes"?

If it is the narrower issue, then we would have the choice of either not checking for the error (if it is impossible) or having a more generic macro with a generic "unexpected error" message.

The underlying principles that I feel strongly about are these:

1) It should be easy to process and recover from errors, particularly in async cases where you MUST do some sort of callback in both success or error. Too frequently we do NS_ENSURE_SUCCESS and miss an important error callback. do {} while (false); blocks using standard error handling macros work well for this. I particularly hate code like:

  rv = do1();
  if (NS_SUCCEEDED(rv) {
    rv = do2();
    if (NS_SUCCEEDED(rv)) {
      rv = do3();

etc.

2) In important paths where errors are going to cause user-visible issues, there should be better reporting of errors to the user. Too frequently we ask "Is there anything in the error console?" and the answer is no, because the error that occurred is only in C++ and thrown away in release builds.

So if I replaced the unexpected errors with a more generic message like "Unexpected error in Send" (which would also include file and line number to trace) would that work for you?

Comment 51

[Kent James (:rkent)]

"For the other strings, you're inviting throwing messages into the error console that have absolutely 0 context. For example, suppose you saw this in the error console: Could not get message header

What does that mean? Who could not get the message header? Which one could you not? Your comments imply that you intend to use this sort of error reporting more widely, which only exacerbates the issue."

The choices for an error like "Could not get message header" are:

1) Throw it away and not report to the user. I hope that this bug, if anything, proved that this is not the answer. It was precisely that error message appearing that enabled the root cause of this bug to be determined.
2) Always generate extensive error messages. There is always a tradeoff of effort here. Many of these errors we don't expect, and it is a waste of developer time to spend too much effort generating context messages for rare or unexpected errors.
3) Just give a generic message "Unexpected error in file ... at line ...". While this may be OK for errors that you really never expect to see, if there is any reasonable error message like "Could not get message header" I think that is better.

So I don't understand what the alternative is that you are proposing. Error handling is a pain, but when errors occur we need to see them.

Comment 52

[Magnus Melin [:mkmelin]]

(In reply to Joshua Cranmer [:jcranmer] from comment #49)
> inviting throwing messages into the error console that have absolutely 0
> context. For example, suppose you saw this in the error console:
> Could not get message header

You have the file an even line number as context, no?

Comment 53

[Kent James (:rkent)]

Attachment: Always add the FCC file to the database

What I am going to do is split off the portions of the patch that deal with expanded error processing into a new patch. The fix for the immediate problem of this bug can stand on its own.

Comment 54

[Kent James (:rkent)]

Responses to previous review.

(In reply to [e-mail] from comment #48)
> >+    nsCOMPtr<nsISeekableStream> seekable;
> Why move this?
As it turned out, seekable was made unused by a previous patch, so I removed all of this.
> 
> >+    if (aStoreOffline)
> This variable is only used once. Furthermore, its computation does not
> depend on any local variables. This means you could just compute it here
> instead of passing it as a parameter.

Done

> 
> >     SetFlag(nsMsgFolderFlags::OfflineEvents);
> Is this true in the !aStoreOffline case?

I did a bit of investigation of what happens after this method. The expectation is that the email header will be downloaded from the server, and then the existing msgHdr replaced with the new one. The offline op is used to delete the fake header. I think we still need to do that so that the local information accurately reflects what is on the server. Once we add the header to the database, we really need to also prepare to delete it after an update.

> 
> >+      if (offlineStore)
> [A bit confusing without the aid of diff -w]
> 
> >+            if (offlineStore)
> >+              rv = offlineStore->Write(newLine, numBytesInLine, &bytesWritten);
> >+
> >             NS_Free(newLine);
> >+            NS_ENSURE_SUCCESS(rv, rv);
> Mismatch between the set and read of rv.
That is intentional. We need to free the newLine even if the previous call failed.

> Is it worth breaking after the header when we're not storing this offline?

I don't understand this comment.

I did other changes to this as well.

See try run https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=3ace7775c224 which is from a slightly earlier patch that only differs in trivial ways from this one.

Comment 55

[[e-mail]]

(In reply to Kent James from comment #54)
> (In reply to comment #48)
> > >     SetFlag(nsMsgFolderFlags::OfflineEvents);
> > Is this true in the !aStoreOffline case?
> I did a bit of investigation of what happens after this method. [snip]
Fair enough, that makes sense, thanks.

> > >+            if (offlineStore)
> > >+              rv = offlineStore->Write(newLine, numBytesInLine, &bytesWritten);
> > >+
> > >             NS_Free(newLine);
> > >+            NS_ENSURE_SUCCESS(rv, rv);
> > Mismatch between the set and read of rv.
> That is intentional. We need to free the newLine even if the previous call
> failed.
Ah, I notice there's an rv = NS_OK; that means this makes sense (although some sort of RAII would make even more sense).

> > Is it worth breaking after the header when we're not storing this offline?
> I don't understand this comment.
If we're not actually storing the message, we could just parse the header and stop.

Comment 56

[Kent James (:rkent)]

(In reply to [e-mail] from comment #55)
> > > Is it worth breaking after the header when we're not storing this offline?
> > I don't understand this comment.
> If we're not actually storing the message, we could just parse the header
> and stop.

I investigated this issue to try to anticipate the side effects of this. By continuing to parse the message body, we accumulate the lineCount and messageSize. lineCount seems to be used mostly in the search body handler, even when searching for arbitrary headers (which I don't understand). messageSize would be an important parameter of the message if stored offline, when not storing it is much less important, but still is displayable in the UI in, for example, the size column of the thread pane 

So although you could make a case for not bothering to calculate these two items for this message header, that choice is not obvious. As this bug already has a high risk of introducing unforeseen regressions, I would rather not contribute to that by partly calculating the values in the message header for this edge case.

Comment 57

[Kent James (:rkent)]

Comment on attachment 8567333 [details] [diff] [review]
Always add the FCC file to the database

Pushed https://hg.mozilla.org/comm-central/rev/7eeb90bee7f4

Comment 58

[Kent James (:rkent)]

Comment on attachment 8567333 [details] [diff] [review]
Always add the FCC file to the database

[Triage Comment]

This patch is pushed to comm-beta for TB 37, but after build 2 of beta 1.

Comment 59

[Kent James (:rkent)]

https://hg.mozilla.org/releases/comm-beta/rev/e830770c8cd4

Comment 61

[ISHIKAWA, Chiaki]

(In reply to Magnus Melin from comment #52)
> (In reply to Joshua Cranmer [:jcranmer] from comment #49)
> > inviting throwing messages into the error console that have absolutely 0
> > context. For example, suppose you saw this in the error console:
> > Could not get message header
> 
> You have the file an even line number as context, no?

I know this is already closed, but with file, line number, maybe the function where the error occurs and error codes, this is not such a bad idea to record such errors in error console.
TB is full of bugs (as we all know), and getting where the errors/issues occur
is really important to figure out where the knonw bugs are triggered, and where
unknown bugs may lurk IMHO. 
So printing such error info in Error Console is not such a bad idea.
(Firefox has moved to Web console, though.)

I am stealing rkent's code to fix
Bug 1116055 - Performance issue: Failure to use buffered write (comm-central thunderbird).
I intend to use the logging code to record if unexpected file pointer position changes occurs, and also, print a sanity check for every 10,000 lines downloaded (for making sure the code does work.)
But this is only for ensuring that the fileposition change does NOT occur before
we remove a seemingly redundant seek(), which prevents us from buffering the write operation of downloaded message to a mail store.
Once we know that the unexpected file pointer change does not occur [logically it should not, but the |seek| has been there all along.|, we can remove it and enable buffering!

TIA

Comment 62

[marinar]

We have the same problem in Thunderbird 38.0.1.
Users get the following message when
sending email
"Your message has been sent and saved, but there was an error while
running message filters on it."

No filters are defined.
IMAP sync is off, all emails stay on IMAP server.

Please advise how it could be fixed.

Thank you

Comment 63

[Kent James (:rkent)]

marinar: This bug solved a particular issue and is now resolved, and so any new issues with the same symptoms need to be opened in a new bug. Please open a new bug, and try to give a detailed set of steps to reproduce, such that a developer would be able to duplicate the symptoms that you are seeing.

Comment 64

[marinar]

I tried to construct new bug report and found out cause of this problem.

The old server setting left behind in prefs.js caused this problem. 
 user_pref("mail.server.server1.userName", "nobody");
Previous versions of Thunderbird just ignored this settings.

Thank you