854172 - Add a missing check of the return value of MoveIncorporatedMessage, and the failure to log such filter failure.

Status: RESOLVED FIXED

(MailNews Core :: Filters, defect)

Description

[ISHIKAWA, Chiaki]

Attachment: Checking the return value of MoveIncorporatedMessage() and skip the next function call if failed.

During investigating the failure to move a downloaded article by a filter rule
when the destination folder is missing ".msf" file
(Recently re-opened Bug 261419),
I noticed
a place where a return value of MoveIncorporatedMessage() is not properly checked,
and also where such failure to move the error is not
properly logged.
I am attaching a fix for the return value check, and a place holder for
the logging change. 
Unfortunately, the logging for the failure is not filled in.
I looked at the logging code for the successful case:
https://mxr.mozilla.org/comm-central/source/mailnews/base/search/src/nsMsgFilter.cpp#480

The function looks so complex and large, and so I was
not willing to re-create a similar  function for filtering action failure
(I am not talking about the hit, etc. I am talking about the failure of actions such as copy/move/delete, etc. due to low-level issues such
as .msf file missing, disk space too low, etc.)

TIA.

PS: I am compiling the attached patch, but it seems that I was
just hitting a massive change (after python client.py checkout) and
the compilation takes time locally. So I will report the
compilation/test (make mozmill) result later.

I hope someone can comment if the patch and my idea of logging the failure
is going in the proper direction in the meantime.

Comment 1

[ISHIKAWA, Chiaki]

David, can you check the attachment and see
if the checking of return value  of MoveIncorporatedMessage()
is warranted (I think it is), and more importantly
if you can comment whether we should log the failure to operate the filter
successfully (and moving the article to the destination).

TIA

At this moment, I have no idea where and how we can give
a clear UI feedback to the user to remind that filtering failed.

Comment 2

[:aceman]

You could log it at least to the error console and the filter log.

Comment 3

[ISHIKAWA, Chiaki]

Attachment: RFC: work-in-progress patch f

I am attaching a work-in-progress patch that
 - prints the warning using NS_ERROR() to the invoking console,
 - brings up an alert (re-using an existing function) for figuring out
   how to give a clear UI feedback to the user.

This is a work-in-progress and I welcome feedback.

How I tested the patch:

I used  DEBUG BUILD of TB (comm-central.)

I defined a filter rule to move articles that have a certain string in
the subject into "FilteredFolder", and send e-mails with that string
in the subject line. 

It worked with corretct .msf DB file.

After shutting down TB, I removed the .msf file for the folder for
simulating the problem(s) reported earlier, and restarted TB.
The filtering failed.

But now it failed loudly.
I saw the filter failure now reported using the methods I added.

(a) Dump on invoking console.

With the work-in-progress fix, I dumped the failure, with the folder
name as string, to tty console where thunderbird was started, and an
alert was shown.

(b) Alert 

Alert Dialog came up. 

I re-used the |ThrowAlertMsg| to see what type of alert it would generate.

It is filled with pre-defined boilerplate for the failure of
writing an article or filterlog to a folder (incorrect permission, remaining space
issue, etc.)

So I have to go and find out where the message is defined, and try to
have it modified to contain a message for filter failure. I think I
need to define a string bundle or something.

This is something I need to improve.
But since I *DO* get alert loud and clear, and possibly fix it or define a new alert display function in a similar fashion, it is going in the right direction.

(c) I have not done any logging to the filter.log for now.

    The successful filter logging code is rather complicated.

    LogRuleHit()    
    https://mxr.mozilla.org/comm-central/source/mailnews/base/search/src/nsMsgFilter.cpp#480

    I don't think we need all the complexity of successful logging.
    
    We just need to say, filter failed due to "error reason" (error
    reason can be a numeric or symbol error value even. Just enough
    for someone to investigate later assuming that proper alert is
    shown.

FYI, an excerpt from the session log on the invoking console with the
work-in-progress patch:

###!!! ASSERTION: Filtering to destination folder failed for some reason.: 'Error', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2118
folder path=<<mailbox://mtest2@127.0.0.1/FilteredFolder>>
Incorporate message complete.
Incorporate message begin:
uidl string: OS-!!EhS"!L;>!!MYK"!
Incorporate message complete.
Incorporate message begin:
uidl string: @nf"!'=A!!,jT"!WKh!!
WARNING: failed to open mail db parsing folder: 'destMailDB && NS_SUCCEEDED(rv)', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2585
++DOCSHELL 0xb5e7bb0 == 14 [id = 17]
++DOMWINDOW == 31 (0xaaaf060) [serial = 41] [outer = (nil)]
++DOMWINDOW == 32 (0xbe53200) [serial = 42] [outer = 0xaaaf060]

	    [... these are repeated for each failure.
	    [... Alert is shown for each message. ]


(b) Rate-limiting of Alert(s)

Rate-limiting of the alert dialog is necessary. I don't want to see
100-200 such alerts to close before I can look into the cause of the
filter failure problem and fix it and invoke filter afterward.  

Too many alert dialogs to overwhelm the user is a real-life experience
before. I have a rough idea for rate-limiting, which is outlined in
the work-in-progress patch.

(b) Strange SQL warning later in the session log.

When I quit the session, I saw strange SQL warnings.
I suppose that these are due to the failure of moving 
of articles from Inbox to a different folder because of missing .msf DB file.
Just to be sure I am quoting them below. 

If anyone notices something fishy, let me know.
If so, TB is affected with an unnoticed bug.

WARNING: SQL statement 'REPLACE INTO 'main'.'messagesText_segdir' VALUES(?,?,?,?,?,?)' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'REPLACE INTO 'main'.'messagesText_segments'(blockid, block) VALUES(?, ?)' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'SELECT coalesce((SELECT max(blockid) FROM 'main'.'messagesText_segments') + 1, 1)' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'SELECT (SELECT max(idx) FROM 'main'.'messagesText_segdir' WHERE level = ?) + 1' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'REPLACE INTO 'main'.'conversationsText_segdir' VALUES(?,?,?,?,?,?)' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'SELECT coalesce((SELECT max(blockid) FROM 'main'.'conversationsText_segments') + 1, 1)' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'SELECT (SELECT max(idx) FROM 'main'.'conversationsText_segdir' WHERE level = ?) + 1' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'INSERT INTO 'main'.'messagesText_content' VALUES(?,(?),(?),(?),(?),(?))' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758
WARNING: SQL statement 'INSERT INTO 'main'.'conversationsText_content' VALUES(?,(?))' was not finalized: file /COMM-CENTRAL/comm-central/mozilla/storage/src/mozStorageConnection.cpp, line 758


I will attach a whole session log when TB started
with missing .msf DB file for "FilteredFolder" and
received articles that should be filtered into this folder.
The filering (moving the articles) failed due to the missing .msf DB
file. Then TB is terminated.


TIA

Comment 4

[ISHIKAWA, Chiaki]

Attachment: A short session log when the filtering failed (with the work-in-progress patch)

TTY console log.

Comment 5

[ISHIKAWA, Chiaki]

Attachment: RFC: work-in-progress patch (take 2) with working rate-throttling

Short Progress Report.

My previous patch was not quite correct. I am attaching a new
work-in-progress patch, which is much better with working rate-throttling. 

Background:

I have found out that depending on some factors (not sure what they
are,)

 case-A:
 - there are internal error states (when .msf DB file is missing) when
   a filtering failure (move/copy, etc) is reported by the existing
   logic, and

 case-B: - there are other internal error states when a filtering
 failure is NOT REPORTED AT ALL.

I hit case-B while testing 4GB+ mail folder size issues, and thus
filed this bugzilla entry to have fix for
 - reporting the filtering error (which may be silent sometimes) to
   the user, and
 - suggesting to the user that filtering is manually invoked after repairing
   the .msf DB file.

Now, based on my finding that there are times when the existing logic
spews out error dialog when filtering operation fails, I inserted
"rate-limit" throttling to the existing alerts as well as to my own
addition.  

Attached is the work-in-progress patch. (Rate-limiting works.)

Another finding is that my alert was not at all shown as of now.  I
traced the code to figure out where the string bundle is used for
alert() and found, to my surprise, oh well, that nothing is shown if
the constant message key string passed to ThrowAlertMsg() does not
match anything in the string bundle (not even a default
boiler-plate.)  That is when I realize something is fishy and noticing
that my implementation of rate-throttling is not effective to the
alerts really shown led to the above realization.

So the work-in-progress takes care of the rate-throttling of the
existing alerts, but I need to define the string bundle for the
following part:
> - the filtering error (already occurred), and
> - suggest to the user that filtering is manually invoked after repairing
>   the .msf DB file.

Long report: how I tested the work-in-progress patch.

I used a folder titled "FilteredFolder" as the destination of
filtering move operation

CAUTION: Very puzzling initially during test.  

If a folder is selected on exit of TB, it will be selected on the
restart of TB.  If a folder is selected on startup of TB, its .msf DB
file is automatically created if it does not exist (!).  

Clever, but this interferes my testing of removing .msf file for a
destination folder.

So, a tester should not select this "FilteredFolder" upon exit of TB.
FilteredFolder.msf is manually deleted for testing purposes..

TB is restarted, and the filtering to FilteredFolder is
tested while FitleredFolder.msf does not exist.

TB received e-mails via POP3 and some e-mails are filtered to
be moved to FilteredFolder. (my test
sends articles with subject that matches the filter to
move the article to FilteredFolder every two e-mails.)

Since .msf is not there, filtering operation (MOVE in particular)
fails.

I have applied rate-limiting to existing alerts as well as my
newly introduced alert when the filtering fails as explained above.
So with the work-in-progress patch, I get consistent alert(s) and not
bombed with too many alerts.

Also, my earlier observation about boiler-template alert was wrong.

 - Since my message "MovingbyFilteringGFailed" in the added call to
   ThrowAlertMsg() did not match any bundle, my alert was
   not really created and visible at all. I should have known.

 - But rather, the alert from the existing logic was SOMETIMES shown
   in the failed case in the particular state. That alert was
   consistently shown the day before and fooled me.

   Strange, that such alerts had not been shown earlier when I tested
   4GB+ mailfolder issue.  

   But yesterday, during the test, I noticed the runs where the alerts
   were consistently displayed, and runs where no alert was shown at
   all. That is when I realized that the visible alert is coming from
   the existing code and not new code. So the work-in-progress patch
   was modified to rate-limit the alerts from the existing code, too.

   In any case, the failed filtering needs to be EXPLICITLY MENTIONED
   in an alert to reduce user confusion (this is one of my main points
   of filing the bug). So I do need to create an alert with desired
   message.  So I have to go the way of creating such a message bundle
   and make sure it is shown at least once during a long run of POP3
   download, or something similar.

I am attaching also the log from the short test run of the above
scenario:

But here is the highlight from the log that shows the operation of
rate limiting, etc..

   *** I hit GetMail and obtained messages.
       But the message filtering operation failed due to the
       missing destMailDB on the second article.

       The initial alert thrown and shown is for
       "filterFolderWriteFailed" from existing logic.

       ****

Begin mail message delivery.
GetDiskSpaceAvailable returned: 8431374336 bytes
Incorporate message begin:   <--- this one did not trigger filtering.
uidl string: 6CU!!pX6!!/Kd"!-,'#!
Incorporate message complete. <--- so this ended peacefully.
Incorporate message begin:   <--- this one triggered filtering.
uidl string: ?U8"!Q0E"!gl\"!j>\!!
WARNING: failed to open mail db parsing folder: 'destMailDB && NS_SUCCEEDED(rv)', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2724
shouldSuprressAlert: mbuf:msg=mailbox://mtest2@127.0.0.1/FilteredFolder:filterFolderWriteFailed

     [... rate limiting function dump ...]			  

returning was_shown_recently = false  <=== the alert is new, so show it.

	   [...]

	   *** CI My new code then explicitly
	       throws an alert for "MovingByFilteringFailed".
	       But since this has no string defined in string bundle,
	       it IS THROWN, but not now shown on the screen (YET).
	       ****

###!!! ASSERTION: Filtering to destination folder failed for some reason.: 'Error', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2278
folder path=<<mailbox://mtest2@127.0.0.1/FilteredFolder>>
shouldSuprressAlert: mbuf:msg=mailbox://mtest2@127.0.0.1/FilteredFolder:MovingByFilteringFailed

     [... rate limiting function dump ...]			  

returning was_shown_recently = false <=== the alert is new, so show it.
Incorporate message complete.
Incorporate message begin:          <--- this message did not trigger filtering.
uidl string: 7]n"!A7:!!+,!#!klG"!
Incorporate message complete.       <--- So this ends peacefully.
Incorporate message begin:
uidl string: "%]!!;CA!!W?N"!N*_"!

     **** Another message triggers filtering, but failed again.
          The alerts from the existing code and my new addition
	  are suppressed due to rate-limiting ****

WARNING: failed to open mail db parsing folder: 'destMailDB && NS_SUCCEEDED(rv)', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2724
shouldSuprressAlert: mbuf:msg=mailbox://mtest2@127.0.0.1/FilteredFolder:filterFolderWriteFailed
	     [... dump from rate limiting function.]
returning was_shown_recently = true <==== It has been thrown (and shown) lately.
###!!! ASSERTION: Filtering to destination folder failed for some reason.: 'Error', file /COMM-CENTRAL/comm-central/mailnews/local/src/nsParseMailbox.cpp, line 2278
folder path=<<mailbox://mtest2@127.0.0.1/FilteredFolder>>
shouldSuprressAlert: mbuf:msg=mailbox://mtest2@127.0.0.1/FilteredFolder:MovingByFilteringFailed
	     [... dump from rate limiting function.]
returning was_shown_recently = true <==== It has been thrown (and shown, well not actually yet) lately.
Incorporate message complete.


PLAN:

Once I define the proper string bundle and can show the desired alert
with the warning about "invoking filtering again once repairing .msf
DB file", I will propose a patch for review. Hopefully soon.

Also, I may investigate if similar overflooding of alerts may occur if
we try to copy/move a large number of selected articles to a
destination folder which has broken or missing .msf DB file. [Thinking
along this way, I feel that the rate-throttling can be part of the
ThrowAlertMsg(), i.e., part of the folder class(?) or something, but I
don't know mozilla code very well, and it has a chance of breaking
existing test-suite which expects every single alert to show. We need
a hook to disable rate-limiting in that case. That sounds too much
trouble for fixing the particular bug I experienced. So I am not
proposing this time although that does sound attractive.]

TIA

PS: TB is wonderful when it works under normal conditions. But when an
major error occurs, sometimes I find there is much room for
improvement (like properly checking the return value of low-level
functions.)

Comment 6

[ISHIKAWA, Chiaki]

Attachment: A short session log when the filtering failed (with the work-in-progress take 2 patch)

Comment 7

[Mark Banner (:standard8)]

Comment on attachment 728705 [details] [diff] [review]
Checking the return value of MoveIncorporatedMessage() and skip the next function call if failed.

Its unclear to me where you are with this, so I'm cancelling the outstanding review as it looks like you have a newer patch. When ready, I suggest you ask review from :rkent as he's done work on the filter and related code.

Comment 8

[ISHIKAWA, Chiaki]

(In reply to Mark Banner (:standard8) from comment #7)
> Comment on attachment 728705 [details] [diff] [review]
> Checking the return value of MoveIncorporatedMessage() and skip the next
> function call if failed.
> 
> Its unclear to me where you are with this, so I'm cancelling the outstanding
> review as it looks like you have a newer patch. When ready, I suggest you
> ask review from :rkent as he's done work on the filter and related code.

Sorry, I was more like asking for feedback: hit the wrong entry, I think, and
anyway, I will ask :rkent for his feedback once I tested the patch to see if the proper dialog shows up. (I edited message.properties or some such file to see if I can show the desired message panel.)

TIA

Comment 9

[ISHIKAWA, Chiaki]

I have a patch ready on local PC. With a minor fix of bcopy -> memset, it should work
for WIN32 build, too.

It does rate-throttling of alerts.
It now picks up desired message of my own writing from "messenger.properties" which I modified to incorporate the desired message.

But I hit a snug.

Very strangely, TB passes NULL msgWindow parameter to the low-level routines involved.
(For example, https://mxr.mozilla.org/comm-central/source/mailnews/local/src/nsParseMailbox.cpp#2473
The last paramter.
nsresult nsParseNewMailState::MoveIncorporatedMessage(nsIMsgDBHdr *mailHdr,
2474                                                       nsIMsgDatabase *sourceDB,
2475                                                       nsIMsgFolder *destIFolder,
2476                                                       nsIMsgFilter *filter,
2477                                                       nsIMsgWindow *msgWindow)

When this is the case, the call to show alert, 
ThrowAlertMsg(msgKey, msgWindow) does not show anything obviously.
Other times, when msgWindow is passed non-null pointer, the alerts are shown properly and
rate-limited, thus I am not bombarded by too many alerts.

So basically, my desire of
 - rate-limitng alerts, and
 - showing  a proper warning about filtering failed, and re-run filtering manually
   after .msf DB issues are sorted

is now answered.

But sometimes, TB does not show alerts at all. [this is what I encountered several days ago and realized yesterday when all of a sudden my patch did not show alerts at all although the basic logic worked as expected and I got tty console dump correctly. Only alerts on the screen were missing.]

So far, I noticed the pattern as follows:

 - if I start TB with empty, 0-size .msf DB, and THEN send test messages to the
   test account to trigger filtering to the broken folder, 
   msgWindow parameter is null, and so
   warning/error alert is not shown at all. [we get the tty console dump for DEBUG build.] Not good.

    [To start with a 0-size .msf DB, you have to start TB, choose a folder, say, Inbox,
     and make sure that it is not receiving e-mails or doing other I/O activity, and
     then externally remove the .msf DB file for the folder of filtering destination.
     Yes, I know this is crude, but I have no idea how one can get corrupt .msf DB
     under normal conditions. This is my hack to create this corrupt state of .msf DB.
     Then quit TB immediately. On the next starup, TB seems to try to re-create
     the .msf DB file, but ends up with 0-size file. This is how I noticed the issue.]


But if the test account has a set of outstanding e-mails waiting to be received,
and some of these trigger filtering to the broken folder BEFORE TB is stared, and
the option to query the mail host on startup is enabled, 
as soon as TB starts up, the messages are downloaded, and
in this scenario, msgWindow is not null, and thus alerts for failed filtering operation are properly shown, and
my rate-limiting feature kicks in, and all is well.

Well how would I fix this so that we get the 
warning / alerts all the time?

I think we may want to pass a more permanent value (a msgWindow value for
always visible window , a non-null)  instead of the passed msgWindow which are
sometimes null.

But I am not sure what is the proper value instead msgWindow parameter to pass
to the low-level routines in the case of error reporting.

Does anyone have suggestions?
I am putting :rkent for feedback on this idea for the second patch.

TIA

Comment 10

[ISHIKAWA, Chiaki]

> Very strangely, TB passes NULL msgWindow parameter to the low-level routines involved.

I missed putting "sometimes". This randomness is an issue.
So the above should read:

Very strangely, TB sometimes passes NULL msgWindow parameter to the low-level routines involved.

Comment 11

[Kent James (:rkent)]

Let me try to clarify what I think are the issues being addressed here.

Issue 1: MoveIncorporatedMessage can fail, and there are cases where that failure is ignored.

Issue 2: Failures in message filters are not typically reported in a convenient fashion.

Issue 3: The one existing mechanism to report failures, "folder->ThrowAlertMsg", can result in large numbers of alerts being thrown, forcing closing of many windows.

Now my comments on these issues.

Issue 1) is real, and as I understand it is the main purpose of this bug. I suggest that you submit a patch that deals narrowly with that issue, rather than try to deal with the other issues.

Issue 2) is also a significant issue, and I would welcome a fix for this. That would consist of a new bug, and probably a new method added to nsIMsgFilter to log a filter error. I could have used such a method in my recent rewrite of nsMsgFilterAfterTheFact in bug 695671.

Issue 3) shows why throwing a dialog is not a good approach to dealing with filter errors, so I am not enthusiastic about trying to fix a fundamentally flawed approach by throttling the dialogs. Filters run automatically, and in my opinion automatic operations should not be throwing dialogs up to the user except in the most catastrophic situations (and a failed filter does not meet this threshold).

There are unfortunately no good mechanisms to deal well with user alerts in Thunderbird. I would like to see a method such as a sticky warning alert in the message status bar, that shows that there is some issue that the user should be aware of, and then goes away when the user opens the message. But that is a much bigger issue than this bug. For filters, what is needed is to make sure that any errors are shown in the existing mechanisms, which would be 1) a non-sticky message in the status bar, 2) an entry in the filter log, and 3) an entry in the activity manager.

Concerning specific questions:

"Well how would I fix this so that we get the warning / alerts all the time?"

The window watcher can return a valid window if needed, but I do not recommend doing this in filters for the reasons above. Null msgWindow is passed intentionally in some cases where you do not want to show any alerts (for example in testing, but also by people such as myself who disagree with the whole concept of showing dialogs during filter processing).

Comment 12

[ISHIKAWA, Chiaki]

(In reply to Kent James (:rkent) from comment #11)
> Let me try to clarify what I think are the issues being addressed here.
> 

Thank you for the feedback.

> Issue 1: MoveIncorporatedMessage can fail, and there are cases where that
> failure is ignored.
> 
> Issue 2: Failures in message filters are not typically reported in a
> convenient fashion.
> 
> Issue 3: The one existing mechanism to report failures,
> "folder->ThrowAlertMsg", can result in large numbers of alerts being thrown,
> forcing closing of many windows.
> 

These are the main purposes.

From reading your description below, now I realize there may be other methods
(sticky warning alert, status bar-like thingy.)
But I wrote the patch using alert since it was the mechanism used elsewhere in the file.

> Now my comments on these issues.
> 
> Issue 1) is real, and as I understand it is the main purpose of this bug. I
> suggest that you submit a patch that deals narrowly with that issue, rather
> than try to deal with the other issues.
>

Fine, I will narrow the scope down initially.
 
> Issue 2) is also a significant issue, and I would welcome a fix for this.
> That would consist of a new bug, and probably a new method added to
> nsIMsgFilter to log a filter error. I could have used such a method in my
> recent rewrite of nsMsgFilterAfterTheFact in bug 695671.

If not using alert, I am not sure what I can do. Do you know of a code I could
borrow?

> 
> Issue 3) shows why throwing a dialog is not a good approach to dealing with
> filter errors, so I am not enthusiastic about trying to fix a fundamentally
> flawed approach by throttling the dialogs. Filters run automatically, and in
> my opinion automatic operations should not be throwing dialogs up to the
> user except in the most catastrophic situations (and a failed filter does
> not meet this threshold).
>

From the user's point of view, unless point 2 is fixed (that is, unless
the deficiency of not being told of error), we do need something that tells
the user that errors have occurred.

I think here we agree to disagree on the severeness of the issue.
I, for one, was pretty disturbed until I realized that the messages that
were not filtered not lost completely, but remain in the Inbox.
This is a serious psychological burden and that is why I wrote a kludge (rate-limiting). 

Yes, if a sticky warning dialog, instead of dialog, can be shown that is great.
 
> There are unfortunately no good mechanisms to deal well with user alerts in
> Thunderbird. I would like to see a method such as a sticky warning alert in
> the message status bar, that shows that there is some issue that the user
> should be aware of, and then goes away when the user opens the message. But
> that is a much bigger issue than this bug. For filters, what is needed is to
> make sure that any errors are shown in the existing mechanisms, which would
> be 1) a non-sticky message in the status bar, 2) an entry in the filter log,
> and 3) an entry in the activity manager.
> 

What is the activity manager? I have never heard of it as a TB user.

> Concerning specific questions:
> 
> "Well how would I fix this so that we get the warning / alerts all the time?"
> 
> The window watcher can return a valid window if needed, but I do not
> recommend doing this in filters for the reasons above. Null msgWindow is
> passed intentionally in some cases where you do not want to show any alerts
> (for example in testing, but also by people such as myself who disagree with
> the whole concept of showing dialogs during filter processing).

Yes, I found the comment below.
/COMM-CENTRAL/comm-central/mailnews/base/util/nsMsgDBFolder.cpp

      if (NS_SUCCEEDED(rv))
        // We use a null nsIMsgWindow because we don't want some sort of ui
        // appearing in the middle of automatic filtering (plus I really don't
        // want to propagate that value.)
        rv = filterService->ApplyFilters(nsMsgFilterType::PostPlugin,
                                         mPostBayesMessagesToFilter,
                                         this, nullptr /* nsIMsgWindow */);

For testing difficulty,
 - we should create a flag / a probe to change
   the behavior during testing. [If we do need to pass nullptr during
   testing, we will.] Is there a probe to check whether we are under testing?

For philosophical difference, all I can say is TB's failure NOW to show the error
is really bad.

Anyway, I will try to figure out sticky window / status / activity manager (whatever that is) to show the error in that direction.

Hmm. Sharing the infrastructure with browser may not be the best thing for a mailer. Sharing an infrastructure with an editor where the loss of data is very critical might have been.

TIA

 -

Comment 13

[WADA:World Anti-bad-Duping Agency]

