816254 - Add logging to Downloads Panel

Status: RESOLVED FIXED

(Firefox :: Downloads Panel, defect)

Description

[Mike Conley (:mconley) (:⚙️)]

As an insurance measure to help debug problems with the Downloads Panel feature down the road, it's advisable that we log certain actions to ensure that they're happening when expected.

Comment 1

[Mike Conley (:mconley) (:⚙️)]

Attachment: WIP Patch 1

Comment 2

[Mike Conley (:mconley) (:⚙️)]

Attachment: WIP Patch 2

Ok, I think this might be enough to get an idea of what's going on in bug 816986.

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 687103 [details] [diff] [review]
WIP Patch 2

This proved pretty handy in determining where dolske's problem lay in bug 816986.

Comment 4

[Marco Bonardo [:mak]]

Comment on attachment 687103 [details] [diff] [review]
WIP Patch 2

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

I think we should go for something simpler and no-op when not needed.

My thinking is something as simple as a DownloadsCommon.log() method, if browser.downloads.debug is true we load the logger module and log. We may add a weak pref observer to it, or just request the user to set the pref and restart browser. regardless this is useful when reproducing bugs, so a restart should not matter (otherwise the bug already happened and you didn't have any logging yet).
reportError for now stays as is.

This will save the module price for most users who don't need logging. When we'll have log4moz as a toolkit module we'll re-evaluate, at that point the price will be shared across the whole project, so won't matter.

::: browser/components/downloads/content/downloads.js
@@ +45,5 @@
>  XPCOMUtils.defineLazyModuleGetter(this, "DownloadsCommon",
>                                    "resource:///modules/DownloadsCommon.jsm");
> +XPCOMUtils.defineLazyModuleGetter(this, "DownloadsLogger",
> +                                  "resource:///modules/DownloadsLogger.jsm",
> +                                  "Logger");

I'd prefer if you'd just expose an object named like the module, there are other modules exposing a "Logger" object, so the name should be downloads related... if too long maybe we could use DownloadsLog or DownloadsDbg

@@ +57,5 @@
> +  error: function(...aMessageArgs)
> +  {
> +    DownloadsLogger.reportError.apply(DownloadsLogger,
> +                                      ["downloads.js"].concat(aMessageArgs));
> +  },

Looks a bit strange to make a nice module, and then having immediately to wrap it to be able to use it, sounds like its design could be improved? Why can't DownloadsLogger directly expose log and error functions?


A wrapper could at a maximum be useful if we want to just define a log function, and import the module only if the debug pref is set.
This would mean the user has to set the pref and restart browser, though it would save the module costs in all cases where we don't need to log, that is vast majority.
I think may be a better idea than having to pay this additional cost for all of the users... Once we have a global log4moz or whatever module then the price will be splitted across the whole app and we can stop caring.

@@ +439,5 @@
>                               null);
>        } else {
> +        DownloadsLog.error("We can't find the anchor! Failure case - opening ",
> +                           "downloads panel on TabsToolbar. We should never ",
> +                           "get here!");

there should not be the need to manually add trailing whitespaces, the concat method should be able to handle that.

::: browser/components/downloads/src/DownloadsCommon.jsm
@@ +98,5 @@
> +
> +function error(...aMessageArgs) {
> +  Logger.reportError.apply(Logger,
> +                           ["DownloadsCommon.jsm"].concat(aMessageArgs));
> +}

And here it's using again a different wrapper around the module...

::: browser/components/downloads/src/DownloadsLogger.jsm
@@ +25,5 @@
> +
> +function DownloadsLogger() {
> +  Services.prefs.addObserver(PREF_DEBUG, this, false);
> +  this._debug = Services.prefs.getBoolPref(PREF_DEBUG);
> +  return this;

not needed

@@ +29,5 @@
> +  return this;
> +}
> +
> +DownloadsLogger.prototype = {
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsISupports, Ci.nsIObserver]),

nsISupports is not needed for generateQI, it's added automatically

@@ +31,5 @@
> +
> +DownloadsLogger.prototype = {
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsISupports, Ci.nsIObserver]),
> +
> +  observe: function observe(aSubject, aTopic, aData) {

when naming functions we usually prefix some unique to the module name, like DL_observe

@@ +38,5 @@
> +        this._debug = Services.prefs.getBoolPref(PREF_DEBUG);
> +        break;
> +
> +      case "quit-application-granted":
> +        Services.prefs.removeObserver(PREF_DEBUG, this);

implement Ci.nsISupportsWeakReference so you can add a weak observer and never remove it

that way you can quite simplify the observe method, since you can just get a single topic

@@ +53,5 @@
> +    let strings = [];
> +
> +    // XXX bug 770418 - args look like flattened array, not list of strings
> +
> +    args.forEach(function(arg) {

for (let arg of args)

@@ +56,5 @@
> +
> +    args.forEach(function(arg) {
> +      if (typeof arg === 'string') {
> +        strings.push(arg);
> +      } else if (typeof arg === 'undefined') {

not sure what this gains vs a plain '=== undefined'

@@ +97,5 @@
> +
> +    // Report the error in the browser
> +    let output = this._generateLogMessage(aPrefix, aArgs);
> +    Cu.reportError(output);
> +    dump("ERROR: " + output + "\n");

looks like we may end up with multiple repeated 'ERROR' strings? the prefix contains one, this another one... don't remember off-hand if reportError also prefixes it

Comment 5

[Christian Sonne [:cers]]

Attachment: WIP Patch 3

Previous patch was somewhat bit rotted, but I think I've caught all the rejects. I've also tried to accommodate all of the comments from comment #4.

Comment 6

[Marco Bonardo [:mak]]

Comment on attachment 704109 [details] [diff] [review]
WIP Patch 3

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

This actually introduces one regression (see .data comment below), apart that it's mostly some indentation and trailing space, and a suggested small refactoring.

I think I'm fine with this, though if you want a second check later feel free to ask.

::: browser/app/profile/firefox.js
@@ +301,5 @@
>  pref("browser.urlbar.trimURLs", true);
>  
>  pref("browser.altClickSave", false);
>  
> +pref("browser.download.debug", false);

it's good habit to add a brief comment above the pref to state what it does.
I think somethng like "// Enable logging downloads operations to the Error Console."

::: browser/components/downloads/content/downloads.js
@@ +555,5 @@
>                               null);
>        } else {
> +        DownloadsCommon.error("We can't find the anchor! Failure case - opening",
> +                           "downloads panel on TabsToolbar. We should never",
> +                           "get here!");

indentation

@@ +693,5 @@
>     */
>    _itemCountChanged: function DV_itemCountChanged()
>    {
> +    DownloadsCommon.log("The downloads item count has changed - we are tracking",
> +                     this._dataItems.length, "downloads in total.");

indentation

@@ +767,5 @@
>     */
>    onDataInvalidated: function DV_onDataInvalidated()
>    {
> +    DownloadsCommon.log("Downloads data has been invalidated. Cleaning up",
> +                     "DownloadsView.");

indentation

@@ +795,5 @@
>     */
>    onDataItemAdded: function DV_onDataItemAdded(aDataItem, aNewest)
>    {
> +    DownloadsCommon.log("A new download data item was added - aNewest =",
> +                     aNewest);

indentation

::: browser/components/downloads/src/DownloadsCommon.jsm
@@ +101,5 @@
>   * This object is exposed directly to the consumers of this JavaScript module,
>   * and provides shared methods for all the instances of the user interface.
>   */
>  this.DownloadsCommon = {
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsIObserver, 

trailing space

@@ +104,5 @@
>  this.DownloadsCommon = {
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsIObserver, 
> +                                         Ci.nsISupportsWeakReference]),
> +  observe: function DC_observe(aSubject, aTopic, aData) {
> +    if (aTopic == "nsPref:changed") {

currently it can't be anything else, so this check can be removed for now.

@@ +108,5 @@
> +    if (aTopic == "nsPref:changed") {
> +      this._debug = Services.prefs.getBoolPref(kPrefDebug);
> +    }
> +  },
> +  initPrefObserver: function DC_initPrefObserver() {

I suggest instead to create a separate DebugPrefObserver object out of DownloadsCommon that implements nsIObserver and nsISupportsWeakReference, and has an ensureInitialized() method. So it's hidden from external consumers of DownloadsCommon.

@@ +109,5 @@
> +      this._debug = Services.prefs.getBoolPref(kPrefDebug);
> +    }
> +  },
> +  initPrefObserver: function DC_initPrefObserver() {
> +    if(!("_debug" in this)) {

add space after if

@@ +754,5 @@
>          // Returns null if the download was removed and we can't reuse the item.
>          return existingItem;
>        }
>      }
> +    DownloadsCommon.log("Creating a new DownloadsDataItem with downloadGuid =", 

trailing space

@@ +905,5 @@
>    },
>  
>    handleError: function DD_handleError(aError)
>    {
> +    DownloadsCommon.error("Database statement execution error (", 

trailing space

@@ +911,5 @@
>    },
>  
>    handleCompletion: function DD_handleCompletion(aReason)
>    {
> +    DownloadsCommon.log("Loading all downloads from database completed with reason:", 

trailing space

@@ +941,5 @@
>      switch (aTopic) {
>        case "download-manager-remove-download-guid":
>          // If a single download was removed, remove the corresponding data item.
>          if (aSubject) {
> +            let downloadId = aSubject.QueryInterface(Ci.nsISupportsCString);

should be downloadGuid, not downloadId, and it should also include .data

@@ +942,5 @@
>        case "download-manager-remove-download-guid":
>          // If a single download was removed, remove the corresponding data item.
>          if (aSubject) {
> +            let downloadId = aSubject.QueryInterface(Ci.nsISupportsCString);
> +            DownloadsCommon.log("A single download with id", 

trailing space

@@ +943,5 @@
>          // If a single download was removed, remove the corresponding data item.
>          if (aSubject) {
> +            let downloadId = aSubject.QueryInterface(Ci.nsISupportsCString);
> +            DownloadsCommon.log("A single download with id", 
> +                                downloadId.data, "was removed.");

so here there shouldn't be .data once we add it above

@@ +944,5 @@
>          if (aSubject) {
> +            let downloadId = aSubject.QueryInterface(Ci.nsISupportsCString);
> +            DownloadsCommon.log("A single download with id", 
> +                                downloadId.data, "was removed.");
> +          this._removeDataItem(downloadId);

and this is wrong, since we were passing downloadId.data before... adding .data above will fix this

@@ +959,5 @@
>              let dataItemBinding = dataItem;
>              Services.downloads.getDownloadByGUID(dataItemBinding.downloadGuid,
>                                                   function(aStatus, aResult) {
>                if (aStatus == Components.results.NS_ERROR_NOT_AVAILABLE) {
> +                DownloadsCommon.log("Removing download with id", 

trailing space

::: browser/components/downloads/src/DownloadsLogger.jsm
@@ +27,5 @@
> +  _generateLogMessage: function _generateLogMessage(args) {
> +    // create a string representation of a list of arbitrary things
> +    let strings = [];
> +
> +    // XXX bug 770418 - args look like flattened array, not list of strings

that bug is fixed and thus I'm not sure what the comment is pointing out

@@ +70,5 @@
> +    let output = this._generateLogMessage(aArgs);
> +    Cu.reportError(output);
> +    dump("ERROR:" + output + "\n");
> +    for (let frame = Components.stack.caller; frame; frame = frame.caller) {
> +      dump(frame + "\n");

I suppose a \t in front of the stack entries may help readability

::: browser/components/downloads/src/Makefile.in
@@ +19,5 @@
>    $(NULL)
>  
>  EXTRA_PP_JS_MODULES = \
>    DownloadsCommon.jsm \
> +  DownloadsLogger.jsm \

I don't see any preprocessing directive in the file, I suppose should just be in EXTRA_JS_MODULES

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b16497a56714