Open Bug 1564141 Opened 5 years ago Updated 2 years ago

Normandy console errors are displayed only when checking the "Show Content Messages" option

Categories

(Firefox :: Normandy Client, defect, P2)

69 Branch
Desktop
All
defect

Tracking

()

Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 --- fix-optional
firefox70 --- fix-optional

People

(Reporter: ppop, Unassigned)

References

(Regression)

Details

(Keywords: regression)

Attachments

(4 files, 1 obsolete file)

Attached image console_errors.gif

[Affected Platforms]:

  • All Windows
  • All Mac
  • All Linux

[Affected Versions]:

  • Firefox Nightly 69.0a1, Build ID 20190703162038

[Prerequisites]:

  • Have access to the delivery console.
  • Have 2 active opt-out recipes using the same add-on extension.
  • Have a profile that can be targeted by the opt-out recipes.

[Steps to reproduce]:

  1. Open the browser with the profile from prerequisites.
  2. Open the browser console and observe the console output.

[Expected result]:

  • The "Cannot install study add-on for <experiment name>: an add-on with this ID is already installed." error is displayed.

[Actual result]:

  • No errors are displayed in the console.

[Regression Window]:

[Notes]:

  • This issue is reproducible with all the console errors.
  • The console errors are redisplayed when the "Show Content Messages" checkbox is ticked.
  • I have attached a screen recording of the issue:
Has Regression Range: --- → yes

Nicolas, can you shed any light on why messages like this one are only seen when "Show Content Messages" is checked?

Flags: needinfo?(nchevobbe)

We have a new-ish mechanism to flag console messages from "Chrome", which enable us to filter out what we consider "content" messages when the checkbox is unchecked.
Unfortunately we have some false negative when setting this flag (we already fixed a couple regressions in regard to this).

Flags: needinfo?(nchevobbe)

Shorter STR:

  1. Open the Browser Console
  2. Make sure the Show Content Messages checkbox is unchecked
  3. Evaluate the following
var { LogManager } = ChromeUtils.import("resource://normandy/lib/LogManager.jsm");
var log = LogManager.getLogger("recipe-runner");
log.warn("this is a warning");
log.error("this is an error");

Expected result:

Both the warning and the error message are displayed in the browser console output

Actual result:

Only the warning message is displayed. The error message only appears when the Show Content Messages checkbox is checked

When calling log.error, we end up calling this toolkit/modules/Log.jsm#718-728, which has a different behaviour depending on the log level.

For errors, it calls Cu.reportError, which we know don't flag chrome messages as it should (see Bug 1561930).
This bug will probably be fixed when 1561930 lands.

Am I correct Eden?


Also, this looks like this part was temporary and should directly log things to the browser console (FIXME comment was added in 2014), I may look briefly into this to not be blocked by 1561930.

Depends on: 1561930
Flags: needinfo?(echuang)

Attached patch fixed STR from Comment 3.
Michael, could you give it a try and report back here if you see any issue remaining?

I think this should handle all the issues, but I'd like Patriciu to take a look instead. Do you have a try build that he could test with?

Patriciu, can you see if this problem is reproducible in the build linked to from comment 8?

Flags: needinfo?(patriciu.pop)

Sure thing! Following the steps from comment 3 both of the warnings are displayed as expected, however the normandy console errors are still not displayed unless the "Show Content Messages" checkbox is checked. I retested the behavior using the build provided in comment 8 on Windows 10 x64, Ubuntu 18.04 and macOS 10.14.

Flags: needinfo?(patriciu.pop)

Yes, the Cu.reportError should be fixed by bug 1561930.

Flags: needinfo?(echuang)

Patriciu, could you check that the problem is fixed in today's Nightly since 1561930 landed?
Thanks!

Flags: needinfo?(patriciu.pop)
Attachment #9076800 - Attachment is obsolete: true

I retested the issue and it is still reproducible. After following the steps from comment 3 only the warning message is displayed and the error appears when the "Show Content Messages" checkbox is checked.
However the normandy console errors are still not displayed unless the "Show Content Messages" option is checked. Tested using the latest Firefox Nightly build (Version 70.0a1, Build ID 20190718215316) on Windows 10 x64, Ubuntu 18.04 and macOS 10.14.

Flags: needinfo?(patriciu.pop)

The priority flag is not set for this bug.
:mythmon, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(mcooper)

I tested with today's nightly build by the steps in comment 3. And the result is attached.
It seems that warning and error messages are shown on the browser console. And I think this is the expected behavior.

