Closed Bug 1762887 Opened 4 years ago Closed 2 years ago

Intermittent Assertion failure: mFramesDropped <= 100 (Buffers must be leaking), at /builds/worker/checkouts/gecko/dom/media/VideoFrameConverter.h:371

Categories

(Core :: Audio/Video, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [retriggered])

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


[task 2022-04-04T10:43:07.092Z] 10:43:07     INFO - GECKO(1736) | (ice/INFO) ICE-PEER(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_:default)/ICE-STREAM(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0 - af414889:16d5745ae755ddacc095a297fcbcc342): all active components have nominated candidate pairs
[task 2022-04-04T10:43:07.092Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Flow[transport_0(none)]; Layer[ice]: ICE Ready(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0,1)
[task 2022-04-04T10:43:07.093Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Flow[transport_0(none)]; Layer[dtls]: Lower layer is now open; starting TLS
[task 2022-04-04T10:43:07.093Z] 10:43:07     INFO - GECKO(1736) | (ice/INFO) ICE-PEER(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_:default): all checks completed success=1 fail=0
[task 2022-04-04T10:43:07.094Z] 10:43:07     INFO - GECKO(1736) | (ice/INFO) ICE(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_): peer (PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_:default) cancelling grace period timer
[task 2022-04-04T10:43:07.095Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2022-04-04T10:43:07.096Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport NrIceCtx(PC:{77b62b57-c6cb-4f84-ae9a-b3745729a175} 1649068986955000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_): state 1->2
[task 2022-04-04T10:43:07.096Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2022-04-04T10:43:07.097Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport NrIceCtx(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_): state 1->2
[task 2022-04-04T10:43:07.097Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Handshake would have blocked
[task 2022-04-04T10:43:07.098Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: ****** SSL handshake completed ******
[task 2022-04-04T10:43:07.098Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Selected ALPN string: webrtc
[task 2022-04-04T10:43:07.099Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Created SRTP flow!
[task 2022-04-04T10:43:07.100Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport NrIceCtx(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_)/STREAM(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0) : parsing trickle candidate candidate:0 1 UDP 2122252543 10.0.0.21 57936 typ host
[task 2022-04-04T10:43:07.101Z] 10:43:07     INFO - GECKO(1736) | (ice/ERR) ICE(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_): peer (PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_:default), stream(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0 - af414889:16d5745ae755ddacc095a297fcbcc342) tried to trickle ICE in inappropriate state 4
[task 2022-04-04T10:43:07.102Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0' because it is completed: candidate:0 1 UDP 2122252543 10.0.0.21 57936 typ host
[task 2022-04-04T10:43:07.103Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport NrIceCtx(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_)/STREAM(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0) : parsing trickle candidate candidate:1 1 TCP 2105524479 10.0.0.21 9 typ host tcptype active
[task 2022-04-04T10:43:07.104Z] 10:43:07     INFO - GECKO(1736) | (ice/ERR) ICE(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_): peer (PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_:default), stream(PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0 - af414889:16d5745ae755ddacc095a297fcbcc342) tried to trickle ICE in inappropriate state 4
[task 2022-04-04T10:43:07.105Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:{43595ed3-7642-457b-a3ef-fcf00fcf9631} 1649068986937000 (id=197568495617 url=http://mochi.test:8888/tests/dom/canvas/test/test_ transport-id=transport_0' because it is completed: candidate:1 1 TCP 2105524479 10.0.0.21 9 typ host tcptype active
[task 2022-04-04T10:43:07.106Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: ****** SSL handshake completed ******
[task 2022-04-04T10:43:07.107Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: I/mtransport Flow[transport_0(none)]; Layer[dtls]: Selected ALPN string: webrtc
[task 2022-04-04T10:43:07.107Z] 10:43:07     INFO - GECKO(1736) | [Child 4968: Socket Thread]: D/mtransport Created SRTP flow!
[task 2022-04-04T10:43:07.116Z] 10:43:07     INFO - GECKO(1736) | [RDD 1588, COM MTA] WARNING: NS_ENSURE_TRUE(actsNum > 0) failed: file /builds/worker/checkouts/gecko/dom/media/platforms/wmf/MFTDecoder.cpp:59
[task 2022-04-04T10:43:07.121Z] 10:43:07     INFO - GECKO(1736) | [Parent 6340, Main Thread] WARNING: IPC message 'PContent::Msg_UpdateMediaCodecsSupported' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:506
[task 2022-04-04T10:43:10.579Z] 10:43:10     INFO - GECKO(1736) | Assertion failure: mFramesDropped <= 100 (Buffers must be leaking), at /builds/worker/checkouts/gecko/dom/media/VideoFrameConverter.h:371
[task 2022-04-04T10:43:10.648Z] 10:43:10     INFO - GECKO(1736) | [Child 4968: WebrtcWorker #3]: I/signaling [WebrtcWorker #3|WebrtcVideoSessionConduit] VideoStreamFactory.cpp:204: CreateEncoderStreams Input frame 100x100, RID  scaling to 100x100
[task 2022-04-04T10:43:10.677Z] 10:43:10     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2022-04-04T10:43:20.996Z] 10:43:20     INFO - GECKO(1736) | #01: mozilla::VideoFrameConverter::ProcessVideoFrame(mozilla::VideoFrameConverter::FrameToProcess const&) [dom/media/VideoFrameConverter.h:371]
[task 2022-04-04T10:43:21.011Z] 10:43:21     INFO - GECKO(1736) | #02: mozilla::detail::RunnableMethodImpl<mozilla::VideoFrameConverter *,void (mozilla::VideoFrameConverter::*)(const mozilla::VideoFrameConverter::FrameToProcess &) __attribute__((thiscall)),1,mozilla::RunnableKind::Standard,StoreCopyPassByLRef<mozilla::VideoFrameConverter::FrameToProcess> >::Run() [xpcom/threads/nsThreadUtils.h:1203]
[task 2022-04-04T10:43:21.012Z] 10:43:21     INFO - GECKO(1736) | #03: mozilla::TaskQueue::Runner::Run() [xpcom/threads/TaskQueue.cpp:203]
[task 2022-04-04T10:43:21.012Z] 10:43:21     INFO - GECKO(1736) | #04: nsThreadPool::Run() [xpcom/threads/nsThreadPool.cpp:312]
[task 2022-04-04T10:43:21.013Z] 10:43:21     INFO - GECKO(1736) | #05: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1181]
[task 2022-04-04T10:43:21.013Z] 10:43:21     INFO - GECKO(1736) | #06: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:465]
[task 2022-04-04T10:43:21.014Z] 10:43:21     INFO - GECKO(1736) | #07: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:300]
[task 2022-04-04T10:43:21.014Z] 10:43:21     INFO - GECKO(1736) | #08: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:380]
[task 2022-04-04T10:43:21.014Z] 10:43:21     INFO - GECKO(1736) | #09: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:374]
[task 2022-04-04T10:43:21.015Z] 10:43:21     INFO - GECKO(1736) | #10: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:356]
[task 2022-04-04T10:43:21.015Z] 10:43:21     INFO - GECKO(1736) | #11: static nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:387]
[task 2022-04-04T10:43:21.200Z] 10:43:21     INFO - GECKO(1736) | #12: _PR_NativeRunThread(void*) [nsprpub/pr/src/threads/combined/pruthr.c:399]
[task 2022-04-04T10:43:21.211Z] 10:43:21     INFO - GECKO(1736) | #13: pr_root(void*) [nsprpub/pr/src/md/windows/w95thred.c:139]
[task 2022-04-04T10:43:21.215Z] 10:43:21     INFO -  fix-stacks: error: failed to read debug info file `ucrtbase.pdb` for `C:\Windows\System32\ucrtbase.dll`
[task 2022-04-04T10:43:21.215Z] 10:43:21     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2022-04-04T10:43:21.215Z] 10:43:21     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2022-04-04T10:43:21.216Z] 10:43:21     INFO - GECKO(1736) | #14: o_iswdigit [C:\Windows\System32\ucrtbase.dll + 0x44f9f]
[task 2022-04-04T10:43:21.219Z] 10:43:21     INFO -  fix-stacks: error: failed to read debug info file `wkernel32.pdb` for `C:\Windows\System32\KERNEL32.DLL`
[task 2022-04-04T10:43:21.219Z] 10:43:21     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2022-04-04T10:43:21.219Z] 10:43:21     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2022-04-04T10:43:21.220Z] 10:43:21     INFO - GECKO(1736) | #15: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x1fa29]
[task 2022-04-04T10:43:21.264Z] 10:43:21     INFO - GECKO(1736) | #16: patched_BaseThreadInitThunk(int, void*, void*) [toolkit/xre/dllservices/mozglue/WindowsDllBlocklist.cpp:568]
[task 2022-04-04T10:43:21.280Z] 10:43:21     INFO -  fix-stacks: error: failed to read debug info file `wntdll.pdb` for `C:\Windows\SYSTEM32\ntdll.dll`
[task 2022-04-04T10:43:21.281Z] 10:43:21     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2022-04-04T10:43:21.281Z] 10:43:21     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2022-04-04T10:43:21.281Z] 10:43:21     INFO - GECKO(1736) | #17: RtlGetAppContainerNamedObjectPath [C:\Windows\SYSTEM32\ntdll.dll + 0x67a9e]
[task 2022-04-04T10:43:21.282Z] 10:43:21     INFO - GECKO(1736) | #18: RtlGetAppContainerNamedObjectPath [C:\Windows\SYSTEM32\ntdll.dll + 0x67a6e]
[task 2022-04-04T10:43:21.283Z] 10:43:21     INFO - GECKO(1736) | [Parent 6340, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 1579622B3698B757.D5E1DA95C44B8840: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:340
[task 2022-04-04T10:43:21.283Z] 10:43:21     INFO - GECKO(1736) | [Parent 6340, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 1579622B3698B757.D5E1DA95C44B8840: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:340
[task 2022-04-04T10:43:21.284Z] 10:43:21     INFO - GECKO(1736) | [Parent 6340, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 1579622B3698B757.D5E1DA95C44B8840: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:340
[task 2022-04-04T10:43:21.284Z] 10:43:21     INFO - GECKO(1736) | [2022-04-04T10:43:11Z WARN  audioipc2::ipccore] AudioIPC Server RPC: EventLoop drop - closing connection for Token(6) failed: Custom { kind: NotFound, error: "I/O source not registered with `Registry`" }
[task 2022-04-04T10:43:21.285Z] 10:43:21     INFO - GECKO(1736) | [Parent 6340, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 1579622B3698B757.D5E1DA95C44B8840: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:340
Summary: Intermittent [tier 2] Assertion failure: mFramesDropped <= 100 (Buffers must be leaking), at /builds/worker/checkouts/gecko/dom/media/VideoFrameConverter.h:371 → Intermittent Assertion failure: mFramesDropped <= 100 (Buffers must be leaking), at /builds/worker/checkouts/gecko/dom/media/VideoFrameConverter.h:371
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.