1723759 - Browsertime test fails if --verbose is passed

Status: NEW

(Testing :: Raptor, defect, P3)

Description

[Jon Coppeard (:jonco)]

Attachment: pass_log.txt

If I run browsertime like this, it appears to run but then fails with an error before printing the results:

MOZCONFIG=mozconfig-opt ./mach raptor --verbose --browsertime -t reddit --chimera --page-cycles 2 --browser-cycles 1 --post-startup-delay 1

There's a bunch of error lines (see attached logfile) the first of which says "Browsertime failed to run".

If I run without --verbose, it works as expected.

Comment 1

[Jon Coppeard (:jonco)]

Attachment: fail_log.txt

Comment 2

[Dave Hunt [:davehunt] [he/him] ⌚BST]

:kimberlythegeek could you see if you can replicate this locally?

:jonco it looks like your command line is truncated (it's missing the value for --post-startup-delay) is there anything else missing? Looking at the logs I see several failures in mozfile, mozsystemmonitor and possible in Marionette. We'll see if we can replicate.

Comment 3

[Jon Coppeard (:jonco)]

(In reply to Dave Hunt [:davehunt] [he/him] ⌚GMT from comment #2)
Sorry, I missed the last character. There was nothing else after this. I'll edit the description.

Comment 4

[Kimberly Sereduck :kimberlythegeek]

Attachment: browsertime.txt

This is the output I get when running that command (without MOZCONFIG)

Comment 5

[Jon Coppeard (:jonco)]

(In reply to Kimberly Sereduck :kimberlythegeek from comment #4)

This is the output I get when running that command (without MOZCONFIG)

Looks like this is failing in the same way for you then.

Comment 6

[Jon Coppeard (:jonco)]

Any luck tracking this down?

Comment 7

[Kimberly Sereduck :kimberlythegeek]

I ran on my linux machine and this was the traceback: https://gist.github.com/kimberlythegeek/321c627ceb77870561fa61f7b9eff86c

It completed without error.

I ran again on my macbook and received the same failure as before, in the attached file browsertime.txt

It looks like this may only affect OSX machines. What operating system are you running?

Comment 8

[Jon Coppeard (:jonco)]

This is happening on linux.

Comment 9

[Kimberly Sereduck :kimberlythegeek]

Can you provide your MOZCONFIG file?

Comment 10

[Jon Coppeard (:jonco)]

Attachment: mozconfig-opt

Here's my mozconfig.

Comment 11

[Kimberly Sereduck :kimberlythegeek]

thanks!

Comment 12

[Greg Mierzwinski [:sparky]]

This looks more like it may be an intermittent browsertime issue, not something within mozilla-central.

Here's the part it fails on from what I can tell:

14:51:51     INFO -  raptor-browsertime Info: [browsertime] Browsertime pageload ended.
14:51:51     INFO -  raptor-browsertime Info: b'1628002311829\twebdriver::server\tDEBUG\t-> DELETE /session/34bfabc8-9721-45b0-b1c9-d0f21c3f0512'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311829\tMarionette\tDEBUG\t0 -> [0,117,"Marionette:Quit",{"flags":["eForceQuit"]}]'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311829\tMarionette\tINFO\tStopped listening on port 43079'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311850\tMarionette\tTRACE\tReceived observer notification quit-application'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311850\tRemoteAgent\tDEBUG\tResetting recommended pref apz.content_response_timeout'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311850\tRemoteAgent\tDEBUG\tResetting recommended pref browser.contentblocking.introCount'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311850\tRemoteAgent\tDEBUG\tResetting recommended pref browser.download.panel.shown'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311850\tRemoteAgent\tDEBUG\tResetting recommended pref browser.newtabpage.enabled'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311851\tRemoteAgent\tDEBUG\tResetting recommended pref browser.search.update'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311851\tRemoteAgent\tDEBUG\tResetting recommended pref browser.tabs.disableBackgroundZombification'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311851\tRemoteAgent\tDEBUG\tResetting recommended pref browser.tabs.remote.separatePrivilegedContentProcess'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311852\tRemoteAgent\tDEBUG\tResetting recommended pref browser.tabs.warnOnCloseOtherTabs'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311852\tRemoteAgent\tDEBUG\tResetting recommended pref browser.tabs.warnOnOpen'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311852\tRemoteAgent\tDEBUG\tResetting recommended pref browser.toolbars.bookmarks.visibility'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311852\tRemoteAgent\tDEBUG\tResetting recommended pref browser.usedOnWindows10.introURL'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311852\tRemoteAgent\tDEBUG\tResetting recommended pref browser.urlbar.suggest.searches'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref dom.file.createInChild'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref extensions.getAddons.cache.enabled'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref network.http.prompt-temp-redirect'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref security.notification_enable_delay'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311854\tRemoteAgent\tDEBUG\tResetting recommended pref signon.autofillForms'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311856\tRemoteAgent\tDEBUG\tResetting recommended pref signon.rememberSignons'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311857\tRemoteAgent\tDEBUG\tResetting recommended pref browser.topsites.contile.enabled'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311857\tRemoteAgent\tDEBUG\tResetting recommended pref dom.disable_beforeunload'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311857\tMarionette\tTRACE\tReceived observer notification quit-application'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311858\tMarionette\tDEBUG\tMarionette stopped listening'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311859\tMarionette\tDEBUG\t0 <- [1,117,null,{"cause":"shutdown","forced":false}]'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311879\twebdriver::server\tDEBUG\tDeleting session'
14:51:51     INFO -  raptor-browsertime Info: b'JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311881\tMarionette\tDEBUG\t0 -> [0,118,"Marionette:Quit",{"flags":["eForceQuit"]}]'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311881\tMarionette\tDEBUG\t0 <- [1,118,{"error":"invalid session id","message":"WebDriver session does not exist, or is not active","stacktrace":"WebDriverEr ... ote/content/marionette/server.js:253:9\\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\\n"},null]'
14:51:51     INFO -  raptor-browsertime Info: b'1628002311883\tMarionette\tDEBUG\tClosed connection 0'
14:51:52     INFO -  raptor-browsertime Info: b''
14:51:52    ERROR -  raptor-browsertime Error: Browsertime failed to run
14:51:52     INFO -  raptor-browsertime Info: b''

Comment 13

[Kimberly Sereduck :kimberlythegeek]

I'm not so sure this is an intermittent. I built with the mozconfig :jonco provided and ran this command several times, it failed each time, with different tests. I tried removing some of the flags for the test command, as well as some of the mozconfig options, and without the mozconfig altogether.

Comment 14

[Greg Mierzwinski [:sparky]]

Ah interesting, have you had any luck with removing any of the flags and rebuilding or did they always fail?

One thing to note here is that we use artifact mode for most of our work whereas this mozconfig has firefox built locally.

Comment 15

[Kimberly Sereduck :kimberlythegeek]

No. I tried with and without --chimera (this is the only one I wasn't familiar with and the others seemed unlikely to cause a failure), and built without --disable-debug. It was taking quite a while (almost an hour) to build each time.

I ran against several browsertime tests as well. It consistently fails with --verbose and passes without it.

I don't really understand why that flag would cause a test to fail, since it's only add -vvv to the mach command

Comment 16

[Greg Mierzwinski [:sparky]]

Sounds like it's the local build that is causing the issue within browsertime or marionette. It looks like there may be a command being run in browsertime after the browser has shutdown or a race condition.