> Bug summary :  Add a missing check of the return value of MoveIncorporatedMessage
(In reply to ISHIKAWA, chiaki from comment #0)
> Checking the return value of MoveIncorporatedMessage() and skip the next function call if failed.

Similar MoveIncorporatedMessage() is defined for IMAP.
> http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#4075
And, for message filter, MoveIncorporatedMessage() is called at;
> http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#3494
> 3494             nsresult err = MoveIncorporatedMessage(msgHdr, mDatabase, actionTargetFolderUri, filter, msgWindow);
> 3495             if (NS_SUCCEEDED(err))
> 3496               m_msgMovedByFilter = true;
It's "assertion in Debug build only if err"?
No need of change in IMAP code?

Comment 14

[WADA:World Anti-bad-Duping Agency]

(In reply to ISHIKAWA, chiaki from comment #12)
> If not using alert, I am not sure what I can do. Do you know of a code I could borrow?

How about use Error Console for logging in debug build, or while nightly / beta build?
Logger sample in JavaScript.
> function PutLog(StringOrArray)
> {
>    var MyConsole =
>        Components.classes["@mozilla.org/consoleservice;1"]
>        .getService(Components.interfaces.nsIConsoleService);
>    var dte0=new Date() ;
>    var dte1=dte0.toJSON() ;        // 2012-12-04T03:28:50.671Z
>    var dte2=dte1.split("T") ;
>    var dte3=new Array();
>    dte3[0]=dte2[0].split("-").join("/") ;
>    dte3[1]=dte2[1].split("Z")[0] ;
>    var timestamp=dte3.join(" ") + " GMT" ;  // 2012/12/04 03:28:50.671 in GMT
>
>    if( Array.isArray(StringOrArray) ) MyConsole.logStringMessage( timestamp + "\n" + StringOrArray.join("\n") );
>    else                               MyConsole.logStringMessage( timestamp + "\n" + StringOrArray            );
> }
"XPCOM Wrapped object which produces Exception by conversion to string" may be passed by caller. So, try/catch block may be better, if such exception is not surely ruled out at caller side.
If prefs.js entry for the logging is introduced, logging is easily enabled/disabled by user.

Comment 15

[ISHIKAWA, Chiaki]

(In reply to WADA from comment #13)
> > Bug summary :  Add a missing check of the return value of MoveIncorporatedMessage
> (In reply to ISHIKAWA, chiaki from comment #0)
> > Checking the return value of MoveIncorporatedMessage() and skip the next function call if failed.
> 
> Similar MoveIncorporatedMessage() is defined for IMAP.
> > http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#4075
> And, for message filter, MoveIncorporatedMessage() is called at;
> > http://mxr.mozilla.org/comm-central/source/mailnews/imap/src/nsImapMailFolder.cpp#3494
> > 3494             nsresult err = MoveIncorporatedMessage(msgHdr, mDatabase, actionTargetFolderUri, filter, msgWindow);
> > 3495             if (NS_SUCCEEDED(err))
> > 3496               m_msgMovedByFilter = true;
> It's "assertion in Debug build only if err"?
> No need of change in IMAP code?

IMAP code probably needs similar checking, yes. But I am not a user of IMAP and so can't test it.

(In reply to WADA from comment #14)
> (In reply to ISHIKAWA, chiaki from comment #12)
> > If not using alert, I am not sure what I can do. Do you know of a code I could borrow?
> 
> How about use Error Console for logging in debug build, or while nightly /
> beta build?

I think Error Console is being put on the background in favor of Web Console or something. I recently read about it in the newsgroup/mailing list.

But there is a problem. Error Console (or presumably Web Console) is NOT ALWAYS
visible and thus NOT good for error NOTIFICATION. Sure, it is good for error logging. [I thik 99.9 % of TB users never bothered to look at Error Console unless being told to do so when error occurs.]

So I think I may simply put a short error message in the status bar/activity manager,  some sticky dialog or something, and then put the detail in either Error Console, easier to access Web Console or whatever.

Comment 16

[ISHIKAWA, Chiaki]

Hi, I found a document (draft) about Activity Manager.
https://developer.mozilla.org/en-US/docs/Thunderbird/Activity_Manager
But this is kind of sparce.
I wonder if there is more examples, etc. (Well, I could find the call to
this function, but they are all from JS code. Hmm. I am interested in reporting the error from C++ code.)

Also, as far as I can tell, Activity Manager needs rate-limiting, too.
If the low-level code reports more than 250 failed mail moves to a folder
due to corrupted/missing .msf DB file, then other entries are purged from 
ACtivity MAnager and it is not useful at all.

By the way, rate-limiting is a kluge, but to avoid DoS like spamming of
similar messages, it is indispensable. syslog daemon has used it
to its benefit all these years.

Maybe I can concoct a routine to interface to Activity Manager and put the
rate-limit feature in it. 

TIA

Comment 17

[Kent James (:rkent)]

Re activity manager:

I looked at one of my own implementations of this, and I ended up creating a new interface to receive the notifications, a js-based component that is instantiated in a C++ method, calls in the C++ method to do the actual reporting, and a js module to actually write to the activity manager. That is quite a bit of code to do some simple reporting. So this is not an easy subsystem to interface to.

In response to most of your comments, all I can really do is to reiterate that I am not happy with the error reporting mechanisms available to filter code, nor for that matter to error reporting in general in mailnews code, but you really need to avoid getting absorbed by that issue at the expense of resolving the root issue in this bug.

What is very doable though, and reasonably within the user expectation fo the current reporting, is my suggestion of issue 2) in comment 11, namely to add a new error reporting capability to the existing filter log. I specifically do not like alerts in filter code, even though there are existing examples of that. Trying to be add other mechanisms (error console, status messages) is really outside of the existing paradigm of error reporting in filter code, and should not be done without discussion, probably in a new bug.

So to make progress with this I would encourage you to do the simpler patch, possible combining it with a new error message to the filter log.

Comment 18

[ISHIKAWA, Chiaki]

(In reply to Kent James (:rkent) from comment #17)
> Re activity manager:
> 
Thank you for the feedback.

> I looked at one of my own implementations of this, and I ended up creating a
> new interface to receive the notifications, a js-based component that is
> instantiated in a C++ method, calls in the C++ method to do the actual
> reporting, and a js module to actually write to the activity manager. That
> is quite a bit of code to do some simple reporting. So this is not an easy
> subsystem to interface to.
Hmm... That certainly sounds rather complex, but I was afraid that I would do something similar to create a proxy for reporting to the activity manager.
(BTW, recently my firefox got updated and I do notice the new download manager that has a fancy notification mechanism.)

> 
> In response to most of your comments, all I can really do is to reiterate
> that I am not happy with the error reporting mechanisms available to filter
> code, nor for that matter to error reporting in general in mailnews code,
> but you really need to avoid getting absorbed by that issue at the expense
> of resolving the root issue in this bug.
> 
> What is very doable though, and reasonably within the user expectation fo
> the current reporting, is my suggestion of issue 2) in comment 11, namely to
> add a new error reporting capability to the existing filter log. I
> specifically do not like alerts in filter code, even though there are
> existing examples of that. Trying to be add other mechanisms (error console,
> status messages) is really outside of the existing paradigm of error
> reporting in filter code, and should not be done without discussion,
> probably in a new bug.


> So to make progress with this I would encourage you to do the simpler patch,
> possible combining it with a new error message to the filter log.

I am re-digesting your comment. So you are suggesting some simple notification mechanism of a sort to the filter log function (?).
Anyway, I will simply add an error mesage in the filter log, and
then I would think of how to get this error status to the user in a visible manner as the next step.

TIA

Comment 19

[Wayne Mery (:wsmwk)]

This blocks dataloss bugs, so increasing severity

(In reply to Kent James (:rkent) from comment #17)
>...
> So to make progress with this I would encourage you to do the simpler patch,
> possible combining it with a new error message to the filter log.

(In reply to ISHIKAWA, Chiaki from comment #18)
>...
> I am re-digesting your comment. So you are suggesting some simple
> notification mechanism of a sort to the filter log function (?).
> Anyway, I will simply add an error mesage in the filter log, and
> then I would think of how to get this error status to the user in a visible
> manner as the next step.
> 
> TIA

(having reread rkent's previous comments.) 

Yes, that is what he is asking for.  And, like rkent I am keen on getting the more important bits landed soon.  OTOH, would it not be dead simple to do NSPR, which is one of aceman's ideas in bug 697522?

Comment 20

[ISHIKAWA, Chiaki]

(In reply to Wayne Mery (:wsmwk) from comment #19)
> This blocks dataloss bugs, so increasing severity
> 
> (In reply to Kent James (:rkent) from comment #17)
> >...
> > So to make progress with this I would encourage you to do the simpler patch,
> > possible combining it with a new error message to the filter log.
> 
> (In reply to ISHIKAWA, Chiaki from comment #18)
> >...
> > I am re-digesting your comment. So you are suggesting some simple
> > notification mechanism of a sort to the filter log function (?).
> > Anyway, I will simply add an error mesage in the filter log, and
> > then I would think of how to get this error status to the user in a visible
> > manner as the next step.
> > 
> > TIA
> 
> (having reread rkent's previous comments.) 
> 
> Yes, that is what he is asking for.  And, like rkent I am keen on getting
> the more important bits landed soon.  OTOH, would it not be dead simple to
> do NSPR, which is one of aceman's ideas in bug 697522?

The summer heat, and other issues have distracted me a bit.
Sorry for not realizing this needinfo request.

Let me see what I can concoct out of the existing outdated patch.

Comment 21

[ISHIKAWA, Chiaki]

I noticed a couple of things after reviewing what has transpired before.

(1) I need to log the error using a log function somehow. (It could be a single hack although L10N may make it a little awkward.)

(2) I have not introduced alert() call on my own.
    They have been there and in the current code, too.

(3) I have introduced the rate-limiting feature because
    during a test, I was overwhelmed by a reappearing dialog (x N where N is
    a message that is filtered into the problematic folder without .msf.)
    The rate-limiting of alert IS NECESSARY irrespective of 
    how the filter logging is done in (1).

I think I should separate the rate-logging code into a separate bug.

Anyway, I am concocting a patch based on new code.

TIA

Comment 22

[ISHIKAWA, Chiaki]

(In reply to ISHIKAWA, Chiaki from comment #21)
> I noticed a couple of things after reviewing what has transpired before.
> 
> (1) I need to log the error using a log function somehow. (It could be a
> single hack although L10N may make it a little awkward.)
> 
> (2) I have not introduced alert() call on my own.
>     They have been there and in the current code, too.
> 
> (3) I have introduced the rate-limiting feature because
>     during a test, I was overwhelmed by a reappearing dialog (x N where N is
>     a message that is filtered into the problematic folder without .msf.)
>     The rate-limiting of alert IS NECESSARY irrespective of 
>     how the filter logging is done in (1).
> 
> I think I should separate the rate-logging code into a separate bug.
> 
> Anyway, I am concocting a patch based on new code.
> 
> TIA


This is my own reply.
Due to hardware problems since early August, I could not work on TB issues muchfor the past few weeks.
The bulk of the hardware issues is over although I still have booting order issue (default grub boots from unintended disk, and files are mounted to incorrect directories due to this), and display driver issue which makes it very hard to use the X console :-(

But anyway, I have started to work on the following three files, even before the hardware misbehavior, to incorporate a function to log filter error (this is the minimal rkent wanted me to focus initially.)

ishikawa@vm-debian-amd64:/REF-COMM-CENTRAL/comm-central$ hg status
M mailnews/base/search/public/nsIMsgFilter.idl  <-- declaration
M mailnews/base/search/src/nsMsgFilter.cpp      <-- implementation
M mailnews/local/src/nsParseMailbox.cpp         <-- the user of an error-reporting
                                                function.


For me the problem is that nsMsgFilter.cpp implements the functions which
are declared in nsMsgFilter.idl (exposed as XPCOM interface, it seems)
and the new error reporting function needs to be declared in the IDL file.

This means two things:

1. The IDL description, i.e., the interface needs to be changed.
I think the interface change needs to be approved in one of the mailing lists
after a discussion. 
(I *think* the approval is a MUST: currently there is no way to report an error
in the log file even. Not a trace for handling of errors. Please take a look at the
nsMsgFilter.idl if you are in doubt.)

2. I am total newbie when it comes to XPCOM or the use of IDL.
I have a tough time to figure out to declare a function that is exposed to
XPCOM via the IDL file.
Basically all I want to add is a single error-reporting function
that would be in plain c++ declared as

NS_IMETHODIMP nsMsgFilter::LogRuleHitFail(nsIMsgRuleAction *aFilterAction, nsIMsgDBHdr *aMsgHdr, char *errmsg)
or something similar to that effect (I may want to add numerical error code and
another error message for further expansion, but I digress.)
So far,  I have not been able to figure out how to declare this function
in IDL, especially the "char *errmsg", the error string part. 
It is not clear to me how to pass string via XPCOM.

I looked at other IDL files, and the closest I can find to
char* is something called AUT8String, but googling does not produce any comprehensible description about this datatype?

I would appreciate any tips regarding learning the basics of creating an IDL declaration for
function with a signature like the above?

TIA

Comment 23

[Wayne Mery (:wsmwk)]

(In reply to ISHIKAWA, Chiaki from comment #22)
> ...
> NS_IMETHODIMP nsMsgFilter::LogRuleHitFail(nsIMsgRuleAction *aFilterAction,
> nsIMsgDBHdr *aMsgHdr, char *errmsg)
> or something similar to that effect (I may want to add numerical error code
> and
> another error message for further expansion, but I digress.)
> So far,  I have not been able to figure out how to declare this function
> in IDL, especially the "char *errmsg", the error string part. 
> It is not clear to me how to pass string via XPCOM.
> 
> I looked at other IDL files, and the closest I can find to
> char* is something called AUT8String, but googling does not produce any
> comprehensible description about this datatype?
> 
> I would appreciate any tips regarding learning the basics of creating an IDL
> declaration for
> function with a signature like the above?
> 
> TIA

perhaps rkent or jcranmer can help here

Comment 24

[Joshua Cranmer [:jcranmer]]

(In reply to ISHIKAWA, Chiaki from comment #22)
> Basically all I want to add is a single error-reporting function
> that would be in plain c++ declared as
> 
> NS_IMETHODIMP nsMsgFilter::LogRuleHitFail(nsIMsgRuleAction *aFilterAction,
> nsIMsgDBHdr *aMsgHdr, char *errmsg)

You don't want that header. You want const nsACString &errMsg.

> I would appreciate any tips regarding learning the basics of creating an IDL
> declaration for
> function with a signature like the above?

void logRuleHitFail(in nsIMsgRuleAction aFilterAction, in nsIMsgDBHdr aMsgHdr, in AUTF8String errMsg);

<https://developer.mozilla.org/en-US/docs/Mozilla/XPIDL> has a detailed list of the XPIDL->C++ and XPIDL->JS mappings.

Comment 25

[ISHIKAWA, Chiaki]

(In reply to Joshua Cranmer [:jcranmer] from comment #24)
> (In reply to ISHIKAWA, Chiaki from comment #22)
> > Basically all I want to add is a single error-reporting function
> > that would be in plain c++ declared as
> > 
> > NS_IMETHODIMP nsMsgFilter::LogRuleHitFail(nsIMsgRuleAction *aFilterAction,
> > nsIMsgDBHdr *aMsgHdr, char *errmsg)
> 
> You don't want that header. You want const nsACString &errMsg.
> 
> > I would appreciate any tips regarding learning the basics of creating an IDL
> > declaration for
> > function with a signature like the above?
> 
> void logRuleHitFail(in nsIMsgRuleAction aFilterAction, in nsIMsgDBHdr
> aMsgHdr, in AUTF8String errMsg);
> 
> <https://developer.mozilla.org/en-US/docs/Mozilla/XPIDL> has a detailed list
> of the XPIDL->C++ and XPIDL->JS mappings.

Thank you for the hint. Finally I have time to start working on this.
Errors during filtering really ought to be reported in a visible manner IMHO.

TIA

Comment 26

[ISHIKAWA, Chiaki]

Attachment: WIP: to add error logging to filter code.

Hi,

This is a work-in-progress patch to log filtering error (move/copy failure).


At least, for now, the .idl, and .cpp files are in sync and by adding
a code to call LogRuleHitFail() I could
record the failure as part of the log file.

Now that the basic form is in place, it is a matter of
creating an interface to display "sticky" message or whatever
instead of logging.

BTW, I found that
 - move action failure caused by missing .msf at the startup of TB
   seems to be recorded by the added error logging code, but
 - copy action failure does not happen any more even .msf is missing
   at the startup of TB: it seems that TB now creates .msf when it notices
   .msf is missing. Thus my trial to record such copy action failure 
   did not succeed.
   (Of course, still, copy/move can fail due to almost full file systems, 
    transient network failure [if the file system is a remote mount of a network
    file system, etc.])

Sticky message, etc. may still need rate-throttling so that no DoS-like
verbose display can happen.

TIA

TIA

Comment 27

[Kent James (:rkent)]

Comment on attachment 8544659 [details] [diff] [review]
WIP: to add error logging to filter code.

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

Thanks Chiaki for working on this. Let me give you some comments on your recent efforts.

First, Neil and I did a lot of work on the after-the-fact filtering code recently, cleaning up many of the inconsistencies that existed in the handling of errors (which you have rightly pointed out are very common in this before-the-fact code as well). For the after-the-fact code, which is used in many different contexts, the error management philosophy that resulted was this: First, when errors occur, if at all reasonably possible do not interrupt filtering, but instead continue with any other actions. A single "error occurred" return value was maintained that was returned as a final result of the processing. Also, error handling is all handled by macros, and it would be straightforward to take the error logging that you are adding here, and add it to those error-handling macros.

So overall I like the concept of extending the filter log to include recording errors. Perhaps that could be included with a simple message to the status bar, like "One or more filters failed during incoming message processing" that would suffice for now to alert users of the problem, and give them the means to dig deeper (by enabling and observing the filter log).

I'll make a few comments on your code itself as well. I realize it is a work in progress, so many of may comments might be things that you intended to fix anyway, but I thought I'd warn you of what might come up in a review.

::: mailnews/base/search/public/nsIMsgFilter.idl
@@ +15,5 @@
>  interface nsIMsgSearchScopeTerm;
>  interface nsIMsgSearchValue;
>  interface nsIMsgSearchTerm;
>  
> +// [scriptable, uuid(36d2748e-9246-44f3-bb74-46cbb0b8c23a)]

You won't want to keep the old value here in a comment.

@@ +92,5 @@
>                    //                  [array, size_is(headerSize)] in string headers,
>                    in unsigned long headerSize, out boolean result);
>  
> +
> +    //     we may not want to expose this.

I agree, do not expose this.

@@ +108,5 @@
> +    void logRuleHitFail(in nsIMsgRuleAction aFilterAction,
> +                        in nsIMsgDBHdr aHeader,
> +                        in string errmsg,
> +                        in nsresult rcode,
> +                        in string errmsg2);

For any new methods added to an interface we will require detailed documentation in standard format.

::: mailnews/base/search/src/nsMsgFilter.cpp
@@ +480,5 @@
> +
> +//
> +// This function handles the logging for both
> +// simple rule hit case errflag == false, and
> +// error reporting when the resulting action (such as file move/copy) fails.

Can't you just use the rcode for this, with NS_OK for non-errors?

@@ +491,5 @@
> +                               bool errflag, 
> +                               const char *errmsg, // UTF8 error string
> +                               nsresult rcode, 
> +                               const char *errmsg2 // UTF8 auxiliary error string
> +  )

Trailing spaces here. Also note that the primary documentation of these should be in the idl, which frequently makes it less important or unnecessary to add comments like "UTF8 error string" here.

@@ +512,5 @@
>  
> +#if DEBUG
> +    if(errflag)
> +      NS_WARNING("(debug) we are calling nsMsgFilter::LogRuleHitGeneric to report filtering error!");
> +#endif

You'll remove this in the final code, right?

@@ +621,5 @@
> +      buffer += errmsg;
> +
> +    // TODO/FIXME: We have enough context and buffer (string) to display
> +    // the filtering error if we want: for example,
> +    // a sticky error message in status bar, etc.

Right. Perhaps we could even do this in the status bar, only showing the first failure with an extra warning if multiple failures occurred. That could be a followup bug.

::: mailnews/local/src/nsParseMailbox.cpp
@@ +1843,5 @@
>                      MoveIncorporatedMessage(m_newMsgHdr, m_mailDB, trash,
>                                              nullptr, msgWindow);
>                      m_mailDB->RemoveHeaderMdbRow(m_newMsgHdr);
> +                  } else {
> +                    NS_ERROR("MoveIncorporatedMessage failed for some reason.");

If you are going to collect error info here, you should probably also do it in the MoveIncorpororatedMessage as well, like:

                   if (NS_SUCCEEDED(rv) && !msgMoved) {
                     rv = MoveIncorporatedMessage(m_newMsgHdr, m_mailDB, trash,
                                             nullptr, msgWindow);
                     if (NS_SUCCEEDED(rv))
                       rv = m_mailDB->RemoveHeaderMdbRow(m_newMsgHdr);
                   }
                   if (NS_FAILED(rv))
                     NS_ERROR("MoveIncorporatedMessage failed for some reason.");

This style results in ever increasing depths of calls, which is why personally I prefer to use do {} while (false); with breaks for errors, but I am in the minority here, and some reviewers don't like that style.

@@ +2066,5 @@
>              m_msgMovedByFilter = NS_SUCCEEDED(err);
> +            if (! m_msgMovedByFilter)
> +            {
> +              // TODO/DONE: We should log the filtering (move) failure.
> +              // Ignore the value of loggingEnabled

I don't think that you should ignore loggingEnabled. Ultimately you need an alternate way to record that an error occurred that you could report to the standard UI, but the log file should be reserved for loggingEnabled.

@@ +2078,5 @@
> +
> +        // NOTE: Above, failure in moving results in setting false to m_msgMovedByFilter.
> +        // However, below, failure to copy results in early exit.
> +        // Note  NS_ENSURE_SUCCESS(rv, rv) before |m_msgCopiedByFilter = true;|
> +        // Why is the difference? I suspect no particular reason...

Right, these are the issues that need cleanup. As I suggested earlier, I think that the right philosophy is to continue if at all possible (that is do not NS_ENSURE_SUCCESS to abort) but report the error somehow to the user.

@@ +2263,5 @@
>  
>          customAction->Apply(messageArray, value, nullptr,
>                              nsMsgFilterType::InboxRule, msgWindow);
> +        // TODO/FIXME: should we not check the return code above?
> +        // Or is it already done within Apply recursively?

With your error logging, you will probably want to add error checks in places like this with an entry to the error log.

Comment 28

[Kent James (:rkent)]

Comment on attachment 733735 [details] [diff] [review]
RFC: work-in-progress patch  (take 2) with working rate-throttling

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

As I said elsewhere, I don't think that throttled alert messages are the answer. Use the filter log for details, keep track of whether an error occurred in a batch of messages, and if it did report that error in the status bar (or preferably in a new sticky-error status bar).

Comment 29

[ISHIKAWA, Chiaki]

Reply to the comments in a reversed order: (the last one comes first.)


(In reply to Kent James (:rkent) from comment #28)
> Comment on attachment 733735 [details] [diff] [review]
> RFC: work-in-progress patch  (take 2) with working rate-throttling
> 
> Review of attachment 733735 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> As I said elsewhere, I don't think that throttled alert messages are the
> answer. Use the filter log for details, keep track of whether an error
> occurred in a batch of messages, and if it did report that error in the
> status bar (or preferably in a new sticky-error status bar).

I will follow the path to a sticky error report or something.

(In reply to Kent James (:rkent) from comment #27)
> Comment on attachment 8544659 [details] [diff] [review]
> WIP: to add error logging to filter code.
> 
> Review of attachment 8544659 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks Chiaki for working on this. Let me give you some comments on your
> recent efforts.
> 
> First, Neil and I did a lot of work on the after-the-fact filtering code
> recently, cleaning up many of the inconsistencies that existed in the
> handling of errors (which you have rightly pointed out are very common in
> this before-the-fact code as well). For the after-the-fact code, which is
> used in many different contexts, the error management philosophy that
> resulted was this: First, when errors occur, if at all reasonably possible
> do not interrupt filtering, but instead continue with any other actions. A
> single "error occurred" return value was maintained that was returned as a
> final result of the processing. Also, error handling is all handled by
> macros, and it would be straightforward to take the error logging that you
> are adding here, and add it to those error-handling macros.
> 
> So overall I like the concept of extending the filter log to include
> recording errors. Perhaps that could be included with a simple message to
> the status bar, like "One or more filters failed during incoming message
> processing" that would suffice for now to alert users of the problem, and
> give them the means to dig deeper (by enabling and observing the filter log).
> 
> I'll make a few comments on your code itself as well. I realize it is a work
> in progress, so many of may comments might be things that you intended to
> fix anyway, but I thought I'd warn you of what might come up in a review.
> 

Thank you for your comment.
This is indeed a very first try after the hassle with .idl file on my own.

> ::: mailnews/base/search/public/nsIMsgFilter.idl
> @@ +15,5 @@
> >  interface nsIMsgSearchScopeTerm;
> >  interface nsIMsgSearchValue;
> >  interface nsIMsgSearchTerm;
> >  
> > +// [scriptable, uuid(36d2748e-9246-44f3-bb74-46cbb0b8c23a)]
> 
> You won't want to keep the old value here in a comment.

OK, I will remove it.
 
> @@ +92,5 @@
> >                    //                  [array, size_is(headerSize)] in string headers,
> >                    in unsigned long headerSize, out boolean result);
> >  
> > +
> > +    //     we may not want to expose this.
> 
> I agree, do not expose this.

Right. I will take it out.
 
> @@ +108,5 @@
> > +    void logRuleHitFail(in nsIMsgRuleAction aFilterAction,
> > +                        in nsIMsgDBHdr aHeader,
> > +                        in string errmsg,
> > +                        in nsresult rcode,
> > +                        in string errmsg2);
> 
> For any new methods added to an interface we will require detailed
> documentation in standard format.

I take note that .idl file needs documentation.
 
> ::: mailnews/base/search/src/nsMsgFilter.cpp
> @@ +480,5 @@
> > +
> > +//
> > +// This function handles the logging for both
> > +// simple rule hit case errflag == false, and
> > +// error reporting when the resulting action (such as file move/copy) fails.
> 
> Can't you just use the rcode for this, with NS_OK for non-errors?

Hmm. I was looking at the older code before the recent cleanup, and
and in the old days, log was done BEFORE even the result was known, correct?
That is why I think I added this errflag to
use the same body of code for different purposes (pre-action report, and post-action failure logging).
But if the use of logging is all post-action, then
I can certainly try to take up the suggestion. Let me see.

> @@ +491,5 @@
> > +                               bool errflag, 
> > +                               const char *errmsg, // UTF8 error string
> > +                               nsresult rcode, 
> > +                               const char *errmsg2 // UTF8 auxiliary error string
> > +  )
> 
> Trailing spaces here. Also note that the primary documentation of these
> should be in the idl, which frequently makes it less important or
> unnecessary to add comments like "UTF8 error string" here.

OK. I will add comment to .idl file.
To be frank, I have never looked at .idl files very much in detail. Maybe I should.

> 
> @@ +512,5 @@
> >  
> > +#if DEBUG
> > +    if(errflag)
> > +      NS_WARNING("(debug) we are calling nsMsgFilter::LogRuleHitGeneric to report filtering error!");
> > +#endif
> 
> You'll remove this in the final code, right?

Yes, of course :-)
I was just trying to see if my new code works.


> @@ +621,5 @@
> > +      buffer += errmsg;
> > +
> > +    // TODO/FIXME: We have enough context and buffer (string) to display
> > +    // the filtering error if we want: for example,
> > +    // a sticky error message in status bar, etc.
> 
> Right. Perhaps we could even do this in the status bar, only showing the
> first failure with an extra warning if multiple failures occurred. That
> could be a followup bug.

Yes, that would be my next goal along this line of efforts.
 
> ::: mailnews/local/src/nsParseMailbox.cpp
> @@ +1843,5 @@
> >                      MoveIncorporatedMessage(m_newMsgHdr, m_mailDB, trash,
> >                                              nullptr, msgWindow);
> >                      m_mailDB->RemoveHeaderMdbRow(m_newMsgHdr);
> > +                  } else {
> > +                    NS_ERROR("MoveIncorporatedMessage failed for some reason.");
> 
> If you are going to collect error info here, you should probably also do it
> in the MoveIncorpororatedMessage as well, like:
> 
>                    if (NS_SUCCEEDED(rv) && !msgMoved) {
>                      rv = MoveIncorporatedMessage(m_newMsgHdr, m_mailDB,
> trash,
>                                              nullptr, msgWindow);
>                      if (NS_SUCCEEDED(rv))
>                        rv = m_mailDB->RemoveHeaderMdbRow(m_newMsgHdr);
>                    }
>                    if (NS_FAILED(rv))
>                      NS_ERROR("MoveIncorporatedMessage failed for some
> reason.");
> 
> This style results in ever increasing depths of calls, which is why
> personally I prefer to use do {} while (false); with breaks for errors, but
> I am in the minority here, and some reviewers don't like that style.

I will take not of it. There are places where I am not sure
- if I should return immediately, or 
- defer the error return until more important internal data structure
  is updated.
 
> @@ +2066,5 @@
> >              m_msgMovedByFilter = NS_SUCCEEDED(err);
> > +            if (! m_msgMovedByFilter)
> > +            {
> > +              // TODO/DONE: We should log the filtering (move) failure.
> > +              // Ignore the value of loggingEnabled
> 
> I don't think that you should ignore loggingEnabled. Ultimately you need an
> alternate way to record that an error occurred that you could report to the
> standard UI, but the log file should be reserved for loggingEnabled.

Right. The above comment was premature in the sense that
- unless the user enables logging of filtering, we don't get
  the error log (pretty obvious), but
- I realize that by default filter logging is disabled,
as a result, I scratched my head until I realize I disabled logging and
not see the error log report. For convenience, the above W-I-P patch ignore
the logging so that I don't have to enable it every time new profile is used, etc.
 
> @@ +2078,5 @@
> > +
> > +        // NOTE: Above, failure in moving results in setting false to m_msgMovedByFilter.
> > +        // However, below, failure to copy results in early exit.
> > +        // Note  NS_ENSURE_SUCCESS(rv, rv) before |m_msgCopiedByFilter = true;|
> > +        // Why is the difference? I suspect no particular reason...
> 
> Right, these are the issues that need cleanup. As I suggested earlier, I
> think that the right philosophy is to continue if at all possible (that is
> do not NS_ENSURE_SUCCESS to abort) but report the error somehow to the user.

I will try to cope with things like these in the future. But I think I may need to leave
these as TODO items along the way.
 
> @@ +2263,5 @@
> >  
> >          customAction->Apply(messageArray, value, nullptr,
> >                              nsMsgFilterType::InboxRule, msgWindow);
> > +        // TODO/FIXME: should we not check the return code above?
> > +        // Or is it already done within Apply recursively?
> 
> With your error logging, you will probably want to add error checks in
> places like this with an entry to the error log.

I see.

Thank you again for your valuable comments.

I never realized until lately that there are so many things to do inside TB code.

TIA

Comment 30

[ISHIKAWA, Chiaki]

Attachment: to add error logging to filter code.

Hi I am asking for review.

My plan for this bug:
A new logging function feature to print a sticky message to message status line or something will take time to create. So I would like to leave this patch as is (after proper fix)
and would like to create a new bugzilla entry to handle the  fancy logging feature in the future (WITH THE SAME INTERFACE, of course.)

Anyway, for the patch, 
I reflected all the comments (in places where I cannot do the modification in
the near future, I inserted comments so that people in the future can work on the
raised points).

There is one remaining point.
It was not easy to hide the generic logging function to be used for
both success and error failure from .idl since
hiding it from .idl meant massive (well not so massive actually) rewrite of
the function so that it can properly reference the class variables, etc. and
I am not familiar with how IDL and ordinary C++ headers co-exist and not sure
what the proper / acceptable rewrite and so I gave up on this point.

[I could have simply created the new bodies for logRuleHit and logRuleHitFailed without bothering to create the overloaded generic routine:
the former carrying over the original log code and the latter copying the
bulk of the successful log code, etc. and be done with it although
I hate seeing the duplication of the bulk of the code.

I also have done away with some trailing blanks on the files
involved, etc.

In one place, dealing with copying failure was not quite obvious since
there is a mention of "imap" of all things that seems to have bearing on
the error handling with I am not familiar at all.

Using the patch, the following is one of the
filter failure log I could obtain during testing.

<p>
Filter Action Failed:
Move failed
Applied filter &quot;folder-F&quot; to message from ishikawa &lt;[e-mail]&gt; - [folder-F][3F] test 44 1421573729 at 2015年01月18日 18時35分32秒
moved message id = [e-mail] to mailbox://ishikawa@localhost/folder-F

Auxiliary Error Message.
rcode=0x8055000a

</p>

Egad, I just realized that
there is no user-friendly interface for viewing filter logging,
(invoked via [Filter Log]log button in the message filter control window)
- there is no SEARCH feature for looking for "fail" string,
- there is no way I can COPY the filter message thus shown.
So I didn't bother to show how the above looks in the TB message logging viewer.
Hmm... Anyway, people have always been advised to look into filterlog.html by an editor so far.

Because of the better interlocks, etc., triggering filter error
is not easy under normal operations: I created the above by moving a large number of messages to a filter (filter-F| above, just before
I began downloading many messages in which some messages were to be filtered
to Folder-F by a filter rule. The manual move of messages interrupted the
filtering of a downloaded message due to folder lock (and as a matter of fact,
this particular error was also notified (!) by a dailog.
I suspect there *ARE* other many cases where no such dialog is shown and
logging is the only hint as to the failure of filtering.)
I think compacting folders and begin downloading can result in similar error log entries.

The error code in the above failure log is a very generic failure code :-(
It did not refer to "folder locked, etc." : NS_ERROR_FILE_IS_LOCKED (0x8052000E)

It is NOT the filtering error code's failure, but rather
the various routines not passing the most specific error code to the caller.
We many need to tweak the error code as soon as non proper error code is noticed
and users claim for more specific better code. It would be a todo item. Good software pays attention to these minor issues for better user experience.

But AT LEST NOW WE HAVE A MEANS to record the filter error (!) :-)

TIA

Comment 31

[Kent James (:rkent)]

Comment on attachment 8550864 [details] [diff] [review]
to add error logging to filter code.

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

There are a lot of comments on coding style to try to get the style to match what we typically do.

There are a few substantial comments. Not convinced of errmsg2, plus not convinced we should log errors when disabled. It would be good to get a second opinion on that, as I see why you want to log them anyway.

::: mailnews/base/search/public/nsIMsgFilter.idl
@@ +105,5 @@
> +                           in nsIMsgDBHdr aMsgHdr,
> +                           in nsresult rcode,
> +                           in string errmsg,
> +                           in string errmsg2);
> +

Don't include this here. Instead, define it in nsMsgFilter.h See for example other local methods, like SaveRule().

@@ +117,5 @@
> +    void logRuleHitFail(in nsIMsgRuleAction aFilterAction,
> +                        in nsIMsgDBHdr aHeader,
> +                        in string errmsg, // main error message
> +                        in nsresult rcode,  // error code that led to filter failure.
> +                        in string errmsg2); // auxiliary error message

Changes to interfaces should be documented using Javadoc style comments. See for example msgIStructuredHeaders.idl as an example of a newer interface that follows conventions.

Also, as in other places, parameters should start with a like aErrmsg.

::: mailnews/base/search/src/nsMsgFilter.cpp
@@ +478,5 @@
>  #define LOG_ENTRY_END_TAG_LEN (strlen(LOG_ENTRY_END_TAG))
>  
> +
> +//
> +

Don't include so much space. On blank line before a line with text is sufficient.

@@ +482,5 @@
> +
> +// This function handles the logging for both
> +// simple rule hit case (NS_SUCCEEDED(rcode))
> +// error reporting (NS_FAILED(errflag)) when the resulting
> +// action (such as file move/copy) fails.

I don't understand that sentence. Also, you should wrap comments at 80 characters, here the wrapping is much shorter.

@@ +498,5 @@
> +// CAUTION: Until the sticky temporary message mechanism is
> +// implemented the ERROR message should be LOGGED always irrespective of what
> +// the user setting for filter logging. (So it is caller's responsibility to make
> +// error logging code is called always. )
> +//

My own sense is that we do not want to do this, that is that error logging to the log file is only done when logging is enabled. I think it is too confusing to disable the log, and yet still it is getting written to. Perhaps we need another opinion here.

@@ +502,5 @@
> +//
> +// rcode ... NS_OK in the case of success reporting.
> +// errmsg ... main error message in the case of error reporting (NS_FAILED(rcode)
> +// errmsg2 ... auxiliary error message for additional information.
> +//

Using "..." as a spacer in comments is not typical. Please just use spaces, lining up (ideally) all of the comments.

Overall my sense is that this preamble comment is too long, with descriptions of hoped-for features and editorial comments. Please try to make it shorter and more direct.

@@ +510,5 @@
> +                               nsIMsgDBHdr *aMsgHdr,
> +                               nsresult rcode,
> +                               const char *errmsg,
> +                               const char *errmsg2
> +  )

Prefix all input parameters with "a", so aRcode, and aErrmsg.

As for errmsg2, I am not convinced this has any value. You could always construct a more complex errmsg if you need additional information.

@@ +533,5 @@
> +    if (NS_FAILED(rcode))
> +      errflag = true;
> +    else
> +      errflag = false;
> +

Just use errflag = NS_FAILED(rcode). I am not convinced that you need this at all, just use NS_FAILED(rcode) directly in the two places that you use it.

@@ +567,5 @@
> +
> +    //
> +    // add preamble for error.
> +    //
> +    if(errflag) {

You don't need four lines for this message. Use single blank line (which is already there), and then:

    // add preamble for error
    if (aErrflag)
    {

Note also:

1) space before (
2) { on new line. Yes I realize that there are some new styles in Mozilla like this, but the rest of this file follows the older convention, and I think we should stick with that for now.
3) For comments, either give an uncapitalized phrase with no period, or a capitalized sentence with a period.

@@ +568,5 @@
> +    //
> +    // add preamble for error.
> +    //
> +    if(errflag) {
> +      buffer += "Filter Action Failed:\n";

buffer += "Filter Action Failed: ";

@@ +614,5 @@
>          getter_Copies(logMoveStr));
>        NS_ENSURE_SUCCESS(rv, rv);
>  
>        buffer += NS_ConvertUTF16toUTF8(logMoveStr);
> +

Don't add this blank line.

@@ +649,5 @@
> +      snprintf(tmess, 50, "\nAuxiliary Error Message.\nrcode=0x%08x\n", rcode);
> +      buffer += tmess;
> +      buffer += errmsg2;
> +      buffer += "\n";
> +    }

Again, my sense is that this whole errmsg2 is not needed. You could include the rcode printout along with errmsg.

::: mailnews/local/src/nsParseMailbox.cpp
@@ +1853,5 @@
> +                    // in released binary?
> +                    NS_ERROR("moveDupsToTrash failed for some reason.");
> +#if DEBUG
> +                    fprintf(stderr,"(debug) rv = 0x%08x\n", rv);
> +#endif

I would replace all of this with simply
  if (NS_FAILED(rv))
    NS_WARNING("moveDupsToTrash failed for some reason");

@@ +2006,1 @@
>  

Why did you remove the (void)?

@@ +2073,5 @@
>              if (NS_SUCCEEDED(err) && !msgMoved)
>                err = MoveIncorporatedMessage(msgHdr, m_mailDB, destIFolder,
>                                              filter, msgWindow);
>              m_msgMovedByFilter = NS_SUCCEEDED(err);
> +            if (! m_msgMovedByFilter)

Nit: no space after !

@@ +2079,5 @@
> +              // TODO/DONE: We should log the filtering (move) failure.
> +              // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> +              // because it may use a  different error reporting mechanism
> +              // from the ordinary logging.
> +              filter->LogRuleHitFail(filterAction, msgHdr, "Move failed", err, "");

Again, I would only do this if (loggingEnabled)

@@ +2105,5 @@
> +        //        StringBeginsWith(actionTargetFolderUri, NS_LITERAL_CSTRING("imap:")))
> +        // End quote
> +
> +        // and so we cannot easily use the value for
> +        // continued processing in the case of error easily for now.

This comment is too long. Can you just make the copy behavior consistent with the move behavior? If not, then try to give a more concise reason.

@@ +2123,3 @@
>              rv = GetExistingFolder(actionTargetFolderUri,
>                                     getter_AddRefs(dstFolder));
> +            // TODO/FIXME: We should report error here, also!

Why don't you just add the error message rather than saying that you need to?

@@ +2135,5 @@
> +              {
> +                // We should log the filtering (copy) failure.
> +                // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> +                // because it may use a  different error reporting mechanism
> +                // from the ordinary logging.

This comment adds no value, just log the message (again qualified with logging enabled).

@@ +2148,2 @@
>              NS_ENSURE_SUCCESS(rv, rv);
>              m_msgCopiedByFilter = true;

What I think you should do is:

  if (NS_SUCCEEDED(rv))
    m_msgCopiedByFilter = true;

without the NS_ENSURE_SUCCESS. Then you can remove the comment as well.

@@ +2304,5 @@
> +          // We should log the custom ufiltering error.
> +          // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> +          // because it may use a  different error reporting mechanism
> +          // from the ordinary logging.
> +          filter->LogRuleHitFail(filterAction, msgHdr, "Copy failed", rv, "");

Same issues as previously, ie no comment and logging enabled.

Comment 32

[ISHIKAWA, Chiaki]

Attachment: Adding filter logging function (in final form).

(In reply to Kent James (:rkent) from comment #31)
> Comment on attachment 8550864 [details] [diff] [review]
> to add error logging to filter code.
> 
> Review of attachment 8550864 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> There are a lot of comments on coding style to try to get the style to match
> what we typically do.
> 

Thank you for the comment. I tried to reflect them in the attached new patch.


> There are a few substantial comments. Not convinced of errmsg2,

I removed that.

> plus not
> convinced we should log errors when disabled. It would be good to get a
> second opinion on that, as I see why you want to log them anyway.

This is a good point. I have seen so many posts AFTER users notice
the filtering did not work as expected.
The helpful developers have no clue what happened.
So I thought forcing the logging of ERROR cases only no matter what the
user setting of filter logging may be a good idea.

For the attached patch, I obey the enableLogging variable, though.

> ::: mailnews/base/search/public/nsIMsgFilter.idl
> @@ +105,5 @@
> > +                           in nsIMsgDBHdr aMsgHdr,
> > +                           in nsresult rcode,
> > +                           in string errmsg,
> > +                           in string errmsg2);
> > +
> 
> Don't include this here. Instead, define it in nsMsgFilter.h See for example
> other local methods, like SaveRule().

I reflected this in the new patch.
I should have realized how the headers generated by IDL magic and
manually edied header files co-exist.

 
> @@ +117,5 @@
> > +    void logRuleHitFail(in nsIMsgRuleAction aFilterAction,
> > +                        in nsIMsgDBHdr aHeader,
> > +                        in string errmsg, // main error message
> > +                        in nsresult rcode,  // error code that led to filter failure.
> > +                        in string errmsg2); // auxiliary error message
> 
> Changes to interfaces should be documented using Javadoc style comments. See
> for example msgIStructuredHeaders.idl as an example of a newer interface
> that follows conventions.

I tried to use a javadoc style comment.
 
> Also, as in other places, parameters should start with a like aErrmsg.
> 

I followed the "a" convention.

> ::: mailnews/base/search/src/nsMsgFilter.cpp
> @@ +478,5 @@
> >  #define LOG_ENTRY_END_TAG_LEN (strlen(LOG_ENTRY_END_TAG))
> >  
> > +
> > +//
> > +
> 
> Don't include so much space. On blank line before a line with text is
> sufficient.

Removed.
 
> @@ +482,5 @@
> > +
> > +// This function handles the logging for both
> > +// simple rule hit case (NS_SUCCEEDED(rcode))
> > +// error reporting (NS_FAILED(errflag)) when the resulting
> > +// action (such as file move/copy) fails.
> 
> I don't understand that sentence. Also, you should wrap comments at 80
> characters, here the wrapping is much shorter.

NS_FAILED(rcode) was the correct expression, but anyway, I modified it and
wrapped with longer margin.
 
> @@ +498,5 @@
> > +// CAUTION: Until the sticky temporary message mechanism is
> > +// implemented the ERROR message should be LOGGED always irrespective of what
> > +// the user setting for filter logging. (So it is caller's responsibility to make
> > +// error logging code is called always. )
> > +//
> 
> My own sense is that we do not want to do this, that is that error logging
> to the log file is only done when logging is enabled. I think it is too
> confusing to disable the log, and yet still it is getting written to.
> Perhaps we need another opinion here.

We need a second opinion here, especially from those who were bitten by
filter errors.
 
> @@ +502,5 @@
> > +//
> > +// rcode ... NS_OK in the case of success reporting.
> > +// errmsg ... main error message in the case of error reporting (NS_FAILED(rcode)
> > +// errmsg2 ... auxiliary error message for additional information.
> > +//
> 
> Using "..." as a spacer in comments is not typical. Please just use spaces,
> lining up (ideally) all of the comments.

Fixed.
 
> Overall my sense is that this preamble comment is too long, with
> descriptions of hoped-for features and editorial comments. Please try to
> make it shorter and more direct.

Tried to shorten it.
 
> @@ +510,5 @@
> > +                               nsIMsgDBHdr *aMsgHdr,
> > +                               nsresult rcode,
> > +                               const char *errmsg,
> > +                               const char *errmsg2
> > +  )
> 
> Prefix all input parameters with "a", so aRcode, and aErrmsg.
> 
> As for errmsg2, I am not convinced this has any value. You could always
> construct a more complex errmsg if you need additional information.

Used "a" prefix, and removed errmsg2.
I thought that there may be some creative usage coming up for errmsg2
AFTER the interface in IDL file is changed.
If changing an interface in IDL is not abhored as much as possible, I am fine
with someone coming up with a new idea of the interface and adding a few parameters as they become necessary for the future needs.

I added errmsg2 just in case we may need to add another parameter and the change in IDL is to be avoided as much as possible. Actually, I was even thinking of adding dummy array of longs so that IDL can remain the same for a long time and we can use the long array for additional paramters.
(Looking at the friction an API change causes
for add-on package writers, I think IDL change is to be avoided as much as possible, correct?)
 
> @@ +533,5 @@
> > +    if (NS_FAILED(rcode))
> > +      errflag = true;
> > +    else
> > +      errflag = false;
> > +
> 
> Just use errflag = NS_FAILED(rcode). I am not convinced that you need this
> at all, just use NS_FAILED(rcode) directly in the two places that you use it.

Removed errflag.

> @@ +567,5 @@
> > +
> > +    //
> > +    // add preamble for error.
> > +    //
> > +    if(errflag) {
> 
> You don't need four lines for this message. Use single blank line (which is
> already there), and then:
> 

I consolidated the message handling in one if statement.

>     // add preamble for error
>     if (aErrflag)
>     {
> 
> Note also:
> 
> 1) space before (

OK, I took care of that. I noticed a few other existing instances of "if(" and so took care of them, too.

> 2) { on new line. Yes I realize that there are some new styles in Mozilla
> like this, but the rest of this file follows the older convention, and I
> think we should stick with that for now.

I followed the "{" on new line style for the if-statement.

> 3) For comments, either give an uncapitalized phrase with no period, or a
> capitalized sentence with a period.

I take note here.
 
> @@ +568,5 @@
> > +    //
> > +    // add preamble for error.
> > +    //
> > +    if(errflag) {
> > +      buffer += "Filter Action Failed:\n";
> 
> buffer += "Filter Action Failed: ";

This part is changed a lot.
 
> @@ +614,5 @@
> >          getter_Copies(logMoveStr));
> >        NS_ENSURE_SUCCESS(rv, rv);
> >  
> >        buffer += NS_ConvertUTF16toUTF8(logMoveStr);
> > +
> 
> Don't add this blank line.

Removed. 
 
> @@ +649,5 @@
> > +      snprintf(tmess, 50, "\nAuxiliary Error Message.\nrcode=0x%08x\n", rcode);
> > +      buffer += tmess;
> > +      buffer += errmsg2;
> > +      buffer += "\n";
> > +    }
> 
> Again, my sense is that this whole errmsg2 is not needed. You could include
> the rcode printout along with errmsg.

I removed errmsg2 and put the error code printing with errmsg in the earlier place.
 
> ::: mailnews/local/src/nsParseMailbox.cpp
> @@ +1853,5 @@
> > +                    // in released binary?
> > +                    NS_ERROR("moveDupsToTrash failed for some reason.");
> > +#if DEBUG
> > +                    fprintf(stderr,"(debug) rv = 0x%08x\n", rv);
> > +#endif
> 
> I would replace all of this with simply
>   if (NS_FAILED(rv))
>     NS_WARNING("moveDupsToTrash failed for some reason");

Did this.
 
> @@ +2006,1 @@
> >  
> 
> Why did you remove the (void)?

I was mistaken.
logRuleHit was declared void in the IDL, but actually returns a value.
So I restored the cast.

(I wondered why GCC did not warn such usage, and then realized that there are so many ignored return values from low-level routines, that the specific check is not done.)

We may want to force the checking of low-level I/O routines by declaring them as in

http://www.virtualroadside.com/blog/index.php/2008/12/14/useful-gcc-only-trick-warn-if-return-value-is-unused/

by deciding on a flag day for the beginning of checks to I/O routine return value ...

> @@ +2073,5 @@
> >              if (NS_SUCCEEDED(err) && !msgMoved)
> >                err = MoveIncorporatedMessage(msgHdr, m_mailDB, destIFolder,
> >                                              filter, msgWindow);
> >              m_msgMovedByFilter = NS_SUCCEEDED(err);
> > +            if (! m_msgMovedByFilter)
> 
> Nit: no space after !

OK, removed space.
I noticed a few places where "!" was followed by " " and so fixed a couple of them.
There is one place where "!" was followed by " (... complex expression", but
I left it as is.

> @@ +2079,5 @@
> > +              // TODO/DONE: We should log the filtering (move) failure.
> > +              // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> > +              // because it may use a  different error reporting mechanism
> > +              // from the ordinary logging.
> > +              filter->LogRuleHitFail(filterAction, msgHdr, "Move failed", err, "");
> 
> Again, I would only do this if (loggingEnabled)

I follow if (loggingEnabled), but we may indeed need to ask for opinions from
the people who need to deal with user complaints AFTER the user notices
the filter doesn't seem to work, but logging was not enabled and so there was
no clue of what went wrong.
(As of now, the returned code seems to be rather generic, but
we may need to polish this over time. Right now the LACK of error processing is
something we need to address.) 

> @@ +2105,5 @@
> > +        //        StringBeginsWith(actionTargetFolderUri, NS_LITERAL_CSTRING("imap:")))
> > +        // End quote
> > +
> > +        // and so we cannot easily use the value for
> > +        // continued processing in the case of error easily for now.
> 
> This comment is too long. Can you just make the copy behavior consistent
> with the move behavior? If not, then try to give a more concise reason.

I tried to make the behavior consistent, but I have no idea what
the interaction of "imap" mentioned in about a dozen or so line above, and
so left a BEWARE comment, and set m_* variable below at the end of processing.
 
> @@ +2123,3 @@
> >              rv = GetExistingFolder(actionTargetFolderUri,
> >                                     getter_AddRefs(dstFolder));
> > +            // TODO/FIXME: We should report error here, also!
> 
> Why don't you just add the error message rather than saying that you need to?

I put in an NS_WARNING() statement there for now.

> @@ +2135,5 @@
> > +              {
> > +                // We should log the filtering (copy) failure.
> > +                // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> > +                // because it may use a  different error reporting mechanism
> > +                // from the ordinary logging.
> 
> This comment adds no value, just log the message (again qualified with
> logging enabled).

Done.

> @@ +2148,2 @@
> >              NS_ENSURE_SUCCESS(rv, rv);
> >              m_msgCopiedByFilter = true;
> 
> What I think you should do is:
> 
>   if (NS_SUCCEEDED(rv))
>     m_msgCopiedByFilter = true;
> 
> without the NS_ENSURE_SUCCESS. Then you can remove the comment as well.

I did so, but
left a comment in a path that reaches here (see my comment above)
because there was an existing cryptic comment about imap coalescing that is used
depending on the value of m_msgCopiedByFilter, and I am not so sure
whether not returning immediately from the failure works well with this
coalescing thing.
  
> @@ +2304,5 @@
> > +          // We should log the custom ufiltering error.
> > +          // We call LogRuleHitFail irrespective of |loggingEnabled| setting
> > +          // because it may use a  different error reporting mechanism
> > +          // from the ordinary logging.
> > +          filter->LogRuleHitFail(filterAction, msgHdr, "Copy failed", rv, "");
> 
> Same issues as previously, ie no comment and logging enabled.

Ditto, taken care of, but I welcome second opinion 
about if (enabledLogging)

The new patch  is
tested with |make mozmill| and |make xpcshell-tests| locally. No new bugs were introduced.
(I wonder if there is a test case for the imap coalescing thing, though.
generally speaking, error conditions do not seem to be tested very well, so I don't have high hopes here.)

TIA

Comment 33

[Wayne Mery (:wsmwk)]

I haven't given this a great deal of thought whether and how we should log. But, it simply occurs to me that the most important point is to do what we reasonably can to help users to self diagnose their issues.  

I'm unsure which is best approach is best. But IMO nspr logging is too complex. filter log might be nice because you'd presumbably see all successes and failures in one place, and the enabling and viewing UI is reasonable for most users. But that alone is insufficient - we must first alert the user that a problem exists and provide sufficient information to get them started in the next step.

Comment 34

[ISHIKAWA, Chiaki]

(In reply to Wayne Mery (:wsmwk) from comment #33)
> I haven't given this a great deal of thought whether and how we should log.
> But, it simply occurs to me that the most important point is to do what we
> reasonably can to help users to self diagnose their issues.  
> 
> I'm unsure which is best approach is best. But IMO nspr logging is too
> complex. filter log might be nice because you'd presumbably see all
> successes and failures in one place, and the enabling and viewing UI is
> reasonable for most users. But that alone is insufficient - we must first
> alert the user that a problem exists and provide sufficient information to
> get them started in the next step.

I realize that when "logging" is mentioned, it refers to two things
- append a success/failure notice to filterlog.html file, AND
- nspr logging.

I am more concerned with the appending the message to filterlog.html file for
easy to view user-visible record. (And BECAUSE the whole error/success logging function
is now called only when user logging is enabled, even if the
mechanism is implemented to show a transient sticky message in mail status window, it is not shown.

I agree with the following point:
>  we must first
> alert the user that a problem exists and provide sufficient information to
> get them started in the next step.

The issue is that in the current code, we don't realize the problem exists immediately. Only
when someone suspects that the filtering didn't work as expected and check manually
we find out the problem exists (this is how I found out strange filter failure due to folder locking, etc.)
And today, if the unsuspecting user has not enabled filterlogging,
we tell him/her to do that and hope the problem hits in the immediate future (but without the patch here,
the failure is NOT reported in filterlog.html, but in nspr logging only, I think.)

We do not have a satisfactory solution yet, I think.

Maybe we can call

 - the logging functions for failure/success all the time, BUT
 - only do the real logging/writing inside these logging functions
   when logging is enabled, AND
 - shows the transient sticky message (in the future when such mechanism is available.)

This is a future issue though. The transient sticky message that won't go away sounds a very attractive solution. Nowadays, I notice that TB shows a transient window in the lower right corner of the screen 
about newly arrived messages (their subjects are shown in the window) from time to time (mostly after
an automatic download is done, I think.). It disappears when I click on the close button.
Maybe we can steal the code from there to report the filter error, too.

TIA





TIA

Comment 35

[Kent James (:rkent)]

In bug 1119529 when faced with a logging issue, the approach that seemed most natural to me was to use the error console. I've got a patch there that adds a simple error console output to results from the filter-after-the-fact code that will see more use than in the past since it is used by both Archive and After Sending filters.

We'll need to make a decision soon about right approach to take, and we should be consistent in both before-the-fact filters (this bug) and after-the-fact.

In the send and archive filter contexts, the user is presumably at his terminal initiating the action, and a direct, interrupting popup window is appropriate (and is used in both places) for the initial warning. Using the errorConsole also bypasses the issue that we have not resolved here whether we should always log the error.

What I suspect is likely to be the solution is 1) log to both the errorConsole and the filter log (but only if filterLog is enabled to the filter log), and 2) in the biff case (this bug) add an error message to the status bar. That is less optimal than the sticky error (since it will be constantly overridden) but is the best we can do in the short run.

In any case, in bug 1119529 we have a couple of users who can download the try build to diagnose existing errors. I'd like to get some feedback there on the use of the error console before we make the decision. So let's put this bug on hold for a few days while we try the error console on that other bug.

Comment 36

[ISHIKAWA, Chiaki]

(In reply to Kent James (:rkent) from comment #35)
> In bug 1119529 when faced with a logging issue, the approach that seemed
> most natural to me was to use the error console. I've got a patch there that
> adds a simple error console output to results from the filter-after-the-fact
> code that will see more use than in the past since it is used by both
> Archive and After Sending filters.
> 
> We'll need to make a decision soon about right approach to take, and we
> should be consistent in both before-the-fact filters (this bug) and
> after-the-fact.
> 

May be I misunderstood the meaning of "before-the-fact" and "after-the-fact", but I digress.

> In the send and archive filter contexts, the user is presumably at his
> terminal initiating the action, and a direct, interrupting popup window is
> appropriate (and is used in both places) for the initial warning. Using the
> errorConsole also bypasses the issue that we have not resolved here whether
> we should always log the error.
> 
> What I suspect is likely to be the solution is 1) log to both the
> errorConsole and the filter log (but only if filterLog is enabled to the
> filter log), and 2) in the biff case (this bug) add an error message to the
> status bar. That is less optimal than the sticky error (since it will be
> constantly overridden) but is the best we can do in the short run.
> 

biff case is when we receive the e-mails, I suppose.

> In any case, in bug 1119529 we have a couple of users who can download the
> try build to diagnose existing errors. I'd like to get some feedback there
> on the use of the error console before we make the decision. So let's put
> this bug on hold for a few days while we try the error console on that other
> bug.

Ok, let us wait and see how things work out.
Chiaki (my firstname)

Comment 37

[Kent James (:rkent)]

The patches are now up on bug 1119529. I'm still waiting from comments from Magnus and Joshua on the concept of more extensive error-console logging.

The changes to your code will be fairly minor, mostly adding a call to MSG_LOG_TO_CONSOLE to send error messages to the error console in addition to logging them in the filter log (which I still think is a good idea).

One issue to consider is that MSG_LOG_TO_CONSOLE is intended to be placed at the point of failure so that the line number and filename are recorded as well. You'll need to consider whether that is appropriate in your case.

Looking over your code, I see that you added an interface change. Under normal rules that means the patch needs to land before TB 38 moves to aurora in a week. So I'll look at this now and see if we can finish it before then, as we could add the MSG_LOG_TO_CONSOLE stuff at the aurora phase if we decide to do so.

Comment 38

[Kent James (:rkent)]

Comment on attachment 8551500 [details] [diff] [review]
Adding filter logging function (in final form).

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

Overall I think this is the right direction, though there are enough little issues that I need to see it again. It would be good to try to land this next week so that it will make Thunderbird 38.

::: mailnews/base/search/public/nsIMsgFilter.idl
@@ +15,5 @@
>  interface nsIMsgSearchScopeTerm;
>  interface nsIMsgSearchValue;
>  interface nsIMsgSearchTerm;
>  
> +[scriptable, uuid(e618f0e8-9ef2-11e4-a669-afce1d5d46b0)]

This is changed on the wrong interface, you want to change it on nsIMsgFilter below.

@@ +91,5 @@
>                    in unsigned long headerSize, out boolean result);
>  
> +
> +    // Report that Rule was matched and executed when filter logging is enabled.
> +    //

The convention is that idl comments are done like this:

/**
 * The comment ...
 */

::: mailnews/base/search/src/nsMsgFilter.cpp
@@ +475,5 @@
>  #define LOG_ENTRY_START_TAG_LEN (strlen(LOG_ENTRY_START_TAG))
>  #define LOG_ENTRY_END_TAG "</p>\n"
>  #define LOG_ENTRY_END_TAG_LEN (strlen(LOG_ENTRY_END_TAG))
>  
> +// This function handles the logging both for sucess of filtering

Nit: "success"

@@ +554,5 @@
> +    // If error, prefix with the error code and error message.
> +    if (NS_FAILED(aRcode))
> +    {
> +      char tmess[50];
> +      snprintf(tmess, 50, "Filter Action Failed: error code=0x%08x: ", aRcode);

This fails in Windows. Use PR_snprintf

instead of 50, write sizeof(tmess)

But in fact, you need to get rid of this completely, and localize that string "Filter Action Failed: error code". See the other code in this section for how that is done.

I think that it is OK to have the specific error details like "Move failed" to be non-localized, but the intro that mentions the failure needs localization.

@@ +558,5 @@
> +      snprintf(tmess, 50, "Filter Action Failed: error code=0x%08x: ", aRcode);
> +      buffer += tmess;
> +      buffer += aErrmsg;
> +      buffer += "\n";
> +    }

This is the result that I see in the error console for a failed move:

Filter Action Failed: error code=0x80004005: Move failed Applied filter "test" to message from Msq Test <[e-mail]> - send test 3 at 2/13/2015 11:32:53 AM moved message id = [e-mail] to mailbox://nobody@Local%20Folders/test 

(Hard to see here, but there is only a space after "Move failed" and the beginning of the "Applied filter".)

Given that, there needs to be some wording that says that what follows is the failed filter action, otherwise it just looks like you failed to insert a blank line before the next action. So something like:

Filter Action Failed "Move failed" with error code=0x80004005 while attempting: Applied filter "test" to message from Msq Test <[e-mail]> - send test 3 at 2/13/2015 11:32:53 AM moved message id = [e-mail] to mailbox://nobody@Local%20Folders/test

::: mailnews/base/search/src/nsMsgFilter.h
@@ +76,5 @@
> +  //
> +  nsresult LogRuleHitGeneric(nsIMsgRuleAction *aFilterAction,
> +                         nsIMsgDBHdr *aMsgHdr,
> +                         nsresult aRcode,
> +                         const char *aErrmsg);

Nit: line up the parameters on additional lines with the nsIMsgRuleAction of the first line.

::: mailnews/local/src/nsParseMailbox.cpp
@@ +2068,5 @@
>                                              filter, msgWindow);
>              m_msgMovedByFilter = NS_SUCCEEDED(err);
> +            if (!m_msgMovedByFilter)
> +            {
> +              if (loggingEnabled)

Just use

  if (!m_msgMovedByFilter && loggingEnabled)

@@ +2079,5 @@
> +
> +        // XXX Failure in moving results in setting false to
> +        // m_msgMovedByFilter.  However, below, it used to be that
> +        // failure in copying results in early exit before setting 
> +        // a value to m_msgCopiedByFilter in if-statement.

Nit: trailing blank

@@ +2123,1 @@
>            }

Personally I dislike an error handling style where each actual working line has to be prefixed with if (NS_SUCCEEDED ...). I prefer this style, but I am still in the minority:

do { // break on error or done
  rv = fooBar();
  BREAK_IF_FAILURE(rv, "foobar failed");

  rv = fooBar2();
  BREAK_IF_FAILURE(rv, "foobar2 failed");

} while(false);

But alas the style you wrote is the prevailing pattern, so it is fine. But IMHO that awkward style is one of the reason that error reporting is often inconsistent in mailnews code.

@@ +2274,5 @@
> +          rv = customAction->Apply(messageArray, value, nullptr,
> +                                   nsMsgFilterType::InboxRule, msgWindow);
> +        if (NS_FAILED(rv)) {
> +          if (loggingEnabled)
> +            (void) filter->LogRuleHitFail(filterAction, msgHdr, rv, "Copy failed");

again I think you can combine the two checks into a single line.

@@ +2281,5 @@
>        break;
>  
>  
>        default:
> +        // XXX should not be reached. Check in debug build. 

Nit: trailing space.

Comment 39

[ISHIKAWA, Chiaki]

(In reply to Kent James (:rkent) from comment #38)
> Comment on attachment 8551500 [details] [diff] [review]
> Adding filter logging function (in final form).
> 
> Review of attachment 8551500 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Overall I think this is the right direction, though there are enough little
> issues that I need to see it again. It would be good to try to land this
> next week so that it will make Thunderbird 38.
> 

Thank you for valuable comments. I will roll up a new patch over the weekend hopefully.

I liked the use of do { ... } while (false) and use of break to make error handling easy. I wonder why I didn't think of it. Let me see if I can use the style somewhere in the patch. But as you say, it may need some time to get use to for many people.

TIA

Comment 40

[ISHIKAWA, Chiaki]

Attachment: 8551500: Adding filter logging function (in final form).

Here is the updated patch.

(In reply to Kent James (:rkent) from comment #38)
> Comment on attachment 8551500 [details] [diff] [review]
> Adding filter logging function (in final form).
> 
> Review of attachment 8551500 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Overall I think this is the right direction, though there are enough little
> issues that I need to see it again. It would be good to try to land this
> next week so that it will make Thunderbird 38.
> 
> ::: mailnews/base/search/public/nsIMsgFilter.idl
> @@ +15,5 @@
> >  interface nsIMsgSearchScopeTerm;
> >  interface nsIMsgSearchValue;
> >  interface nsIMsgSearchTerm;
> >  
> > +[scriptable, uuid(e618f0e8-9ef2-11e4-a669-afce1d5d46b0)]
> 
> This is changed on the wrong interface, you want to change it on
> nsIMsgFilter below.

This is a pure editing error. I have no idea how this happened, but I suspect
that I modified a wrong line while updating a patch.

> 
> @@ +91,5 @@
> >                    in unsigned long headerSize, out boolean result);
> >  
> > +
> > +    // Report that Rule was matched and executed when filter logging is enabled.
> > +    //
> 
> The convention is that idl comments are done like this:
> 
> /**
>  * The comment ...
>  */

I changed the comment style.

> ::: mailnews/base/search/src/nsMsgFilter.cpp
> @@ +475,5 @@
> >  #define LOG_ENTRY_START_TAG_LEN (strlen(LOG_ENTRY_START_TAG))
> >  #define LOG_ENTRY_END_TAG "</p>\n"
> >  #define LOG_ENTRY_END_TAG_LEN (strlen(LOG_ENTRY_END_TAG))
> >  
> > +// This function handles the logging both for sucess of filtering
> 
> Nit: "success"

fixed.

> 
> @@ +554,5 @@
> > +    // If error, prefix with the error code and error message.
> > +    if (NS_FAILED(aRcode))
> > +    {
> > +      char tmess[50];
> > +      snprintf(tmess, 50, "Filter Action Failed: error code=0x%08x: ", aRcode);
> 
> This fails in Windows. Use PR_snprintf
> 
> instead of 50, write sizeof(tmess)
> 
> But in fact, you need to get rid of this completely, and localize that
> string "Filter Action Failed: error code". See the other code in this
> section for how that is done.
> 
> I think that it is OK to have the specific error details like "Move failed"
> to be non-localized, but the intro that mentions the failure needs
> localization.

I changed the code according to the suggestion.
But I have yet to run the full manual test to produce a filtering error.
Maybe can you?

The change necessitated a string bundle change, too.
I inserted an entry to "filter.properties" file.
I wonder how I go about I10N change. Should I split this part and create a 
different bugzilla entry?

> @@ +558,5 @@
> > +      snprintf(tmess, 50, "Filter Action Failed: error code=0x%08x: ", aRcode);
> > +      buffer += tmess;
> > +      buffer += aErrmsg;
> > +      buffer += "\n";
> > +    }
> 
> This is the result that I see in the error console for a failed move:
> 
> Filter Action Failed: error code=0x80004005: Move failed Applied filter
> "test" to message from Msq Test <[e-mail]> - send test 3 at
> 2/13/2015 11:32:53 AM moved message id = [e-mail] to
> mailbox://nobody@Local%20Folders/test 
> 
  ... snip ...

> So something like:
> 
> Filter Action Failed "Move failed" with error code=0x80004005 while
> attempting: Applied filter "test" to message from Msq Test
> <[e-mail]> - send test 3 at 2/13/2015 11:32:53 AM moved message
> id = [e-mail] to mailbox://nobody@Local%20Folders/test

I tried to modify the code to produce the desirable message line, but
have not been able to test it fully yet. I wonder if you can try this patch and
see if that produce the desired output.

BTW, do we want to ADD the timestamp of WHEN the filter action was applied?
Between the filter name and 'to' in 'Applied filter "test" to' so that it may look like
'Applied filter "test" at hh:mm:ss, mm/dd/yyyy to'?

(I was testing a filter that would move an old e-mail message in Inbox
to another folder and the filterlog.html mentioned ONLY the timestamp of the
message and I was quite confused since it was an old email with 2013 timestamp
and I was not sure immediately if my modification added a new log or not. There was no indication of the timestamp when the action was performed...
But THIS CAN WAIT UNTIL THE INTERFACE CHANGE IS CHECKED IN.
 
> ::: mailnews/base/search/src/nsMsgFilter.h
> @@ +76,5 @@
> > +  //
> > +  nsresult LogRuleHitGeneric(nsIMsgRuleAction *aFilterAction,
> > +                         nsIMsgDBHdr *aMsgHdr,
> > +                         nsresult aRcode,
> > +                         const char *aErrmsg);
> 
> Nit: line up the parameters on additional lines with the nsIMsgRuleAction of
> the first line.

I lined them up.
 
> ::: mailnews/local/src/nsParseMailbox.cpp
> @@ +2068,5 @@
> >                                              filter, msgWindow);
> >              m_msgMovedByFilter = NS_SUCCEEDED(err);
> > +            if (!m_msgMovedByFilter)
> > +            {
> > +              if (loggingEnabled)
> 
> Just use
> 
>   if (!m_msgMovedByFilter && loggingEnabled)
> 

Here I have to ponder a bit.

|loggingEnabled| is set by a user action by toggling "logging filter"
in the message filter dialog panel to explicitly record filter action in
filterlog.html.
On the other hand, I see in  bug 1119529 that
LOG_MSG_TO_CONSOLE is invoked when an error occurs (withtout |loggingEnabled| checking if I am not mistaken.)

So I left the code as is but with the added comment about LOG_MSG_TO_CONSOLE
like this (in a few places).
---------- begin quote 
            if (NS_FAILED(rv))
              {
                // XXX: Invoke MSG_LOG_TO_CONSOLE once the patch part-1 in bug 1119529 lands.
                if (loggingEnabled)
                  (void) filter->LogRuleHitFail(filterAction, msgHdr, rv, "Copy failed");
              }
------------  end quote

Do we want to call LOG_MSG_TO_CONSOLE if and only iff |loggingEnabled| ?
If so, I need to change the if-statement to merge the conditions as suggested.

> @@ +2079,5 @@
> > +
> > +        // XXX Failure in moving results in setting false to
> > +        // m_msgMovedByFilter.  However, below, it used to be that
> > +        // failure in copying results in early exit before setting 
> > +        // a value to m_msgCopiedByFilter in if-statement.
> 
> Nit: trailing blank

I took out the trailing blank here and in a few other files in the patch.
 
> @@ +2123,1 @@
> >            }
> 
> Personally I dislike an error handling style where each actual working line
> has to be prefixed with if (NS_SUCCEEDED ...). I prefer this style, but I am
> still in the minority:
> 
> do { // break on error or done
>   rv = fooBar();
>   BREAK_IF_FAILURE(rv, "foobar failed");
> 
>   rv = fooBar2();
>   BREAK_IF_FAILURE(rv, "foobar2 failed");
> 
> } while(false);
> 
> But alas the style you wrote is the prevailing pattern, so it is fine. But
> IMHO that awkward style is one of the reason that error reporting is often
> inconsistent in mailnews code.

I think either your style or a disciplined use of "goto" may be
a way to go. Series of if(NS_SUCCEEDED(rv)) ... is hard to understand. I agree.
cf. 
"Study concludes use of GOTOs in code is *not* harmful in practice"
http://catless.ncl.ac.uk/Risks/28.51.html#subj3
CI's comment: Surprise, erh? 
As long as the usage of GOTO is well disciplined, that is.

 
> @@ +2274,5 @@
> > +          rv = customAction->Apply(messageArray, value, nullptr,
> > +                                   nsMsgFilterType::InboxRule, msgWindow);
> > +        if (NS_FAILED(rv)) {
> > +          if (loggingEnabled)
> > +            (void) filter->LogRuleHitFail(filterAction, msgHdr, rv, "Copy failed");
> 
> again I think you can combine the two checks into a single line.

See above. It depends on whether LOG_MSG_TO_CONSOLE should be conditioned on
|loggingEnabled|.

> @@ +2281,5 @@
> >        break;
> >  
> >  
> >        default:
> > +        // XXX should not be reached. Check in debug build. 
> 
> Nit: trailing space.

Took out the trailing space.
I did so in other files and fixed a few spelling mistakes (basically I forgot to update the argument names in comment when the argument was prefixed with "a", etc.).

I think the interface change part needs to be checked in this week.

If I understand correctly minor tweaks can be incorporated during the beta period of aurora?

Should I break the patch so that the interface change is isolated and can go in quickly?

TIA

Comment 41

[Kent James (:rkent)]

Comment on attachment 8564928 [details] [diff] [review]
8551500: Adding filter logging function (in final form).

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

There are lots of little issues, plus you need to explain some of your comments. I've been sitting on this incomplete review for 3 days, I suppose I simply need to say I'm done and ask for your next round of changes.

::: mail/locales/en-US/chrome/messenger/filter.properties
@@ +25,5 @@
>  cannotEnableFilter=This filter was probably created by future version of mozilla/netscape. You cannot enable this filter because we don't know how to apply it.
>  dontWarnAboutDeleteCheckbox=Don't ask me again
> +
> +# LOCALIZATION NOTE(filterFAilureWarningPrefix)
> +# %1$S=filter error action 

Nit: trailing space.

::: mailnews/base/search/public/nsIMsgFilter.idl
@@ +103,5 @@
> +
> +    /* Report that filtering failed for some reason when filter logging is enabled.
> +     *
> +     * @param aFilterAction Filter rule that was invoked.
> +     * @param aHeader Header of the message acted on by the filter

Nit: period at end.

@@ +106,5 @@
> +     * @param aFilterAction Filter rule that was invoked.
> +     * @param aHeader Header of the message acted on by the filter
> +     * @param aRcode  Error code returned by low-level routine that
> +     *                led to the filter failure.
> +     * @param aErrmsg Error message

Nit: period at end.

::: mailnews/base/search/src/nsMsgFilter.cpp
@@ +480,5 @@
> +// (NS_SUCCEEDED(aRcode)), and for error reporting (NS_FAILED(aRcode)
> +// when the filter action (such as file move/copy) failed.
> +//
> +// @param aRcode  NS_OK for successful filtering
> +//               operation, otherwise, an error code for filtering failure

Nit: line up second line "operation" with "NS_OK" of previous line. (Also see the next line for the same issue).

@@ +561,5 @@
>      NS_ENSURE_SUCCESS(rv, rv);
>  
> +    // If error, prefix with the error code and error message.
> +    // A desired wording:
> +    // Filter Action Failed "Move failed" with error code=0x80004005 while attempting: Applied filter "test" to message from Msq Test <[e-mail]> - send test 3 at 2/13/2015 11:32:53 AM moved message id = [e-mail] to mailbox://nobody@Local%20Folders/test

This line extends way over the official limit of 80 columns. Split over multiple lines. Also, don't include real email email address here, but <[e-mail]> and id [e-mail]

::: mailnews/base/search/src/nsMsgFilterService.cpp
@@ +423,5 @@
>      // reset the filter index to apply all filters to this new folder
>      m_curFilterIndex = 0;
>      m_nextAction = 0;
>      rv = m_folders->QueryElementAt(m_curFolderIndex++, NS_GET_IID(nsIMsgFolder), getter_AddRefs(m_curFolder));
> +    CONTINUE_IF_FAILURE(rv, "Could not get next folder"); 

Nit: trailing space.

@@ +434,5 @@
> +    // But then after I hit OK, I get a segmentaton error.
> +    // This segmentation error is now avoided by a simple check of
> +    // !m_curFolder below.
> +    if (!m_curFolder) // m_curFolder may be null when the folder is deleted externally.
> +        continue;

(Just to be clear, we need to resolve this issue then remove the comments about).

I would be very surprised that this is necessary. The normal rule would be that a query interface returned a failure code if it failed to put a valid value in the result.

What do you mean be "deleted the folder"? What exactly did you do to make that happen?

If indeed you needed to check the value, then the correct thing to do would be to use, instead of CONTINUE_IF_FAILURE, use CONTINUE_IF_FALSE(m_curFolder).

@@ +1082,5 @@
>    NS_WARN_IF_FALSE(NS_SUCCEEDED(rv), "Failed to run filters");
> +  // XXX how can we record the filter failure here? Or we should not?
> +  // It seems that the error at this level is handled by a panel in some cases.
> +  // If dialog panel is shown all the time, the user is aware of the filter error,
> +  // and there is little need to record the filter failure.

The expectation here is that the failure is already recorded through one of the macro expressions, that will have console logging added to them. So an additional console warning is not needed here.

The dialog panel does not occur in cases where there is no msgWindow passed to the service.

::: mailnews/local/src/nsParseMailbox.cpp
@@ +1995,5 @@
>      if (NS_SUCCEEDED(filterAction->GetType(&actionType)))
>      {
> +      // XXX: maybe we should invoke MSG_LOG_TO_CONSOLE once the patch part-1
> +      // in bug 1119529 lands (although here we just to start a processing of a filter
> +      // and still do not know whether the filter acton will succeed or not.)

Why would you want to log to console at this point?

@@ +2001,4 @@
>        if (loggingEnabled)
> +        {
> +          (void) filter->LogRuleHit(filterAction, msgHdr);
> +        }

Please do not add these brackets here.

@@ +2064,5 @@
>            }
>            else
>            {
>              nsCOMPtr<nsIMsgPluggableStore> msgStore;
> +            // The code here can be improved by using do { if (error cond) break;...; ) while (false) construct.

Either do this or don't, but the comment suggesting it should not be here.

@@ +2089,5 @@
> +        // failure in copying results in early exit before setting
> +        // a value to m_msgCopiedByFilter in if-statement.
> +        // BEWARE: There may be an intended interaction with imap:
> +        // See the comment above that starts with
> +        // "if we're moving to an imap folder, or this message has already..."

I don't understand what you are trying to say here. Are you expecting a bug?

Comment 42

[ISHIKAWA, Chiaki]

Attachment: 8551500: Adding filter logging function (in final form).: filter-error-log-patch-rev07.patch

(In reply to Kent James (:rkent) from comment #41)
> Comment on attachment 8564928 [details] [diff] [review]
> 8551500: Adding filter logging function (in final form).
> 
> Review of attachment 8564928 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> There are lots of little issues, plus you need to explain some of your
> comments. I've been sitting on this incomplete review for 3 days, I suppose
> I simply need to say I'm done and ask for your next round of changes.
> 

Thank you again for your comments.

I have a logistic problem. I don't have access to my PC with the local modification until Sunday evening (Japan Standard Time.)
So the uploaded patch is not a completely correct patch in the sense that
I edited the patch MANUALLY to show what changes I would make to reflect your comments: the line numbers are not quite correct. I have no idea how clever the 
|patch| is clever to handle this. I can certainly create a politically correct patch Sunday evening [close to midnight :-( ]

Here is my comments.

> ::: mail/locales/en-US/chrome/messenger/filter.properties
> @@ +25,5 @@
> >  cannotEnableFilter=This filter was probably created by future version of mozilla/netscape. You cannot enable this filter because we don't know how to apply it.
> >  dontWarnAboutDeleteCheckbox=Don't ask me again
> > +
> > +# LOCALIZATION NOTE(filterFAilureWarningPrefix)
> > +# %1$S=filter error action 
> 
> Nit: trailing space.

Done.

> 
> ::: mailnews/base/search/public/nsIMsgFilter.idl
> @@ +103,5 @@
> > +
> > +    /* Report that filtering failed for some reason when filter logging is enabled.
> > +     *
> > +     * @param aFilterAction Filter rule that was invoked.
> > +     * @param aHeader Header of the message acted on by the filter
> 
> Nit: period at end.

Took out the period in the argument description. This is what I needed to do. Correct?

 
> @@ +106,5 @@
> > +     * @param aFilterAction Filter rule that was invoked.
> > +     * @param aHeader Header of the message acted on by the filter
> > +     * @param aRcode  Error code returned by low-level routine that
> > +     *                led to the filter failure.
> > +     * @param aErrmsg Error message
> 
> Nit: period at end.

Ditto (above)
 
> ::: mailnews/base/search/src/nsMsgFilter.cpp
> @@ +480,5 @@
> > +// (NS_SUCCEEDED(aRcode)), and for error reporting (NS_FAILED(aRcode)
> > +// when the filter action (such as file move/copy) failed.
> > +//
> > +// @param aRcode  NS_OK for successful filtering
> > +//               operation, otherwise, an error code for filtering failure
> 
> Nit: line up second line "operation" with "NS_OK" of previous line. (Also
> see the next line for the same issue).

fixed.
 
> @@ +561,5 @@
> >      NS_ENSURE_SUCCESS(rv, rv);
> >  
> > +    // If error, prefix with the error code and error message.
> > +    // A desired wording:
> > +    // Filter Action Failed "Move failed" with error code=0x80004005 while attempting: Applied filter "test" to message from Msq Test <[e-mail]> - send test 3 at 2/13/2015 11:32:53 AM moved message id = [e-mail] to mailbox://nobody@Local%20Folders/test
> 
> This line extends way over the official limit of 80 columns. Split over
> multiple lines. Also, don't include real email email address here, but
> <[e-mail]> and id [e-mail]


fixed. I used a slightly different imaginative test user name. "test".
 
> ::: mailnews/base/search/src/nsMsgFilterService.cpp
> @@ +423,5 @@
> >      // reset the filter index to apply all filters to this new folder
> >      m_curFilterIndex = 0;
> >      m_nextAction = 0;
> >      rv = m_folders->QueryElementAt(m_curFolderIndex++, NS_GET_IID(nsIMsgFolder), getter_AddRefs(m_curFolder));
> > +    CONTINUE_IF_FAILURE(rv, "Could not get next folder"); 
> 
> Nit: trailing space.

Done.

> @@ +434,5 @@
> > +    // But then after I hit OK, I get a segmentaton error.
> > +    // This segmentation error is now avoided by a simple check of
> > +    // !m_curFolder below.
> > +    if (!m_curFolder) // m_curFolder may be null when the folder is deleted externally.
> > +        continue;
> 
> (Just to be clear, we need to resolve this issue then remove the comments
> about).
> 
> I would be very surprised that this is necessary. The normal rule would be
> that a query interface returned a failure code if it failed to put a valid
> value in the result.
> 
> What do you mean be "deleted the folder"? What exactly did you do to make
> that happen?

This was a surprise myself.
What I did is that I deleted the folder manually from the command line
when TB is not running.

It seems that internal database of TB recalls that the folder existed and
so created an array of folders, *BUT* since the folder file does not exist
the variable was nullptr. That is why there was a crash.
Once I put the check, TB did not crash and worked.


> 
> If indeed you needed to check the value, then the correct thing to do would
> be to use, instead of CONTINUE_IF_FAILURE, use
> CONTINUE_IF_FALSE(m_curFolder).

I used the suggested macro.

> 
> @@ +1082,5 @@
> >    NS_WARN_IF_FALSE(NS_SUCCEEDED(rv), "Failed to run filters");
> > +  // XXX how can we record the filter failure here? Or we should not?
> > +  // It seems that the error at this level is handled by a panel in some cases.
> > +  // If dialog panel is shown all the time, the user is aware of the filter error,
> > +  // and there is little need to record the filter failure.
> 
> The expectation here is that the failure is already recorded through one of
> the macro expressions, that will have console logging added to them. So an
> additional console warning is not needed here.
> 
> The dialog panel does not occur in cases where there is no msgWindow passed
> to the service.

I see. I reflected your comment in the comment here.
 
> ::: mailnews/local/src/nsParseMailbox.cpp
> @@ +1995,5 @@
> >      if (NS_SUCCEEDED(filterAction->GetType(&actionType)))
> >      {
> > +      // XXX: maybe we should invoke MSG_LOG_TO_CONSOLE once the patch part-1
> > +      // in bug 1119529 lands (although here we just to start a processing of a filter
> > +      // and still do not know whether the filter acton will succeed or not.)
> 
> Why would you want to log to console at this point?

Aha. Sorry, this is a success case, and so we don't need to !
Took out the comment.
 
> @@ +2001,4 @@
> >        if (loggingEnabled)
> > +        {
> > +          (void) filter->LogRuleHit(filterAction, msgHdr);
> > +        }
> 
> Please do not add these brackets here.

Reverted as suggested.
 
> @@ +2064,5 @@
> >            }
> >            else
> >            {
> >              nsCOMPtr<nsIMsgPluggableStore> msgStore;
> > +            // The code here can be improved by using do { if (error cond) break;...; ) while (false) construct.
> 
> Either do this or don't, but the comment suggesting it should not be here.

Took out the comment for now.
 
> @@ +2089,5 @@
> > +        // failure in copying results in early exit before setting
> > +        // a value to m_msgCopiedByFilter in if-statement.
> > +        // BEWARE: There may be an intended interaction with imap:
> > +        // See the comment above that starts with
> > +        // "if we're moving to an imap folder, or this message has already..."
> 
> I don't understand what you are trying to say here. Are you expecting a bug?

Well, as I explain in the first half of the comment block,
the error is recorded in a different manner now.
I have absolutely NO IDEA what effect this has for the error handling in imap case. So this is a warning that unexpected thing *MAY HAPPEN* during error
handling of imap.
I changed the comment slightly.

Thank you again for your comment and I will create another patch Sunday evening (late at night, JST). If you have additional comments, I will include them in the next politically correct hg patch that is produced by hg command.

TIA

Comment 43

[Kent James (:rkent)]

I'll try to get this landed before the string freeze.

Comment 44

[Kent James (:rkent)]

Attachment: Nits fixed (RKJ patch)

I cleaned up a few more nits to get this ready to land. If I don't hear from Chiaki, or hear other objections, I'll land this patch as is before the string freeze.

The changes are all formatting changes for consistency, and comment revisions. The only substantial change is deletion of this comment:

+        // XXX Failure in moving results in setting false to
+        // m_msgMovedByFilter.  However, below, it used to be that
+        // failure in copying results in early exit before setting
+        // a value to m_msgCopiedByFilter in if-statement.
+        // BEWARE: There may be an intended interaction with imap during
+        // error recovery now that error is handled in a different manner:
+        // See the comment above that starts with
+        // "if we're moving to an imap folder, or this message has already..."
+

That imap interaction is simply to prevent the delete from an async move, which would truncate the inbox in the mbox case, if there is a pending copy. If the copy failed, there is no pending copy. I don't believe you changed the behavior, and this long, difficult to understand comment is not really helpful (nor entirely accurate).

It would be worth making the behavior of this method more consistent, but not in this bug.

Comment 45

[ISHIKAWA, Chiaki]

(In reply to Kent James (:rkent) from comment #44)
> Created attachment 8567564 [details] [diff] [review]
> Nits fixed (RKJ patch)
> 
> I cleaned up a few more nits to get this ready to land. If I don't hear from
> Chiaki, or hear other objections, I'll land this patch as is before the
> string freeze.
> 
> The changes are all formatting changes for consistency, and comment
> revisions. The only substantial change is deletion of this comment:
> 
> +        // XXX Failure in moving results in setting false to
> +        // m_msgMovedByFilter.  However, below, it used to be that
> +        // failure in copying results in early exit before setting
> +        // a value to m_msgCopiedByFilter in if-statement.
> +        // BEWARE: There may be an intended interaction with imap during
> +        // error recovery now that error is handled in a different manner:
> +        // See the comment above that starts with
> +        // "if we're moving to an imap folder, or this message has
> already..."
> +
> 
> That imap interaction is simply to prevent the delete from an async move,
> which would truncate the inbox in the mbox case, if there is a pending copy.
> If the copy failed, there is no pending copy. I don't believe you changed
> the behavior, and this long, difficult to understand comment is not really
> helpful (nor entirely accurate).
> 
> It would be worth making the behavior of this method more consistent, but
> not in this bug.

Dear Kent,

Thank you for cleaning up.
I came back late and could not attend to mozilla issues due to other house chores.

I will be grateful if you can land this.

TIA

Comment 46

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Pushed to comm-central changeset b50441dcdf0d

Comment 47

[Philip Chee]

(In reply to Philipp Kewisch [:Fallen] from comment #46)
> Pushed to comm-central changeset b50441dcdf0d

https://hg.mozilla.org/comm-central/rev/b50441dcdf0d#l1.13
Doesn't the suite version of filter.properties need to be updated too?

Comment 48

[Kent James (:rkent)]

(In reply to Philip Chee from comment #47)
> (In reply to Philipp Kewisch [:Fallen] from comment #46)
> > Pushed to comm-central changeset b50441dcdf0d
> 
> https://hg.mozilla.org/comm-central/rev/b50441dcdf0d#l1.13
> Doesn't the suite version of filter.properties need to be updated too?

Yes, sorry we missed that.

Comment 49

[ISHIKAWA, Chiaki]

(In reply to Philip Chee from comment #47)
> (In reply to Philipp Kewisch [:Fallen] from comment #46)
> > Pushed to comm-central changeset b50441dcdf0d
> 
> https://hg.mozilla.org/comm-central/rev/b50441dcdf0d#l1.13
> Doesn't the suite version of filter.properties need to be updated too?

Mea culpa.
I missed this angle :-(
Am I still in time to submit the patch for the next release cycle?

TIA

Comment 50

[Philip Chee]

(In reply to ISHIKAWA, Chiaki from comment #49)

> Mea culpa.
> I missed this angle :-(
> Am I still in time to submit the patch for the next release cycle?
Please submit a patch. Which has to land everywhere that https://hg.mozilla.org/comm-central/rev/b50441dcdf0d also landed.

Comment 51

[ISHIKAWA, Chiaki]

Attachment: This is the missing part: patch to the suite portion of filter.properties

This is the missing part: the patch to the suite part of filter.properties.

I have not run a tryserver or anything since I don't build suite locally.
I mean this should not break anything for now, but can anyone check this?


TIA

Comment 52

[Philip Chee]

Comment on attachment 8577748 [details] [diff] [review]
This is the missing part: patch to the suite portion of filter.properties

This looks OK

Comment 53

[ISHIKAWA, Chiaki]

Thank you(In reply to Philip Chee from comment #52)
> Comment on attachment 8577748 [details] [diff] [review]
> This is the missing part: patch to the suite portion of filter.properties
> 
> This looks OK

Thank you.
I put the checkin-needed keyword.

Please someone land only this new patch
https://bugzilla.mozilla.org/attachment.cgi?id=8577748

TIA

Comment 54

[Philipp Kewisch [:Fallen] [:📆][:🧩]]

Pushed to comm-central changeset f498a2108835