Closed Bug 1432025 Opened 7 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | dom/media/tests/mochitest/test_peerConnection_transceivers.html | application timed out after 370 seconds with no output

Categories

(Core :: WebRTC, defect, P2)

defect

Tracking

()

RESOLVED FIXED

People

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

References

(Depends on 1 open bug)

Details

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

Attachments

(2 files)

Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=157607000&repo=autoland https://queue.taskcluster.net/v1/task/eAt8CottSLONb78jAISAFg/runs/0/artifacts/public/logs/live_backing.log [task 2018-01-21T11:54:53.473Z] 11:54:53 INFO - Call getUserMedia for {"audio":{"autoGainControl":false,"echoCancellation":false,"noiseSuppression":false},"video":true} [task 2018-01-21T11:54:53.474Z] 11:54:53 INFO - Buffered messages logged at 11:48:27 [task 2018-01-21T11:54:53.475Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | One audio track shall be present [task 2018-01-21T11:54:53.476Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track kind should be audio [task 2018-01-21T11:54:53.477Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track id should be defined [task 2018-01-21T11:54:53.478Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track should not be muted [task 2018-01-21T11:54:53.479Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | One video track shall be present [task 2018-01-21T11:54:53.480Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track kind should be video [task 2018-01-21T11:54:53.481Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track id should be defined [task 2018-01-21T11:54:53.482Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | Track should not be muted [task 2018-01-21T11:54:53.483Z] 11:54:53 INFO - Waiting for ICE connected... [task 2018-01-21T11:54:53.484Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:0 1 UDP 2122252543 172.17.0.4 36323 typ host","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.485Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:1 1 TCP 2105524479 172.17.0.4 9 typ host tcptype active","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.486Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:0 2 UDP 2122252542 172.17.0.4 50431 typ host","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.487Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:1 2 TCP 2105524478 172.17.0.4 9 typ host tcptype active","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.488Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.489Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:0 1 UDP 2122252543 172.17.0.4 53959 typ host","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.490Z] 11:54:53 INFO - Adding ICE candidate: {"candidate":"candidate:1 1 TCP 2105524479 172.17.0.4 9 typ host tcptype active","sdpMid":"sdparta_0","sdpMLineIndex":0} [task 2018-01-21T11:54:53.491Z] 11:54:53 INFO - Buffered messages logged at 11:48:28 [task 2018-01-21T11:54:53.491Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.493Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | ICE connected [task 2018-01-21T11:54:53.494Z] 11:54:53 INFO - Waiting for ICE connected... [task 2018-01-21T11:54:53.495Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | ICE connected [task 2018-01-21T11:54:53.495Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.496Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.497Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.498Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.499Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should be muted after onmute [task 2018-01-21T11:54:53.500Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should be muted after onmute [task 2018-01-21T11:54:53.501Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should be muted after onmute [task 2018-01-21T11:54:53.502Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should be muted after onmute [task 2018-01-21T11:54:53.503Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.504Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.505Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.506Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.507Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.508Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.509Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.509Z] 11:54:53 INFO - Buffered messages logged at 11:48:29 [task 2018-01-21T11:54:53.510Z] 11:54:53 INFO - Adding ICE candidate: null [task 2018-01-21T11:54:53.511Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.512Z] 11:54:53 INFO - TEST-PASS | dom/media/tests/mochitest/test_peerConnection_transceivers.html | track should not be muted after onunmute [task 2018-01-21T11:54:53.513Z] 11:54:53 INFO - TEST-FAIL | dom/media/tests/mochitest/test_peerConnection_transceivers.html | The author of the test has indicated that flaky timeouts are expected. Reason: WebRTC inherently depends on timeouts [task 2018-01-21T11:54:53.514Z] 11:54:53 INFO - Buffered messages finished [task 2018-01-21T11:54:53.515Z] 11:54:53 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/tests/mochitest/test_peerConnection_transceivers.html | application timed out after 370 seconds with no output [task 2018-01-21T11:54:53.516Z] 11:54:53 ERROR - Force-terminating active process(es). [task 2018-01-21T11:54:53.517Z] 11:54:53 INFO - Determining child pids from psutil... [task 2018-01-21T11:54:53.518Z] 11:54:53 INFO - [3261] [task 2018-01-21T11:54:53.519Z] 11:54:53 INFO - ==> process 3159 launched child process 3182 [task 2018-01-21T11:54:53.520Z] 11:54:53 INFO - ==> process 3159 launched child process 3210 [task 2018-01-21T11:54:53.521Z] 11:54:53 INFO - ==> process 3159 launched child process 3261 [task 2018-01-21T11:54:53.522Z] 11:54:53 INFO - ==> process 3159 launched child process 4158 [task 2018-01-21T11:54:53.523Z] 11:54:53 INFO - ==> process 3159 launched child process 4578 [task 2018-01-21T11:54:53.523Z] 11:54:53 INFO - ==> process 3159 launched child process 5019 [task 2018-01-21T11:54:53.524Z] 11:54:53 INFO - ==> process 3159 launched child process 5497 [task 2018-01-21T11:54:53.526Z] 11:54:53 INFO - Found child pids: set([4578, 3210, 3182, 5497, 5019, 3261, 4158]) [task 2018-01-21T11:54:53.527Z] 11:54:53 INFO - Failed to get child procs [task 2018-01-21T11:54:53.528Z] 11:54:53 INFO - Killing process: 4578 [task 2018-01-21T11:54:53.529Z] 11:54:53 INFO - TEST-INFO | started process screentopng [task 2018-01-21T11:54:53.682Z] 11:54:53 INFO - TEST-INFO | screentopng: exit 0 [task 2018-01-21T11:54:53.683Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.685Z] 11:54:53 INFO - Killing process: 3210 [task 2018-01-21T11:54:53.689Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.690Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.691Z] 11:54:53 INFO - Killing process: 3182 [task 2018-01-21T11:54:53.692Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.693Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.694Z] 11:54:53 INFO - Killing process: 5497 [task 2018-01-21T11:54:53.695Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.696Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.697Z] 11:54:53 INFO - Killing process: 5019 [task 2018-01-21T11:54:53.698Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.699Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.700Z] 11:54:53 INFO - Killing process: 3261 [task 2018-01-21T11:54:53.701Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.702Z] 11:54:53 INFO - Killing process: 4158 [task 2018-01-21T11:54:53.704Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.705Z] 11:54:53 INFO - Can't trigger Breakpad, process no longer exists [task 2018-01-21T11:54:53.707Z] 11:54:53 INFO - Killing process: 3159 [task 2018-01-21T11:54:53.709Z] 11:54:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-01-21T11:54:53.935Z] 11:54:53 INFO - psutil found pid 3159 dead [task 2018-01-21T11:54:54.085Z] 11:54:54 WARNING - runtests.py | Failed to get app exit code - running/crashed? [task 2018-01-21T11:54:54.087Z] 11:54:54 INFO - TEST-INFO | Main app process: exit 0 [task 2018-01-21T11:54:54.088Z] 11:54:54 INFO - runtests.py | Application ran for: 0:19:39.144087 [task 2018-01-21T11:54:54.089Z] 11:54:54 INFO - zombiecheck | Reading PID log: /tmp/tmpXa3Ftqpidlog [task 2018-01-21T11:54:54.091Z] 11:54:54 INFO - ==> process 3159 launched child process 3182 [task 2018-01-21T11:54:54.093Z] 11:54:54 INFO - ==> process 3159 launched child process 3210 [task 2018-01-21T11:54:54.093Z] 11:54:54 INFO - ==> process 3159 launched child process 3261 [task 2018-01-21T11:54:54.094Z] 11:54:54 INFO - ==> process 3159 launched child process 4158 [task 2018-01-21T11:54:54.094Z] 11:54:54 INFO - ==> process 3159 launched child process 4578 [task 2018-01-21T11:54:54.094Z] 11:54:54 INFO - ==> process 3159 launched child process 5019 [task 2018-01-21T11:54:54.095Z] 11:54:54 INFO - ==> process 3159 launched child process 5497 [task 2018-01-21T11:54:54.095Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 4578 [task 2018-01-21T11:54:54.095Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 3210 [task 2018-01-21T11:54:54.095Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 3182 [task 2018-01-21T11:54:54.096Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 5497 [task 2018-01-21T11:54:54.096Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 5019 [task 2018-01-21T11:54:54.096Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 3261 [task 2018-01-21T11:54:54.097Z] 11:54:54 INFO - zombiecheck | Checking for orphan process with PID: 4158 [task 2018-01-21T11:54:54.097Z] 11:54:54 INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpUOcupg.mozrunner/minidumps/55c6f926-fa54-cd5e-cafd-00056bb7794e.dmp /builds/worker/workspace/build/symbols [task 2018-01-21T11:55:03.102Z] 11:55:03 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/55c6f926-fa54-cd5e-cafd-00056bb7794e.dmp [task 2018-01-21T11:55:03.103Z] 11:55:03 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/55c6f926-fa54-cd5e-cafd-00056bb7794e.extra [task 2018-01-21T11:55:03.165Z] 11:55:03 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ linux-gate.so + 0xcd9] [task 2018-01-21T11:55:03.166Z] 11:55:03 INFO - Crash dump filename: /tmp/tmpUOcupg.mozrunner/minidumps/55c6f926-fa54-cd5e-cafd-00056bb7794e.dmp [task 2018-01-21T11:55:03.167Z] 11:55:03 INFO - Operating system: Linux [task 2018-01-21T11:55:03.168Z] 11:55:03 INFO - 0.0.0 Linux 4.4.0-98-generic #121~14.04.1-Ubuntu SMP Wed Oct 11 11:54:55 UTC 2017 x86_64 [task 2018-01-21T11:55:03.168Z] 11:55:03 INFO - CPU: x86 [task 2018-01-21T11:55:03.169Z] 11:55:03 INFO - GenuineIntel family 6 model 62 stepping 4 [task 2018-01-21T11:55:03.170Z] 11:55:03 INFO - 2 CPUs [task 2018-01-21T11:55:03.171Z] 11:55:03 INFO - [task 2018-01-21T11:55:03.172Z] 11:55:03 INFO - GPU: UNKNOWN [task 2018-01-21T11:55:03.173Z] 11:55:03 INFO - [task 2018-01-21T11:55:03.174Z] 11:55:03 INFO - Crash reason: SIGABRT [task 2018-01-21T11:55:03.175Z] 11:55:03 INFO - Crash address: 0x3c6 [task 2018-01-21T11:55:03.176Z] 11:55:03 INFO - Process uptime: not available [task 2018-01-21T11:55:03.177Z] 11:55:03 INFO - [task 2018-01-21T11:55:03.177Z] 11:55:03 INFO - Thread 0 (crashed) [task 2018-01-21T11:55:03.179Z] 11:55:03 INFO - 0 linux-gate.so + 0xcd9 [task 2018-01-21T11:55:03.180Z] 11:55:03 INFO - eip = 0xf76ffcd9 esp = 0xff922a84 ebp = 0xff922af8 ebx = 0xe42c3aa0 [task 2018-01-21T11:55:03.181Z] 11:55:03 INFO - esi = 0xf71437b0 edi = 0xe42c3aa0 eax = 0xfffffffc ecx = 0x00000004 [task 2018-01-21T11:55:03.182Z] 11:55:03 INFO - edx = 0xffffffff efl = 0x00000296 [task 2018-01-21T11:55:03.183Z] 11:55:03 INFO - Found by: given as instruction pointer in context [task 2018-01-21T11:55:03.183Z] 11:55:03 INFO - 1 libglib-2.0.so.0.4800.2 + 0x4711c [task 2018-01-21T11:55:03.184Z] 11:55:03 INFO - eip = 0xf5da811c esp = 0xff922b00 ebp = 0x00000004 [task 2018-01-21T11:55:03.185Z] 11:55:03 INFO - Found by: previous frame's frame pointer [task 2018-01-21T11:55:03.186Z] 11:55:03 INFO - 2 libglib-2.0.so.0.4800.2 + 0x8cfec [task 2018-01-21T11:55:03.187Z] 11:55:03 INFO - eip = 0xf5dedfec esp = 0xff922b10 ebp = 0x00000004 [task 2018-01-21T11:55:03.188Z] 11:55:03 INFO - Found by: stack scanning [task 2018-01-21T11:55:03.189Z] 11:55:03 INFO - 3 libxul.so!IsFrameContentNodeInNamespace [nsNativeThemeGTK.cpp:9fe69ff0762d : 115 + 0x4] [task 2018-01-21T11:55:03.190Z] 11:55:03 INFO - eip = 0xf131a943 esp = 0xff922b14 ebp = 0x00000004 [task 2018-01-21T11:55:03.190Z] 11:55:03 INFO - Found by: stack scanning [task 2018-01-21T11:55:03.191Z] 11:55:03 INFO - 4 libglib-2.0.so.0.4800.2 + 0x1285b0 [task 2018-01-21T11:55:03.192Z] 11:55:03 INFO - eip = 0xf5e895b0 esp = 0xff922b24 ebp = 0x00000004 [task 2018-01-21T11:55:03.193Z] 11:55:03 INFO - Found by: stack scanning [task 2018-01-21T11:55:03.194Z] 11:55:03 INFO - 5 libglib-2.0.so.0.4800.2 + 0x46f8d [task 2018-01-21T11:55:03.195Z] 11:55:03 INFO - eip = 0xf5da7f8d esp = 0xff922b3c ebp = 0xff922b58 [task 2018-01-21T11:55:03.196Z] 11:55:03 INFO - Found by: stack scanning
Depends on: gUM_timeout
This has gotten extremely bad sometime around the 1st or 2nd. I see lots of failures like the following: [task 2018-03-03T16:32:19.138Z] 16:32:19 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::Atomic<bool, (mozilla::MemoryOrdering)2u, void>::operator bool]
Depends on: 1443803
Seems permanently orange for me on Linux x64 QuantumRender debug: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b1dbb3f07cc7311b186e642aa8a8e1774088f8a6&selectedJob=166630581 Logs show PROCESS-CRASH messages like the one in comment 9. Resetting the priority to get this reconsidered -- something has changed.
Priority: P5 → --
Raising priority. Byron has been looking at intermittent failures lately and is active on this bug, but I'll leave a needinfo just in case :)
Rank: 15
Flags: needinfo?(docfaraday)
Priority: -- → P2
Bug 1443803 seems to be a regression due to bug 1440040 according to pehrsons. I am looking into it right now, but this is deep in unfamiliar code for me.
Flags: needinfo?(docfaraday)
Created a disable patch in case it is needed.
Assignee: nobody → aiakab
Attachment #8958021 - Flags: review?(jmaher)
Comment on attachment 8958021 [details] [diff] [review] Disabled on Linux jsdcov platform Review of attachment 8958021 [details] [diff] [review]: ----------------------------------------------------------------- please adjust the comment, this says | on Linux jsdcov platform|, and it should be | on Linux debug platform|
Attachment #8958021 - Flags: review?(jmaher) → review+
Updated the patch, corrected the message.
Attachment #8958813 - Flags: review?(jmaher)
Attachment #8958813 - Flags: review?(jmaher) → review+
Pushed by aiakab@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/700bfd08642d disabling test_peerConnection_transceivers.html on Linux debug platform r=jmaher
Keywords: checkin-needed
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
The leave-open keyword is there and there is no activity for 6 months. :aiakab, maybe it's time to close this bug?
Flags: needinfo?(aiakab)
Closing.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Flags: needinfo?(aiakab)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: