Closed Bug 1844809 Opened 2 years ago Closed 11 months ago

Intermittent /webrtc/RTCPeerConnection-ondatachannel.html | single tracking bug

Categories

(Core :: WebRTC, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase)

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


[task 2023-07-21T14:50:20.922Z] 14:50:20     INFO - TEST-PASS | /webrtc/RTCPeerConnection-ondatachannel.html | Open event should not be raised when closing the channel in the datachannel event 
[task 2023-07-21T14:50:20.922Z] 14:50:20     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCPeerConnection-ondatachannel.html | Open event should be raised when closing the channel in the datachannel event after enqueuing a task - Test timed out
[task 2023-07-21T14:50:20.922Z] 14:50:20     INFO - 
[task 2023-07-21T14:50:20.922Z] 14:50:20     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCPeerConnection-ondatachannel.html | Open event should not be raised when sending and immediately closing the channel in the datachannel event - expected PASS
[task 2023-07-21T14:50:20.923Z] 14:50:20     INFO - 
[task 2023-07-21T14:50:20.923Z] 14:50:20     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCPeerConnection-ondatachannel.html | In-band negotiated channel created on remote peer should match the same configuration as local peer - expected PASS
[task 2023-07-21T14:50:20.924Z] 14:50:20     INFO - 
[task 2023-07-21T14:50:20.924Z] 14:50:20     INFO - TEST-KNOWN-INTERMITTENT-NOTRUN | /webrtc/RTCPeerConnection-ondatachannel.html | In-band negotiated channel created on remote peer should match the same (default) configuration as local peer 
[task 2023-07-21T14:50:20.925Z] 14:50:20     INFO - 
[task 2023-07-21T14:50:20.925Z] 14:50:20     INFO - TEST-KNOWN-INTERMITTENT-NOTRUN | /webrtc/RTCPeerConnection-ondatachannel.html | Negotiated channel should not fire datachannel event on remote peer 
[task 2023-07-21T14:50:20.926Z] 14:50:20     INFO - TEST-KNOWN-INTERMITTENT-TIMEOUT | /webrtc/RTCPeerConnection-ondatachannel.html | took 181810ms
[task 2023-07-21T14:50:20.927Z] 14:50:20     INFO - PID 1322 | 1689951020922	Marionette	INFO	Stopped listening on port 45307
[task 2023-07-21T14:50:21.119Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2603: Close: Closing PeerConnectionImpl {dbcfd288-db1c-4443-a6c8-81fb50a24ad7}; ending call
[task 2023-07-21T14:50:21.121Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/jsep [{dbcfd288-db1c-4443-a6c8-81fb50a24ad7} 1689950843661971 (id=47244640258 url=http://web-platform.test:8000/webrtc/RTCPeerConnection-ondatachannel.html)]: stable -> closed
[task 2023-07-21T14:50:21.123Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2609: Close: Destroying DataChannelConnection 6170000efc80 for {dbcfd288-db1c-4443-a6c8-81fb50a24ad7}
[task 2023-07-21T14:50:21.125Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Destroying DataChannelConnection 6170000efc80
[task 2023-07-21T14:50:21.126Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Closing all channels (connection 6170000efc80)
[task 2023-07-21T14:50:21.127Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (6170000efc80) switching connection state OPEN -> CLOSED
[task 2023-07-21T14:50:21.128Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Connection 6170000efc80: Sending outgoing stream reset for 0 streams
[task 2023-07-21T14:50:21.129Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel No streams to reset
[task 2023-07-21T14:50:21.130Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: D/DataChannel Deregistered 7 from the SCTP stack.
[task 2023-07-21T14:50:21.130Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: D/DataChannel Shutting down connection 6170000efc80, id 7
[task 2023-07-21T14:50:21.133Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2603: Close: Closing PeerConnectionImpl {f83669ed-af1f-466a-9833-c0ac7b5197e9}; ending call
[task 2023-07-21T14:50:21.142Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/jsep [{f83669ed-af1f-466a-9833-c0ac7b5197e9} 1689950843666705 (id=47244640258 url=http://web-platform.test:8000/webrtc/RTCPeerConnection-ondatachannel.html)]: stable -> closed
[task 2023-07-21T14:50:21.142Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2609: Close: Destroying DataChannelConnection 6170000f2d80 for {f83669ed-af1f-466a-9833-c0ac7b5197e9}
[task 2023-07-21T14:50:21.142Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Destroying DataChannelConnection 6170000f2d80
[task 2023-07-21T14:50:21.143Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Closing all channels (connection 6170000f2d80)
[task 2023-07-21T14:50:21.143Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (6170000f2d80) switching connection state OPEN -> CLOSED
[task 2023-07-21T14:50:21.144Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Connection 6170000f2d80: Sending outgoing stream reset for 0 streams
[task 2023-07-21T14:50:21.144Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel No streams to reset
[task 2023-07-21T14:50:21.145Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: D/DataChannel Deregistered 8 from the SCTP stack.
[task 2023-07-21T14:50:21.146Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: D/DataChannel Shutting down connection 6170000f2d80, id 8
[task 2023-07-21T14:50:21.147Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Deregistering connection ulp = 7
[task 2023-07-21T14:50:21.147Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Deleting DataChannelConnection 6170000efc80
[task 2023-07-21T14:50:21.148Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Deregistering connection ulp = 8
[task 2023-07-21T14:50:21.150Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Deleting DataChannelConnection 6170000f2d80
[task 2023-07-21T14:50:21.151Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel Calling usrsctp_finish 60700006f140
[task 2023-07-21T14:50:21.152Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: I/mtransport NrIceCtx(PC:{dbcfd288-db1c-4443-a6c8-81fb50a24ad7} 1689950843661971 (id=47244640258 url=http://web-platform.test:8000/webrtc/RTCPeerConnection-ondatachannel.html)): Destroy
[task 2023-07-21T14:50:21.152Z] 14:50:21     INFO - PID 1322 | [Child 5145: Socket Thread]: I/mtransport NrIceCtx(PC:{f83669ed-af1f-466a-9833-c0ac7b5197e9} 1689950843666705 (id=47244640258 url=http://web-platform.test:8000/webrtc/RTCPeerConnection-ondatachannel.html)): Destroy
[task 2023-07-21T14:50:21.279Z] 14:50:21     INFO - PID 1322 | console.error: ({})
[task 2023-07-21T14:50:21.292Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: D/DataChannel 60f0001facb0: Close()ing 61100021b280
[task 2023-07-21T14:50:21.295Z] 14:50:21     INFO - PID 1322 | Timecard created 1689950843.663431
[task 2023-07-21T14:50:21.297Z] 14:50:21     INFO - PID 1322 |  Timestamp   | Delta       | Event                                  | File                         | Function
[task 2023-07-21T14:50:21.302Z] 14:50:21     INFO - PID 1322 | ====================================================================================================================================
[task 2023-07-21T14:50:21.302Z] 14:50:21     INFO - PID 1322 |     0.002737 |    0.002737 | Constructor Completed                  | PeerConnectionImpl.cpp:387   | PeerConnectionImpl
[task 2023-07-21T14:50:21.302Z] 14:50:21     INFO - PID 1322 |     0.003306 |    0.000569 | Initializing PC Ctx                    | PeerConnectionImpl.cpp:472   | Initialize
[task 2023-07-21T14:50:21.302Z] 14:50:21     INFO - PID 1322 |     0.066962 |    0.063656 | Set Remote Description                 | PeerConnectionImpl.cpp:1788  | SetRemoteDescription
[task 2023-07-21T14:50:21.306Z] 14:50:21     INFO - PID 1322 |     0.076828 |    0.009866 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.307Z] 14:50:21     INFO - PID 1322 |     0.077461 |    0.000633 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.308Z] 14:50:21     INFO - PID 1322 |     0.077797 |    0.000336 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.308Z] 14:50:21     INFO - PID 1322 |     0.078113 |    0.000316 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.309Z] 14:50:21     INFO - PID 1322 |     0.078431 |    0.000318 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.316Z] 14:50:21     INFO - PID 1322 |     0.078801 |    0.000370 | Add Ice Candidate                      | PeerConnectionImpl.cpp:1904  | AddIceCandidate
[task 2023-07-21T14:50:21.316Z] 14:50:21     INFO - PID 1322 |     0.079216 |    0.000415 | Create Answer                          | PeerConnectionImpl.cpp:1608  | CreateAnswer
[task 2023-07-21T14:50:21.317Z] 14:50:21     INFO - PID 1322 |     0.091043 |    0.011827 | Set Local Description                  | PeerConnectionImpl.cpp:1678  | SetLocalDescription
[task 2023-07-21T14:50:21.317Z] 14:50:21     INFO - PID 1322 |     0.106183 |    0.015140 | Ice gathering state: gathering         | PeerConnectionImpl.cpp:3424  | IceGatheringStateChange
[task 2023-07-21T14:50:21.318Z] 14:50:21     INFO - PID 1322 |     0.106426 |    0.000243 | Ice Candidate gathered                 | PeerConnectionImpl.cpp:3251  | CandidateReady
[task 2023-07-21T14:50:21.318Z] 14:50:21     INFO - PID 1322 |     0.106880 |    0.000454 | Send Ice Candidate to content          | PeerConnectionImpl.cpp:3315  | SendLocalIceCandidateToContent
[task 2023-07-21T14:50:21.319Z] 14:50:21     INFO - PID 1322 |     0.107777 |    0.000897 | Ice Candidate gathered                 | PeerConnectionImpl.cpp:3251  | CandidateReady
[task 2023-07-21T14:50:21.320Z] 14:50:21     INFO - PID 1322 |     0.108254 |    0.000477 | Send Ice Candidate to content          | PeerConnectionImpl.cpp:3315  | SendLocalIceCandidateToContent
[task 2023-07-21T14:50:21.321Z] 14:50:21     INFO - PID 1322 |     0.108869 |    0.000615 | Ice Candidate gathered                 | PeerConnectionImpl.cpp:3251  | CandidateReady
[task 2023-07-21T14:50:21.326Z] 14:50:21     INFO - PID 1322 |     0.109319 |    0.000450 | Send Ice Candidate to content          | PeerConnectionImpl.cpp:3315  | SendLocalIceCandidateToContent
[task 2023-07-21T14:50:21.327Z] 14:50:21     INFO - PID 1322 |     0.110169 |    0.000850 | Ice Candidate gathered                 | PeerConnectionImpl.cpp:3251  | CandidateReady
[task 2023-07-21T14:50:21.327Z] 14:50:21     INFO - PID 1322 |     0.110666 |    0.000497 | Send Ice Candidate to content          | PeerConnectionImpl.cpp:3315  | SendLocalIceCandidateToContent
[task 2023-07-21T14:50:21.328Z] 14:50:21     INFO - PID 1322 |     0.111265 |    0.000599 | Ice Candidate gathered                 | PeerConnectionImpl.cpp:3251  | CandidateReady
[task 2023-07-21T14:50:21.329Z] 14:50:21     INFO - PID 1322 |     0.111690 |    0.000425 | Send Ice Candidate to content          | PeerConnectionImpl.cpp:3315  | SendLocalIceCandidateToContent
[task 2023-07-21T14:50:21.330Z] 14:50:21     INFO - PID 1322 |     0.112259 |    0.000569 | Ice gathering state: complete          | PeerConnectionImpl.cpp:3427  | IceGatheringStateChange
[task 2023-07-21T14:50:21.330Z] 14:50:21     INFO - PID 1322 |     0.120802 |    0.008543 | Ice state: checking                    | PeerConnectionImpl.cpp:3347  | IceConnectionStateChange
[task 2023-07-21T14:50:21.338Z] 14:50:21     INFO - PID 1322 |     0.141800 |    0.020998 | Ice state: connected                   | PeerConnectionImpl.cpp:3350  | IceConnectionStateChange
[task 2023-07-21T14:50:21.338Z] 14:50:21     INFO - PID 1322 |   177.467549 |  177.325749 | Close                                  | PeerConnectionImpl.cpp:2591  | Close
[task 2023-07-21T14:50:21.339Z] 14:50:21     INFO - PID 1322 |   177.628436 |    0.160887 | Destructor Invoked                     | PeerConnectionImpl.cpp:404   | ~PeerConnectionImpl
[task 2023-07-21T14:50:21.344Z] 14:50:21     INFO - PID 1322 |   177.628437 |    0.000001 | {f83669ed-af1f-466a-9833-c0ac7b5197e9} | PeerConnectionImpl.cpp:405   | ~PeerConnectionImpl
[task 2023-07-21T14:50:21.346Z] 14:50:21     INFO - PID 1322 | [Child 5145: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:412: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for {f83669ed-af1f-466a-9833-c0ac7b5197e9}
[task 2023-07-21T14:50:21.347Z] 14:50:21     INFO - PID 1322 | Timecard created 1689950843.660805
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

With the landing of Bug 1903905 this has become rather frequent as can be seen by retriggers & backfills here. Byron, could you take a look at this please? Thank you!

Flags: needinfo?(docfaraday)
Summary: Intermittent /webrtc/RTCPeerConnection-ondatachannel.html | single tracking bug → Frequent /webrtc/RTCPeerConnection-ondatachannel.html | single tracking bug

Looks like this is another way that bug 1613433 can manifest.

Assignee: nobody → docfaraday
Depends on: 1613433
Flags: needinfo?(docfaraday)

Almost all of the failures are happening on beta, where the meta file is missing some updates from central. If we let those updates ride the trains, this should clear up. If there are still some stragglers, I can uplift the necessary meta file changes.

Summary: Frequent /webrtc/RTCPeerConnection-ondatachannel.html | single tracking bug → Intermittent /webrtc/RTCPeerConnection-ondatachannel.html | single tracking bug
Whiteboard: [stockwell disable-recommended]
Status: REOPENED → RESOLVED
Closed: 2 years ago11 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.