1903905 - Intermittent Assertion failure: stream != (0xFFFF), at /builds/worker/checkouts/gecko/netwerk/sctp/datachannel/DataChannel.cpp:2472

Status: RESOLVED FIXED

(Core :: Networking, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2024-06-20T22:00:33.347Z] 22:00:33     INFO - TEST-START | /webrtc/idlharness.https.window.html
[task 2024-06-20T22:00:33.348Z] 22:00:33     INFO - Setting pref media.navigator.permission.disabled to true
[task 2024-06-20T22:00:33.355Z] 22:00:33     INFO - Setting pref media.navigator.streams.fake to true
[task 2024-06-20T22:00:33.366Z] 22:00:33     INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter to true
[task 2024-06-20T22:00:33.376Z] 22:00:33     INFO - Setting pref privacy.reduceTimerPrecision to true
[task 2024-06-20T22:00:33.388Z] 22:00:33     INFO - Setting pref media.peerconnection.ice.trickle_grace_period to 5000
[task 2024-06-20T22:00:33.398Z] 22:00:33     INFO - Setting pref media.peerconnection.ice.obfuscate_host_addresses to true
[task 2024-06-20T22:00:33.409Z] 22:00:33     INFO - Setting pref media.peerconnection.allow_old_setParameters to true
[task 2024-06-20T22:00:33.419Z] 22:00:33     INFO - Setting pref media.peerconnection.description.legacy.enabled to false
[task 2024-06-20T22:00:33.428Z] 22:00:33     INFO - Setting pref media.aboutwebrtc.hist.poll_interval_ms to 250
[task 2024-06-20T22:00:33.447Z] 22:00:33     INFO - Setting pref media.navigator.permission.disabled to true
[task 2024-06-20T22:00:33.464Z] 22:00:33     INFO - Setting pref media.navigator.streams.fake to true
[task 2024-06-20T22:00:33.482Z] 22:00:33     INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter to false
[task 2024-06-20T22:00:33.502Z] 22:00:33     INFO - Setting pref privacy.reduceTimerPrecision to false
[task 2024-06-20T22:00:33.521Z] 22:00:33     INFO - Setting pref media.peerconnection.ice.trickle_grace_period to 10000
[task 2024-06-20T22:00:33.542Z] 22:00:33     INFO - Setting pref media.peerconnection.ice.obfuscate_host_addresses to false
[task 2024-06-20T22:00:33.560Z] 22:00:33     INFO - Setting pref media.peerconnection.allow_old_setParameters to false
[task 2024-06-20T22:00:33.578Z] 22:00:33     INFO - Setting pref media.peerconnection.description.legacy.enabled to false
[task 2024-06-20T22:00:33.596Z] 22:00:33     INFO - Setting pref media.aboutwebrtc.hist.poll_interval_ms to 2000
[task 2024-06-20T22:00:33.610Z] 22:00:33     INFO - Closing window 83e6d99b-0fa9-40a4-aa8b-fc448e33df76
<...>
[task 2024-06-20T22:00:35.758Z] 22:00:35     INFO - PID 3596 | [Child 1752: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:3499: UpdateIceConnectionState: 4 -> 6 (f199d00)
[task 2024-06-20T22:00:35.759Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2024-06-20T22:00:35.760Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2024-06-20T22:00:35.761Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2024-06-20T22:00:35.761Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: ****** SSL handshake completed ******
[task 2024-06-20T22:00:35.762Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Selected ALPN string: webrtc
[task 2024-06-20T22:00:35.763Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/mtransport Created SRTP flow!
[task 2024-06-20T22:00:35.763Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Transport is open!
[task 2024-06-20T22:00:35.764Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel dtls open
[task 2024-06-20T22:00:35.765Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Calling usrsctp_bind
[task 2024-06-20T22:00:35.766Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Calling usrsctp_connect
[task 2024-06-20T22:00:35.767Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: E/DataChannel usrsctp: PMTUD disabled, MTU set to 1179
[task 2024-06-20T22:00:35.767Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: ****** SSL handshake completed ******
[task 2024-06-20T22:00:35.767Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Selected ALPN string: webrtc
[task 2024-06-20T22:00:35.768Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/mtransport Created SRTP flow!
[task 2024-06-20T22:00:35.769Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Transport is open!
[task 2024-06-20T22:00:35.770Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel dtls open
[task 2024-06-20T22:00:35.770Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Calling usrsctp_bind
[task 2024-06-20T22:00:35.771Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Calling usrsctp_connect
[task 2024-06-20T22:00:35.772Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: E/DataChannel usrsctp: PMTUD disabled, MTU set to 1179
[task 2024-06-20T22:00:35.772Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel SendDeferredMessages called, pending type: NONE
[task 2024-06-20T22:00:35.773Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel SendDeferredMessages called, pending type: NONE
[task 2024-06-20T22:00:35.774Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel In receive_cb, ulp_info=1
[task 2024-06-20T22:00:35.775Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel In ReceiveCallback
[task 2024-06-20T22:00:35.775Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Association change: SCTP_COMM_UP
[task 2024-06-20T22:00:35.776Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel DataChannelConnection labeled transport_0 (10620c00) switching connection state CONNECTING -> OPEN
[task 2024-06-20T22:00:35.777Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Negotiated number of incoming streams: 256
[task 2024-06-20T22:00:35.777Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Negotiated number of outgoing streams: 256
[task 2024-06-20T22:00:35.778Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel DTLS connect() succeeded!  Entering connected mode
[task 2024-06-20T22:00:35.779Z] 22:00:35     INFO - PID 3596 | [Child 1752: Socket Thread]: D/DataChannel Processing queued open for 106e9030 (65535)
[task 2024-06-20T22:00:35.780Z] 22:00:35     INFO - PID 3596 | [1752] Assertion failure: stream != (0xFFFF), at /builds/worker/checkouts/gecko/netwerk/sctp/datachannel/DataChannel.cpp:2472
[task 2024-06-20T22:00:35.783Z] 22:00:35     INFO - PID 3596 | [Child 1752: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:410: PeerConnectionImpl: PeerConnectionImpl constructor for {5b96f489-a9df-4c57-a0e0-1c41c00ff446}
[task 2024-06-20T22:00:35.784Z] 22:00:35     INFO - PID 3596 | [Parent 5508: Socket Thread]: D/mtransport NrIceCtx static call to find local stun addresses
[task 2024-06-20T22:00:35.877Z] 22:00:35     INFO - STDOUT: Initializing stack-fixing for the first stack frame, this may take a while...
[task 2024-06-20T22:00:36.576Z] 22:00:36     INFO - Browser not responding, setting status to CRASH
[task 2024-06-20T22:00:36.581Z] 22:00:36     INFO - mozcrash Copy/paste: D:\task_171891832380636\fetches\minidump-stackwalk\minidump-stackwalk.exe --symbols-url=https://symbols.mozilla.org/ --cyborg=C:\Users\task_171891832380636\AppData\Local\Temp\tmpbha1hwez\ecffd72f-822d-4e7c-a907-a552e7f23bfb.trace C:\Users\task_171891832380636\AppData\Local\Temp\tmpmu8_ki9y\minidumps\ecffd72f-822d-4e7c-a907-a552e7f23bfb.dmp D:\task_171891832380636\build\symbols
[task 2024-06-20T22:00:50.154Z] 22:00:50     INFO - mozcrash Saved minidump as D:\task_171891832380636\build\blobber_upload_dir\ecffd72f-822d-4e7c-a907-a552e7f23bfb.dmp
[task 2024-06-20T22:00:50.157Z] 22:00:50     INFO - mozcrash Saved app info as D:\task_171891832380636\build\blobber_upload_dir\ecffd72f-822d-4e7c-a907-a552e7f23bfb.extra
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - PROCESS-CRASH | MOZ_ASSERT(stream != (0xFFFF)) [@ mozilla::DataChannelConnection::OpenFinish] | /webrtc/idlharness.https.window.html 
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - Process type: content
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - Process pid: 1752
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - Mozilla crash reason: MOZ_ASSERT(stream != (0xFFFF))
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - Crash dump filename: C:\Users\task_171891832380636\AppData\Local\Temp\tmpmu8_ki9y\minidumps\ecffd72f-822d-4e7c-a907-a552e7f23bfb.dmp
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - Operating system: Windows NT
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO -                   10.0.22621
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO - CPU: x86
[task 2024-06-20T22:00:50.501Z] 22:00:50     INFO -      GenuineIntel family 6 model 106 stepping 6
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO -      8 CPUs
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - 
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - Crash reason:  EXCEPTION_BREAKPOINT
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - Crash address: 0x65680adb
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - Process uptime: 609 seconds
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - 
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO - Thread 3 Socket Thread (crashed)
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO -  0  xul.dll!mozilla::DataChannelConnection::OpenFinish(already_AddRefed<mozilla::DataChannel>&&) [DataChannel.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 2472 + 0x0]
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO -      eip = 0x65680adb    esp = 0x0a3ff74c    ebp = 0x0a3ff768    ebx = 0x0000ffff
[task 2024-06-20T22:00:50.502Z] 22:00:50     INFO -      esi = 0x10620c00    edi = 0x10620c00    eax = 0x71966f00    ecx = 0xc675cdfb
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      edx = 0x0a3fe7f5 eflags = 0x00000202
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -     Found by: given as instruction pointer in context
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -  1  xul.dll!mozilla::DataChannelConnection::ProcessQueuedOpens() [DataChannel.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 1018 + 0x9]
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      eip = 0x6568074c    esp = 0x0a3ff770    ebp = 0x0a3ff7cc    ebx = 0x04f07130
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      esi = 0x0a3ff77c    edi = 0x0a3ff788
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -  2  xul.dll!mozilla::DataChannelConnection::HandleAssociationChangeEvent(sctp_assoc_change const*) [DataChannel.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 1896 + 0x7]
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      eip = 0x65683f2c    esp = 0x0a3ff7d4    ebp = 0x0a3ff7ec    ebx = 0x00000000
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      esi = 0x10620c00    edi = 0x0da25ca0
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -  3  xul.dll!mozilla::DataChannelConnection::HandleNotification(sctp_notification const*, unsigned int) [DataChannel.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 2312 + 0x7]
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      eip = 0x656855aa    esp = 0x0a3ff7f4    ebp = 0x0a3ff800    ebx = 0x0c984420
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -      esi = 0x10620c00    edi = 0x0f12d1a0
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -  4  xul.dll!mozilla::DataChannelConnection::ReceiveCallback::<lambda_9>::operator()() [DataChannel.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 2372]
[task 2024-06-20T22:00:50.503Z] 22:00:50     INFO -     Found by: inlining
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -  5  xul.dll!mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/netwerk/sctp/datachannel/DataChannel.cpp:2365:7'>::Run() [nsThreadUtils.h:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 548 + 0x77]
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      eip = 0x6568aca4    esp = 0x0a3ff808    ebp = 0x0a3ff824    ebx = 0x0c984420
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      esi = 0x00002008    edi = 0x10620c00
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -  6  xul.dll!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 1198 + 0xd]
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      eip = 0x64d3b795    esp = 0x0a3ff82c    ebp = 0x0a3ff960    ebx = 0x0c984420
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      esi = 0x04f7d320    edi = 0x04f7d400
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -  7  xul.dll!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 480 + 0x15]
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      eip = 0x64d42014    esp = 0x0a3ff968    ebp = 0x0a3ff984    ebx = 0x00000000
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      esi = 0x04f7d320    edi = 0x0a3ffa58
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -  8  xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 300 + 0x9]
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      eip = 0x6571de31    esp = 0x0a3ff98c    ebp = 0x0a3ff9b8    ebx = 0x00000000
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -      esi = 0x04f9b430    edi = 0x0a3ffa58
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.504Z] 22:00:50     INFO -  9  xul.dll!MessageLoop::RunInternal() [message_loop.cc:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 370 + 0x10]
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      eip = 0x656a8f53    esp = 0x0a3ff9c0    ebp = 0x0a3ff9e4    ebx = 0x6571dd50
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      esi = 0x0a3ffa58    edi = 0x04f9b430
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO - 10  xul.dll!MessageLoop::RunHandler() [message_loop.cc:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 363 + 0x4]
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      eip = 0x656a8e51    esp = 0x0a3ff9ec    ebp = 0x0a3ffa18    ebx = 0x0000000d
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      esi = 0x0a3ffa58    edi = 0x04f8bd14
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO - 11  xul.dll!MessageLoop::Run() [message_loop.cc:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 345 + 0x4]
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      eip = 0x656a8d16    esp = 0x0a3ffa20    ebp = 0x0a3ffa38    ebx = 0x0000000d
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      esi = 0x0a3ffa58    edi = 0x04f8bd14
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO - 12  xul.dll!nsThread::ThreadFunc(void*) [nsThread.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 370 + 0x6]
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      eip = 0x64d36ee0    esp = 0x0a3ffa40    ebp = 0x0a3ffb3c    ebx = 0x0000000d
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -      esi = 0x0a3ffa58    edi = 0x04f8bd14
[task 2024-06-20T22:00:50.505Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO - 13  nss3.dll!_PR_NativeRunThread(void*) [pruthr.c:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 399 + 0xe]
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      eip = 0x714db0c4    esp = 0x0a3ffb44    ebp = 0x0a3ffb60    ebx = 0x04f8bd10
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      esi = 0x04f55430    edi = 0x04f554e0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO - 14  nss3.dll!pr_root(void*) [w95thred.c:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 139 + 0xe]
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      eip = 0x714ccfe6    esp = 0x0a3ffb68    ebp = 0x0a3ffb70    ebx = 0x767e59a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      esi = 0x04f55430    edi = 0x04b0c0a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO - 15  ucrtbase.dll!thread_start<unsigned int (__stdcall*)(void *),1> + 0x42
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      eip = 0x767e59e3    esp = 0x0a3ffb78    ebp = 0x0a3ffba8    ebx = 0x767e59a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      esi = 0x714ccfd0    edi = 0x04b0c0a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO - 16  kernel32.dll!BaseThreadInitThunk + 0x18
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      eip = 0x766c7ba9    esp = 0x0a3ffbb0    ebp = 0x0a3ffbb8    ebx = 0x767e59a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -      esi = 0x714ccfd0    edi = 0x04b0c0a0
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.506Z] 22:00:50     INFO - 17  mozglue.dll!mozilla::interceptor::FuncHook<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyShared>,void (*)(int, void *, void *) __attribute__((fastcall))>::operator()(int&, void*&, void*&) const [nsWindowsDllInterceptor.h:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 150]
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -     Found by: inlining
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO - 18  mozglue.dll!patched_BaseThreadInitThunk(int, void*, void*) [WindowsDllBlocklist.cpp:d9e1c4b495cb148848fd3ad0b73fb8ba03b71f30 : 562 + 0x13]
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      eip = 0x718ee3c0    esp = 0x0a3ffbc0    ebp = 0x0a3ffbec    ebx = 0x767e59a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      esi = 0x714ccfd0    edi = 0x04b0c0a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO - 19  ntdll.dll!__RtlUserThreadStart + 0x2a
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      eip = 0x7726be3b    esp = 0x0a3ffbf4    ebp = 0x0a3ffc44    ebx = 0x04b0c0a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      esi = 0x766c7b90    edi = 0x767e59a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO - 20  ntdll.dll!_RtlUserThreadStart + 0x1a
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      eip = 0x7726bdbf    esp = 0x0a3ffc4c    ebp = 0x0a3ffc54    ebx = 0x04b0c0a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -      esi = 0x766c7b90    edi = 0x767e59a0
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO -     Found by: call frame info
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO - 
[task 2024-06-20T22:00:50.507Z] 22:00:50     INFO - Thread 0 MainThread

Comment 1

[Norisz Fay [:noriszfay]]

Retriggers & Backfills point to this push. Nika, could you take a look please? Thank you!

Comment 2

[Nika Layzell [:nika] (ni? for response)]

I can't think of any reason why this would be connected to process selection tweaks without there being an existing underlying issue with the networking code. :jesup do you know who would be familiar with this code?

Comment 3

[Intermittent Failures Robot]

11 failures in 4577 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-central: 1

Platform and build breakdown:

• windows11-32-2009-qr: 9
  • debug: 9
• linux1804-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1903905&startday=2024-06-17&endday=2024-06-23&tree=all

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

I wrote most of that code. It's odd that it would be related to those patches, though I haven't looked at them in any detail.
The assertion implies that somehow the stream got set to INVALID_STREAM (got closed/cleaned up, etc) and then OpenFinish() was called. Perhaps the changes caused a timing change and exposed a hole in the DataChannels code.

Comment 5

[Byron Campen [:bwc]]

So the only place I see us going from INVALID_STREAM to something valid is when we hook the DataChannelConnection to the transport; if that has already happened, and a new DataChannel is then added, and then we get the callback from libusrsctp, we'll hit this assertion I think. Small variations on the timing of network stuff could easily make this happen.

We probably need to be checking whether we're already hooked to a transport (and know our max stream id) whenever we add a channel, and assign it an id if so.

Comment 6

[Byron Campen [:bwc]]

Hmm. The trouble with that hypothesis is that the only place I see where we set the id to INVALID_STREAM is prior to us hooking the DataChannelConnection to the transport, so it is unclear how we got here... looking some more.

Comment 7

[Byron Campen [:bwc]]

I think I see what's happening here. We're creating a channel, and then pretty much immediately closing it. This removes it from mChannels, but not mPending. Then, ICE connects, and the DataChannelConnection connects, and calls ProcessQueuedOpens, which processes mPending, which still contains that closed channel. Let me try to write a crashtest.

Comment 8

[Intermittent Failures Robot]

12 failures in 4116 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5
• autoland: 7

Platform and build breakdown:

• linux1804-64-qr: 4
  • debug: 4
• windows11-32-2009-qr: 6
  • debug: 6
• windows11-64-2009-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1903905&startday=2024-06-24&endday=2024-06-30&tree=all

Comment 9

[Byron Campen [:bwc]]

Attachment: Bug 1903905: Test case for bug. r?ng

The issue here is that closing a DataChannel before the transport is connected
does not remove that channel from the data structure that holds DataChannels
that are waiting to open.

Comment 10

[Byron Campen [:bwc]]

Attachment: Bug 1903905: Remove channels from mPending when they are closed. r?ng

Also, put mPending in the "main and STS" group where it belonged, and add a lock annotation.

Depends on D215419

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fc7a23cf4c8e
Test case for bug. r=ng
https://hg.mozilla.org/integration/autoland/rev/adc2c8c49de2
Remove channels from mPending when they are closed. r=ng

Comment 12

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/fc7a23cf4c8e
https://hg.mozilla.org/mozilla-central/rev/adc2c8c49de2

Comment 13

[Intermittent Failures Robot]

4 failures in 3199 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2
• mozilla-central: 2

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1
• windows11-64-2009-qr: 3
  • debug: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1903905&startday=2024-07-01&endday=2024-07-07&tree=all