1353653 - Increase log level for spammy-looking logs

Status: RESOLVED INCOMPLETE

(Toolkit :: Safe Browsing, enhancement, P3)

Description

[Henry Chang [:hchang]]

When I tried to enable urlclassifier log on try for debugging, I ended up with truncated logs, which is totally not helpful. This bug is to increase the log level (from debug to verbose) for those spammy logs (they are not spam though)

Comment 1

[Henry Chang [:hchang]]

Attachment: Bug1353653.patch

Comment 2

[Henry Chang [:hchang]]

Attachment: Bug 1353653 - Increase spammy log's log level.

Review commit: https://reviewboard.mozilla.org/r/127474/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/127474/

Comment 3

[François Marier [:francois]]

Comment on attachment 8855619 [details]
Bug 1353653 - Increase spammy log's log level.

https://reviewboard.mozilla.org/r/127474/#review132220

I agree with the gist of this patch and I flagged a few LOG lines that we may want to keep for a bit longer because I remember using them quite a few times. Maybe we should start without these ones and do a follow-up patch later if noise is still a big concern?

::: toolkit/components/url-classifier/Classifier.cpp:459
(Diff revision 1)
>    nsTArray<nsCString> activeTables;
>    SplitTables(aTables, activeTables);
>  
>    nsTArray<LookupCache*> cacheArray;
>    for (uint32_t i = 0; i < activeTables.Length(); i++) {
> -    LOG(("Checking table %s", activeTables[i].get()));
> +    LOG_VERBOSE(("Checking table %s", activeTables[i].get()));

This one is actually quite useful when you're trying to figure out which table is blocking a given URL.

::: toolkit/components/url-classifier/Classifier.cpp:488
(Diff revision 1)
>      lookupHash.FromPlaintext(fragments[i], mCryptoHash);
>  
>      if (LOG_ENABLED()) {
>        nsAutoCString checking;
>        lookupHash.ToHexString(checking);
> -      LOG(("Checking fragment %s, hash %s (%X)", fragments[i].get(),
> +      LOG_VERBOSE(("Checking fragment %s, hash %s (%X)", fragments[i].get(),

This one is also kind of useful when trying to determine which prefix actually matched I think.

::: toolkit/components/url-classifier/HashStore.cpp:691
(Diff revision 1)
>                        reinterpret_cast<const Bytef*>(aIn.Elements()),
>                        insize);
>    if (zerr != Z_OK) {
>      return NS_ERROR_FAILURE;
>    }
> -  LOG(("DeflateWriteTArray: %lu in %lu out", insize, outsize));
> +  LOG_VERBOSE(("DeflateWriteTArray: %lu in %lu out", insize, outsize));

I agree 100% about hiding these ones :)

::: toolkit/components/url-classifier/LookupCache.cpp:414
(Diff revision 1)
>  
>    bool found;
>    nsresult rv = mPrefixSet->Contains(prefix, &found);
>    NS_ENSURE_SUCCESS(rv, rv);
>  
> -  LOG(("Probe in %s: %X, found %d", mTableName.get(), prefix, found));
> +  LOG_VERBOSE(("Probe in %s: %X, found %d", mTableName.get(), prefix, found));

I use this one a lot when debugging tracking protection problems.

::: toolkit/components/url-classifier/LookupCacheV4.cpp:14
(Diff revision 1)
>  #include <string>
>  
>  // MOZ_LOG=UrlClassifierDbService:5
>  extern mozilla::LazyLogModule gUrlClassifierDbServiceLog;
>  #define LOG(args) MOZ_LOG(gUrlClassifierDbServiceLog, mozilla::LogLevel::Debug, args)
> +#define LOG_VERBOSE(args) MOZ_LOG(gUrlClassifierDbServiceLog, mozilla::LogLevel::Verbose, args)

Yes, we should define this here even if we don't end up using it in the file. We will likely use it later.

::: toolkit/components/url-classifier/LookupCacheV4.cpp:102
(Diff revision 1)
>    *aHas = length >= PREFIX_SIZE;
>    *aMatchLength = length;
>  
>    if (LOG_ENABLED()) {
>      uint32_t prefix = aCompletion.ToUint32();
> -    LOG(("Probe in V4 %s: %X, found %d, complete %d", mTableName.get(),
> +    LOG_VERBOSE(("Probe in V4 %s: %X, found %d, complete %d", mTableName.get(),

Will be useful in the future. I would also suggest keeping it as `LOG()`.

::: toolkit/components/url-classifier/nsUrlClassifierDBService.cpp:216
(Diff revision 1)
>  
>    // We ignore failures from Check because we'd rather return the
>    // results that were found than fail.
>    mClassifier->Check(spec, tables, gFreshnessGuarantee, *results);
>  
> -  LOG(("Found %" PRIuSIZE " results.", results->Length()));
> +  LOG_VERBOSE(("Found %" PRIuSIZE " results.", results->Length()));

Potentially quite useful too.

::: toolkit/components/url-classifier/nsUrlClassifierDBService.cpp:273
(Diff revision 1)
>    if (NS_FAILED(rv)) {
>      c->LookupComplete(nullptr);
>      return rv;
>    }
>  
> -  LOG(("Found %" PRIuSIZE " results.", results->Length()));
> +  LOG_VERBOSE(("Found %" PRIuSIZE " results.", results->Length()));

I think that one is also kind of useful and probably not that frequent (once per lookup only).

Comment 4

[Henry Chang [:hchang]]

Hi Francois,

I didn't remove those "verbose" logs at all. That means, if you follow the same instruction:
(which can be found on the wiki so I guess everyone is using that)

MOZ_LOG="UrlClassifierDbService:5,nsChannelClassifier:5,UrlClassifierProtocolParser:5,UrlClassifierStreamUpdater:5,UrlClassifierPrefixSet:5"

You will get the same log. But for people who want to see fewer log while debugging, 
they can use UrlClassifierDbService:4, for example. 

So based on my explanation, would you like to review again? Thanks!

Comment 5

[François Marier [:francois]]

(In reply to Henry Chang [:henry][:hchang] from comment #4)
> I didn't remove those "verbose" logs at all. That means, if you follow the
> same instruction:
> (which can be found on the wiki so I guess everyone is using that)
> 
> MOZ_LOG="UrlClassifierDbService:5,nsChannelClassifier:5,
> UrlClassifierProtocolParser:5,UrlClassifierStreamUpdater:5,
> UrlClassifierPrefixSet:5"
> 
> You will get the same log. But for people who want to see fewer log while
> debugging, 
> they can use UrlClassifierDbService:4, for example. 

Ah, so LOG => level 5 and LOG_VERBOSE => level 4?

Comment 6

[Henry Chang [:hchang]]

Exactly the reverse:

LOG ==> level 4 as it's defined as
#define LOG(args) MOZ_LOG(gUrlClassifierDbServiceLog, mozilla::LogLevel::Debug, args)

LOG_VERBOSE ==> level 5
#define LOG_VERBOSE(args) MOZ_LOG(gUrlClassifierDbServiceLog, mozilla::LogLevel::Verbose, args)

enum class LogLevel {
  Disabled = 0,
  Error,
  Warning,
  Info,
  Debug,   // 4
  Verbose, // 5
};

We have been using higher log level (UrlClassifierDbService:5) than 
the log's actual level (mozilla::LogLevel::Debug is 4) so we got an
unused log level (mozilla::LogLevel::Verbose) for the spammy logs :)

Comment 7

[François Marier [:francois]]

Ah I see what you mean. Essentially, we'll be able to update the wiki so that these numbers are all `:4` unless you really need the gory details. I do think that the LOG lines I pointed out in my review are fairly useful and worthy of being level 4.

So maybe we start with moving the worst offenders (and the least generally useful) messages to level 5 and then see if the noise is down to an acceptable level?

Comment 8

[Henry Chang [:hchang]]

What I am sure is 

1) For current codebase, we are NOT able to have useful log when running try with 
   MOZ_LOG=UrlClassifierDbService:5

2) With this patch applied, we are able to have useful log with
   MOZ_LOG=UrlClassifierDbService:4 (i.e. without LOG_VERBOSE() in the patch)

What I cannot tell is "the exact amount of logs to be suppressed" would make it able to
give useful log on try. (After all, the original intention of this bug for me is to
be able to see MOZ_LOG on try)

Or, instead of tweaking the log level, having more tags for different purposes might
be an alternative. For example, why I wanted to change the log levels in the first
place was I only need logs related to "update" on try for debugging.
(Actually I don't mind seeing irrelevant logs but the logs on try will be truncated, so....)
In this case, we need new tag to split "update" and "lookup" logs apart.
However, given the convention of log tagging seems like "file based" and DBService/Classifier/LookupCache
are in charge of both update and lookup, I don't know if this idea really
works :(

Anyways, I probably don't need to have MOZ_LOG on try at the moment, so how about
just leave this bug open until I get better idea?

Comment 9

[Henry Chang [:hchang]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b9efdecbb884

Comment 10

[François Marier [:francois]]

(In reply to Henry Chang [:henry][:hchang] from comment #8)
> 2) With this patch applied, we are able to have useful log with
>    MOZ_LOG=UrlClassifierDbService:4 (i.e. without LOG_VERBOSE() in the patch)

And would it also be the case if you made the changes I suggested or are some of the ones I flagged too noisy still?

> Anyways, I probably don't need to have MOZ_LOG on try at the moment, so how
> about
> just leave this bug open until I get better idea?

I think it's worth fixing and that we shouldn't wait on having a perfect solution (splitting things between updates and lookups). There's an awful lot of noise that your patch would be filtering out and it's worth landing because it will make our debugging much easier.

Comment 11

[François Marier [:francois]]

I've removed a lot of this noise recently. Let's close this bug since this patch has bitrotted quite a bit.