Closed
Bug 1353653
Opened 7 years ago
Closed 6 years ago
Increase log level for spammy-looking logs
Categories
(Toolkit :: Safe Browsing, enhancement, P3)
Toolkit
Safe Browsing
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: hchang, Unassigned)
Details
Attachments
(1 file, 1 obsolete file)
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)
Reporter | ||
Comment 1•7 years ago
|
||
Reporter | ||
Updated•7 years ago
|
Assignee: nobody → hchang
Updated•7 years ago
|
Status: NEW → ASSIGNED
Priority: -- → P3
Comment hidden (mozreview-request) |
Reporter | ||
Updated•7 years ago
|
Attachment #8854742 -
Attachment is obsolete: true
Reporter | ||
Updated•7 years ago
|
Attachment #8855619 -
Flags: review?(francois)
Comment 3•7 years ago
|
||
mozreview-review |
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).
Attachment #8855619 -
Flags: review?(francois) → review-
Reporter | ||
Comment 4•7 years ago
|
||
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!
Flags: needinfo?(francois)
Comment 5•7 years ago
|
||
(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?
Flags: needinfo?(francois) → needinfo?(hchang)
Reporter | ||
Comment 6•7 years ago
|
||
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 :)
Flags: needinfo?(hchang)
Comment 7•7 years ago
|
||
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?
Reporter | ||
Comment 8•7 years ago
|
||
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?
Reporter | ||
Comment 9•7 years ago
|
||
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b9efdecbb884
Comment 10•7 years ago
|
||
(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.
Reporter | ||
Updated•7 years ago
|
Assignee: hchang → nobody
Status: ASSIGNED → NEW
Comment 11•6 years ago
|
||
I've removed a lot of this noise recently. Let's close this bug since this patch has bitrotted quite a bit.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•