Closed Bug 1507121 Opened 6 years ago Closed 3 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(firefox-esr91 disabled, firefox94 disabled, firefox95 disabled, firefox96 fixed)

RESOLVED FIXED
96 Branch
Tracking Status
firefox-esr91 --- disabled
firefox94 --- disabled
firefox95 --- disabled
firefox96 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Filed by: ccoroiu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=211637913&repo=mozilla-central

https://queue.taskcluster.net/v1/task/AUwDe8zMSw-0Lb45Ixjgjg/runs/0/artifacts/public/logs/live_backing.log

[task 2018-11-14T11:10:34.683Z] 11:10:34     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py::test_valid[test:extension-value26] 
[task 2018-11-14T11:10:34.684Z] 11:10:34     INFO - PID 32452 | 1542193834681	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2018-11-14T11:10:35.240Z] 11:10:35     INFO - PID 32452 | 1542193835233	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: resource://pdf.js/
[task 2018-11-14T11:10:35.240Z] 11:10:35     INFO - PID 32452 | 1542193835234	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: about:reader*
[task 2018-11-14T11:10:35.430Z] 11:10:35     INFO - PID 32452 | 1542193835424	Marionette	DEBUG	Received observer notification profile-after-change
[task 2018-11-14T11:10:35.749Z] 11:10:35     INFO - PID 32452 | 1542193835744	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-11-14T11:10:35.749Z] 11:10:35     INFO - PID 32452 | 1542193835744	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-11-14T11:10:35.750Z] 11:10:35     INFO - PID 32452 | 1542193835744	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2018-11-14T11:10:36.331Z] 11:10:36     INFO - PID 32452 | 1542193836324	Marionette	DEBUG	Received observer notification toplevel-window-ready
[task 2018-11-14T11:10:39.930Z] 11:10:39     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_firstMatch.py | expected OK
[task 2018-11-14T11:10:39.930Z] 11:10:39     INFO - TEST-INFO took 185001ms
[task 2018-11-14T11:10:40.002Z] 11:10:40     INFO - Closing logging queue
[task 2018-11-14T11:10:40.002Z] 11:10:40     INFO - queue closed
[task 2018-11-14T11:10:40.003Z] 11:10:40     INFO - Starting runner
[task 2018-11-14T11:10:40.031Z] 11:10:40     INFO - PID 11593 | 1542193840026	webdriver::httpapi	DEBUG	Creating routes
[task 2018-11-14T11:10:40.039Z] 11:10:40     INFO - PID 11593 | 1542193840031	geckodriver	DEBUG	Listening on 127.0.0.1:4445
[task 2018-11-14T11:10:40.529Z] 11:10:40     INFO - WebDriver HTTP server listening at http://127.0.0.1:4445/
Even with an extended timeout set for this file it run into a timeout. Lets see how often it fails...
(In reply to Cristina Coroiu [:ccoroiu] from comment #8)
> This started to frequently fail after
> https://bugzilla.mozilla.org/show_bug.cgi?id=1418778 was disabled. 

This is also all about ccov, and as it looks like it would need to be disabled too. Christina, mind creating a similar patch for that test?
Flags: needinfo?(ccoroiu)
Assignee: nobody → ccoroiu
Flags: needinfo?(ccoroiu)
Attachment #9034931 - Flags: review?(jmaher)
Attachment #9034931 - Flags: review?(jmaher) → review+
Keywords: leave-open
Whiteboard: [stockwell disabled]
Pushed by dvarga@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d3d18e1a63e3
disable create_firstMatch.py on win ccov for frequently failing. r=whimboo

This bug should actually depend on the same bugs as the equivalent bug 1418778 which is for create_always_Match.py

Assignee: ccoroiu → nobody
Depends on: 1451621, 1460193, 1464756

The test got accidentally unskipped for ccov builds, and has been marked as skipped again via https://hg.mozilla.org/mozilla-central/rev/ab359d0369df.

Depends on: 1382162

There is a new kind of intermittent which came up over the last month on Linux, which all seem to be related to a delayed marionette-startup-requested notification as covered by bug 1577713.

Depends on: 1577713
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → DUPLICATE

No, this isn't a duplicate given that all the failures are not only about ccov or qr but also general shippable builds. This is basically the catch all for all remaining timeouts of that test.

Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Keywords: leave-open
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Flags: needinfo?(hskupin)

Andreea, please see those lines which appear a lot and cause shutdown delays:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293094870&repo=mozilla-beta&lineNumber=45266-45269

[task 2020-03-13T20:06:04.467Z] 20:06:04     INFO - PID 2948 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Value error: message was deserialized, but contained an illegal value
[task 2020-03-13T20:06:04.467Z] 20:06:04     INFO - PID 2948 | 
[task 2020-03-13T20:06:19.272Z] 20:06:19     INFO - PID 2948 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2020-03-13T20:06:21.606Z] 20:06:21     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/timeouts.py | expected OK

This looks very similar to bug 1545438 comment 27, which is an indexdb shutdown hang. See also bug 1478371 where I asked Andrew about it, but haven't gotten a reply yet.

It started to happen on 2020-03-04 which was the first 75b1 beta simulation? Any idea whom to ask beside Andrew for the indexdb bits?

Flags: needinfo?(hskupin) → needinfo?(bugmail)

Aryx can you answer the above?

Flags: needinfo?(aryx.bugmail)

Yes, this sounds like remote settings continuing to use IndexedDB late in the shutdown process is triggering the IndexedDB bug. We want to fix both things (Remote Settings and IndexedDB).

Flags: needinfo?(bugmail)
Flags: needinfo?(aryx.bugmail)

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #51)

Yes, this sounds like remote settings continuing to use IndexedDB late in the shutdown process is triggering the IndexedDB bug. We want to fix both things (Remote Settings and IndexedDB).

So you mean bug bug 1597312? What is the timeline for the fix? This is a perma failure for us on beta now. Are there any workarounds for now? Thanks.

Flags: needinfo?(bugmail)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #52)

So you mean bug bug 1597312? What is the timeline for the fix? This is a perma failure for us on beta now. Are there any workarounds for now? Thanks.

Can you provide a treeherder link filtered down to the thing that's permafailing? Permafail should make it very easy to fix.

Flags: needinfo?(bugmail)

For the March 9th regression please use bug 1623007 for classification. We should move all discussion over there.

Please ignore the above comment, those should be bug 1623007.

Depends on: 1418778
Assignee: nobody → hskupin
Status: REOPENED → RESOLVED
Closed: 5 years ago3 years ago
Resolution: --- → FIXED
Whiteboard: [stockwell disabled][stockwell needswork:owner] → [stockwell needswork:owner]
Target Milestone: --- → 96 Branch
See Also: → 1745514
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: