1800942 - Intermittent /webrtc/RTCRtpSender-encode-same-track-twice.https.html | application crashed [@ MOZ_Crash]

Status: NEW

(Core :: WebRTC, defect, P3)

Description

[Treeherder Bug Filer]

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

---

[task 2022-11-16T17:12:48.237Z] 17:12:48     INFO - TEST-START | /webrtc/RTCRtpSender-encode-same-track-twice.https.html
[task 2022-11-16T17:12:48.270Z] 17:12:48     INFO - Closing window f7ce579c-bd78-45e1-8a84-7cf51b21647f
[task 2022-11-16T17:13:06.293Z] 17:13:06     INFO - Browser not responding, setting status to CRASH
[task 2022-11-16T17:13:06.628Z] 17:13:06     INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump-stackwalk/minidump-stackwalk --symbols-url=https://symbols.mozilla.org/ --human /tmp/tmp2cbcipt6/38263594-2954-9822-26c0-384c20ef797c.dmp /builds/worker/workspace/build/symbols
[task 2022-11-16T17:13:11.236Z] 17:13:11     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/38263594-2954-9822-26c0-384c20ef797c.dmp
[task 2022-11-16T17:13:11.236Z] 17:13:11     INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/38263594-2954-9822-26c0-384c20ef797c.extra
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - PROCESS-CRASH | /webrtc/RTCRtpSender-encode-same-track-twice.https.html | application crashed [@ MOZ_Crash(char const*, int, char const*)]
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Mozilla crash reason: abort() called from libxul.so:4f4ef7a ()
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Crash dump filename: /tmp/tmp2cbcipt6/38263594-2954-9822-26c0-384c20ef797c.dmp
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Operating system: Android
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO -                   0.0.0 Linux 3.10.0+ #260 SMP PREEMPT Fri May 19 12:48:14 PDT 2017 x86_64
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - CPU: amd64
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO -      family 6 model 6 stepping 3
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO -      4 CPUs
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - 
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Crash reason:  SIGSEGV / SEGV_MAPERR
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Crash address: 0x0
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Process uptime: not available
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - 
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO - Thread 35 WebrtcWorker #2 (crashed)
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO -  0  libmozglue.so!MOZ_Crash(char const*, int, char const*) [Assertions.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 261]
[task 2022-11-16T17:13:11.476Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -  1  libmozglue.so!mozalloc_abort [mozalloc_abort.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 35 + 0x12]
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rax = 0x00007e76ba6b6d50    rdx = 0x0000000000000004
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rcx = 0x2d1dfbb4865dde62    rbx = 0x00007e7693cfe820
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rsi = 0x00007e7693cfe150    rdi = 0x000000000000001b
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rbp = 0x00007e7693cfe810    rsp = 0x00007e7693cfe800
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -       r8 = 0x0000000000000000     r9 = 0x00007e76c6784090
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r10 = 0x0000000000000022    r11 = 0x0000000000000246
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r12 = 0x00007e76a49463c3    r13 = 0x00007e76a494713a
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r14 = 0x00007e7693cfe9e0    r15 = 0x00007e7693cfea00
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rip = 0x00007e76ba374a0b
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -     Found by: given as instruction pointer in context
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -  2  libmozglue.so!abort [mozalloc_abort.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 88 + 0x7]
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rbx = 0x00007e7693cfe820    rbp = 0x00007e7693cfe870
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rsp = 0x00007e7693cfe820    r12 = 0x00007e76a49463c3
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r13 = 0x00007e76a494713a    r14 = 0x00007e7693cfe9e0
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r15 = 0x00007e7693cfea00    rip = 0x00007e76ba374a4e
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -  3  libxul.so!(anonymous namespace)::WriteFatalLogAndAbort(absl::string_view) [checks.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 54 + 0x4]
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rbx = 0x00007e76c3d6fbf0    rbp = 0x00007e7693cfe8b0
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rsp = 0x00007e7693cfe880    r12 = 0x00007e76a49463c3
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r13 = 0x00007e76a494713a    r14 = 0x00007e7693cfe9e0
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      r15 = 0x00007e7693cfea00    rip = 0x00007e76a0c49f7a
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -  4  libxul.so!rtc::webrtc_checks_impl::FatalLog(char const*, int, char const*, rtc::webrtc_checks_impl::CheckArgType const*, ...) [checks.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 170 + 0x13]
[task 2022-11-16T17:13:11.477Z] 17:13:11     INFO -      rbx = 0x00007e7693cfe970    rbp = 0x00007e7693cfea30
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      rsp = 0x00007e7693cfe8c0    r12 = 0x00007e76a49463c3
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      r13 = 0x00007e76a494713a    r14 = 0x00007e7693cfe9e0
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      r15 = 0x00007e7693cfea00    rip = 0x00007e76a0c49ede
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -  5  libxul.so!rtc::webrtc_checks_impl::LogStreamer<>::CallCheckOp<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long>, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int> >(char const*, int, char const*, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long> const, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int>&) [checks.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 257]
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -  6  libxul.so!rtc::webrtc_checks_impl::LogStreamer<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long> >::CallCheckOp<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int> >(char const*, int, char const*, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int> const&) const [checks.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 306]
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -  7  libxul.so!rtc::webrtc_checks_impl::LogStreamer<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int>, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long> >::CallCheckOp<>(char const*, int, char const*, const&) const [checks.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 306]
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -  8  libxul.so!rtc::webrtc_checks_impl::FatalLogCall<true>::operator&<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int>, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long> >(rtc::webrtc_checks_impl::LogStreamer<rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)1, int>, rtc::webrtc_checks_impl::Val<(rtc::webrtc_checks_impl::CheckArgType)2, long> > const&) [checks.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 335]
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -  9  libxul.so!webrtc::rtc_units_impl::UnitBase<webrtc::Timestamp>::FromValue<long, (void*)0>(long) [unit_base.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 98 + 0x24]
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      rbx = 0xfffffffffd3b044b    rbp = 0x00007e7693cfea40
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      rsp = 0x00007e7693cfea40    r12 = 0x00007e76950d9a08
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0xfffffffffff6b554
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -      r15 = 0x000000003196474d    rip = 0x00007e769f461e4a
[task 2022-11-16T17:13:11.478Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO - 10  libxul.so!webrtc::Timestamp::Micros<long>(long) [timestamp.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 44]
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO - 11  libxul.so!webrtc::Timestamp::operator+(webrtc::TimeDelta) const [timestamp.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 82 + 0x7]
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rbx = 0xfffffffffd3b044b    rbp = 0x00007e7693cfea70
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rsp = 0x00007e7693cfea50    r12 = 0x00007e76950d9a08
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0xfffffffffff6b554
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r15 = 0x000000003196474d    rip = 0x00007e769f45dace
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO - 12  libxul.so!webrtc::TimestampExtrapolator::ExtrapolateLocalTime(unsigned int) const [timestamp_extrapolator.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 0 + 0xa]
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rbx = 0x00007e76950dd580    rbp = 0x00007e7693cfea90
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rsp = 0x00007e7693cfea80    r12 = 0x00007e76950d9a08
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0xfffffffffff6b554
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r15 = 0x000000003196474d    rip = 0x00007e76a0c5bc3f
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO - 13  libxul.so!webrtc::VCMTiming::RenderTimeInternal(unsigned int, webrtc::Timestamp) const [timing.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 202 + 0x4]
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rbx = 0x00007e76950d9a00    rbp = 0x00007e7693cfead0
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      rsp = 0x00007e7693cfeaa0    r12 = 0x00007e76950d9a08
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0x0000000001016744
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -      r15 = 0x000000003196474d    rip = 0x00007e76a0c15427
[task 2022-11-16T17:13:11.479Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO - 14  libxul.so!webrtc::VCMTiming::RenderTime(unsigned int, webrtc::Timestamp) const [timing.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 184 + 0xd]
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rbx = 0x00007e76950d9a00    rbp = 0x00007e7693cfeb00
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rsp = 0x00007e7693cfeae0    r12 = 0x00007e76950d9a08
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0x0000000001016744
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r15 = 0x000000003196474d    rip = 0x00007e76a0c153d4
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO - 15  libxul.so!webrtc::video_coding::FrameBuffer::FindNextFrame(webrtc::Timestamp) [frame_buffer2.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 222 + 0x9]
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rbx = 0x0000000000000861    rbp = 0x00007e7693cfebb0
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rsp = 0x00007e7693cfeb10    r12 = 0x00007e7695bc9000
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r13 = 0x00007e769490c730    r14 = 0x00007e769490ca30
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r15 = 0x00007e769490c670    rip = 0x00007e76a0c1716a
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO - 16  libxul.so!webrtc::video_coding::FrameBuffer::StartWaitForNextFrameOnQueue() [frame_buffer2.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 108 + 0x17]
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rbx = 0x00007e769490c670    rbp = 0x00007e7693cfec20
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      rsp = 0x00007e7693cfebc0    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e769490c7c8
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -      r15 = 0x00007e769490c7c8    rip = 0x00007e76a0c16e40
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO - 17  libxul.so!webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5::operator()() const [frame_buffer2.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 530]
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.480Z] 17:13:11     INFO - 18  libxul.so!std::__ndk1::__invoke<webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5, >(webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5&&, &&) [type_traits : 3501]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 19  libxul.so!std::__ndk1::invoke<webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5, >(webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5&&, &&) [functional : 2902]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 20  libxul.so!absl::internal_any_invocable::InvokeR<void, webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5, , void>(webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5&&, &&) [any_invocable.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 130]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 21  libxul.so!absl::internal_any_invocable::LocalInvoker<false, void, webrtc::video_coding::FrameBuffer::InsertFrame(std::__ndk1::unique_ptr<webrtc::EncodedFrame, std::__ndk1::default_delete<webrtc::EncodedFrame> >)::$_5&&, >(absl::internal_any_invocable::TypeErasedState*, absl::internal_any_invocable::ForwardedParameter<>::type) [any_invocable.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 302 + 0x3b]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rbx = 0x00007e769490c670    rbp = 0x00007e7693cfec50
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rsp = 0x00007e7693cfec30    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e769490c780
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r15 = 0x00007e769490c7c8    rip = 0x00007e76a0c204e7
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 22  libxul.so!webrtc::(anonymous namespace)::Task::Run() [task_queue_base.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 101 + 0x8]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rbx = 0x00007e76950d2220    rbp = 0x00007e7693cfec60
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rsp = 0x00007e7693cfec60    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e7692fefc68
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r15 = 0x00007e7693cfec70    rip = 0x00007e76a0aa27af
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 23  libxul.so!mozilla::TaskQueueWrapper<(mozilla::DeletionPolicy)0>::CreateTaskRunner(std::__ndk1::unique_ptr<webrtc::QueuedTask, std::__ndk1::default_delete<webrtc::QueuedTask> >)::{lambda()#1}::operator()() [TaskQueueWrapper.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 85 + 0x5]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rbx = 0x00007e76950d2220    rbp = 0x00007e7693cfed00
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rsp = 0x00007e7693cfec70    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e7692fefc68
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r15 = 0x00007e7693cfec70    rip = 0x00007e769f5429c0
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO - 24  libxul.so!mozilla::detail::RunnableFunction<mozilla::TaskQueueWrapper<(mozilla::DeletionPolicy)0>::CreateTaskRunner(std::__ndk1::unique_ptr<webrtc::QueuedTask, std::__ndk1::default_delete<webrtc::QueuedTask> >)::{lambda()#1}>::Run() [nsThreadUtils.h:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 531 + 0x8]
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rbx = 0x00007e7693cfed30    rbp = 0x00007e7693cfed10
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      rsp = 0x00007e7693cfed10    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.481Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e7693cfed90
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r15 = 0x00007e7693cfed40    rip = 0x00007e769f5428e3
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO - 25  libxul.so!mozilla::TaskQueue::Runner::Run() [TaskQueue.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 259 + 0x10]
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rbx = 0x00007e7693cfed30    rbp = 0x00007e7693cfee30
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rsp = 0x00007e7693cfed20    r12 = 0x00007e7693cfeda0
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r13 = 0x00007e76925bc218    r14 = 0x00007e7693cfed90
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r15 = 0x00007e7693cfed40    rip = 0x00007e769d1203ff
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO - 26  libxul.so!nsThreadPool::Run() [nsThreadPool.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 309 + 0x10]
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rbx = 0x00007e7693cfeea0    rbp = 0x00007e7693cfef50
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rsp = 0x00007e7693cfee40    r12 = 0x00007e7693cfee90
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r13 = 0x00007e7693cfeec0    r14 = 0x0000000000000000
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r15 = 0x00007e76c06943a0    rip = 0x00007e769d131a3b
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO - 27  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 1198 + 0x10]
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rbx = 0x00007e7693cfef90    rbp = 0x00007e7693cff090
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rsp = 0x00007e7693cfef60    r12 = 0x00007e76c066e118
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r13 = 0x00007e7693cff000    r14 = 0xaaaaaaaaaaaaaaaa
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r15 = 0x00007e76c066dff0    rip = 0x00007e769d12bfaf
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO - 28  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 465 + 0x12]
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rbx = 0x00007e76c066dff0    rbp = 0x00007e7693cff0d0
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      rsp = 0x00007e7693cff0a0    r12 = 0x00007e7693cff0e8
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r13 = 0x00007e76950c3f60    r14 = 0x0000000000000000
[task 2022-11-16T17:13:11.482Z] 17:13:11     INFO -      r15 = 0x00007e7693cff0af    rip = 0x00007e769d130290
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO - 29  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 300 + 0x9]
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rbx = 0x00007e7693cff1f0    rbp = 0x00007e7693cff120
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rsp = 0x00007e7693cff0e0    r12 = 0x00007e7693cff0e8
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r13 = 0x00007e76950c3f60    r14 = 0x00007e76950c3f40
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r15 = 0x00007e76c066dff0    rip = 0x00007e769d815f5e
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO - 30  libxul.so!MessageLoop::RunInternal() [message_loop.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 381 + 0x16]
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rbx = 0x00007e7693cff1f0    rbp = 0x00007e7693cff160
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rsp = 0x00007e7693cff130    r12 = 0x00007e76c066e038
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r13 = 0x0000000000000002    r14 = 0x00007e7693cff170
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r15 = 0x00007e76c066dff0    rip = 0x00007e769d7b9a94
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO - 31  libxul.so!MessageLoop::RunHandler() [message_loop.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 374]
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -     Found by: inlining
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO - 32  libxul.so!MessageLoop::Run() [message_loop.cc:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 356 + 0x7]
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rbx = 0x00007e7693cff1f0    rbp = 0x00007e7693cff1a0
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rsp = 0x00007e7693cff170    r12 = 0x00007e76c066e038
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r13 = 0x0000000000000002    r14 = 0x00007e7693cff170
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      r15 = 0x00007e76c066dff0    rip = 0x00007e769d7b99fd
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO - 33  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 383 + 0x7]
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rbx = 0x00007e7693cff1f0    rbp = 0x00007e7693cff3a0
[task 2022-11-16T17:13:11.483Z] 17:13:11     INFO -      rsp = 0x00007e7693cff1b0    r12 = 0x00007e76c066e038
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r13 = 0x0000000000000002    r14 = 0x000000000000000f
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r15 = 0x00007e76c066dff0    rip = 0x00007e769d128ce2
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO - 34  libnss3.so!_pt_root [ptthread.c:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 201 + 0x9]
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rbx = 0x00007e7693cff4f8    rbp = 0x00007e7693cff3e0
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rsp = 0x00007e7693cff3b0    r12 = 0x00007e76950a3020
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r13 = 0x0000000000000002    r14 = 0x00000000000005eb
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r15 = 0x00007e7693cff450    rip = 0x00007e76a7efefdd
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO - 35  libc.so!__pthread_start(void*) + 0xb1
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rbx = 0x00007e7693cff4d0    rbp = 0x00000000000005ba
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rsp = 0x00007e7693cff3f0    r12 = 0x00007e7693cff450
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r13 = 0x00007e76a7efee92    r14 = 0x00007e7693cff450
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r15 = 0x00007e7693cff4e8    rip = 0x00007e76c3d06772
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO - 36  libc.so!__start_thread + 0xb
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rbx = 0x00007e7694a4c450    rbp = 0x00000000000005ba
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rsp = 0x00007e7693cff440    r12 = 0x0000000000000016
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r13 = 0x00007e76a7efee92    r14 = 0x00007e7693cff450
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r15 = 0x00007e7693cff4e8    rip = 0x00007e76c3ca69ec
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO - 37  libc.so!__bionic_clone + 0x35
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rbx = 0x00007e7694a4c450    rbp = 0x00000000000005ba
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      rsp = 0x00007e7693cff450    r12 = 0x0000000000000016
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r13 = 0x00007e76a7efee92    r14 = 0x00007e7693cff450
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -      r15 = 0x00007e7693cff4e8    rip = 0x00007e76c3c99a66
[task 2022-11-16T17:13:11.484Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO - 38  0x7e769464f44f
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -      rbx = 0x00007e7694a4c450    rbp = 0x00000000000005ba
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -      rsp = 0x00007e7693cff458    r12 = 0x0000000000000016
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -      r13 = 0x00007e76a7efee92    r14 = 0x00007e7693cff450
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -      r15 = 0x00007e7693cff4e8    rip = 0x00007e769464f450
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -     Found by: call frame info
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO - 39  libnss3.so!pt_recvfrom_cont [ptio.c:6dc6fdc72146b26115d437eea71671f73d6c1a95 : 0 + 0x4]
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -      rsp = 0x00007e7693cff4b8    rip = 0x00007e76a7efee92
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO -     Found by: stack scanning
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO - 
[task 2022-11-16T17:13:11.485Z] 17:13:11     INFO - Thread 0 st_runner:tab36

Comment 1

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

From stack frame 11 it seems we're here, but some assert is triggered, causing a "FatalLogCall" with some error message.

Two problems:

1. the logging of the error probably shouldn't crash (or is it output somewhere?)
2. what caused the assert here?

Any chance either of these have been fixed upstream?

Comment 2

[Intermittent Failures Robot]

1 failures in 3589 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1800942&startday=2022-11-14&endday=2022-11-20&tree=all

Comment 3

[Michael Froman [:mjf]]

This is not the logging asserting, this is libwebrtc's debug assert (RTC_DCHECK_GE) firing (and logging) from here. That would appear to mean we're getting a negative value somewhere around here:
https://searchfox.org/mozilla-central/rev/83b86005c6913c2062419efb8aabdf2e683aa47f/third_party/libwebrtc/modules/video_coding/timing/timing.cc#201-202

Comment 4

[Byron Campen [:bwc]]

Maybe related to bug 1774429? Not seeing this crash on crash-stats, although there are a handful of other (rare) crashes in rtc_units_impl.

Comment 5

[Michael Froman [:mjf]]

We now have 2 other intermittents that are likely duplicates of this bug. It appears something weird is happening with a timestamp in VCMTiming::RenderTimeInternal. Andreas, is this something you'd have time to look into?

Comment 6

[Andreas Pehrson [:pehrsons]]

This particular bug has frame_buffer2.cc on the stack, and we now use FrameBuffer3 (aka VideoStreamBufferController).

That said, the root cause seems orthogonal to which jitter buffer is being used. Also, related: https://bugs.webrtc.org/14387.

Some notes:

• In bug 1809085 we give the Timestamp a value of -4283370913.
  From the log we know that this is not the timestamp of the first frame, because the dimensions of the sink are known:

  [task 2023-01-08T19:25:06.249Z] 19:25:06     INFO - testing max-fs withVP8
  [task 2023-01-08T19:25:06.250Z] 19:25:06     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_maxFsConstraint.html | v2.currentTime is zero at outset 
  [task 2023-01-08T19:25:06.251Z] 19:25:06     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_maxFsConstraint.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
  [task 2023-01-08T19:25:06.252Z] 19:25:06     INFO - Buffered messages logged at 19:24:52
  [task 2023-01-08T19:25:06.253Z] 19:25:06     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_maxFsConstraint.html | sink width should be 184 for VP8 
  [task 2023-01-08T19:25:06.254Z] 19:25:06     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_maxFsConstraint.html | sink height should be 138 for VP8 
  [task 2023-01-08T19:25:06.255Z] 19:25:06     INFO - Buffered messages finished
  [task 2023-01-08T19:25:06.256Z] 19:25:06    ERROR - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_maxFsConstraint.html | application terminated with exit code 245
  

• In bug 1809414 we give the Timestamp a value of -4234360650. This is close to what we saw in bug 1809085.
• Both known timestamps are reasonably close to -0xFFFFFFFF in int64. This is interesting given that uint32 is an input to ExtrapolateLocalTime.
• In both cases we know that the inputs to the extrapolator can not originate from timestamps close to 0 on the send side's clock.
• In bug 1809414 we know that the inputs to the extrapolator can not originate from the first received frame for the stream, since we had already rendered a frame.

I did some auditing and the only possible path I see is that the current time when the extrapolator was created is smaller than the absolute value of a negative diff_ms here. On the other hand, diff_ms being close to -std::numeric_limits<uint32_t>::max seems weird too.

In either case, we should verify what's happening with some new DCHECKs.

Comment 7

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1800942 - Add DCHECKs to TimestampExtrapolator::ExtrapolateLocalTime. r?mjf!

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c5df7f403924
Add DCHECKs to TimestampExtrapolator::ExtrapolateLocalTime. r=mjf

Comment 9

[Marian-Vasile Laza]

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

Comment 10

[Andreas Pehrson [:pehrsons]]

Bug 1809414 has hit one of the new asserts:

# Fatal error in: /builds/worker/checkouts/gecko/third_party/libwebrtc/rtc_base/time/timestamp_extrapolator.cc, line 146
# Check failed: start_.ms() >= -diff_ms (10312 vs. 4290079)

Comment 11

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1800942 - Temporarily log inputs to ExtrapolateLocalTime. r?mjf!

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/612964d3bb31
Temporarily log inputs to ExtrapolateLocalTime. r=mjf

Comment 13

[Marian-Vasile Laza]

https://hg.mozilla.org/mozilla-central/rev/612964d3bb31

Comment 14

[Andreas Pehrson [:pehrsons]]

The last patch wasn't effective because the test runner only processes stdout, not stderr.

Comment 15

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1800942 - Switch to stdout as it will get logged by the mochitest runner. r?mjf!

Also log this to distinguish between potentially more than one extrapolator.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6ba79ee429e5
Switch to stdout as it will get logged by the mochitest runner. r=mjf

Comment 17

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/6ba79ee429e5

Comment 18

[Andreas Pehrson [:pehrsons]]

It seems that last logging patch made the crash go away. Or did we fix it elsewhere?

Comment 19

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1800942 - Remove continuous logging to stdout in TimestampExtrapolator. r?mjf!

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/43b95ba3c529
Remove continuous logging to stdout in TimestampExtrapolator. r=mjf

Comment 21

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/43b95ba3c529