1371868 - Timeout during session creation in Nightly build for 2017-06-09

Status: RESOLVED WORKSFORME

(Remote Protocol :: Marionette, defect)

Description

[Mike Pennisi [:jugglinmike]]

The Web Platform Tests project uses the Nightly build of Firefox in its
continuous integration system. As of 10:00 EST on Friday, June 9, all
continuous integration build jobs that rely on automating the Firefox web
browser began to time out. More information is available at [1], and an example
of a failing build can be found at [2].

Environment: Ubuntu 14.04 LTS Server Edition 64 bit [3]

[1] https://github.com/w3c/web-platform-tests/issues/6202
[2] https://travis-ci.org/w3c/web-platform-tests/builds/241383560
[3] https://docs.travis-ci.com/user/ci-environment/

Comment 1

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

So if that started on Friday the following Nightly build of Firefox should be related:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=f4262773c4331d4ae139be536ce278ea9aad3436&filter-searchStr=Firefox+&filter-tier=1&filter-tier=2&filter-tier=3

All the changes between June 8th and 9th:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=7efda263a842&tochange=f4262773c433

Comment 2

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

Oh, it would be great to get geckodriver tracing logs. So far the visible logs on Travis are not that helpful. And I cannot spot a bug which could have caused this.

Comment 3

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

Hm, maybe this is due to bug 1368264? But it hasn't been synced to upstream yet, or?

Comment 4

[Mike Pennisi [:jugglinmike]]

Judging from the latest builds on `master`, it looks like this was a hiccup
that was resolved in subsequent builds of Nightly. Ideally, I'd like to know
what went wrong and verify that a regression test is written, but I don't know
what the team prioritizes bugs on the Nightly channel. Do you typically label
reports like these "not a bug" and move on? Or would someone be willing to
follow up if I retrieved that information?

Comment 5

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

So, we can only act on issues when enough information is available. If the problem cannot be reproduced anymore, even not with the build you were using when reporting the bug, it will be very unlikely that a fix can be created. As I mentioned we miss details tracing logs, which could have given us the information we need.

Maybe try the affected build from June 9th again, and if it fails can we get a trace log created? Or is that not possible via Travis? 

I would close this bug for now as incomplete, but if you can provide the requested information, we can certainly have a look into it. But right now I don't see a way to investigate it. Sorry.

Comment 6

[Mike Pennisi [:jugglinmike]]

Attachment: 17.06.12-nightly-hang-177277376.log

I'm happy to collect the necessary information. I've created a branch on my fork
of the Web Platform Tests project that does the following:

- hard-codes the Nightly build published on 2017-06-09
- eliminates superfluous continuous integration jobs
- sets the GeckoDriver binary's "--log" option to "trace"
- prints the contents of `geckodriver.log` as the file changes

The resultant output is available at
https://travis-ci.org/jugglinmike/web-platform-tests/builds/242105240, and I'm
also attaching it here for posterity.

Comment 7

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

Fantastic information Mike!

Here the last lines from the log:

1497287647083	Marionette	TRACE	0 -> [0,2,"get",{"url":"https://web-platform.test:9003/resources/test/harness.html"}]
1497287647086	Marionette	DEBUG	Received DOM event "beforeunload" for "about:tabcrashed?e=tabcrashed&u=about%3Ablank&c=&f=regular&d=%20"
1497287647101	Marionette	DEBUG	Received DOM event "pagehide" for "about:tabcrashed?e=tabcrashed&u=about%3Ablank&c=&f=regular&d=%20"
1497287647101	Marionette	DEBUG	Received DOM event "unload" for "about:tabcrashed?e=tabcrashed&u=about%3Ablank&c=&f=regular&d=%20"
1497287647164	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "16"
[Parent 5833] WARNING: pipe error (73): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[Parent 5833] WARNING: pipe error (127): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353
[Parent 5833] WARNING: pipe error (125): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353

###!!! [Parent][MessageChannel] Error: (msgtype=0x280080,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv

1497287647459	Marionette	DEBUG	loaded listener.js
[Parent 5833] WARNING: waitpid failed pid:5996 errno:10: file /home/worker/workspace/build/src/ipc/chromium/src/base/process_util_posix.cc, line 276

So we started to load the `harness.html` file, which interestingly fires unload events for `about:tabcrashed`. It means we have a startup crash here which kills the content process. That reminds me on bug 1371319, which Andreas filed on Friday and which is also a startup crash on Linux. Maybe this is exactly the same - at least the timing would correlate perfectly.

Given that this is fixed now I wouldn't dive deeper into this issue. But I would advise you to keep running the latest nightly build if possible. That way we could find bugs which we might not see on our side.

Thanks for providing this helpful log!

Comment 8

[Mike Pennisi [:jugglinmike]]

Sounds good!