Intermittent TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media.js | application timed out after 370 seconds with no output
Categories
(Core :: WebRTC, defect, P5)
Tracking
()
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])
Attachments
(3 files)
Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=289194245&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IJBYL7IqQvaGHOxq_PQrCA/runs/0/artifacts/public/logs/live_backing.log
task 2020-02-17T09:58:50.933Z] 09:58:50 INFO - TEST-START | browser/base/content/test/webrtc/browser_devices_get_user_media.js
[task 2020-02-17T10:05:00.991Z] 10:05:00 INFO - Buffered messages logged at 09:58:50
[task 2020-02-17T10:05:00.992Z] 10:05:00 INFO - Entering test bound test
[task 2020-02-17T10:05:00.992Z] 10:05:00 INFO - Buffered messages finished
[task 2020-02-17T10:05:00.993Z] 10:05:00 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media.js | application timed out after 370 seconds with no output
[task 2020-02-17T10:05:00.994Z] 10:05:00 ERROR - Force-terminating active process(es).
[task 2020-02-17T10:05:00.994Z] 10:05:00 INFO - Determining child pids from psutil...
[task 2020-02-17T10:05:00.995Z] 10:05:00 INFO - [8707, 8731, 8788]
[task 2020-02-17T10:05:00.995Z] 10:05:00 INFO - ==> process 8654 launched child process 8680
[task 2020-02-17T10:05:00.995Z] 10:05:00 INFO - ==> process 8654 launched child process 8707
[task 2020-02-17T10:05:00.995Z] 10:05:00 INFO - ==> process 8654 launched child process 8731
[task 2020-02-17T10:05:00.996Z] 10:05:00 INFO - ==> process 8654 launched child process 8788
[task 2020-02-17T10:05:00.996Z] 10:05:00 INFO - Found child pids: set([8731, 8680, 8707, 8788])
[task 2020-02-17T10:05:00.996Z] 10:05:00 INFO - Failed to get child procs
[task 2020-02-17T10:05:00.996Z] 10:05:00 INFO - Killing process: 8731
[task 2020-02-17T10:05:00.997Z] 10:05:00 INFO - TEST-INFO | started process screentopng
[task 2020-02-17T10:05:01.260Z] 10:05:01 INFO - TEST-INFO | screentopng: exit 0
[task 2020-02-17T10:05:01.260Z] 10:05:01 INFO - Killing process: 8680
[task 2020-02-17T10:05:01.262Z] 10:05:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-02-17T10:05:01.264Z] 10:05:01 INFO - Can't trigger Breakpad, process no longer exists
[task 2020-02-17T10:05:01.265Z] 10:05:01 INFO - Killing process: 8707
[task 2020-02-17T10:05:01.265Z] 10:05:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-02-17T10:05:01.266Z] 10:05:01 INFO - Killing process: 8788
[task 2020-02-17T10:05:01.266Z] 10:05:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-02-17T10:05:01.267Z] 10:05:01 INFO - Killing process: 8654
[task 2020-02-17T10:05:01.267Z] 10:05:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-02-17T10:05:01.405Z] 10:05:01 INFO - psutil found pid 8654 dead
[task 2020-02-17T10:05:01.453Z] 10:05:01 WARNING - runtests.py | Failed to get app exit code - running/crashed?
[task 2020-02-17T10:05:01.453Z] 10:05:01 INFO - TEST-INFO | Main app process: exit 0
[task 2020-02-17T10:05:01.453Z] 10:05:01 INFO - runtests.py | Application ran for: 0:06:24.377318
[task 2020-02-17T10:05:01.454Z] 10:05:01 INFO - zombiecheck | Reading PID log: /tmp/tmpgSKxs4pidlog
[task 2020-02-17T10:05:01.454Z] 10:05:01 INFO - ==> process 8654 launched child process 8680
[task 2020-02-17T10:05:01.454Z] 10:05:01 INFO - ==> process 8654 launched child process 8707
[task 2020-02-17T10:05:01.454Z] 10:05:01 INFO - ==> process 8654 launched child process 8731
[task 2020-02-17T10:05:01.455Z] 10:05:01 INFO - ==> process 8654 launched child process 8788
[task 2020-02-17T10:05:01.455Z] 10:05:01 INFO - zombiecheck | Checking for orphan process with PID: 8680
[task 2020-02-17T10:05:01.455Z] 10:05:01 INFO - zombiecheck | Checking for orphan process with PID: 8731
[task 2020-02-17T10:05:01.455Z] 10:05:01 INFO - zombiecheck | Checking for orphan process with PID: 8707
[task 2020-02-17T10:05:01.456Z] 10:05:01 INFO - zombiecheck | Checking for orphan process with PID: 8788
[task 2020-02-17T10:05:01.456Z] 10:05:01 INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aoxy8r-tSkK_cSlQ9eVtmA/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-02-17T10:05:07.130Z] 10:05:07 INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpOs9lVO.mozrunner/minidumps/3fb7f698-eb9e-f03c-9f69-4300f204bd1d.dmp /tmp/tmpoPm0kM
[task 2020-02-17T10:05:12.521Z] 10:05:12 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/3fb7f698-eb9e-f03c-9f69-4300f204bd1d.dmp
Comment 1•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 2•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 4•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 5•4 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 8•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 9•4 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=308841967&repo=autoland&lineNumber=2846
Comment hidden (Intermittent Failures Robot) |
Comment hidden (obsolete) |
Comment hidden (me-too) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (obsolete) |
Comment hidden (me-too) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 23•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 24•3 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=356592985&repo=autoland&lineNumber=3286
Comment 25•3 years ago
|
||
Update:
There have been 39 failures since the bug has been reopened:
- 5 failures on Linux 18.04 x64 WebRender asan opt
- 15 failures on Linux 18.04 x64 WebRender opt
- 19 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=357061578&repo=mozilla-central&lineNumber=4179
[task 2021-11-04T22:22:43.361Z] 22:22:43 INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media.js | expected audio to be shared - {"audio":true} deepEqual {"audio":true} -
[task 2021-11-04T22:22:43.362Z] 22:22:43 INFO - closing the stream
[task 2021-11-04T22:22:43.363Z] 22:22:43 INFO - Buffered messages finished
[task 2021-11-04T22:22:43.364Z] 22:22:43 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media.js | application timed out after 370 seconds with no output
[task 2021-11-04T22:22:43.365Z] 22:22:43 ERROR - Force-terminating active process(es).
[task 2021-11-04T22:22:43.365Z] 22:22:43 INFO - Determining child pids from psutil...
[task 2021-11-04T22:22:43.370Z] 22:22:43 INFO - [2772, 2789, 2837, 2876, 2895, 2933]
[task 2021-11-04T22:22:43.370Z] 22:22:43 INFO - ==> process 2697 launched child process 2713
[task 2021-11-04T22:22:43.371Z] 22:22:43 INFO - ==> process 2697 launched child process 2772
[task 2021-11-04T22:22:43.371Z] 22:22:43 INFO - ==> process 2697 launched child process 2789
[task 2021-11-04T22:22:43.372Z] 22:22:43 INFO - ==> process 2697 launched child process 2837
[task 2021-11-04T22:22:43.373Z] 22:22:43 INFO - ==> process 2697 launched child process 2876
[task 2021-11-04T22:22:43.373Z] 22:22:43 INFO - ==> process 2697 launched child process 2895
[task 2021-11-04T22:22:43.374Z] 22:22:43 INFO - ==> process 2697 launched child process 2933
[task 2021-11-04T22:22:43.374Z] 22:22:43 INFO - Found child pids: {2789, 2895, 2772, 2837, 2933, 2713, 2876}
[task 2021-11-04T22:22:43.375Z] 22:22:43 INFO - Failed to get child procs
[task 2021-11-04T22:22:43.375Z] 22:22:43 INFO - Killing process: 2789
[task 2021-11-04T22:22:43.375Z] 22:22:43 INFO - TEST-INFO | started process screentopng
[task 2021-11-04T22:22:43.602Z] 22:22:43 INFO - TEST-INFO | screentopng: exit 0
Michael, as the owner of this component, could you help us assign this to someone?
Thank you.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 28•3 years ago
|
||
This is most likely a duplicate of Bug 1738787, which currently working on. I'll hold off making that connection official until I can get a fix landed and we'll see if this bug resolves.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 31•3 years ago
|
||
There have been 51 failures in the last 7 days:
- 3 failures on linux1804-64-asan-qr opt
- 28 failures on linux1804-64-qr opt
- 20 failures on linux1804-64-shippable-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=358676374&repo=mozilla-central&lineNumber=3853
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment 33•3 years ago
|
||
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 35•3 years ago
|
||
Hi Michael, can we land the disabling patch or should the patch in 1738787 get landed?
Comment hidden (Intermittent Failures Robot) |
Comment 37•3 years ago
|
||
Sorry - I haven't gotten through my backlog from Thanksgiving yet. I'll land the patch in 1738787 later today or tomorrow. Let's see if that does indeed help.
Updated•3 years ago
|
Comment 38•3 years ago
|
||
Michael, the failure rate hasn't changed since the patches in Bug 1738787 landed, could you please take another look?
Comment 39•3 years ago
•
|
||
Update:
There have been 41 failures within the last 7 days, more than half of them are after the patch in Bug 1738787 landed:
• 1 failures on Linux 18.04 x64 WebRender asan opt
• 20 failures on Linux 18.04 x64 WebRender opt
• 20 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=360190987&repo=mozilla-central&lineNumber=4251
[task 2021-12-04T23:42:49.862Z] 23:42:49 INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media.js | expected video and audio to be shared - {"video":true,"audio":true} deepEqual {"video":true,"audio":true} -
[task 2021-12-04T23:42:49.863Z] 23:42:49 INFO - closing the stream
[task 2021-12-04T23:42:49.863Z] 23:42:49 INFO - Buffered messages finished
[task 2021-12-04T23:42:49.864Z] 23:42:49 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/webrtc/browser_devices_get_user_media.js | application timed out after 370 seconds with no output
[task 2021-12-04T23:42:49.865Z] 23:42:49 ERROR - Force-terminating active process(es).
[task 2021-12-04T23:42:49.866Z] 23:42:49 INFO - Determining child pids from psutil...
[task 2021-12-04T23:42:49.866Z] 23:42:49 INFO - [4739, 4760, 4853, 4895, 4928]
[task 2021-12-04T23:42:49.867Z] 23:42:49 INFO - ==> process 4667 launched child process 4687
[task 2021-12-04T23:42:49.867Z] 23:42:49 INFO - ==> process 4667 launched child process 4739
[task 2021-12-04T23:42:49.868Z] 23:42:49 INFO - ==> process 4667 launched child process 4760
[task 2021-12-04T23:42:49.869Z] 23:42:49 INFO - ==> process 4667 launched child process 4853
[task 2021-12-04T23:42:49.871Z] 23:42:49 INFO - ==> process 4667 launched child process 4895
[task 2021-12-04T23:42:49.871Z] 23:42:49 INFO - ==> process 4667 launched child process 4928
[task 2021-12-04T23:42:49.872Z] 23:42:49 INFO - Found child pids: {4928, 4739, 4687, 4853, 4760, 4895}
[task 2021-12-04T23:42:49.873Z] 23:42:49 INFO - Failed to get child procs
[task 2021-12-04T23:42:49.873Z] 23:42:49 INFO - Killing process: 4928
[task 2021-12-04T23:42:49.876Z] 23:42:49 INFO - TEST-INFO | started process screentopng
[task 2021-12-04T23:42:50.028Z] 23:42:50 INFO - TEST-INFO | screentopng: exit 0
[task 2021-12-04T23:42:50.029Z] 23:42:50 INFO - Killing process: 4739
[task 2021-12-04T23:42:50.029Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.029Z] 23:42:50 INFO - Killing process: 4687
[task 2021-12-04T23:42:50.030Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.030Z] 23:42:50 INFO - Can't trigger Breakpad, process no longer exists
[task 2021-12-04T23:42:50.030Z] 23:42:50 INFO - Killing process: 4853
[task 2021-12-04T23:42:50.031Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.031Z] 23:42:50 INFO - Killing process: 4760
[task 2021-12-04T23:42:50.031Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.032Z] 23:42:50 INFO - Killing process: 4895
[task 2021-12-04T23:42:50.032Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.032Z] 23:42:50 INFO - Killing process: 4667
[task 2021-12-04T23:42:50.033Z] 23:42:50 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-04T23:42:50.207Z] 23:42:50 INFO - psutil found pid 4667 dead
[task 2021-12-04T23:42:50.211Z] 23:42:50 INFO - TEST-INFO | Main app process: exit 0
[task 2021-12-04T23:42:50.211Z] 23:42:50 INFO - runtests.py | Application ran for: 0:06:17.243452
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Updated•3 years ago
|
Comment 41•3 years ago
|
||
Comment 42•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment 44•3 years ago
|
||
Comment 45•3 years ago
|
||
Comment 46•3 years ago
|
||
bugherder |
Comment 47•3 years ago
|
||
Andrew, this test was disabled 5 days ago on Linux64 but somehow its still failing on it. I
m not sure why, can you please take a look?
Comment 48•3 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 51•3 years ago
|
||
Comment 52•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 62•2 years ago
|
||
I have a number of fixes to the webrtc frontend tests lined up in various bugs, but this issue remains.
The crashing frame varies wildly but the stack seems consistent:
[task 2023-02-20T12:57:40.495Z] 12:57:40 INFO - Thread 0 firefox-bin (crashed)
[task 2023-02-20T12:57:40.508Z] 12:57:40 INFO - 1 libxul.so!nsWindow::ReleaseGdkWindow() [nsWindow.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 5770 + 0x7]
[task 2023-02-20T12:57:40.512Z] 12:57:40 INFO - 2 libxul.so!nsWindow::OnUnrealize() [nsWindow.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 4124 + 0x7]
[task 2023-02-20T12:57:40.518Z] 12:57:40 INFO - 3 libxul.so!widget_unrealize_cb(_GtkWidget*) [nsWindow.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 7887 + 0x7]
[task 2023-02-20T12:57:40.525Z] 12:57:40 INFO - 4 libgobject-2.0.so.0!g_closure_invoke [gclosure.c : 804 + 0x17]
[task 2023-02-20T12:57:40.531Z] 12:57:40 INFO - 5 libgobject-2.0.so.0!signal_emit_unlocked_R [gsignal.c : 3636 + 0x4]
[task 2023-02-20T12:57:40.538Z] 12:57:40 INFO - 6 libgobject-2.0.so.0!g_signal_emit_valist [gsignal.c : 3392 + 0x1d]
[task 2023-02-20T12:57:40.545Z] 12:57:40 INFO - 7 libgobject-2.0.so.0!g_signal_emit [gsignal.c : 3448 + 0x4]
(...)
[task 2023-02-20T12:57:40.571Z] 12:57:40 INFO - 13 libgobject-2.0.so.0!g_closure_invoke [gclosure.c : 804 + 0x17]
[task 2023-02-20T12:57:40.574Z] 12:57:40 INFO - 14 libgobject-2.0.so.0!signal_emit_unlocked_R [gsignal.c : 3674 + 0x7]
[task 2023-02-20T12:57:40.581Z] 12:57:40 INFO - 15 libgobject-2.0.so.0!g_signal_emit_valist [gsignal.c : 3392 + 0x1d]
[task 2023-02-20T12:57:40.584Z] 12:57:40 INFO - 16 libgobject-2.0.so.0!g_signal_emit [gsignal.c : 3448 + 0x4]
(...)
[task 2023-02-20T12:57:40.592Z] 12:57:40 INFO - 20 libgobject-2.0.so.0!g_object_run_dispose [gobject.c : 1102 + 0x8]
[task 2023-02-20T12:57:40.594Z] 12:57:40 INFO - 21 libxul.so!nsWindow::Destroy() [nsWindow.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 659 + 0xc]
(...)
[task 2023-02-20T12:57:40.603Z] 12:57:40 INFO - 28 libxul.so!mozilla::AppWindow::Destroy() [AppWindow.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 646 + 0x5]
[task 2023-02-20T12:57:40.604Z] 12:57:40 INFO - 29 libxul.so!nsChromeTreeOwner::Destroy() [nsChromeTreeOwner.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 257]
[task 2023-02-20T12:57:40.605Z] 12:57:40 INFO - 30 libxul.so!{virtual override thunk({offset(-8)}, nsChromeTreeOwner::Destroy())} [nsChromeTreeOwner.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 0 + 0xd]
[task 2023-02-20T12:57:40.607Z] 12:57:40 INFO - 31 libxul.so!nsGlobalWindowOuter::ReallyCloseWindow() [nsGlobalWindowOuter.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 6211 + 0x8]
[task 2023-02-20T12:57:40.608Z] 12:57:40 INFO - 32 libxul.so!nsCloseEvent::Run() [nsGlobalWindowOuter.cpp:985043f4d1b57b0df23ea812753f2e7b6a80d47d : 6012 + 0x4]
Martin, does this tell you anything?
Comment 63•2 years ago
|
||
It's a crash in nsWindow::DestroyChildWindows() / get_window_for_gdk_window() where we iterate through embedded child windows and delete them and looks like a child window is already deleted.
This is very rarely used, I think it's used in the testsuite only. May be worth to run with MOZ_LOG="Widget:5 WidgetPopup:5" env variables and log how the windows are deleted to see what's going on.
Comment 64•2 years ago
|
||
I can try that locally on Ubuntu 18.04 - how can run such setup here? I don't see such crash when I just run
./mach mochitest browser/base/content/test/webrtc/browser_devices_get_user_media.js
./mach mochitest browser/base/content/test/webrtc
Comment 65•2 years ago
|
||
It might be hard to catch locally. I haven't tried myself. But to mimic that try push in comment 62, do this:
hg pull -r a544d51c6334ff121217fce897de2cbc21bb1059 try
hg up tip
./mach build
./mach test browser/base/content/test/webrtc/browser_devices_get_user_media.js --verify
Seems like you're better off with a non-debug config.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 68•19 days ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Updated•17 days ago
|
Description
•