964318 - Global console listener tries to handle all console messages and causes a disconnect of the application when loading web pages with lots of errors and warnings

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[mario garbi]

Attachment: Minimized.js

With the latest mozmill from github (master branch) we seem to get stuck loading the remote webpage until we hit the timeout after which mozmill is unable to close the client for whatever reasons. There are no modal windows involved here, unlike in bug 962514.

I have tried using other remote pages both existent and nonexistent but we only seem to get this freeze when using a nonexistent page of AMO. Loading an existent AMO page takes much longer than expected (5-10 sec) but doesn't cause a failure.

I have attached a minimized case that reproduces the failure 10/10 times on Linux with latest mozmill 2.0.3 from github.

Comment 1

[mario garbi]

I am still investigating why this happens and will provide more info as I find it.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

On master we do not have Mozmill 2.0.3. It is 2.1-dev. But anyway, we will have to check if this should block 2.0.4 given that it seems to be a regression from the 2.0.3 release.

Comment 3

[mario garbi]

So far we've only been able to reproduce this when opening addons.mozilla.org and only with the 2.1-dev. This is also reproducible by opening the Firefox client with mozmill -b and pasting the URL in the url bar directly, therefore not using controller.open. This might be caused by a preference that we set when we open the client with mozmill but I will continue the investigation and come with more accurate results.

Comment 4

[Andrei Eftimie]

Indeed I see a freeze of 10-15 secs while opening http://addons.mozilla.org from mozmill with --manual. During this time Firefox is completely unresponsive. Something is blocking the main thread.

This does not happen with a normal Firefox session.

This is the regressor in mozmill:
https://github.com/mozilla/mozmill/commit/d9100a5dd0bcc756543f510b3d0bd251904f2897

More specifically this made the error reporting work.

However, this freeze that we are seeing is because we are trying to match _every_ exception.
This includes all sorts of `JavaScript Warning` which refer to the actual content of the page.
This shows JS and CSS warnings.

For every such `warning` we have a detailed description that includes the whole minimised CSS file for the page.

I've dumped all messages. We have around 600 warnings, each once includes the whole CSS of the addons.mozilla.org page. And we try to match() these based on our regular expressions.

In total these amount to 17MB of data.
This is blocking the thread.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This is indeed blocking our 2.0.4 release. Andrei, could you have a look at it? As you say we should not catch all of them but only care about errors and exceptions on the chrome side. Most likely it is so intensive because we are creating the Regex for each message now. Can you move this up the chain so both regexes are getting defined only once? I would think this should help.

Comment 6

[Andrei Eftimie]

Sure.

As you said, we should only get the chrome errors and not concern ourselves at all with CSS warnings.

I'm not sure that creating the regexes only once will help. The problem is they try to parse 17MB of data (out of which 16.8MB is really out of scope for us)

Comment 7

[Andrei Eftimie]

ATM we are using Services.console to check errors:
https://developer.mozilla.org/en-US/docs/XPCOM_Interface_Reference/nsIConsoleService

Which is deprecated:
> The Error Console is deprecated in Firefox, and is now only made available if you set the devtools.
> errorconsole.enabled preference to true. Use the Web Console instead, for web content, or the 
> Browser Console for chrome content.

Since its split into 2 distinct parts, one for web and the other for chrome messages, it might be worth it to use the newer Browser Console. That way we should exclude all irrelevant Web messages and should make our lives easier.

I'm checking this avenue now.

Comment 8

[Andrei Eftimie]

Well, the Browser console actually logs EVERYTHING: chrome + content (from all tabs) and there doesn't seem to be any easy way of turning off content logging. So this might not help us after all.

There have been avenues from separating messages between chrome and content in the old logger, most notable: bug 593540. But none has finished/shipped.

There is bug 860705 to remove content messages from the Browser console, but no work has been done there.

=====

Disappointed that we can't filter the messages properly.
I'll work on optimising what we have now.

Comment 9

[Andrei Eftimie]

Some data points:

While loading http://addons.mozilla.org

