1594673 - High-frequency /webrtc/RTCDataChannelEvent-constructor.html | unable to find test window

Status: RESOLVED FIXED

(Core :: WebRTC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: aciure [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=275009900&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/P0h2ISvqRv-YyfNfYfBuRg/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-11-07T07:31:43.483Z] 07:31:43 INFO - PID 2300 | [Child 1108: Main Thread]: D/DataChannel 0DC7D820(0DC7D760): OnChannelClosed - Dispatching
[task 2019-11-07T07:31:43.484Z] 07:31:43 INFO - PID 2300 | [Parent 4700, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:43.484Z] 07:31:43 INFO - PID 2300 | [Child 1108, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:53.948Z] 07:31:53 INFO - PID 2300 | [Parent 4700, Gecko_IOThread] WARNING: file z:/task_1573103194/build/src/ipc/chromium/src/base/process_util_win.cc, line 160
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - Traceback (most recent call last):
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 627, in _run
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 735, in do_testharness
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - timeout=10self.timeout_multiplier)
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 226, in get_test_window
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - raise Exception("unable to find test window")
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING - Exception: unable to find test window
[task 2019-11-07T07:31:54.063Z] 07:31:54 WARNING -
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - TEST-UNEXPECTED-ERROR | /webrtc/RTCDataChannelEvent-constructor.html | unable to find test window
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - Traceback (most recent call last):
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 627, in _run
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 735, in do_testharness
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - timeout=10self.timeout_multiplier)
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - File "Z:\task_1573108755\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 226, in get_test_window
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - raise Exception("unable to find test window")
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - Exception: unable to find test window
[task 2019-11-07T07:31:54.064Z] 07:31:54 INFO - TEST-INFO took 10744ms
[task 2019-11-07T07:31:54.071Z] 07:31:54 INFO - PID 2300 | 1573111914056 Marionette INFO Stopped listening on port 49446
[task 2019-11-07T07:31:54.166Z] 07:31:54 INFO - PID 2300 | [Parent 4700, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.166Z] 07:31:54 INFO - PID 2300 | [Child 2456, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.166Z] 07:31:54 INFO - PID 2300 | [Child 2456, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.167Z] 07:31:54 INFO - PID 2300 | [Parent 4700, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.174Z] 07:31:54 INFO - PID 2300 | [Child 4068, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.174Z] 07:31:54 INFO - PID 2300 | [Child 4068, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line[Child 6004, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.313Z] 07:31:54 INFO - PID 2300 | [Child 600[Parent 4700, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.313Z] 07:31:54 INFO - PID 2300 | [Child 3844, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1573103194/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-11-07T07:31:54.600Z] 07:31:54 INFO - PID 2300 | [Child 3844, Chrome_ChildThread] W
[task 2019-11-07T07:31:54.621Z] 07:31:54 INFO - Browser exited with return code 0
[task 2019-11-07T07:31:54.621Z] 07:31:54 INFO - PROCESS LEAKS None
[task 2019-11-07T07:31:54.622Z] 07:31:54 INFO - Closing logging queue
[task 2019-11-07T07:31:54.622Z] 07:31:54 INFO - queue closed
[task 2019-11-07T07:31:54.641Z] 07:31:54 INFO - Setting up ssl
[task 2019-11-07T07:31:54.696Z] 07:31:54 INFO - certutil |
[task 2019-11-07T07:31:54.743Z] 07:31:54 INFO - certutil |
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO - certutil |
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO - Certificate Nickname Trust Attributes
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO - SSL,S/MIME,JAR/XPI
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO -
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO - web-platform-tests CT,,
[task 2019-11-07T07:31:54.763Z] 07:31:54 INFO -
[task 2019-11-07T07:31:54.822Z] 07:31:54 INFO - Application command: Z:\task_1573108755\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile c:\users\task_1573108755\appdata\local\temp\tmpa04js6.mozrunner
[task 2019-11-07T07:31:54.829Z] 07:31:54 INFO - Starting runner
[task 2019-11-07T07:31:55.364Z] 07:31:55 INFO - PID 3440 | 1573111915358 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
[task 2019-11-07T07:31:55.364Z] 07:31:55 INFO - PID 3440 | 1573111915358 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: telemetry
[task 2019-11-07T07:31:55.364Z] 07:31:55 INFO - PID 3440 | 1573111915359 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2019-11-07T07:31:55.365Z] 07:31:55 INFO - PID 3440 | 1573111915359 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
[task 2019-11-07T07:31:57.030Z] 07:31:57 INFO - PID 3440 | 1573111917027 Marionette INFO Listening on port 49446
[task 2019-11-07T07:31:57.592Z] 07:31:57 INFO - TEST-START | /webrtc/RTCIceCandidate-constructor.html
[task 2019-11-07T07:31:57.607Z] 07:31:57 INFO - Setting pref media.navigator.permission.disabled (true)
[task 2019-11-07T07:31:57.622Z] 07:31:57 INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter (false)
[task 2019-11-07T07:31:57.629Z] 07:31:57 INFO - Setting pref media.navigator.streams.fake (true)
[task 2019-11-07T07:31:57.644Z] 07:31:57 INFO - Setting pref privacy.reduceTimerPrecision (false)
[task 2019-11-07T07:31:57.873Z] 07:31:57 INFO - ..................
[task 2019-11-07T07:31:57.873Z] 07:31:57 INFO - TEST-OK | /webrtc/RTCIceCandidate-constructor.html | took 286ms

Comment 1

[Andrei Ciure[:aciure]]

Retriggered:

https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&selectedJob=275017006&searchStr=windows%2C7%2Cshippable%2Copt%2Cweb%2Cplatform%2Ctests%2Ctest-windows7-32-shippable%2Fopt-web-platform-tests-e10s-10%2Cw%28wpt10%29&fromchange=73013c2281fb6aa5f58d1f9c940615fa69372cec&tochange=40a815ecfbe3b248bedafdba52851b774d31efc8

couldn't pinpoint a cause for the high frequency from the above.

Comment 2

[Dan Minor [:dminor]]

This is caused by the changes in Bug 1588817. I also filed Bug 1594018. I ran into this on Try, but I thought I had disabled the problematic test. If this is too high frequency, feel free to back out my changes above. I'll have a look right away.

Comment 3

[Dan Minor [:dminor]]

Looking at the logs, it appears that the test I wanted to disable on windows 7 in https://hg.mozilla.org/mozilla-central/rev/6a7b78f2d462 is still running:

[task 2019-11-07T10:43:12.053Z] 10:43:12 INFO - PID 3760 | (ice/INFO) ICE-PEER(PC:1573123391052000 (id=30064771074 url=http://web-platform.test:8000/webrtc/RTCDataChannel-send.html):default)/STREAM(PC:1573123391052000 (id=30064771074 url=http://web-platform.test:8000/webrtc/RTCDataChannel-send.html) transport-id=transport_0 - 572816fe:1f563f74b15c3830de95a68e9c6e6dd7)/COMP(1)/CAND-PAIR(0f9I): cancelling all pairs but 0f9I|IP4:10.147.40.65:62969/UDP|IP4:10.147.40.65:62971/UDP(host(IP4:10.147.40.65:62969/UDP)|prflx)

Comment 4

[Dan Minor [:dminor]]

I definitely messed up the syntax to disable RTCDataChannel-send.html, but I should just be able to mark RTCDataChannelEvent-constructor.html as intermittent. I've started try jobs for each, I'll see which one is more effective. It's possible that the test after RTCDataChannelEvent-constructor.html will also fail intermittently if the real problem is RTCDataChannel-send.html.

Comment 5

[Dan Minor [:dminor]]

Either I messed up the syntax or the framework doesn't pick up on "unable to find test window" as an error: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e3ae453387bb74672ebc762c53e1ea05689a29b5. Actually disabling the test seems to do the trick though: https://treeherder.mozilla.org/#/jobs?repo=try&revision=70c2f3b5a7b64e33e47b62d61593dd1a5df2e9eb.

Comment 6

[Dan Minor [:dminor]]

Attachment: Bug 1594673 - Actually disable RTCDataChannel-send on win32; r=ng!

I messed up the syntax the first time around, this actually disables
the test. This was exacerbated by accidentally testing the changes on
win32-opt rather than win32-shippable-opt where the intermittent
occurs.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d9a3fbd31fe5
Actually disable RTCDataChannel-send on win32; r=ng

Comment 8

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/d9a3fbd31fe5

Comment 9

[Intermittent Failures Robot]

71 failures in 963 pushes (0.074 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 67
• try: 3
• mozilla-inbound: 1

Platform breakdown:

• windows7-32-shippable: 69
• windows7-32-devedition: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1594673&startday=2019-11-07&endday=2019-11-07&tree=all

Comment 10

[Intermittent Failures Robot]

78 failures in 4850 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #21 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 74
• mozilla-inbound: 1
• try: 3

Platform breakdown:

• windows7-32-shippable: 76
• windows7-32-devedition: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1594673&startday=2019-11-04&endday=2019-11-10&tree=all