Closed Bug 1732488 Opened 3 years ago Closed 3 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-iceRestart.html | Data channel remains usable after ICE restart - Test timed out

Categories

(Core :: WebRTC, defect, P5)

Product:
Core
Component:
WebRTC
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=352676774&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/d-SPgNawSH2pOD9H_ZBZVA/runs/0/artifacts/public/logs/live_backing.log

[task 2021-09-24T20:54:50.240Z] 20:54:50     INFO - TEST-START | /webcodecs/videoFrame-texImage.any.html
[task 2021-09-24T20:54:50.241Z] 20:54:50     INFO - Closing window c06f065a-fbcf-46e0-992e-e1af2c01efd6
[task 2021-09-24T20:54:50.428Z] 20:54:50     INFO - ......
[task 2021-09-24T20:54:50.428Z] 20:54:50     INFO - TEST-OK | /webcodecs/videoFrame-texImage.any.html | took 188ms
[task 2021-09-24T20:54:50.428Z] 20:54:50     INFO - Restarting browser for new test group
[task 2021-09-24T20:54:50.430Z] 20:54:50     INFO - PID 10732 | 1632516890428	Marionette	INFO	Stopped listening on port 54620
[task 2021-09-24T20:54:50.510Z] 20:54:50     INFO - PID 10732 | JavaScript error: resource:///modules/Interactions.jsm, line 201: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-09-24T20:54:50.968Z] 20:54:50     INFO - Browser exited with return code 0
[task 2021-09-24T20:54:50.970Z] 20:54:50     INFO - Closing logging queue
[task 2021-09-24T20:54:50.971Z] 20:54:50     INFO - queue closed
[task 2021-09-24T20:54:51.072Z] 20:54:51     INFO - Application command: Z:\task_1632516003\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_1632516003\AppData\Local\Temp\tmppixl5dfz
[task 2021-09-24T20:54:51.074Z] 20:54:51     INFO - Starting runner
[task 2021-09-24T20:54:51.150Z] 20:54:51     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:51.150Z] 20:54:51     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:51.429Z] 20:54:51     INFO - PID 10476 | 1632516891428	Marionette	INFO	Marionette enabled
[task 2021-09-24T20:54:52.150Z] 20:54:52     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:52.150Z] 20:54:52     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:52.217Z] 20:54:52     INFO - PID 10476 | JavaScript error: resource://gre/modules/XULStore.jsm, line 66: Error: Can't find profile directory.
[task 2021-09-24T20:54:53.035Z] 20:54:53     INFO - PID 10476 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_1632516003\\AppData\\Local\\Temp\\tmppixl5dfz\\search.json.mozlz4", (void 0)))
[task 2021-09-24T20:54:53.151Z] 20:54:53     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:53.151Z] 20:54:53     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:53.859Z] 20:54:53     INFO - PID 10476 | 1632516893858	Marionette	INFO	Listening on port 55022
[task 2021-09-24T20:54:54.148Z] 20:54:54     INFO - 
[task 2021-09-24T20:54:54.148Z] 20:54:54     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-iceRestart.html | Data channel remains usable after ICE restart - Test timed out
[task 2021-09-24T20:54:54.149Z] 20:54:54     INFO - 
[task 2021-09-24T20:54:54.149Z] 20:54:54     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-iceRestart.html | Data channel remains usable at each step of an ICE restart - expected PASS
[task 2021-09-24T20:54:54.150Z] 20:54:54     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-iceRestart.html | expected ERROR
[task 2021-09-24T20:54:54.150Z] 20:54:54     INFO - TEST-INFO expected ERROR | took 60180ms
[task 2021-09-24T20:54:54.152Z] 20:54:54     INFO - PID 5712 | 1632516894150	Marionette	INFO	Stopped listening on port 54623
[task 2021-09-24T20:54:54.152Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:54.153Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:54.226Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:54.228Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2110: CloseInt: Closing PeerConnectionImpl {e903d632-a591-47a2-b07e-fcb42362e7f8}; ending call
[task 2021-09-24T20:54:54.229Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/jsep [{e903d632-a591-47a2-b07e-fcb42362e7f8} 1632516834124000 (id=17179869186 url=http://web-platform.test:8000/webrtc/RTCDataChannel]: stable -> closed
[task 2021-09-24T20:54:54.229Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2116: CloseInt: Destroying DataChannelConnection babb760 for {e903d632-a591-47a2-b07e-fcb42362e7f8}
[task 2021-09-24T20:54:54.230Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Destroying DataChannelConnection babb760
[task 2021-09-24T20:54:54.231Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Closing all channels (connection babb760)
[task 2021-09-24T20:54:54.231Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (babb760) switching connection state CLOSED -> CLOSED
[task 2021-09-24T20:54:54.232Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Connection babb760: Sending outgoing stream reset for 1 streams
[task 2021-09-24T20:54:54.233Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: E/DataChannel ***failed: setsockopt RESET, errno 2
[task 2021-09-24T20:54:54.233Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Clearing resets for 1 streams
[task 2021-09-24T20:54:54.234Z] 20:54:54     INFO - PID 5712 | [Child 6932: Socket Thread]: D/DataChannel Deregistered 1 from the SCTP stack.
[task 2021-09-24T20:54:54.235Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2779: GetStats: Found no pipelines matching selector.
[task 2021-09-24T20:54:54.236Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2110: CloseInt: Closing PeerConnectionImpl {bd542bce-ad3c-4c9f-9e3c-8cd1f00fd8a1}; ending call
[task 2021-09-24T20:54:54.236Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/jsep [{bd542bce-ad3c-4c9f-9e3c-8cd1f00fd8a1} 1632516834129000 (id=17179869186 url=http://web-platform.test:8000/webrtc/RTCDataChannel]: stable -> closed
[task 2021-09-24T20:54:54.237Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2116: CloseInt: Destroying DataChannelConnection babb1a0 for {bd542bce-ad3c-4c9f-9e3c-8cd1f00fd8a1}
[task 2021-09-24T20:54:54.238Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Destroying DataChannelConnection babb1a0
[task 2021-09-24T20:54:54.238Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Closing all channels (connection babb1a0)
[task 2021-09-24T20:54:54.239Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (babb1a0) switching connection state CLOSED -> CLOSED
[task 2021-09-24T20:54:54.239Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Connection babb1a0: Sending outgoing stream reset for 0 streams
[task 2021-09-24T20:54:54.240Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel No streams to reset
[task 2021-09-24T20:54:54.240Z] 20:54:54     INFO - PID 5712 | [Child 6932: Socket Thread]: D/DataChannel Deregistered 2 from the SCTP stack.
[task 2021-09-24T20:54:54.241Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Deleting DataChannelConnection babb760
[task 2021-09-24T20:54:54.241Z] 20:54:54     INFO - PID 5712 | [Child 6932: Main Thread]: D/DataChannel Deleting DataChannelConnection babb1a0
[task 2021-09-24T20:54:54.242Z] 20:54:54     INFO - PID 5712 | JavaScript error: resource:///modules/Interactions.jsm, line 201: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-09-24T20:54:54.247Z] 20:54:54     INFO - PID 5712 | [Parent 1856, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-09-24T20:54:54.402Z] 20:54:54     INFO - TEST-START | /websockets/binary/001.html

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.