We try to match 124 js warnings, each takes about 190ms, which brings the total to about 23 seconds. None of these match because they are only js warnings (and we don't care about them).

Lets bring this number down.

Comment 10

[Andrei Eftimie]

Attachment: 0001-Bug-964318-Discard-unwanted-messages-from-the-consol.patch

String operations are way faster then regular expressions.

To fix this issue we filter out all content messages we don't care about before hitting the regex match().

I've seen both `[JavaScript Warning ...]` and `[JavaScript Error ...]`
This filters both out.

Instead of 190ms each step now takes about 2ms.
Both the testcase and GreeLarry.js are passing.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8367258 [details] [diff] [review]
0001-Bug-964318-Discard-unwanted-messages-from-the-consol.patch

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

This would drop any kind of Javascript error and warning. Even for chrome and specifically for mozmill and jsbridge. An example is:

[JavaScript Error: "missing ; before statement" {file: "resource://mozmill/stdlib/utils.js" line: 15 column: 5 source: "cost Cu = Components.utils;
"}]

So when I move out the declaration of errorRegEx and make it a constant outside of the ConsoleObserver the page load for AMO works wonderful and no further hang is visible. I'm not sure why you aren't seeing this. Can you please show me what you had when you did this test?

Also we need a Mutt test for this specific case.

Comment 12

[Andrei Eftimie]

Attachment: 0001-Bug-964318-Discard-unwanted-messages-from-the-consol.patch

Updated patch.

Thanks Henrik for the input.
This fixes the problem without breaking our error reporting.

This is still missing a mutt test.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8367298 [details] [diff] [review]
0001-Bug-964318-Discard-unwanted-messages-from-the-consol.patch

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

::: mozmill/mozmill/extension/components/handlers.js
@@ +64,5 @@
>    observe: function (aSubject, aTopic, aData) {
>      var msg = aSubject.message;
>  
> +    if (msg.contains('chrome') || msg.contains('resource') ||
> +        msg.contains('mozmill') || msg.contains('jsbridge')) {

It's better to start with mozmill and jsbridge. Also keep in mind that we only want to raise a critical framework issue for errors or exceptions. Further you should check again how those checks have to be combined. You cannot do 'or' on all of them.

Comment 14

[Andrei Eftimie]

> It's better to start with mozmill and jsbridge.
Sure np.

> Also keep in mind that we
> only want to raise a critical framework issue for errors or exceptions.
Great.
What does this have to do with this pre-filtering? We still have both regular expressions down the flow.

> Further you should check again how those checks have to be combined. You
> cannot do 'or' on all of them.
If we don't have any of these 4 strings in the message, we do not pass it further to the regexp matching. I don't understand what combination you are thinking of...

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Andrei Eftimie from comment #14)
> > Also keep in mind that we
> > only want to raise a critical framework issue for errors or exceptions.
> Great.
> What does this have to do with this pre-filtering? We still have both
> regular expressions down the flow.

I don't see a reason why we have to filter more than once on the same conditions. 

> > Further you should check again how those checks have to be combined. You
> > cannot do 'or' on all of them.
> If we don't have any of these 4 strings in the message, we do not pass it
> further to the regexp matching. I don't understand what combination you are
> thinking of...

No, that's not what you are testing here. If the chrome check above passes the remaining conditions are obsolete and will not play into this whole condition anymore. So if any other add-on or even Firefox itself puts an entry into the console which contains 'chrome' the if block will be entered.

Comment 16

[Andrei Eftimie]

(In reply to Henrik Skupin (:whimboo) from comment #15)
> (In reply to Andrei Eftimie from comment #14)
> > > Also keep in mind that we
> > > only want to raise a critical framework issue for errors or exceptions.
> > Great.
> > What does this have to do with this pre-filtering? We still have both
> > regular expressions down the flow.
> 
> I don't see a reason why we have to filter more than once on the same
> conditions. 
> 
> > > Further you should check again how those checks have to be combined. You
> > > cannot do 'or' on all of them.
> > If we don't have any of these 4 strings in the message, we do not pass it
> > further to the regexp matching. I don't understand what combination you are
> > thinking of...
> 
> No, that's not what you are testing here. If the chrome check above passes
> the remaining conditions are obsolete and will not play into this whole
> condition anymore. So if any other add-on or even Firefox itself puts an
> entry into the console which contains 'chrome' the if block will be entered.

Yes, so why not keep the more structured regexp test _when_ its needed.
We filter out most (maybe all) unwanted messages. with a simple and fast method. Doesn't have to be perfect. 

The more expensive method gets called fewer times, but ensures that the messages comply to what we look for.

I don't see why we should try cramming the regex into an overly complicated if-branch maze.

Or maybe I misunderstand what you want here.

Comment 17

[Andrei Eftimie]

Attachment: 3.patch

This might not be polished as it should.
Remote test now based on the testcase from this bug.
We have a python test that asserts that both tests from the JS file pass.
The 2nd one should not pass when we timeout.

I haven't had time to test this thoroughly.

Comment 18

[Andrei Eftimie]

Attachment: 3.patch

Uploaded the old patch by mistake.
This is the good one.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8367429 [details] [diff] [review]
3.patch

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

Andrei, I hope you don't mind when I update the patch so we can get it landed today.

::: mozmill/mozmill/extension/components/handlers.js
@@ +64,5 @@
>    observe: function (aSubject, aTopic, aData) {
>      var msg = aSubject.message;
>  
> +    if (msg.contains('mozmill') || msg.contains('jsbridge') ||
> +        msg.contains('chrome') || msg.contains('resource')) {

I think we should return early here as nesting the following code deeper.

Also if we would exclude everything which is not related to mozmill and jsbridge, we wouldn't have to test for this again in the regex. But yes, I agree that we can leave the remaining parts in the regex.

::: mutt/mutt/tests/python/test_logged_messages.py
@@ +7,5 @@
> +
> +import mozmill
> +
> +class TestFrameworkFailure(unittest.TestCase):
> +    def test_logged_messages(self):

This test should be part of the test_console_errors.py file.

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Patch (updated)

This is an update to Andrei's patch which works the same way, and keeps most of formerly existent code around. I think it is totally enough to check for mozmill and jsbridge only first. There is no need for chrome and resource.

Comment 21

[Andrei Eftimie]

Comment on attachment 8367574 [details] [diff] [review]
Patch (updated)

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

Works fine.

Comment 22

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8367574 [details] [diff] [review]
Patch (updated)

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

Flipping over to Andrew given that Dave is not around.

Comment 23

[Andrew Halberstadt [:ahal]]

Comment on attachment 8367574 [details] [diff] [review]
Patch (updated)

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

Looks fine to me, though lacking a bit of context.

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://github.com/mozilla/mozmill/commit/80d34c988cb47ea41794396e68df8258e0a350c6 (master)
https://github.com/mozilla/mozmill/commit/e3d95870b9887de9c5e60ab74c84b220ecf4e4a3 (hotfix-2.0)