1581530 - File with missing source map led to blank debugger on restart

Status: RESOLVED FIXED

(DevTools :: Debugger, defect, P1)

Description

[:Harald Kirschner :digitarald]

Attachment: image.png

What were you doing?

1. Pausing on exception in ft.com
2. Stack linked to a file with missing source map, which wasn't shown
3. Pretty-printing the generated file caused the stack trace again to jump to the missing source mapped file (I guess because pretty-printing generates an original file and the debugger assumes I want more original files)
4. Tried refresh to see if I can reproduce the error

What happened?

Blank debugger panel.

P2, as many some prod sites ship with missing source maps.

Comment 1

[Jan Honza Odvarko [:Honza] (always need-info? me)]

I can confirm, I was able to reproduce the issue

Here is modified version of STR

1. Load https://www.ft.com/
2. If the debugger isn't paused check Pause on exceptions and Pause on caught exceptions and reload
3. You should see an error message (instead of the source code for either font-loader or o-errors.js):
   Error while fetching an original source: NetworkError when attempting to fetch resource. Source URL: webpack://n-ui/public/n-ui/font-loader.js
   The page is in the middle of loading at this point.
4. Click the X (Stop loading this page button in Firefox toolbar) and again as soon as it changes to Reload current page -> The Debugger panel goes blank.

Definitely P1

Honza

Comment 2

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Btw. this error log might be related:

JavaScript error: resource://devtools/client/debugger/src/client/firefox/commands.js, line 79: Error: Unknown thread front: UnknownThread
JavaScript error: resource://devtools/client/debugger/src/utils/context.js, line 15: Error: Page has navigated
JavaScript error: resource://devtools/client/debugger/src/reducers/sources.js, line 456: Error: source sourceURL-https://www.ft.com/__assets/hashed/n-ui/04670e3e/font-loader.js does not exist
console.error: "The above error occurred in the <Connect(SecondaryPanes)> component:\n    in Connect(SecondaryPanes) (created by App)\n    in div (created by SplitBox)\n    in div (created by SplitBox)\n    in SplitBox (created by App)\n    in div (created by A11yIntention)\n    in A11yIntention (created by App)\n    in div (created by App)\n    in App (created by Connect(App))\n    in Connect(App)\n    in Provider\n    in Provider\n\nConsider adding an error boundary to your tree to customize error handling behavior.\nVisit https://fb.me/react-error-boundaries to learn more about error boundaries."
JavaScript error: resource://devtools/client/debugger/src/reducers/sources.js, line 456: Error: source sourceURL-https://www.ft.com/__assets/hashed/n-ui/04670e3e/font-loader.js does not exist
console.error: "Warning: Can't perform a React state update on an unmounted component. This is a no-op, but it indicates a memory leak in your application. To fix, cancel all subscriptions and asynchronous tasks in %s.%s" "the componentWillUnmount method" "\n    in WhyPaused (created by Connect(WhyPaused))\n    in Connect(WhyPaused) (created by SecondaryPanes)\n    in div (created by SecondaryPanes)\n    in div (created by SecondaryPanes)\n    in div (created by SecondaryPanes)\n    in SecondaryPanes (created by Connect(SecondaryPanes))\n    in Connect(SecondaryPanes) (created by App)\n    in div (created by SplitBox)\n    in div (created by SplitBox)\n    in SplitBox (created by App)\n    in div (created by A11yIntention)\n    in A11yIntention (created by App)\n    in div (created by App)\n    in App (created by Connect(App))\n    in Connect(App)\n    in Provider\n    in Provider"
JavaScript error: resource://devtools/client/debugger/src/utils/resource/selector.js, line 37: Error: Resource sourceURL-https://www.ft.com/__assets/hashed/n-ui/04670e3e/font-loader.js does not exist

Comment 3

[Logan Smyth [:loganfsmyth]]

Yikes I think this goes a lot deeper that I expected.

From what I can gather, the primary cause of this is that thread.js's onWindowReady (https://searchfox.org/mozilla-central/rev/05a22d864814cb1e4352faa4004e1f975c7d2eb9/devtools/server/actors/thread.js#1691) is not running on page refresh like it does on every other page, and that means we don't call this.sources.reset(); which means that on page refresh, we don't send the debugger client notifications about new sources, and thus when we pause at the file and assume that we've gotten the source, it throws.

