1484046 - Intermittent dom/media/webaudio/test/test_convolverNodeChannelInterpretationChanges.html | application crashed [@ mozilla::TimeStamp::operator-(mozilla::TimeStamp const&) const]

Status: RESOLVED FIXED

(Core :: Web Audio, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: aciure [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=194360015&repo=autoland

https://queue.taskcluster.net/v1/task/PMGbGM81TK64ARYDY6Hz5Q/runs/0/artifacts/public/logs/live_backing.log

[task 2018-08-16T17:12:03.518Z] 17:12:03     INFO -  137 INFO TEST-START | dom/media/webaudio/test/test_convolverNodeChannelInterpretationChanges.html
[task 2018-08-16T17:14:09.967Z] 17:14:09     INFO -  wait for org.mozilla.fennec_aurora complete; top activity=com.android.launcher
[task 2018-08-16T17:14:10.175Z] 17:14:10     INFO -  INFO | automation.py | Application ran for: 0:20:02.169929
[task 2018-08-16T17:14:10.176Z] 17:14:10     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpPbduXPpidlog
[task 2018-08-16T17:14:10.817Z] 17:14:10     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2018-08-16T17:14:11.546Z] 17:14:11     INFO -  mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpqcCA3k/2a372035-6d6f-7a19-957c-d23b0756b642.dmp /builds/worker/workspace/build/symbols
[task 2018-08-16T17:14:24.168Z] 17:14:24     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/2a372035-6d6f-7a19-957c-d23b0756b642.dmp
[task 2018-08-16T17:14:24.168Z] 17:14:24     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/2a372035-6d6f-7a19-957c-d23b0756b642.extra
[task 2018-08-16T17:14:24.172Z] 17:14:24  WARNING -  PROCESS-CRASH | dom/media/webaudio/test/test_convolverNodeChannelInterpretationChanges.html | application crashed [@ mozilla::TimeStamp::operator-(mozilla::TimeStamp const&) const]
[task 2018-08-16T17:14:24.172Z] 17:14:24     INFO -  Crash dump filename: /tmp/tmpqcCA3k/2a372035-6d6f-7a19-957c-d23b0756b642.dmp
[task 2018-08-16T17:14:24.172Z] 17:14:24     INFO -  Operating system: Android
[task 2018-08-16T17:14:24.173Z] 17:14:24     INFO -                    0.0.0 Linux 2.6.29-gea477bb #1 Wed Sep 26 11:04:45 PDT 2012 armv7l
[task 2018-08-16T17:14:24.173Z] 17:14:24     INFO -  CPU: arm
[task 2018-08-16T17:14:24.173Z] 17:14:24     INFO -       ARMv7 ARM Cortex-A8 features: swp,half,thumb,fastmult,vfpv2,edsp,neon,vfpv3
[task 2018-08-16T17:14:24.173Z] 17:14:24     INFO -       1 CPU
[task 2018-08-16T17:14:24.174Z] 17:14:24     INFO -  GPU: UNKNOWN
[task 2018-08-16T17:14:24.174Z] 17:14:24     INFO -  Crash reason:  SIGSEGV
[task 2018-08-16T17:14:24.174Z] 17:14:24     INFO -  Crash address: 0x0
[task 2018-08-16T17:14:24.175Z] 17:14:24     INFO -  Process uptime: not available
[task 2018-08-16T17:14:24.175Z] 17:14:24     INFO -  Thread 12 (crashed)
[task 2018-08-16T17:14:24.175Z] 17:14:24     INFO -   0  libxul.so!mozilla::TimeStamp::operator-(mozilla::TimeStamp const&) const [TimeStamp.h:3c2f920f1a2d73d710f18360dc9cd723121d3b42 : 0 + 0x6]
[task 2018-08-16T17:14:24.176Z] 17:14:24     INFO -       r0 = 0x00000000    r1 = 0xd1928dc6    r2 = 0x5f16dd4e    r3 = 0x000001f2
[task 2018-08-16T17:14:24.176Z] 17:14:24     INFO -       r4 = 0x000001f2    r5 = 0x56062880    r6 = 0x56fd9230    r7 = 0x52c152b8
[task 2018-08-16T17:14:24.177Z] 17:14:24     INFO -       r8 = 0x00000000    r9 = 0x00000000   r10 = 0x52c152d0   r12 = 0x00000003
[task 2018-08-16T17:14:24.177Z] 17:14:24     INFO -       fp = 0x52c15308    sp = 0x52c152a0    lr = 0x5bca2119    pc = 0x5bca68b2
[task 2018-08-16T17:14:24.177Z] 17:14:24     INFO -      Found by: given as instruction pointer in context
[task 2018-08-16T17:14:24.178Z] 17:14:24     INFO -   1  libxul.so!mozilla::dom::SharedBuffers::FinishProducingOutputBuffer(mozilla::AudioChunk const&) [ScriptProcessorNode.cpp:3c2f920f1a2d73d710f18360dc9cd723121d3b42 : 141 + 0x7]
[task 2018-08-16T17:14:24.178Z] 17:14:24     INFO -       r4 = 0x573e90a0    r5 = 0x56062880    r6 = 0x56fd9230    r7 = 0x52c15300
[task 2018-08-16T17:14:24.179Z] 17:14:24     INFO -       r8 = 0x52c152d0    r9 = 0x52c153f8   r10 = 0x56fd91f0    fp = 0x52c15308
[task 2018-08-16T17:14:24.179Z] 17:14:24     INFO -       sp = 0x52c152c0    lr = 0x5cf93df7    pc = 0x5cf93df7
[task 2018-08-16T17:14:24.179Z] 17:14:24     INFO -      Found by: call frame info
[task 2018-08-16T17:14:24.180Z] 17:14:24     INFO -   2  libxul.so!mozilla::dom::ScriptProcessorNodeEngine::SendBuffersToMainThread(mozilla::AudioNodeStream*, long long)::Command::Run() [ScriptProcessorNode.cpp:3c2f920f1a2d73d710f18360dc9cd723121d3b42 : 394 + 0x3]
[task 2018-08-16T17:14:24.180Z] 17:14:24     INFO -       r4 = 0x573e90a0    r5 = 0x56062880    r6 = 0x573e6700    r7 = 0x52c15350
[task 2018-08-16T17:14:24.181Z] 17:14:24     INFO -       r8 = 0x00000000    r9 = 0x52c153f8   r10 = 0x52c1586f    fp = 0x52f140b0
[task 2018-08-16T17:14:24.181Z] 17:14:24     INFO -       sp = 0x52c15308    lr = 0x5cf93bd5    pc = 0x5cf93bd5
[task 2018-08-16T17:14:24.181Z] 17:14:24     INFO -      Found by: call frame info
[task 2018-08-16T17:14:24.181Z] 17:14:24     INFO -   3  libxul.so!mozilla::EventTargetWrapper::Runner::Run() [AbstractThread.cpp:3c2f920f1a2d73d710f18360dc9cd723121d3b42 : 150 + 0x5]
[task 2018-08-16T17:14:24.182Z] 17:14:24     INFO -       r4 = 0x573e90e8    r5 = 0x573e90d0    r6 = 0x52c153f5    r7 = 0x52c15370
[task 2018-08-16T17:14:24.182Z] 17:14:24     INFO -       r8 = 0x00000000    r9 = 0x52c153f8   r10 = 0x52c1586f    fp = 0x52f140b0
[task 2018-08-16T17:14:24.182Z] 17:14:24     INFO -       sp = 0x52c15358    lr = 0x5bd0351b    pc = 0x5bd0351b
[task 2018-08-16T17:14:24.183Z] 17:14:24     INFO -      Found by: call frame info

Comment 1

[Karl Tomlinson (:karlt)]

Assertion failure: !aOther.IsNull() (Cannot compute with aOther null value), at /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/TimeStamp.h:498

Comment 2

[Karl Tomlinson (:karlt)]

https://hg.mozilla.org/mozilla-central/annotate/3c2f920f1a2d73d710f18360dc9cd723121d3b42/mozglue/misc/TimeStamp.h#l498
https://hg.mozilla.org/mozilla-central/annotate/3c2f920f1a2d73d710f18360dc9cd723121d3b42/dom/media/webaudio/ScriptProcessorNode.cpp#l141

mLastEventTime is null even though this is the else block for the
mLastEventTime.IsNull() test.

That could happen if Reset() is called between IsNull() and operator-.

Reset() is called from the graph thread.
FinishProducingOutputBuffer() is called on the main thread.

Comment 3

[Karl Tomlinson (:karlt)]

mLatency is also modified on both threads concurrently.

mDelaySoFar is graph thread only.

Comment 4

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0fcbe80c05d4716da48b4c283961c439c1798a0e

Comment 5

[Karl Tomlinson (:karlt)]

Attachment: Bug 1484046 reset variables for main thread buffer dropping logic on the same thread r=padenot

Comment 6

[Intermittent Failures Robot]

18 failures in 527 pushes (0.034 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-central: 8
* autoland: 9
* mozilla-inbound: 1

Platform breakdown:
* android-em-4-3-armv7-api16: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1484046&startday=2018-08-16&endday=2018-08-16&tree=all

Comment 7

[Paul Adenot (:padenot)]

Comment on attachment 9001842 [details]
Bug 1484046 reset variables for main thread buffer dropping logic on the same thread r=padenot

Paul Adenot (:padenot) has approved the revision.

Comment 8

[Tiberius Oros[:tiberius_oros]]

Retriggered jobs for the failure and it seems that this started here:
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=5a18b9c9a5a610cded246291c1c80498eba9dcfb

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/15cca5b18ec4
reset variables for main thread buffer dropping logic on the same thread r=padenot

Comment 10

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/15cca5b18ec4

Comment 11

[Intermittent Failures Robot]

48 failures in 2672 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* try: 6
* mozilla-central: 11
* autoland: 19
* mozilla-inbound: 12

Platform breakdown:
* android-em-4-3-armv7-api16: 48

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1484046&startday=2018-08-13&endday=2018-08-19&tree=all

Comment 12

[Ryan VanderMeulen [:RyanVM]]

IIUC, the underlying bug has been present for a long time, even though this specific failure only spiked recently. That said, probably best to just let this ride the trains?

Comment 13

[Karl Tomlinson (:karlt)]

That's correct.  This was an race that was caught by a new test.

The crash is due to an assertion failure.  The assertion is not made in
release builds.  The race means behavior is undefined, but the consequences
would most likely be dropping some audio output and temporarily producing
silence instead.  There are other perhaps more likely scenarios that could
cause similar behavior, and so I don't see any need to uplift the fix.