Debian 10 - dom/media/tests/crashtests/1185191.html | load failed: timed out waiting for reftest-wait to be removed
Categories
(Core :: WebRTC, defect, P5)
Tracking
()
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=263013661&repo=try
Full log: https://queue.taskcluster.net/v1/task/AMNYOHv4TCGqiDxlaIfgoQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/AMNYOHv4TCGqiDxlaIfgoQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
Platform: debian 10
Suite: crashtest
Context:
[task 2019-08-22T21:57:01.717Z] 21:57:01 INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T21:57:01.717Z] 21:57:01 INFO - REFTEST INFO | RESTORE PREFERENCE pref(media.getusermedia.insecure.enabled,false)
[task 2019-08-22T21:57:01.718Z] 21:57:01 INFO - REFTEST INFO | RESTORE PREFERENCE pref(media.devices.insecure.enabled,false)
[task 2019-08-22T21:57:01.718Z] 21:57:01 INFO - REFTEST INFO | RESTORE PREFERENCE pref(dom.disable_open_during_load,true)
[task 2019-08-22T21:57:01.720Z] 21:57:01 INFO - REFTEST INFO | RESTORE PREFERENCE pref(media.navigator.permission.disabled,false)
[task 2019-08-22T21:57:01.721Z] 21:57:01 INFO - REFTEST INFO | SET PREFERENCE pref(media.navigator.permission.disabled,true)
[task 2019-08-22T21:57:01.721Z] 21:57:01 INFO - REFTEST INFO | SET PREFERENCE pref(dom.disable_open_during_load,false)
[task 2019-08-22T21:57:01.722Z] 21:57:01 INFO - REFTEST INFO | SET PREFERENCE pref(media.devices.insecure.enabled,true)
[task 2019-08-22T21:57:01.722Z] 21:57:01 INFO - REFTEST INFO | SET PREFERENCE pref(media.getusermedia.insecure.enabled,true)
[task 2019-08-22T21:57:01.723Z] 21:57:01 INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html | 680 / 3795 (17%)
[task 2019-08-22T21:57:01.756Z] 21:57:01 INFO - Timecard created 1566511021.143405
[task 2019-08-22T21:57:01.757Z] 21:57:01 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:01.757Z] 21:57:01 INFO - ========================================================================================================
[task 2019-08-22T21:57:01.757Z] 21:57:01 INFO - 0.000024 | 0.000024 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - 0.000326 | 0.000302 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - 0.003907 | 0.003581 | Add Ice Candidate | PeerConnectionImpl.cpp:1506 | AddIceCandidate
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - 0.004248 | 0.000341 | Add Ice Candidate | PeerConnectionImpl.cpp:1506 | AddIceCandidate
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - 0.608957 | 0.604709 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 6a3cb9400b7deac0
[task 2019-08-22T21:57:01.758Z] 21:57:01 INFO - Timecard created 1566511021.189641
[task 2019-08-22T21:57:01.761Z] 21:57:01 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:01.762Z] 21:57:01 INFO - ========================================================================================================
[task 2019-08-22T21:57:01.762Z] 21:57:01 INFO - 0.000021 | 0.000021 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:01.762Z] 21:57:01 INFO - 0.000317 | 0.000296 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:01.763Z] 21:57:01 INFO - 0.562914 | 0.562597 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:01.764Z] 21:57:01 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 45de9ecc06b169db
[task 2019-08-22T21:57:01.764Z] 21:57:01 INFO - Timecard created 1566511021.348377
[task 2019-08-22T21:57:01.765Z] 21:57:01 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:01.766Z] 21:57:01 INFO - ========================================================================================================
[task 2019-08-22T21:57:01.766Z] 21:57:01 INFO - 0.000027 | 0.000027 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:01.766Z] 21:57:01 INFO - 0.000335 | 0.000308 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:01.767Z] 21:57:01 INFO - 0.003356 | 0.003021 | Add Ice Candidate | PeerConnectionImpl.cpp:1506 | AddIceCandidate
[task 2019-08-22T21:57:01.768Z] 21:57:01 INFO - 0.404339 | 0.400983 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:01.769Z] 21:57:01 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for ecf6f1bd2c4af7d8
[task 2019-08-22T21:57:05.847Z] 21:57:05 INFO - Timecard created 1566511021.494896
[task 2019-08-22T21:57:05.848Z] 21:57:05 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:05.848Z] 21:57:05 INFO - ========================================================================================================
[task 2019-08-22T21:57:05.849Z] 21:57:05 INFO - 0.000018 | 0.000018 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:05.849Z] 21:57:05 INFO - 0.000267 | 0.000249 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - 4.347241 | 4.346974 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 1e3ff513de1fb632
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - Timecard created 1566511021.490191
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - ========================================================================================================
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - 0.000029 | 0.000029 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:05.850Z] 21:57:05 INFO - 0.000351 | 0.000322 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:05.852Z] 21:57:05 INFO - 0.019039 | 0.018688 | Create Offer | PeerConnectionImpl.cpp:1202 | CreateOffer
[task 2019-08-22T21:57:05.852Z] 21:57:05 INFO - 0.019533 | 0.000494 | Set Local Description | PeerConnectionImpl.cpp:1263 | SetLocalDescription
[task 2019-08-22T21:57:05.852Z] 21:57:05 INFO - 4.352162 | 4.332629 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:05.853Z] 21:57:05 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 8df004bfc9a9eb05
[task 2019-08-22T21:57:05.854Z] 21:57:05 INFO - Timecard created 1566511021.606665
[task 2019-08-22T21:57:05.855Z] 21:57:05 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:05.855Z] 21:57:05 INFO - ========================================================================================================
[task 2019-08-22T21:57:05.856Z] 21:57:05 INFO - 0.000021 | 0.000021 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:05.856Z] 21:57:05 INFO - 0.000345 | 0.000324 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:05.856Z] 21:57:05 INFO - 4.235889 | 4.235544 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:05.856Z] 21:57:05 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 17e9f80dd982d3ef
[task 2019-08-22T21:57:05.859Z] 21:57:05 INFO - Timecard created 1566511021.663070
[task 2019-08-22T21:57:05.860Z] 21:57:05 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:05.860Z] 21:57:05 INFO - ========================================================================================================
[task 2019-08-22T21:57:05.861Z] 21:57:05 INFO - 0.000020 | 0.000020 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:05.863Z] 21:57:05 INFO - 0.000325 | 0.000305 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:05.863Z] 21:57:05 INFO - 0.027666 | 0.027341 | Create Offer | PeerConnectionImpl.cpp:1202 | CreateOffer
[task 2019-08-22T21:57:05.864Z] 21:57:05 INFO - 0.028130 | 0.000464 | Set Local Description | PeerConnectionImpl.cpp:1263 | SetLocalDescription
[task 2019-08-22T21:57:05.865Z] 21:57:05 INFO - 4.181060 | 4.152930 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:05.865Z] 21:57:05 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 63be06c2458b6aa9
[task 2019-08-22T21:57:05.866Z] 21:57:05 INFO - Timecard created 1566511021.665734
[task 2019-08-22T21:57:05.867Z] 21:57:05 INFO - Timestamp | Delta | Event | File | Function
[task 2019-08-22T21:57:05.867Z] 21:57:05 INFO - ========================================================================================================
[task 2019-08-22T21:57:05.867Z] 21:57:05 INFO - 0.000020 | 0.000020 | Constructor Completed | PeerConnectionImpl.cpp:331 | PeerConnectionImpl
[task 2019-08-22T21:57:05.867Z] 21:57:05 INFO - 0.000190 | 0.000170 | Initializing PC Ctx | PeerConnectionImpl.cpp:457 | Initialize
[task 2019-08-22T21:57:05.868Z] 21:57:05 INFO - 4.178583 | 4.178393 | Destructor Invoked | PeerConnectionImpl.cpp:340 | ~PeerConnectionImpl
[task 2019-08-22T21:57:05.868Z] 21:57:05 INFO - [Child 1094: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:365: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 7fb629b66dbb6bf4
[task 2019-08-22T21:57:05.868Z] 21:57:05 INFO - [Child 1094: Main Thread]: D/DataChannel 0x7f760afeb660: Close()ing 0x7f7609ebf040
[task 2019-08-22T21:57:31.616Z] 21:57:31 INFO - [Child 1094: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f760add6000
[task 2019-08-22T22:02:01.740Z] 22:02:01 INFO - REFTEST TEST-UNEXPECTED-FAIL | file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html | load failed: timed out waiting for reftest-wait to be removed
[task 2019-08-22T22:02:01.741Z] 22:02:01 INFO - REFTEST INFO | Saved log: START file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.742Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering WaitForTestEnd
[task 2019-08-22T22:02:01.743Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2019-08-22T22:02:01.744Z] 22:02:01 INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2019-08-22T22:02:01.745Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_TO_FIRE_INVALIDATE_EVENT
[task 2019-08-22T22:02:01.746Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: dispatching MozReftestInvalidate
[task 2019-08-22T22:02:01.747Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-08-22T22:02:01.747Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for reftest-wait to be removed
[task 2019-08-22T22:02:01.748Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.748Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.749Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.749Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] SendUpdateCanvasForEvent with 0 rects
[task 2019-08-22T22:02:01.750Z] 22:02:01 INFO - REFTEST INFO | Saved log: Updating canvas for invalidation
[task 2019-08-22T22:02:01.750Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-08-22T22:02:01.751Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for reftest-wait to be removed
[task 2019-08-22T22:02:01.751Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.752Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.752Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
[task 2019-08-22T22:02:01.752Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] SendUpdateCanvasForEvent with 1 rects
[task 2019-08-22T22:02:01.753Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] Rect: 0 0 800 1000
[task 2019-08-22T22:02:01.754Z] 22:02:01 INFO - REFTEST INFO | Saved log: Updating canvas for invalidation
[task 2019-08-22T22:02:01.754Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: STATE_WAITING_FOR_REFTEST_WAIT_REMOVAL
[task 2019-08-22T22:02:01.755Z] 22:02:01 INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress: waiting for reftest-wait to be removed
[task 2019-08-22T22:02:01.756Z] 22:02:01 INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/dom/media/tests/crashtests/1185191.html
|
||
Comment 1•6 years ago
|
||
:drno - this appears to be a new permanent failure that is observed on new debian 10 linux test image. For more information on the migration to debian 10 test image, please see https://bugzilla.mozilla.org/show_bug.cgi?id=1565332.
Would you be able to take a look, or redirect the ni to someone that may be able to do so? Would an adjustment of the expected outcome and/or skipping the test on debian 10 platforms be suitable?
|
|
||
Updated•6 years ago
|
|
|
||
Comment 2•6 years ago
|
||
This is possibly a duplicate of bug 1517583 but I will keep this open for the time being to deal with just Debian 10 failure.
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 4•6 years ago
|
||
After trying another approach to initialize pulseaudio (within the harness, using desktop_unittest.py) this test is now green, so it would seem the pulseaudio issues also affected this test.
|
|
||
Comment 5•6 years ago
|
||
I think this bug can be closed now, given that crashtest seems to be reliably green: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=e479951c9080e7a0006a4bfe2a3a7f95fd008bdf&selectedJob=265783881&searchStr=linux%2Cx64%2Copt%2Creftests%2Ctest-linux64%2Fopt-crashtest-e10s%2Cr%28c%29
|
||
Updated•5 years ago
|
Description
•