1113768 - mochitest-e10s-browser-chrome logs with failures on infra don't show all messages

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[:Gijs (he/him)]

cf. https://treeherder.mozilla.org/ui/logviewer.html#?repo=fx-team&job_id=1494921

The test is here:

http://mxr.mozilla.org/mozilla-central/source/browser/components/customizableui/test/browser_988072_sidebar_events.js

showSidebarPopup() calls subviewShown, here:

http://mxr.mozilla.org/mozilla-central/source/browser/components/customizableui/test/head.js#341

which rejects after 20 seconds, which will error out of the add_task() (promise rejections on promises yielded in a task will throw an error).

What's surprising to me is that either this will run more of the tests' tasks, or not, but either way, I would have expected more log messages in the above log file. In particular, if I make the test fail locally by commenting out the resolve() and the clearTimeout() from the panelshown handler, my log shows:

2 INFO TEST-START | browser/components/customizableui/test/browser_988072_sidebar_events.js
3 INFO Entering test 
4 INFO TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_988072_sidebar_events.js | Uncaught exception - Subview (PanelUI-sidebar) did not show within 20 seconds.
5 INFO Leaving test 
6 INFO Entering test 
7 INFO Check that a sidebar that uses a command event listener works

(after which I ctrl-c'd because now it'd wait for another 20 seconds, fail again, and probably keep going in that manner).

Comment 1

[Chris Manchester (limited bugmail, email directly)]

Attachment: Stop buffering a test's output after a failure is seen.

This disables output supression between when a failure is seen and that test ends. Is this closer to what you expect? If you pass '--quiet' to mach, logging locally will behave as it does in infrastructure.

Comment 2

[:Gijs (he/him)]

Comment on attachment 8539864 [details] [diff] [review]
Stop buffering a test's output after a failure is seen.

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

Yup, this restores log output, as far as I can tell.

Comment 3

[Nathan Froyd [:froydnj]]

Comment on attachment 8539864 [details] [diff] [review]
Stop buffering a test's output after a failure is seen.

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

The logic seems fine, but the details seem a little off.

::: testing/mochitest/runtests.py
@@ +124,5 @@
>          # Failures reporting, after the end of the tests execution
>          self.errors = []
>  
> +        # Output buffering is disabled between when a test fails and that test ends.
> +        self.disable_buffering = False

Isn't this just |!self.buffering|?  It seems wrong to have multiple mechanisms to control this.

Comment 4

[Nathan Froyd [:froydnj]]

I still don't understand what improves for Gijs's initial example with this change.  Gijs, can you please enlighten me with some log output?

Comment 5

[Chris Manchester (limited bugmail, email directly)]