As far as I can tell, this comes down to browsing-context.js actor not getting a DOMWindowCreated event (https://searchfox.org/mozilla-central/rev/05a22d864814cb1e4352faa4004e1f975c7d2eb9/devtools/server/actors/targets/browsing-context.js#1548).

Gonna have to dive into C++ I think.

@ochameau Any thoughts on this before I explore more tomorrow?

Comment 4

[Alexandre Poirot [:ochameau]]

I'm not seeing the same thing.

Following Honza's STR from comment 1, I see some window-ready events.
Note that on step 2, when checking "Pause on caught exception", the debugger pauses.
So when reloading, the debugger was paused. I imagine that may cause troubles if we aren't managing pause state correctly.
But I'm not sure it is that...

What is surprising in the following logs is that the UI error (source Foo does not exists) happens before the window-ready events, while the window-ready are emitted very early, as soon as a window global is just created.

May be a first step would be to make it so that the debugger doesn't become all blank because of such frontend exception?

/// Opening the debugger after the page is fully loaded
=> emit window-ready(https://www.ft.com/ readyState:complete)
 => emit window-ready(about:blank readyState:complete)
 => emit window-ready(https://www.ft.com/ readyState:complete)
 => emit window-ready(about:blank readyState:complete)

// Some caught exception is trapped and the debugger is paused, I hit reload

JavaScript warning: resource://devtools/server/actors/targets/browsing-context.js, line 1035: DebuggeeWouldRun: debuggee `https://www.ft.com/__assets/hashed/n-ui/efaa7de4/o-errors.js:3' would run
console.error: (new Error("source sourceURL-https://www.googletagservices.com/activeview/js/current/osd_listener.js?cache=r20110914 does not exist", "resource://devtools/client/debugger/src/reducers/sources.js", 456))
JavaScript error: resource://devtools/client/debugger/src/reducers/sources.js, line 456: Error: source sourceURL-https://www.googletagservices.com/activeview/js/current/osd_listener.js?cache=r20110914 does not exist
JavaScript warning: resource://devtools/server/actors/utils/event-loop.js, line 79: DebuggeeWouldRun: debuggee `https://www.ft.com/__assets/hashed/n-ui/efaa7de4/o-errors.js:3' would run
 => emit window-ready(https://www.ft.com/ readyState:loading)
console.warn: "Error while detaching the worker target front: undefined"
console.warn: "Error while detaching the worker target front: undefined"
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)
 => emit window-ready( readyState:uninitialized)

I get such log with the following patch:

diff --git a/devtools/server/actors/targets/browsing-context.js b/devtools/server/actors/targets/browsing-context.js
index 149bd5b91269..3b22c977224e 100644
--- a/devtools/server/actors/targets/browsing-context.js
+++ b/devtools/server/actors/targets/browsing-context.js
@@ -1326,7 +1326,7 @@ const browsingContextTargetPrototype = {
     if (window == this._originalWindow && !isFrameSwitching) {
       this._updateChildDocShells();
     }
-
+    dump(" => emit window-ready("+window.location.href+" readyState:"+window.document.readyState+")\n");
     this.emit("window-ready", {
       window: window,
       isTopLevel: isTopLevel,

Comment 5

[Logan Smyth [:loganfsmyth]]

What is surprising in the following logs is that the UI error (source Foo does not exists) happens before the window-ready events, while the window-ready are emitted very early, as soon as a window global is just created.

Agreed. We absolutely rely on that event happening before anything else in this current context and I'm very surprised we aren't getting it. Unfortunately this page is such a horrible cluster that I imagine it will be a real pain to trim this down to a smaller reproduction :(

May be a first step would be to make it so that the debugger doesn't become all blank because of such frontend exception?

I don't disagree, but it's definitely something we rely on now and have relied on. As long as the window-ready has fired to clear the previous metadata about sources, we're always send the newSource notification packets before sending anything to the client that uses those sources.

We can add logic to work around that, but that also then assumes that there's no other issues caused by window-ready running after the debugging session has started, and I'd be very hesitant to make that assumption. It seems like the ordering issue would be the main thing to resolve. The only workaround that seems safe would be to ignore the pause entirely and autoresume if the source isn't known.

I can dig into it more on Monday.

Comment 6

[Logan Smyth [:loganfsmyth]]

Woops, forgot this part.

I see some window-ready events. So when reloading, the debugger was paused. I imagine that may cause troubles if we aren't managing pause state correctly.

You're right, I seem to see the event some of the time, and it logs after the exception. Other times, I don't see it at all, but perhaps that is if the document is stuck in some loading state, so it really is never ready.

Comment 7

[Logan Smyth [:loganfsmyth]]

Turns out this is my fault! Welp...

This appears to be a regression due to a missing set of changes for https://bugzilla.mozilla.org/show_bug.cgi?id=1564168.

In that patch, I fixed and landed Jason's patch to remove .enabled from the Debugger objects, but it appears that somehow in the rush to get that settled before I moved, I missed that there were 2 patches on that issue, and only one of them landed. The second one still needs additional work (https://phabricator.services.mozilla.com/D37929).

What this means is that we have places in the server doing .dbg.enabled = false and .dbg.enabled = true that are no-ops. In the context of this issue, it means that we try to disable the debugger, except that we don't, so if we hit a breakpoint during the phase when we expected to be ignoring them, things go wrong.

Comment 8

[Logan Smyth [:loganfsmyth]]

Aha! I was wrong actually! The logic I was looking at that I thought wasn't updated was actually updated, but the changes were then accidentally reverted in https://bugzilla.mozilla.org/show_bug.cgi?id=997119.

Comment 9

[Logan Smyth [:loganfsmyth]]

Attachment: Bug 1581530 - Re-apply usage of .enable/.disable accidentally reverted in Bug 997119. r=jlast

Comment 10

[Alexandre Poirot [:ochameau]]

(In reply to Alexandre Poirot [:ochameau] from comment #4)

May be a first step would be to make it so that the debugger doesn't become all blank because of such frontend exception?

Is there a bug to track why the debugger becomes blank?
Even if there is an issue on server side, which you address here, I would not expect the debugger UI to become 100% blank and may be only miss the sources?

Comment 11

[Jim Blandy :jimb]

Seems like I should bump up the priority of bug 1575024, "Debugger should have a function to reset all current hooks/state", to make this easier to deal with.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c29ec6e0195d
Re-apply usage of .enable/.disable accidentally reverted in Bug 997119. r=jlast

Comment 13

[Logan Smyth [:loganfsmyth]]

I filed https://bugzilla.mozilla.org/show_bug.cgi?id=1589265 to track potential improvements so we don't crash so hard when a source is not in the store yet.

Comment 14

[Natalia Csoregi [:nataliaCs]]

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