Closed Bug 697522 Opened 8 years ago Closed 7 months ago
precise logging of message filter runs and actions
I have one 1 top issue that would help us triage one class of bugs which are currently hard. There are reports that are uncertain whether filters were even run, on what folders etc. It is not sure whether the filters weren't run or they just didn't match anything. We would really need some way to be sure about this. The existing Filter log is almost unusable for this, as it only logs when any filter matched some message. So my proposal is to create some better Filter log (either in the existing Filter log window, or as a new value into NSPR_LOG_MODULES) with at least these properties: + There is 1 block of information for each run of filters (with timestamp). ++ There is then 1 block of data for each account where filters are run (probably only those that have new msgs or where manual run). The block contains this data: ++ How were filters invoked (automatic run, manual, automatic after classification). ++ Which account is subject to the filter run (important for merged/global inbox). ++ The type of the account (like POP, IMAP, News, Local, RSS). ++ How many enabled/disabled filters are being run (which are applicable depending on the invocation type above). +++ Then, for each folder (or newsgroup) in this account there would be this block of data: +++ In case of newsgroup, show the filter count again, as they can be defined per-newsgroup. +++ How many messages are subject to these filters (count of new messages for automatic, count of all messages if manual). +++ List of filter hits in similar format to the existing one (in Filter log) - which filter matched, on which message (subject) and what action was taken. +++ End of block '+++' ++ End of block '++' + End of block '+' This would help us find out if there are cases where filters really do not run or why people have the feeling they do not run. Of course, if the internal loops are structured in some other logic (the proposal is based on "for each account, run all filters there, next"), feel free to restructure the log as best fits the internal logic.
I am marking this bug as blocking the bugs that I would be able to triage/debug better using this logging.
rkent, do you have a preference where this verbose logging should be put? In the NSPR log or the filterlog.html ? We could potentially put a lot of output there, which looks like it would fit in the verbose output we get from the NSPR logs when enabled.
NSPR log being https://wiki.mozilla.org/MailNews:Logging with a new module "filters" added.
If you ask me "what is needed to improve filter logging?", then what I would suggest that you work on is a user-visible way to report errors in filter application. A bare NS_ENSURE_SUCCESS in filter application, which we do now, is useless to users except to prevent crashes. One possible user interface for that would be to add an error line in the status bar that could be used to report filtering errors, that is "sticky" in the sense that it remains visible until the user takes some action to dismiss it after an error occurs. That would allow our 10,000,000 daily users to help themselves for issues. I am not opposed to the NSPR errors though, I just don't think that should be the priority. An NSPR error realistically is targeted to provide input to just a few people on the core Thunderbird team. Our capacity to actually review those logs is of the order of only some tens of logs per year at best. For ExQuilla, I make extensive use of detailed logging such as you are suggesting (though I use an XPCOMified log4moz which introduces performance issues). For a professional product such as ExQuilla, I probably review a log for each 1% of users per year. Scaling that to Thunderbird would require that we review 100,000 logs per year, which is 3 orders of magnitude beyond what is realistic. On the specific question that you asked, I prefer NSPR over the existing filter log for the kind of detailed progress and error reporting that you are planning. The filter log as we are currently adjusting it in bug 935934 is clearly defined as occurring once per action, after the search succeeds but before the action is applied (successfully or unsuccessfully). This precision makes it useful to the users in diagnosing issues. Cluttering that with progress reports would make it more confusing and less useful to the average user. I would however also support a simple error message that can be added to the filter log and shows a failure to apply an action. So before NS_ENSURE_SUCCESS in the filter action code call something like LogRuleHit that would report an error in applying the filter. That would be more useful than the NSPR log, but less useful than the visible error I am suggesting.
My main concern was to help bug where users think filters were not even run or not on the messages they expected. The new log would log even filter runs that do not match any messages. We would just gain the safety that the filters were run, just the user probably misconfigured the rules. Think about the bugs where users claim that all filters stop executing after "stop filter execution" action. So this new NSPR log should be useful to us, bug triagers/coders as you correctly assume. And we would request them from the users only when necessary, like we currently do for e.g. POP3 logs. Adding one line about success/failure to the current user-visible log would be useful and I can try to add it. I am skeptical on the status line feature as I currently do not know how to make a message stick. We have a bug for showing status bar history, maybe that would help to sme extent. But I would not mix this feature into this bug.
Assignee: nobody → acelists
The issue aceman is one of priorities. I believe that it is really bad to silently be eating errors in filters, and logging that in way that the users can see routinely is a more valuable use of your time (and my time) than adding NSPR logging which is targeted to developers. But if you want to add NSPR logging, go ahead. See also discussions in Bug 1071754.
I'm on the side of doing both. NSPR because - having filter NSPR log data with other log data is a plus - it is more efficient? (dunno) user accessible filter log - NSPR can be a bitch for end users While you're in the code, is doing both much harder than doing one?
For me it is not about priorities but about current abilities. I can't do the proposed status bar thingy. But I think I can do the NSPR part from what I learned at bug 1075149. (In reply to Wayne Mery (:wsmwk) from comment #8) > I'm on the side of doing both. > NSPR because > - having filter NSPR log data with other log data is a plus > - it is more efficient? (dunno) Yes, I'll try this. > user accessible filter log > - NSPR can be a bitch for end users I accepted the idea of at least putting info about success/failure of the applied action to the existing user visible log. I will try to do that too. > While you're in the code, is doing both much harder than doing one? I think the two are completely separate so doing both does not add complexity.
I think Firefox has done some new things in the logging area. Unfortunately at the moment I can't remember where. Regardless... Given that this may require strings, and filters is one of the most beloved of features in Thunderbird (I come across examples almost monthly), would you consider doing something for 52 (even if it is a tiny start) so that we can address some of the issues you mention in comment 0?
I *think* when the filter is run, its success or failure can be now reported with some information such as the header lines of the e-mail message, etc. However, looking at the required info, C + There is 1 block of information for each run of filters (with timestamp). ++ There is then 1 block of data for each account where filters are run (probably only those that have new msgs or where manual run). The block contains this data: ? ++ How were filters invoked (automatic run, manual, automatic after classification). ? ++ Which account is subject to the filter run (important for merged/global inbox). ? ++ The type of the account (like POP, IMAP, News, Local, RSS). ? ++ How many enabled/disabled filters are being run (which are applicable depending on the invocation type above). ? +++ Then, for each folder (or newsgroup) in this account there would be this block of data: ? +++ In case of newsgroup, show the filter count again, as they can be defined per-newsgroup. ? +++ How many messages are subject to these filters (count of new messages for automatic, count of all messages if manual). ? +++ List of filter hits in similar format to the existing one (in Filter log) - which filter matched, on which message (subject) and what action was taken. +++ End of block '+++' ++ End of block '++' + End of block '+' (C stands for "Can be done". "?" stands for I have no idea at this moment.) Aha, I was referring to the information about the message thus filtered, and I am not sure if the statistics/filter about the filter (especially the summarized information is available unless such information is stored somewhere and there are accessor functions.) The filter logging function I am referring to is invoked at the time an e-mail message is received for filtering (on the delivery of e-mail), and is invoked from the message delivery code. So it only records automatic invocation I think (but I could be wrong.)
I think we modified the logging to include better info although if I don't think the change we did cover all the info in my previous comment.
One more thing that would help people finding their filters not working as expected: As part of "List of filter hits..." the information about *what rule(s)* made the filter select the message, in case that the user selected "Match any of the following". As an example: I get a whole lot of insurance SPAM that seems impossible to be detected by a SPAM filter. So I create an own filter with all kinds of suspect words. Once in a while, a Non-SPAM message gets selected by the filter, even though I checked the content of the email word by word against all words in my filter. No match found (also considering parts of the words). So it boils down to recheck the matched messages by hand again. With the information, why a message was selected, finding the problem would be easy.
Comment on attachment 9053509 [details] [diff] [review] 697522.patch WIP Review of attachment 9053509 [details] [diff] [review]: ----------------------------------------------------------------- Great to see this. I'm no good at evaluating actual code - Chiaki would be better there than me - so I assume that's not why you asked me for feedback. I skimmed the locations where MOZ_LOG(FILTERLOGMODULE is added and I see a good distribution of logging levels: Warning, Error, Debug, etc. I did not evaluate against comment 0, you are in a much better to understand if you hit all those points. I do have these questions: 1. Are there any performance concerns with the added code? 2. Can "normal" filter logging be added to partly cover the last paragraph of Kent's comment 5 where LogLevel::Error occurs (just 9 locations)? I realize Kent offered it as an alternative to NSPR logging. But it could be helpful because the filter log is much easier for users to read and enable than NSPR. Also I would be happy to give feedback based on a try build.
Attachment #9053509 - Flags: feedback?(vseerror) → feedback+
Comment on attachment 9060534 [details] [diff] [review] 697522.patch v1.1 Review of attachment 9060534 [details] [diff] [review]: ----------------------------------------------------------------- Looks ok to me, r=mkmelin ::: mailnews/base/search/public/nsIMsgFilterList.idl @@ +91,5 @@ > attribute nsIOutputStream logStream; > readonly attribute ACString logURL; > void clearLog(); > void flushLogIfNecessary(); > + // Push a message to the filter log file, adding a timestamp. Let's use real documentation comments for documentation, so we can get generated documentation going at some point. So, either /// or /** */ ::: mailnews/base/search/src/nsMsgFilterList.cpp @@ +45,5 @@ > m_temporaryList = false; > m_curFilter = nullptr; > + m_listId.Assign("List"); > + m_listId.AppendInt(nextListId++); > + MOZ_LOG(FILTERLOGMODULE, LogLevel::Info, ("Creating new filter list %s", m_listId.get())); Can we make that Creating anew filter list with id=%s ::: mailnews/base/util/nsMsgDBFolder.cpp @@ +2581,5 @@ > junkMailPlugin->GetUserHasClassified(&userHasClassified); > if (!userHasClassified) > filterForJunk = false; > > + MOZ_LOG(FILTERLOGMODULE, LogLevel::Info, ("Spam filter will %s run", filterForJunk ? "be" : "not be")); "be" is in both. In actual usage I find cases like these are better to output as one string and a boolean so it's easier to search and compare logs. I mean like "Will run spam filter: %s", filterForJunk ? "true" : "false"
Attachment #9060534 - Flags: review?(mkmelin+mozilla) → review+
Status: ASSIGNED → RESOLVED
Closed: 7 months ago
Resolution: --- → FIXED
Pushed by email@example.com: https://hg.mozilla.org/comm-central/rev/547dab7a9234 Follow-up: reformat logging code. rs=reformat DONTBUILD
Pushed by firstname.lastname@example.org: https://hg.mozilla.org/comm-central/rev/e51d02c81b86 Follow-up: reformat logging code, take 2. rs=reformat DONTBUILD
You need to log in before you can comment on or make changes to this bug.