(In reply to Nathan Froyd (:froydnj) from comment #3)
> Comment on attachment 8539864 [details] [diff] [review]
> Stop buffering a test's output after a failure is seen.
> 
> Review of attachment 8539864 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> The logic seems fine, but the details seem a little off.
> 
> ::: testing/mochitest/runtests.py
> @@ +124,5 @@
> >          # Failures reporting, after the end of the tests execution
> >          self.errors = []
> >  
> > +        # Output buffering is disabled between when a test fails and that test ends.
> > +        self.disable_buffering = False
> 
> Isn't this just |!self.buffering|?  It seems wrong to have multiple
> mechanisms to control this.

|self.buffering| is whether buffering was originally requested, but |self.disable_buffering| is true between when a test fails and that test ends, so to my eye we need to keep track of these separately to know whether to restore the buffering behavior at the end of the test.

Comment 6

[:Gijs (he/him)]

(In reply to Nathan Froyd (:froydnj) from comment #4)
> I still don't understand what improves for Gijs's initial example with this
> change.  Gijs, can you please enlighten me with some log output?

Before:

0 INFO *** Start BrowserChrome Test Results ***
1 INFO checking window state
2 INFO TEST-START | browser/components/customizableui/test/browser_988072_sidebar_events.js
3 INFO Entering test
4 INFO TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_988072_sidebar_events.js | Uncaught exception - Subview (PanelUI-sidebar) did not show within 20 seconds.
5 INFO TEST-OK | browser/components/customizableui/test/browser_988072_sidebar_events.js | took 20598ms
###!!! [Parent][MessageChannel] Error: Channel closing: too late to send/recv, messages will be lost
IPDL protocol error: Handler for PBackgroundTest returned error code
###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x120001,name=PBackground::Msg_PBackgroundTestConstructor) Processing error: message was deserialized, but the handler returned false (indicating failure)
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
TEST-INFO | Main app process: exit status 0

runtests.py | Application ran for: 0:00:24.526000
zombiecheck | Reading PID log: c:\users\gijs\appdata\local\temp\tmpd3mydgpidlog
Stopping web server
Stopping web socket server
Stopping ssltunnel
WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
runtests.py | Running tests: end.
6 INFO checking window state
7 INFO TEST-START | Shutdown
8 INFO Browser Chrome Test Summary
9 INFO Passed:  567
10 INFO Failed:  1
11 INFO Todo:    0
12 INFO *** End BrowserChrome Test Results ***
TEST-INFO | checking window state
Browser Chrome Test Summary
        Passed: 567
        Failed: 1
        Todo: 0
*** End BrowserChrome Test Results ***
The following tests failed:
13 INFO TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_988072_sidebar_events.js | Uncaught exception - Subview (PanelUI-sidebar) did not show within 20 seconds.
SUITE-END | took 26s

After:


0 INFO *** Start BrowserChrome Test Results ***
1 INFO checking window state
2 INFO TEST-START | browser/components/customizableui/test/browser_988072_sidebar_events.js
3 INFO Entering test
4 INFO TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_988072_sidebar_events.js | Uncaught exception - Subview (PanelUI-sidebar) did not show within 20 seconds.

<the first few messages get scrolled out of my Windows terminal, but basically, directly after that, message 5 will have been another TEST-PASS or TEST-INFO or whatever>

<snip>

622 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same checked attribute
623 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same label attribute
624 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same key attribute

625 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same disabled attribute
626 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same hidden attribute
627 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same origin attribute
628 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same image attribute
629 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the same checked attribute
630 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have the right element at the top
631 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have seen the right number of click events
632 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have seen the right number of command events
633 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have seen the right number of onclick events
634 INFO TEST-PASS | browser/components/customizableui/test/browser_988072_sidebar_events.js | Should have seen the right number of oncommand events
635 INFO Leaving test
636 INFO MEMORY STAT vsize after test: 476684288
637 INFO MEMORY STAT vsizeMaxContiguous after test: 1893662720
638 INFO MEMORY STAT residentFast after test: 124596224
639 INFO MEMORY STAT heapAllocated after test: 42563410
640 INFO TEST-OK | browser/components/customizableui/test/browser_988072_sidebar_events.js | took 20755ms
###!!! [Parent][MessageChannel] Error: Channel closing: too late to send/recv, messages will be lost
IPDL protocol error: Handler for PBackgroundTest returned error code
###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x120001,name=PBackground::Msg_PBackgroundTestConstructor) Processing error: message was deserialized, but the handler returned false (indicating failure)
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
TEST-INFO | Main app process: exit status 0

runtests.py | Application ran for: 0:00:24.627000
zombiecheck | Reading PID log: c:\users\gijs\appdata\local\temp\tmps3tjbcpidlog
Stopping web server
Stopping web socket server
Stopping ssltunnel
WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
runtests.py | Running tests: end.
641 INFO checking window state
642 INFO TEST-START | Shutdown
643 INFO Browser Chrome Test Summary
644 INFO Passed:  567
645 INFO Failed:  1
646 INFO Todo:    0
647 INFO *** End BrowserChrome Test Results ***
TEST-INFO | checking window state
Browser Chrome Test Summary
        Passed: 567
        Failed: 1
        Todo: 0
*** End BrowserChrome Test Results ***
The following tests failed:
648 INFO TEST-UNEXPECTED-FAIL | browser/components/customizableui/test/browser_988072_sidebar_events.js | Uncaught exception - Subview (PanelUI-sidebar) did not show within 20 seconds.
SUITE-END | took 27s

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Attachment: Stop buffering a test's output after a failure is seen.

This clarifies the situation somewhat.

Comment 8

[Nathan Froyd [:froydnj]]

Comment on attachment 8540403 [details] [diff] [review]
Stop buffering a test's output after a failure is seen.

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

Better, thank you!

::: testing/mochitest/runtests.py
@@ +196,5 @@
>              self.logger.log_raw(message)
> +        # If we don't do any buffering, or the tests haven't started, or the message was
> +        # unstructured, it is directly logged.
> +        # Buffering logic Also supports "raw" errors (in log messages) because some tests
> +        # manually dump 'TEST-UNEXPECTED-FAIL'

This comment needs a little tweaking: it dropped a semicolon along the way, and it doesn't flow with what comes before it.  Maybe something like "We also support 'raw' errors in log messages, because some tests manually log TEST-UNEXPECTED-FAIL.  Otherwise, we buffer the message." ?

@@ +200,5 @@
> +        # manually dump 'TEST-UNEXPECTED-FAIL'
> +        elif any([not self.buffering,
> +                  unstructured,
> +                  not self.tests_started,
> +                  message['action'] not in self.BUFFERED_ACTIONS]):

I approve of this |any| call.

Comment 9

[Chris Manchester (limited bugmail, email directly)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/507c50a68d58

Comment 10

[Chris Manchester (limited bugmail, email directly)]

I suppose it supports the effort, but the actual fix here is not e10s specific.

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/507c50a68d58