1547508 - logging of message filter actions

Status: RESOLVED FIXED

(MailNews Core :: Filters, enhancement)

Description

[:aceman]

+++ This bug was initially created as a clone of Bug #697522 +++

Preliminary results from users of logging in bug 697522 revealed some cases where filters seem to run correctly and match the messages that they should, but actions didn't seem to be applied, most notably messages were not moved to target folder.

In this bug I'll add logging of each action and whether it succeeded. In current TB code failures of some actions are silently ignored.

Comment 1

[Jorg K (CEST = GMT+2)]

Beware of reformatting in mailnews/base.

Comment 2

[:aceman]

Attachment: 1547508.patch

This one is a bit bigger.
Each action (in ApplyFilterHit() switch) should return the result of it's applying in 'rv'. If it is a failure we report a failure of action and also accumulate the error in 'finalResult', which is then returned as a result of the whole function. Except in nsMsgFilterService, which collects finalResult into mFinalResult, as there the code flow is a bit different.

Try run:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=fe75e354a080025e358f21395251e00920cd8a46

Comment 3

[Jorg K (CEST = GMT+2)]

Attachment: 1547508.patch - reformatted

Comment 4

[Magnus Melin [:mkmelin]]

Comment on attachment 9069218 [details] [diff] [review]
1547508.patch - reformatted

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

::: mail/locales/en-US/chrome/messenger/filter.properties
@@ +40,5 @@
>  filterFailureSendingReplyError=Error sending reply
>  filterFailureSendingReplyAborted=Sending reply aborted
>  filterFailureMoveFailed=Move failed
>  filterFailureCopyFailed=Copy failed
> +filterFailureAction=Failed applying the action

"the filter action" perhaps?

::: mailnews/base/search/src/nsMsgFilterList.cpp
@@ +354,5 @@
>            if (NS_FAILED(rv) || !applyMore) {
> +            // clang-format off
> +            MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
> +                    ("(Auto) Stopping further filter execution on this message"));
> +            // clang-format on

what are these?

::: mailnews/base/search/src/nsMsgFilterService.cpp
@@ +777,5 @@
> +                                  "messages, disabling the filter");
> +          }
> +          nsCOMPtr<nsIMsgCopyService> copyService =
> +              do_GetService(NS_MSGCOPYSERVICE_CONTRACTID, &rv);
> +          BREAK_ACTION_IF_FAILURE(rv, "Could not get copy service");

why the change from continue to break? here and some more cases

Comment 5

[Jorg K (CEST = GMT+2)]

clang-format off/on disables formatting for that section. Sometimes the automatic formatting causes "ugliness" and MOZ_LOG calls are particularly prone to additional line splits due to the "unconventional" arguments. One way to avoid these clang-format off/on would be defining individual penalties in the .clang-format file which which I haven't done and M-C also don't do.

Comment 6

[:aceman]

(In reply to Magnus Melin [:mkmelin] from comment #4)

+filterFailureAction=Failed applying the action
"the filter action" perhaps?

OK.

::: mailnews/base/search/src/nsMsgFilterList.cpp
@@ +354,5 @@

•        // clang-format off
  

•        MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
  

•                ("(Auto) Stopping further filter execution on this message"));
  

•        // clang-format on
  

what are these?

Looks like Jorg added those with the reformatting. Those lines are 81 or 82 chars long and clang will reformat them in an ugly way like:
MOZ_LOG(
FILTERLOGMODULE, LogLevel::Info,
("(Auto) Stopping further filter execution on this message"));

But I can try to help it manually with a better wrapping, so that it is below 80 chars.

::: mailnews/base/search/src/nsMsgFilterService.cpp
@@ +777,5 @@

•                              "messages, disabling the filter");
  

•      }
  

•      nsCOMPtr<nsIMsgCopyService> copyService =
  

•          do_GetService(NS_MSGCOPYSERVICE_CONTRACTID, &rv);
  

•      BREAK_ACTION_IF_FAILURE(rv, "Could not get copy service");
  

why the change from continue to break? here and some more cases

Because I want execution to continue after the 'switch' where a summary message about failure is shown (and only that one will be localized, these strings in the macros are not). Other than that, the logic should be unchanged, we continue on the next action.

Comment 7

[:aceman]

Attachment: 1547508.patch v1.2

Comment 8

[Jorg K (CEST = GMT+2)]

Attachment: 1547508.patch - reformatted

Sorry, if you reformat this, you get the attached patch. Clang-reformat is pretty stubborn, so please at the // clang-format off/on or you end up with some ugly stuff.

EDIT: https://bugzilla.mozilla.org/attachment.cgi?oldid=9070792&action=interdiff&newid=9070802&headers=1

Comment 9

[Jorg K (CEST = GMT+2)]

Comment on attachment 9070792 [details] [diff] [review]
1547508.patch v1.2

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

Large patch and hard to review. I have a few questions from a first glance at it. As Magnus said, some looks like change behaviour changing "continue" to "break". So that's to check errors after the loop? But how does it then continue? Maybe I need to look at some examples in context. Can you please point out the best one to look at?

I guess I'll continue with the review since Magnus is PTO. I'd like to see this in TB 68 so we ship a full "rule logging" package. Never mind the string change, there are plenty more from OTR. Also, brace for bitrot from bug 1557829. And I think you need to fix some ugly stuff that comes from reformatting.

::: mailnews/base/search/src/nsMsgFilterService.cpp
@@ +74,5 @@
>      continue;                                                               \
>    }
>  
>  #define BREAK_IF_FALSE(_assertTrue, _text)                              \
> +  if (MOZ_UNLIKELY(!(_assertTrue))) {                                   \

Educate the reviewer, what is `MOZ_UNLIKELY` ?

@@ +670,5 @@
> +      MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
> +              ("(Post) Applying remaining %" PRIu32
> +               " filter actions to %" PRIu32 " matched messages",
> +               numActions - m_nextAction,
> +               static_cast<uint32_t>(m_searchHits.Length())));

These are almost the same, consider removing the distinction.

@@ +686,5 @@
>        rv = filterAction->GetType(&actionType);
>        CONTINUE_IF_FAILURE(rv, "Could not get type for filter action");
> +      MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
> +              ("(Post) Running filter action at index %" PRIu32
> +               ", action type = %i",

%i ? What's that?

@@ +1407,5 @@
>  
>  /* void OnStopCopy (in nsresult aStatus); */
>  NS_IMETHODIMP nsMsgFilterAfterTheFact::OnStopCopy(nsresult aStatus) {
> +  if (NS_SUCCEEDED(aStatus)) {
> +    MOZ_LOG(

Ugly.

::: mailnews/imap/src/nsImapMailFolder.cpp
@@ +3222,5 @@
>        if (actionType == nsMsgFilterAction::MoveToFolder ||
>            actionType == nsMsgFilterAction::CopyToFolder) {
>          rv = filterAction->GetTargetFolderUri(actionTargetFolderUri);
>          if (NS_FAILED(rv) || actionTargetFolderUri.IsEmpty()) {
> +          MOZ_LOG(

Ugly.

@@ -3220,2 @@
>        msgHdr->GetFlags(&msgFlags);
> -      msgHdr->GetMessageKey(&msgKey);

OK to remove? Unused?

@@ -3222,3 @@
>        bool isRead = (msgFlags & nsMsgMessageFlags::Read);
> -      nsresult rv = GetDatabase();
> -      NS_ENSURE_SUCCESS(rv, rv);

OK to remove?

::: mailnews/local/src/nsParseMailbox.cpp
@@ +1872,5 @@
>        if (actionType == nsMsgFilterAction::MoveToFolder ||
>            actionType == nsMsgFilterAction::CopyToFolder) {
>          rv = filterAction->GetTargetFolderUri(actionTargetFolderUri);
>          if (NS_FAILED(rv) || actionTargetFolderUri.IsEmpty()) {
> +          MOZ_LOG(

Ugly.

@@ -1901,5 @@
>                  m_moveCoalescer =
>                      new nsImapMoveCoalescer(m_downloadFolder, m_msgWindow);
>                NS_ENSURE_TRUE(m_moveCoalescer, NS_ERROR_OUT_OF_MEMORY);
> -              nsMsgKey msgKey;
> -              (void)msgHdr->GetMessageKey(&msgKey);

Why can that be removed? `msgKey` appears to be used on the next line.

@@ -2008,4 @@
>            nsMsgLabelValue filterLabel;
>            filterAction->GetLabel(&filterLabel);
> -          nsMsgKey msgKey;
> -          msgHdr->GetMessageKey(&msgKey);

Same comment, why OK to remove?

@@ +2140,5 @@
>  
>            nsCOMPtr<nsIMutableArray> messageArray(
>                do_CreateInstance(NS_ARRAY_CONTRACTID, &rv));
> +          if (NS_FAILED(rv) || !messageArray) break;
> +          messageArray->AppendElement(msgHdr);

Error checking here removed?

Comment 10

[:aceman]

Thanks for looking over this.

(In reply to Jorg K (GMT+2) from comment #9)

Large patch and hard to review. I have a few questions from a first glance
at it. As Magnus said, some looks like change behaviour changing "continue"
to "break". So that's to check errors after the loop? But how does it then
continue? Maybe I need to look at some examples in context. Can you please
point out the best one to look at?

It just prints the common message after the switch and then continues the loop, so it it almost the same as the previous continue.

I guess I'll continue with the review since Magnus is PTO. I'd like to see
this in TB 68 so we ship a full "rule logging" package. Never mind the
string change, there are plenty more from OTR. Also, brace for bitrot from
bug 1557829.
Done and it looks good.

::: mailnews/base/search/src/nsMsgFilterService.cpp
Educate the reviewer, what is MOZ_UNLIKELY ?

Instructs the compiler that the condition is really unlikely to be true. Optimizes branch prediction in CPU and should run faster.
These macros are run very often and for each message processed (potentially thousands of messages for the periodic filters).

@@ +670,5 @@

•  MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
  

•          ("(Post) Applying remaining %" PRIu32
  

•           " filter actions to %" PRIu32 " matched messages",
  

•           numActions - m_nextAction,
  

•           static_cast<uint32_t>(m_searchHits.Length())));
  

These are almost the same, consider removing the distinction.

This is intentional as the function is entered twice and some async msg copying may be done in between. If the messages were the same (as before the patch), it looked like the action applying is done twice on each message. Any better proposal on how to indicate this?

@@ +686,5 @@

   rv = filterAction->GetType(&actionType);
   CONTINUE_IF_FAILURE(rv, "Could not get type for filter action");

•  MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
  

•          ("(Post) Running filter action at index %" PRIu32
  

•           ", action type = %i",
  

%i ? What's that?

Int. Somehow the 'typedef long nsMsgRuleActionType;' in .idl translates to 'int', not 'long int' (%li). It compiles for me like this and does not with %li. Would you prefer some other formatting type?

@@ -3220,2 @@

   msgHdr->GetFlags(&msgFlags);

•  msgHdr->GetMessageKey(&msgKey);
  

OK to remove? Unused?

Yes, seems unused to me, otherwise it wouldn't compile.

@@ -3222,3 @@

   bool isRead = (msgFlags & nsMsgMessageFlags::Read);

•  nsresult rv = GetDatabase();
  

•  NS_ENSURE_SUCCESS(rv, rv);
  

OK to remove?

No, I just move it to above the action loop as it seemed strange to me to get the same database for each action in the filter.

@@ -1901,5 @@

             m_moveCoalescer =
                 new nsImapMoveCoalescer(m_downloadFolder, m_msgWindow);
           NS_ENSURE_TRUE(m_moveCoalescer, NS_ERROR_OUT_OF_MEMORY);

•          nsMsgKey msgKey;
  

•          (void)msgHdr->GetMessageKey(&msgKey);
  

Why can that be removed? msgKey appears to be used on the next line.

Yes, but we have the msgKey fetched at the top of the function for the logging output. It looks like I added that dupe and now I remove this more local one.

@@ -2008,4 @@

       nsMsgLabelValue filterLabel;
       filterAction->GetLabel(&filterLabel);

•      nsMsgKey msgKey;
  

•      msgHdr->GetMessageKey(&msgKey);
  

Same comment, why OK to remove?

Same answer.

@@ +2140,5 @@

       nsCOMPtr<nsIMutableArray> messageArray(
           do_CreateInstance(NS_ARRAY_CONTRACTID, &rv));

•      if (NS_FAILED(rv) || !messageArray) break;
  

•      messageArray->AppendElement(msgHdr);
  

Error checking here removed?

Yes, because we do not check the success of AppendElement in any other place in the function. Should I add the error checking everywhere for consistency?

Comment 11

[:aceman]

Attachment: 1547508.patch v1.3

The current state of the patch with some suggestions incorporated. Open questions from comment 10 remain.

Comment 12

[Jorg K (CEST = GMT+2)]

Comment on attachment 9078537 [details] [diff] [review]
1547508.patch v1.3

I compared v1.2 and v1.3 - sadly interdiff spits the dummy, so I had to do it locally - and I saw almost no differences. Looks like the patch was rebased for bug 1557829. I looked at my questions in comment #9 again and I'm satisfied with the answers in comment #10. Let's not check AppendElement if it's not checked elsewhere either. I'll reformat now.

Comment 13

[Jorg K (CEST = GMT+2)]

Attachment: 1547508.patch v1.3 with additional clang-format off/on

This should be good to go, if you agree. Sorry about the delay.

Comment 14

[Jorg K (CEST = GMT+2)]

What's happening here now? Shall we land this one day soon?

Comment 15

[:aceman]

Comment on attachment 9081123 [details] [diff] [review]
1547508.patch v1.3 with additional clang-format off/on

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

Yes I'm fine with this if it is just reformatting ad disallowing reformatting where needed.

::: mailnews/base/search/src/nsMsgFilterList.cpp
@@ +380,5 @@
>        } else {
> +        MOZ_LOG(FILTERLOGMODULE, LogLevel::Info,
> +                ("(Auto) Skipping filter of non-matching type"
> +                 " at index %" PRIu32,
> +                 filterIndex));

Why is this wrapping?

Comment 16

[Jorg K (CEST = GMT+2)]

Ask the makers of clang-format. I guess it wants to separate the broken strings fro the other type.

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/6429eb360098
add logging of message filter actions. r=jorgk