Closed Bug 1675584 Opened 4 years ago Closed 3 years ago

Intermittent devtools/client/jsonview/test/browser_jsonview_ignore_charset.js | The charset parameter is ignored and UTF-8 is used. - Got null, expected "❤"

Categories

(DevTools :: JSON Viewer, defect, P5)

Product:
DevTools
Component:
JSON Viewer
Type:
defect

Tracking

(firefox-esr91 fixed, firefox94 wontfix, firefox95 fixed)

Status:
RESOLVED FIXED
Milestone:
95 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- fixed
firefox94 --- wontfix
firefox95 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: Oriol)

References

Details

(Keywords: intermittent-failure, Whiteboard: stockwell needswork:owner])

Attachments

(3 files)

failure_screenshot.png
42.37 KB, image/png
Details
Bug 1675584 - [devtools] Stop assuming React renders JSON Viewer synchronously. r?Honza
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675584 - [devtools] Await TabChanged event in selectJsonViewContentTab. r?Honza
48 bytes, text/x-phabricator-request
RyanVM
: approval-mozilla-esr91+
Details | Review

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=320838649&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Fu3KhH-zSPe8D4T07sNeEw/runs/0/artifacts/public/logs/live_backing.log

[task 2020-11-05T15:25:56.007Z] 15:25:56     INFO - TEST-START | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js
[task 2020-11-05T15:25:56.216Z] 15:25:56     INFO - TEST-INFO | started process screencapture
[task 2020-11-05T15:25:56.320Z] 15:25:56     INFO - TEST-INFO | screencapture: exit 0
[task 2020-11-05T15:25:56.320Z] 15:25:56     INFO - Buffered messages logged at 15:25:56
[task 2020-11-05T15:25:56.320Z] 15:25:56     INFO - Entering test bound 
[task 2020-11-05T15:25:56.320Z] 15:25:56     INFO - Test ignored charset parameter started
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - Adding a new JSON tab with URL: 'data:application/json;charset=ANSI,%E2%9D%A4'
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - Adding a new tab with URL: data:application/json;charset=ANSI,%E2%9D%A4
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - Tab added and finished loading
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - AppReadyState is "uninitialized". Await "complete"
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - AppReadyState is "loading". Await "complete"
[task 2020-11-05T15:25:56.321Z] 15:25:56     INFO - AppReadyState is "interactive". Await "complete"
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - Selecting tab: 'rawdata'
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - Get element text: '.textPanelBox .data'
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - Buffered messages finished
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - TEST-UNEXPECTED-FAIL | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js | The charset parameter is ignored and UTF-8 is used. - Got null, expected "❤"
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - Stack trace:
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - chrome://mochikit/content/browser-test.js:test_is:1332
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - chrome://mochitests/content/browser/devtools/client/jsonview/test/browser_jsonview_ignore_charset.js:null:17
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1069
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1109
[task 2020-11-05T15:25:56.322Z] 15:25:56     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:932
[task 2020-11-05T15:25:56.323Z] 15:25:56     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:1037
[task 2020-11-05T15:25:56.323Z] 15:25:56     INFO - Leaving test bound ```

Update:
There have been 38 failures within the last 7 days:
• 2 failures on Linux 18.04 x64 WebRender debug
• 18 failures on Windows 10 x64 2004 WebRender opt
• 11 failures on Windows 10 x64 2004 WebRender Shippable opt
• 7 failures on Windows 10 x64 CCov WebRender opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349788912&repo=autoland&lineNumber=9539

[task 2021-08-27T20:01:48.451Z] 20:01:48     INFO - TEST-START | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js
[task 2021-08-27T20:01:48.666Z] 20:01:48     INFO - TEST-INFO | started process screenshot
[task 2021-08-27T20:01:48.792Z] 20:01:48     INFO - TEST-INFO | screenshot: exit 0
[task 2021-08-27T20:01:48.792Z] 20:01:48     INFO - Buffered messages logged at 20:01:48
[task 2021-08-27T20:01:48.792Z] 20:01:48     INFO - Entering test bound 
[task 2021-08-27T20:01:48.794Z] 20:01:48     INFO - Test ignored charset parameter started
[task 2021-08-27T20:01:48.794Z] 20:01:48     INFO - Adding a new JSON tab with URL: 'data:application/json;charset=ANSI,%E2%9D%A4'
[task 2021-08-27T20:01:48.795Z] 20:01:48     INFO - Adding a new tab with URL: data:application/json;charset=ANSI,%E2%9D%A4
[task 2021-08-27T20:01:48.795Z] 20:01:48     INFO - DocReadyState is "loading". Await "complete"
[task 2021-08-27T20:01:48.796Z] 20:01:48     INFO - DocReadyState is "interactive". Await "complete"
[task 2021-08-27T20:01:48.796Z] 20:01:48     INFO - AppReadyState is "uninitialized". Await "complete"
[task 2021-08-27T20:01:48.797Z] 20:01:48     INFO - AppReadyState is "loading". Await "complete"
[task 2021-08-27T20:01:48.797Z] 20:01:48     INFO - Tab added and finished loading
[task 2021-08-27T20:01:48.798Z] 20:01:48     INFO - AppReadyState is "interactive". Await "complete"
[task 2021-08-27T20:01:48.798Z] 20:01:48     INFO - Selecting tab: 'rawdata'
[task 2021-08-27T20:01:48.798Z] 20:01:48     INFO - Get element text: '.textPanelBox .data'
[task 2021-08-27T20:01:48.799Z] 20:01:48     INFO - Buffered messages finished
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - TEST-UNEXPECTED-FAIL | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js | The charset parameter is ignored and UTF-8 is used. - Got null, expected "\u2764"
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - Stack trace:
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochikit/content/browser-test.js:test_is:1364
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochitests/content/browser/devtools/client/jsonview/test/browser_jsonview_ignore_charset.js:null:17
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1091
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1131
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:939
[task 2021-08-27T20:01:48.800Z] 20:01:48     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2021-08-27T20:01:48.801Z] 20:01:48     INFO - Leaving test bound 
[task 2021-08-27T20:01:48.801Z] 20:01:48     INFO - Removing tab.
[task 2021-08-27T20:01:48.802Z] 20:01:48     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-08-27T20:01:48.802Z] 20:01:48     INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-08-27T20:01:48.803Z] 20:01:48     INFO - Tab removed and finished closing
[task 2021-08-27T20:01:48.804Z] 20:01:48     INFO - TEST-PASS | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js | The main process DevToolsServer has no pending connection when the test ends - 
[task 2021-08-27T20:01:48.804Z] 20:01:48     INFO - GECKO(6480) | MEMORY STAT | vsize 2104254MB | vsizeMaxContiguous 65425755MB | residentFast 272MB | heapAllocated 116MB
[task 2021-08-27T20:01:48.805Z] 20:01:48     INFO - TEST-OK | devtools/client/jsonview/test/browser_jsonview_ignore_charset.js | took 250ms
[task 2021-08-27T20:01:48.805Z] 20:01:48     INFO - checking window state
[task 2021-08-27T20:01:48.806Z] 20:01:48     INFO - TEST-START | devtools/client/jsonview/test/browser_jsonview_invalid_json.js
Whiteboard: stockwell needswork:owner]

Jan, as the owner of this component, could you help us assign it to someone?
Thank you.

Flags: needinfo?(odvarko)

Julian, could this also be one of the cases where we don't wait long enough for the doc/ui to be ready?

The test is using addJsonViewTab
https://searchfox.org/mozilla-central/rev/ac7da6c7306d86e2f86a302ce1e170ad54b3c1fe/devtools/client/jsonview/test/browser_jsonview_ignore_charset.js#13

And the function is implemented here:
https://searchfox.org/mozilla-central/rev/ac7da6c7306d86e2f86a302ce1e170ad54b3c1fe/devtools/client/jsonview/test/head.js#49

Honza

Flags: needinfo?(odvarko) → needinfo?(jdescottes)

It's possible that it is similar to other bugs we recently had with addTab. If we look at the addJsonViewTab helper, it does the following:

  const tabAdded = BrowserTestUtils.waitForNewTab(gBrowser, url);
  const tabLoaded = addTab(url);

  // The `tabAdded` promise resolves when the JSON Viewer starts loading.
  // This is usually what we want, however, it never resolves for unrecognized
  // content types that trigger a download.
  // On the other hand, `tabLoaded` always resolves, but not until the document
  // is fully loaded, which is too late if `docReadyState !== "complete"`.
  // Therefore, we race both promises.
  const tab = await Promise.race([tabAdded, tabLoaded]);

The addTab used here is the one we already tried to fix for other race conditions. But since we race it against tabAdded in this case, maybe we resolve because tabAdded resolved, and this is too early. Given the comment above Promise.race, we could try to use different strategies depending on the value of the docReadyState argument. If the value is "complete", then we can fully rely on tabLoaded, otherwise we use Promise.race

Flags: needinfo?(jdescottes)

I am not able to reproduce this issue on try so far. For reference my fix attempt was: https://hg.mozilla.org/try/rev/203ba71ad5ce4f0add81524b149917e61c8b6237

But it's strange, because the test awaits appReadyState === "complete", which is set after render(MainTabbedArea(input), content), and AFAIK render is still sync https://reactjs.org/docs/react-dom.html#render

using this return value is legacy and should be avoided because future versions of React may render components asynchronously in some cases

So the text should already be there. But maybe wait for a callback ref before updating appReadyState? And simultaneously fix bug 1421624.

Attached image failure_screenshot.png —

Also if you look at a failure screenshot, it's clear that the JSON viewer UI is not rendered. I wonder if the react render can complete but we would still be missing a reflow? Or there's a bug in the JSON viewer rather than in the test. Maybe we should add a small delay to verify this. If with a small wait, the test consistently passes, it means we are just not waiting enough in the test. If not, there's a bigger issue with the JSONViewer

React has this code:

  if (expirationTime === Sync) {
    performSyncWork();
  } else {
    scheduleCallbackWithExpirationTime(root, expirationTime);
  }

Typically expirationTime === Sync, but if I disable that condition, then the AppReadyStateChange event is fired before mounting the JSON Viewer.

The JSON viewer should probably use a callback:

  const theApp = render(MainTabbedArea(input), content, () => {
    // SAFE!
  });
  // UNSAFE!

Thanks for the info, we can try your suggestion. Do you want to submit a patch?

Flags: needinfo?(oriol-bugzilla)
Assignee: nobody → oriol-bugzilla
Status: NEW → ASSIGNED

Created the patch. Wanted to push to try, but it seems I lost this ability due to inactivity.

Flags: needinfo?(oriol-bugzilla)
Attachment #9242294 - Attachment description: Bug 1675584 - Stop assuming React renders JSON Viewer synchronously. r?Honza → Bug 1675584 - [devtools] Stop assuming React renders JSON Viewer synchronously. r?Honza
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7f5fcd89a1b3
[devtools] Stop assuming React renders JSON Viewer synchronously. r=Honza

https://hg.mozilla.org/mozilla-central/rev/7f5fcd89a1b3

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox94: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 94 Branch

OK, another hypothesis:

function selectJsonViewContentTab(name) {
  info("Selecting tab: '" + name + "'");

  const browser = gBrowser.selectedBrowser;
  const selector = ".tabs-menu .tabs-menu-item." + name + " a";
  return BrowserTestUtils.synthesizeMouseAtCenter(selector, {}, browser);
}

The click will run this:

      this.setState(newState, () => {
        // Properly set focus on selected tab.
        const selectedTab = this.tabsEl.current.querySelector(".is-active > a");
        if (selectedTab) {
          selectedTab.focus();
        }

        if (onAfterChange) {
          onAfterChange(index);
        }
      });

And setState may be async: https://reactjs.org/docs/state-and-lifecycle.html#state-updates-may-be-asynchronous

So I guess we should provide a onAfterChange, or add a mutation observer or something.

Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/dc2ca800da7c
[devtools] Await TabChanged event in selectJsonViewContentTab. r=Honza

I suspect D126751 might have fixed this bug but introduced bug 1734940 instead :S

See Also: → 1734940
Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → FIXED
status-firefox94: affected → wontfix
status-firefox95: --- → fixed
Flags: needinfo?(odvarko)
Target Milestone: 94 Branch → 95 Branch

We're seeing these on esr91 with pretty good frequency. AFAICT, these patches graft cleanly and a Try run looks good. I see some non-test code changes, however, so please nominate for approval unless you feel this is too risky to backport.

Flags: needinfo?(oriol-bugzilla)

The problem was that the patches were done with trial and error. They addressed this issue, but instead produced timeouts (bug 1734940). The patch there was only supposed to debug the problem better, but somehow it avoided the problem. So it's still not clear to me what was the cause and how it got fixed. So not sure if I should nominate all 3 patches, only a mix of D126751 and D128029, or what.

Flags: needinfo?(oriol-bugzilla) → needinfo?(ryanvm)

I included bug 1734940 in the green Try push, so I was planning to take that a=test-only anyway.

Flags: needinfo?(ryanvm)

Comment on attachment 9243155 [details]
Bug 1675584 - [devtools] Await TabChanged event in selectJsonViewContentTab. r?Honza

ESR Uplift Approval Request

  • If this is not a sec:{high,crit} bug, please state case for ESR consideration: Together with bug 1734940, avoids intermittent test failures
  • User impact if declined: None
  • Fix Landed on Version: 95
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Mostly a test-only change. Only dispatches a "TabChanged" custom event that is not used outside tests.
  • String or UUID changes made by this patch:
Attachment #9243155 - Flags: approval-mozilla-esr91?

I guess we can try without D126246 since that might have some effects outside tests and probably it didn't contribute to solving the problem after all.

Comment on attachment 9243155 [details]
Bug 1675584 - [devtools] Await TabChanged event in selectJsonViewContentTab. r?Honza

Approved for ESR91, thanks.

Attachment #9243155 - Flags: approval-mozilla-esr91? → approval-mozilla-esr91+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: