1256081 - Intermittent test_peerConnection_verifyAudioAfterRenegotiation.html | application timed out after 330 seconds with no output | application crashed [@ _pthread_mutex_lock + 0x1e]

Status: RESOLVED INCOMPLETE

(Core :: DOM: Core & HTML, defect, P5)

Description

[Ryan VanderMeulen [:RyanVM]]

Given the InitInternal stuff on the stack, is this related to the other bug I filed today, bz?

https://treeherder.mozilla.org/logviewer.html#?job_id=7980431&repo=fx-team

15:51:48     INFO -  2604 INFO expected audio tracks: 1
15:51:48     INFO -  2605 INFO TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | audio m-line is present in SDP
15:51:48     INFO -  2606 INFO TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | OPUS codec is present in SDP
15:51:48     INFO -  2607 INFO TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | RTCP Mux is offered in SDP
15:51:48     INFO -  2608 INFO expected video tracks: 0
15:51:48     INFO -  2609 INFO TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | video m-line is absent from SDP
15:51:48     INFO -  2610 INFO Run step 30: PC_REMOTE_CREATE_ANSWER
15:51:48     INFO -  2611 INFO PeerConnectionWrapper (pcRemote): Got answer: {"type":"answer","sdp":"v=0\r\no=mozilla...THIS_IS_SDPARTA-48.0a1 2436058496192515126 0 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 B3:3B:91:C0:A7:D8:9E:FF:6B:D2:92:3E:30:80:4F:30:1F:EE:81:5D:C8:68:D7:EF:2D:2F:1A:9A:E7:B1:BF:20\r\na=ice-options:trickle\r\na=msid-semantic:WMS *\r\nm=audio 9 UDP/TLS/RTP/SAVPF 109\r\nc=IN IP4 0.0.0.0\r\na=recvonly\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=fmtp:109 maxplaybackrate=48000;stereo=1\r\na=ice-pwd:c1107837d50050f9e419c9be1451464d\r\na=ice-ufrag:8088a01a\r\na=mid:sdparta_0\r\na=rtcp-mux\r\na=rtpmap:109 opus/48000/2\r\na=setup:active\r\na=ssrc:3135401367 cname:{428e2c48-ddc0-0f4f-8b3d-8eb59ce33287}\r\n"}
15:51:48     INFO -  2612 INFO TEST-PASS | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | Remote createAnswer does not change signaling state
15:51:48     INFO -  2613 INFO Run step 31: PC_REMOTE_SET_LOCAL_DESCRIPTION
15:51:48  WARNING -  TEST-UNEXPECTED-TIMEOUT | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | application timed out after 330 seconds with no output
15:51:48     INFO -  Determining child pids from psutil
15:51:48     INFO -  Found child pids: [1773]
15:51:48     INFO -  Killing process: 1773
15:51:48     INFO -  TEST-INFO | started process screencapture
15:51:48     INFO -  TEST-INFO | screencapture: exit 0
15:51:50     INFO -  psutil found pid 1773 dead
15:51:50     INFO -  Killing process: 1772
15:51:50     INFO -  Not taking screenshot here: see the one that was previously logged
15:51:50     INFO -  TEST-INFO | Main app process: exit 5
15:51:50  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | application terminated with exit code 5
15:51:50     INFO -  runtests.py | Application ran for: 0:07:17.390395
15:51:50     INFO -  zombiecheck | Reading PID log: /var/folders/vs/05tgb2r939n1hg2_z6mc78kw00000w/T/tmp8y_WUlpidlog
15:51:50     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/bLcSeI0iRPmQkU3wFYkNsQ/artifacts/public/build/firefox-48.0a1.en-US.mac.crashreporter-symbols.zip
15:51:56     INFO -  mozcrash Copy/paste: /builds/slave/test/build/macosx64-minidump_stackwalk /var/folders/vs/05tgb2r939n1hg2_z6mc78kw00000w/T/tmpbXzaNm.mozrunner/minidumps/98758450-AB2D-406F-B66E-40D478E29E2F.dmp /var/folders/vs/05tgb2r939n1hg2_z6mc78kw00000w/T/tmpRVTQxJ
15:52:07     INFO -  mozcrash Saved minidump as /builds/slave/test/build/blobber_upload_dir/98758450-AB2D-406F-B66E-40D478E29E2F.dmp
15:52:07     INFO -  mozcrash Saved app info as /builds/slave/test/build/blobber_upload_dir/98758450-AB2D-406F-B66E-40D478E29E2F.extra
15:52:07  WARNING -  PROCESS-CRASH | dom/media/tests/mochitest/test_peerConnection_verifyAudioAfterRenegotiation.html | application crashed [@ _pthread_mutex_lock + 0x1e]
15:52:07     INFO -  Crash dump filename: /var/folders/vs/05tgb2r939n1hg2_z6mc78kw00000w/T/tmpbXzaNm.mozrunner/minidumps/98758450-AB2D-406F-B66E-40D478E29E2F.dmp
15:52:07     INFO -  Operating system: Mac OS X
15:52:07     INFO -                    10.10.5 14F27
15:52:07     INFO -  CPU: amd64
15:52:07     INFO -       family 6 model 69 stepping 1
15:52:07     INFO -       4 CPUs
15:52:07     INFO -  Crash reason:  EXC_SOFTWARE / SIGABRT
15:52:07     INFO -  Crash address: 0x7fff8dd5c4d4
15:52:07     INFO -  Process uptime: 437 seconds
15:52:07     INFO -  Thread 0 (crashed)
15:52:07     INFO -   0  libsystem_pthread.dylib!_pthread_mutex_lock + 0x1e
15:52:07     INFO -      rax = 0x0000000112e0e1d0   rdx = 0x0000000000000010
15:52:07     INFO -      rcx = 0x0000000000000010   rbx = 0x00000001003c1b00
15:52:07     INFO -      rsi = 0x0000000000000000   rdi = 0x00000001003c1b00
15:52:07     INFO -      rbp = 0x00007fff5fbfcc30   rsp = 0x00007fff5fbfcbb0
15:52:07     INFO -       r8 = 0x000000011cc07c00    r9 = 0x0000000000000000
15:52:07     INFO -      r10 = 0x00000000a0000000   r11 = 0x00007fff77fda448
15:52:07     INFO -      r12 = 0x0000000000000001   r13 = 0x000000011cc07c00
15:52:07     INFO -      r14 = 0x0000000112e0a790   r15 = 0x0000000000000000
15:52:07     INFO -      rip = 0x00007fff8dd5c4d4
15:52:07     INFO -      Found by: given as instruction pointer in context
15:52:07     INFO -   1  libnss3.dylib!<name omitted> [ptsynch.c:90f5e1712c25 : 177 + 0x5]
15:52:07     INFO -      rbp = 0x00007fff5fbfcc50   rsp = 0x00007fff5fbfcc40
15:52:07     INFO -      rip = 0x0000000100635a1e
15:52:07     INFO -      Found by: previous frame's frame pointer
15:52:07     INFO -   2  XUL!XPCJSRuntime::ActivityCallback(void*, bool) [XPCJSRuntime.cpp:90f5e1712c25 : 1260 + 0x5]
15:52:07     INFO -      rbx = 0x0000000110fabf60   rbp = 0x00007fff5fbfcc80
15:52:07     INFO -      rsp = 0x00007fff5fbfcc60   rip = 0x0000000101a99ad4
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   3  XUL!JSRuntime::triggerActivityCallback(bool) [Runtime.cpp:90f5e1712c25 : 758 + 0xa]
15:52:07     INFO -      rbx = 0x0000000112e0e000   rbp = 0x00007fff5fbfccb0
15:52:07     INFO -      rsp = 0x00007fff5fbfcc90   r12 = 0x000000011c9c4d00
15:52:07     INFO -      r14 = 0x0000000000000001   r15 = 0x00007fff5fbfcf68
15:52:07     INFO -      rip = 0x0000000104c33e68
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   4  XUL!mozilla::dom::danger::AutoCxPusher::AutoCxPusher(JSContext*, bool) [jsapi.h:90f5e1712c25 : 1037 + 0x8]
15:52:07     INFO -      rbx = 0x00000001003a78c0   rbp = 0x00007fff5fbfccf0
15:52:07     INFO -      rsp = 0x00007fff5fbfccc0   r12 = 0x000000011c9c4d00
15:52:07     INFO -      r14 = 0x00007fff5fbfcf58   r15 = 0x00007fff5fbfcf68
15:52:07     INFO -      rip = 0x000000010209f492
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   5  XUL!mozilla::dom::AutoJSAPI::InitInternal(JSObject*, JSContext*, bool) [ScriptSettings.cpp:90f5e1712c25 : 709 + 0x7]
15:52:07     INFO -      rbx = 0x00007fff5fbfcf50   rbp = 0x00007fff5fbfcd40
15:52:07     INFO -      rsp = 0x00007fff5fbfcd00   r12 = 0x000000011c6d9060
15:52:07     INFO -      r13 = 0x000000011cc07c00   r14 = 0x0000000000000001
15:52:07     INFO -      r15 = 0x000000011cc07c00   rip = 0x000000010209e38b
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   6  XUL!mozilla::dom::AutoEntryScript::AutoEntryScript(nsIGlobalObject*, char const*, bool, JSContext*) [ScriptSettings.cpp:90f5e1712c25 : 373 + 0x12]
15:52:07     INFO -      rbx = 0x00007fff5fbfcf50   rbp = 0x00007fff5fbfcd80
15:52:07     INFO -      rsp = 0x00007fff5fbfcd50   r12 = 0x000000011cc088f8
15:52:07     INFO -      r13 = 0x000000011cc07c00   r14 = 0x0000000105b9b59b
15:52:07     INFO -      r15 = 0x0000000000000001   rip = 0x000000010209ea76
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   7  XUL!mozilla::dom::CallbackObject::CallSetup::CallSetup(mozilla::dom::CallbackObject*, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JSCompartment*, bool) [Maybe.h:90f5e1712c25 : 386 + 0x16]
15:52:07     INFO -      rbx = 0x00007fff5fbfcf38   rbp = 0x00007fff5fbfcde0
15:52:07     INFO -      rsp = 0x00007fff5fbfcd90   r12 = 0x000000011cc08800
15:52:07     INFO -      r13 = 0x000000011cc07c00   r14 = 0x000000011cc088f8
15:52:07     INFO -      r15 = 0x0000000000000000   rip = 0x0000000102a063fe
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   8  XUL!mozilla::dom::CallbackObject::CallSetup::CallSetup(mozilla::dom::CallbackObject*, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JSCompartment*, bool) [CallbackObject.cpp:90f5e1712c25 : 61 + 0x10]
15:52:07     INFO -      rbx = 0x000000011cc088f0   rbp = 0x00007fff5fbfce00
15:52:07     INFO -      rsp = 0x00007fff5fbfcdf0   r12 = 0x0000000117ae2e50
15:52:07     INFO -      r13 = 0x0000000105b9b59b   r14 = 0x000000011be2c160
15:52:07     INFO -      r15 = 0x0000000117c73d80   rip = 0x0000000102a065b4
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -   9  XUL!nsGlobalWindow::RunTimeoutHandler(nsTimeout*, nsIScriptContext*) [FunctionBinding.h:90f5e1712c25 : 48 + 0x26]
15:52:07     INFO -      rbx = 0x000000011cc088f0   rbp = 0x00007fff5fbfd120
15:52:07     INFO -      rsp = 0x00007fff5fbfce10   r12 = 0x0000000117ae2e50
15:52:07     INFO -      r13 = 0x0000000105b9b59b   r14 = 0x000000011be2c160
15:52:07     INFO -      r15 = 0x0000000117c73d80   rip = 0x000000010201e3fa
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  10  XUL!nsGlobalWindow::RunTimeout(nsTimeout*) [nsGlobalWindow.cpp:90f5e1712c25 : 12194 + 0xe]
15:52:07     INFO -      rbx = 0x000000011be2c160   rbp = 0x00007fff5fbfd1a0
15:52:07     INFO -      rsp = 0x00007fff5fbfd130   r12 = 0x000000011c9c4d00
15:52:07     INFO -      r13 = 0x0000000000000001   r14 = 0x000000011cc08800
15:52:07     INFO -      r15 = 0x000000011bfcab30   rip = 0x00000001020148a8
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  11  XUL!nsGlobalWindow::TimerCallback(nsITimer*, void*) [nsGlobalWindow.cpp:90f5e1712c25 : 12440 + 0x8]
15:52:07     INFO -      rbx = 0x000000011be2c160   rbp = 0x00007fff5fbfd1c0
15:52:07     INFO -      rsp = 0x00007fff5fbfd1b0   r12 = 0x000000011be2c1d0
15:52:07     INFO -      r13 = 0x0000000000000000   r14 = 0x000000011be2c178
15:52:07     INFO -      r15 = 0x0000000101ff6b30   rip = 0x0000000101ff6b83
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  12  XUL!nsTimerImpl::Fire() [nsTimerImpl.cpp:90f5e1712c25 : 524 + 0x6]
15:52:07     INFO -      rbx = 0x0000000000000002   rbp = 0x00007fff5fbfd220
15:52:07     INFO -      rsp = 0x00007fff5fbfd1d0   r12 = 0x000000011be2c1d0
15:52:07     INFO -      r13 = 0x0000000000000000   r14 = 0x0000000000000002
15:52:07     INFO -      r15 = 0x0000000101ff6b30   rip = 0x000000010119de95
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  13  XUL!nsTimerEvent::Run() [TimerThread.cpp:90f5e1712c25 : 286 + 0x5]
15:52:07     INFO -      rbx = 0x000000011a4e8020   rbp = 0x00007fff5fbfd250
15:52:07     INFO -      rsp = 0x00007fff5fbfd230   r12 = 0x000000010030d490
15:52:07     INFO -      r13 = 0x0000000000000000   r14 = 0x00007fff5fbfd2e7
15:52:07     INFO -      r15 = 0x000000010030d460   rip = 0x0000000101190373
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  14  XUL!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:90f5e1712c25 : 994 + 0x6]
15:52:07     INFO -      rbx = 0x000000010030d4d0   rbp = 0x00007fff5fbfd2d0
15:52:07     INFO -      rsp = 0x00007fff5fbfd260   r12 = 0x000000010030d490
15:52:07     INFO -      r13 = 0x0000000000000000   r14 = 0x00007fff5fbfd2e7
15:52:07     INFO -      r15 = 0x000000010030d460   rip = 0x0000000101194aa7
15:52:07     INFO -      Found by: call frame info
15:52:07     INFO -  15  XUL!NS_ProcessPendingEvents(nsIThread*, unsigned int) [nsThreadUtils.cpp:90f5e1712c25 : 239 + 0xf]
15:52:07     INFO -      rbx = 0x0000000000000000   rbp = 0x00007fff5fbfd310
15:52:07     INFO -      rsp = 0x00007fff5fbfd2e0   r12 = 0x000000010030d460
15:52:07     INFO -      r13 = 0x00007fff5fbfd2e7   r14 = 0x000000000000000a
15:52:07     INFO -      r15 = 0x000000000025a32c   rip = 0x00000001011c29ff
15:52:07     INFO -      Found by: call frame info

Comment 1

[Boris Zbarsky [:bzbarsky]]

You mean bug 1256008?  Doesn't seem related to me.

What this stack is showing is that we're about to call from C++ into JS for a setTimeout callback.  While setting up the things we need for the call, we call XPCJSRuntime::ActivityCallback which calls WatchdogManager::RecordRuntimeActivity which creates an AutoLockWatchdog (some of this stuff is inlined in that stack trace), which does PR_Lock(mWatchdog->GetLock()).  And there we get stuck (well, more precisely under the _pthread_mutex_lock call it makes).

I'm not sure what else is holding that lock.  The obvious culprit could be WatchdogMain, but that's waiting on its condvar (see stack for thread 5) which means it's not holding the lock.  And other than the watchdog and the main thread I would not expect anyone else to hold this lock...

Comment 2

[Intermittent Failures Robot]

8 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 5
* mozilla-inbound: 2
* ash: 1

Platform breakdown:
* windows7-32: 8

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256081&startday=2016-05-30&endday=2016-06-05&tree=all

Comment 3

[Intermittent Failures Robot]

6 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 4
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* windows7-32-vm: 5
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1256081&startday=2016-08-01&endday=2016-08-07&tree=all

Comment 4

[BMO Automation]

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.

Comment 5

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.