Nicolas, could you help to check if it is correct?

Flags: needinfo?(nchevobbe)

Nicolas, could you help to check if it is correct?

Yes, for me STR from comment 3 is fixed, but we might have other issues, I'll try to debug them.

Patriciu, I don't understand the following

[Prerequisites]:
Have access to the delivery console.
Have 2 active opt-out recipes using the same add-on extension.
Have a profile that can be targeted by the opt-out recipes.

Could you tell me specifically how I do that? Thanks

Flags: needinfo?(nchevobbe) → needinfo?(patriciu.pop)
Attached file user.js

Sure thing! In order to receive Normandy recipes from the stage server there are several preferences that need to be changed. I already prepared the recipes and attached a user.js file, so you should be able to reproduce the issue following these steps:

  1. Open a new browser profile and navigate to the about:support page.
  2. Click the "Open Folder" button from the "Profile Folder" section.
  3. Add the attached user.js file in the folder and restart the browser.
  4. Open the browser console and observe the output.

Expected:

  • The "Cannot install study add-on for <study name>: an add-on with this ID is already installed." error is displayed.

Actual:

  • The "Cannot install study add-on for <study name>: an add-on with this ID is already installed." is displayed only after checking the "Show Content Messages" checkbox.

Also there is a chance you will encounter bug 1568770 and see the associated console errors.

Flags: needinfo?(patriciu.pop)

Thanks a lot Patriciu!

So here's the packet we get from the server:

{
  "errorMessage": "Cannot install study add-on for Cookeh: an add-on with this ID is already installed.",
  "errorMessageName": "",
  "sourceName": "resource://normandy/actions/BranchedAddonStudyAction.jsm",
  "sourceId": null,
  "lineText": "",
  "lineNumber": 68,
  "columnNumber": 0,
  "category": "XPConnect JavaScript",
  "innerWindowID": 0,
  "timeStamp": 1564047954439,
  "warning": false,
  "error": false,
  "exception": false,
  "strict": false,
  "info": false,
  "private": false,
  "stacktrace": [
    {
      "filename": "resource://normandy/actions/BranchedAddonStudyAction.jsm",
      "sourceId": null,
      "lineNumber": 68,
      "columnNumber": 5,
      "functionName": "AddonStudyEnrollError"
    },
    {
      "filename": "resource://normandy/actions/BranchedAddonStudyAction.jsm",
      "sourceId": null,
      "lineNumber": 380,
      "columnNumber": 13,
      "functionName": "enroll/onInstallStarted/<"
    },
    {
      "filename": "resource://gre/modules/AddonManager.jsm",
      "sourceId": null,
      "lineNumber": 1652,
      "columnNumber": 33,
      "functionName": "callInstallListeners"
    },
    {
      "filename": "resource://gre/modules/AddonManager.jsm",
      "sourceId": null,
      "lineNumber": 3532,
      "columnNumber": 54,
      "functionName": "callInstallListeners"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1982,
      "columnNumber": 32,
      "functionName": "_callInstallListeners"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1695,
      "columnNumber": 15,
      "functionName": "startInstall"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1344,
      "columnNumber": 14,
      "functionName": "install"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 2171,
      "columnNumber": 22,
      "functionName": "install"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1684,
      "columnNumber": 10,
      "functionName": "checkForBlockers"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1341,
      "columnNumber": 14,
      "functionName": "install"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 2171,
      "columnNumber": 22,
      "functionName": "install"
    },
    {
      "filename": "resource://gre/modules/addons/XPIInstall.jsm",
      "sourceId": null,
      "lineNumber": 1653,
      "columnNumber": 12,
      "functionName": "checkPrompt/<"
    },
    {
      "filename": "self-hosted",
      "sourceId": null,
      "lineNumber": 1300,
      "columnNumber": 8,
      "functionName": "InterpretGeneratorResume"
    },
    {
      "filename": "self-hosted",
      "sourceId": null,
      "lineNumber": 839,
      "columnNumber": 5,
      "functionName": "AsyncFunctionNext"
    }
  ],
  "notes": null,
  "chromeContext": false,
  "cssSelectors": "",
  "_type": "PageError"
}

I tried to reproduce with a simpler STR, but firing code from the browser console seems to print an error with the appropriate flag.

Flags: needinfo?(mcooper)
Priority: -- → P2
Severity: normal normal → S3 S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: