811764 - Firefox crashes with NSPR logging enabled and opening the testcase | Assertion failure: ok, at ../../../xpcom/build/mozPoisonWriteMac.cpp:89

Status: RESOLVED FIXED

(Core :: WebRTC: Signaling, defect, P1)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:19.0) Gecko/19.0 Firefox/19.0 ID:20121114162125

Opening the updated testcase (attachment 680451 [details]) from bug 801227 can let the browser crash on shutdown if NSPR logging is enabled.

Steps:
1. Enable NSRP logging (export NSPR_LOG_MODULES=ikran:5 && export NSPR_LOG_FILE=webrtc.log)
2. Start Firefox
3. Open the testcase
4. Wait until you get nsIPeerConnection failures like the one below
5. Shutdown Firefox

JavaScript error: file:///Volumes/data/code/firefox/obj/nightly/dist/NightlyDebug.app/Contents/MacOS/components/PeerConnection.js, line 238: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IPeerConnection.initialize]


Could be fixed by bug 811183.

GDB output:

Program received signal EXC_BAD_ACCESS, Could not access memory.
Reason: KERN_INVALID_ADDRESS at address: 0x0000000000000000
[Switching to process 23060 thread 0x13707]
ValidWriteAssert (ok=false) at /Volumes/data/code/firefox/nightly/xpcom/build/mozPoisonWriteMac.cpp:89
89	    MOZ_ASSERT(ok);
(gdb) bt
#0  ValidWriteAssert (ok=false) at /Volumes/data/code/firefox/nightly/xpcom/build/mozPoisonWriteMac.cpp:89
#1  0x000000010371e184 in AbortOnBadWrite (fd=4, wbuf=0x1004cd000, count=76) at /Volumes/data/code/firefox/nightly/xpcom/build/mozPoisonWriteMac.cpp:333
#2  0x000000010371ec93 in wrap_write_temp<write_data> (fd=4, buf=0x1004cd000, count=76) at /Volumes/data/code/firefox/nightly/xpcom/build/mozPoisonWriteMac.cpp:212
#3  0x00000001005354b4 in pt_Write (fd=0x100405eb0, buf=0x1004cd000, amount=76) at /Volumes/data/code/firefox/nightly/nsprpub/pr/src/pthreads/ptio.c:1315
#4  0x00000001005049d6 in PR_Write (fd=0x100405eb0, buf=0x1004cd000, amount=76) at /Volumes/data/code/firefox/nightly/nsprpub/pr/src/io/priometh.c:114
#5  0x00000001005085b0 in PR_LogFlush () at /Volumes/data/code/firefox/nightly/nsprpub/pr/src/io/prlog.c:530
#6  0x0000000100508e94 in PR_LogPrint (fmt=0x104ce6fa6 "%s %s") at /Volumes/data/code/firefox/nightly/nsprpub/pr/src/io/prlog.c:522
#7  0x0000000104402692 in CSFLogV (priority=CSF_LOG_DEBUG, sourceFile=0x104ed8056 "/Volumes/data/code/firefox/nightly/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp", sourceLine=547, tag=0x104ed88c2 "WebrtcAudioSessionConduit", format=0x104ed861a "%s : channel %d", args=0x143b123b0) at CSFLog.cpp:43
#8  0x000000010440285c in CSFLog (priority=CSF_LOG_DEBUG, sourceFile=0x104ed8056 "/Volumes/data/code/firefox/nightly/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp", sourceLine=547, tag=0x104ed88c2 "WebrtcAudioSessionConduit", format=0x104ed861a "%s : channel %d") at CSFLog.cpp:58
#9  0x00000001043fc8e6 in mozilla::WebrtcAudioConduit::SendRTCPPacket (this=0x111623f90, channel=0, data=0x143b12710, len=8) at AudioConduit.cpp:547
#10 0x00000001043fc9fb in non-virtual thunk to mozilla::WebrtcAudioConduit::SendRTCPPacket(int, void const*, int) () at AudioConduit.cpp:557
#11 0x00000001042f618e in webrtc::voe::Channel::SendRTCPPacket (this=0x11c51e000, channel=0, data=0x143b12710, len=8) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/voice_engine/channel.cc:337
#12 0x00000001042f623b in non-virtual thunk to webrtc::voe::Channel::SendRTCPPacket(int, void const*, int) () at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/voice_engine/channel.cc:352
#13 0x00000001042a9f23 in webrtc::RTCPSender::SendToNetwork (this=0x11e6df8b0, dataBuffer=0x143b12710 "??", length=8) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/modules/rtp_rtcp/source/rtcp_sender.cc:1947
#14 0x00000001042a611e in webrtc::RTCPSender::SendRTCP (this=0x11e6df8b0, packetTypeFlags=1, nackSize=0, nackList=0x0, repeat=false, pictureID=0) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/modules/rtp_rtcp/source/rtcp_sender.cc:1937
#15 0x0000000104293da0 in webrtc::ModuleRtpRtcpImpl::Process (this=0x11e6df000) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/modules/rtp_rtcp/source/rtp_rtcp_impl.cc:237
#16 0x00000001041a4987 in webrtc::ProcessThreadImpl::Process (this=0x11a6912e0) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/modules/utility/source/process_thread_impl.cc:181
#17 0x00000001041a4395 in webrtc::ProcessThreadImpl::Run (obj=0x11a6912e0) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/modules/utility/source/process_thread_impl.cc:138
#18 0x0000000104213813 in webrtc::ThreadPosix::Run (this=0x11c741340) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/system_wrappers/source/thread_posix.cc:361
#19 0x0000000104213565 in StartThread (lpParameter=0x11c741340) at /Volumes/data/code/firefox/nightly/media/webrtc/trunk/src/system_wrappers/source/thread_posix.cc:72
#20 0x00007fff96e758bf in _pthread_start ()
#21 0x00007fff96e78b75 in thread_start ()

(gdb) info threads
  92                                  0x00007fff9a165192 in __workq_kernreturn ()
  91                                  0x00007fff9a165192 in __workq_kernreturn ()
  90                                  0x00007fff9a165192 in __workq_kernreturn ()
  89                                  0x00007fff9a165192 in __workq_kernreturn ()
  88                                  0x00007fff9a164bca in __psynch_cvwait ()
  87                                  0x00007fff9a164bca in __psynch_cvwait ()
  86                                  0x00007fff9a164bca in __psynch_cvwait ()
  85                                  0x00007fff9a164bca in __psynch_cvwait ()
  84                                  0x00007fff9a164bca in __psynch_cvwait ()
  83                                  0x00007fff9a164bca in __psynch_cvwait ()
  82                                  0x00007fff9a164bca in __psynch_cvwait ()
  81                                  0x00007fff9a164bca in __psynch_cvwait ()
  80                                  0x00007fff9a164bca in __psynch_cvwait ()
  79                                  0x00007fff9a164bca in __psynch_cvwait ()
  78                                  0x00007fff9a164bca in __psynch_cvwait ()
  77                                  0x00007fff9a164bca in __psynch_cvwait ()
  76                                  0x00007fff9a164bca in __psynch_cvwait ()
  75                                  0x00007fff9a164bca in __psynch_cvwait ()
  74                                  0x00007fff9a164bca in __psynch_cvwait ()
  73                                  0x00007fff9a164bca in __psynch_cvwait ()
  72                                  0x00007fff9a164bca in __psynch_cvwait ()
  71                                  0x00007fff9a164bca in __psynch_cvwait ()
  70                                  0x00007fff9a164bca in __psynch_cvwait ()
  69                                  0x00007fff9a164bca in __psynch_cvwait ()
  68                                  0x00007fff9a164bca in __psynch_cvwait ()
  67                                  0x00007fff9a164bca in __psynch_cvwait ()
  66                                  0x00007fff9a164bca in __psynch_cvwait ()
  65                                  0x00007fff9a164bca in __psynch_cvwait ()
  64                                  0x00007fff9a164bca in __psynch_cvwait ()
  63                                  0x00007fff9a164bca in __psynch_cvwait ()
  62                                  0x00007fff9a164bca in __psynch_cvwait ()
  61                                  0x00007fff9a164bca in __psynch_cvwait ()
  60                                  0x00007fff9a164bca in __psynch_cvwait ()
* 59                                  ValidWriteAssert (ok=false) at /Volumes/data/code/firefox/nightly/xpcom/build/mozPoisonWriteMac.cpp:89
  58                                  0x00007fff9a164bca in __psynch_cvwait ()
  57                                  0x00007fff9a164bca in __psynch_cvwait ()
  56                                  0x00007fff9a164bca in __psynch_cvwait ()
  55                                  0x00007fff9a164bca in __psynch_cvwait ()
  54                                  0x00007fff9a164bca in __psynch_cvwait ()
  53                                  0x00007fff9a164bca in __psynch_cvwait ()
  52                                  0x00007fff9a164bca in __psynch_cvwait ()
  51                                  0x00007fff9a164bca in __psynch_cvwait ()
  50                                  0x00007fff9a164bca in __psynch_cvwait ()
  49                                  0x00007fff9a164bca in __psynch_cvwait ()
  48                                  0x00007fff9a164bca in __psynch_cvwait ()
  47                                  0x00007fff9a164bca in __psynch_cvwait ()
  46                                  0x00007fff9a164bca in __psynch_cvwait ()
  45                                  0x00007fff9a164e42 in __semwait_signal ()
  44 "com.apple.audio.hal.notificati" 0x00007fff9a16367a in mach_msg_trap ()
  43                                  0x00007fff9a164bca in __psynch_cvwait ()
  42                                  0x00007fff9a164bca in __psynch_cvwait ()
  39                                  0x00007fff9a164bca in __psynch_cvwait ()
  38                                  0x00007fff9a164bca in __psynch_cvwait ()
  37                                  0x00007fff9a164df2 in select$DARWIN_EXTSN ()
  36                                  0x00007fff9a164bca in __psynch_cvwait ()
  35                                  0x00007fff9a164df2 in select$DARWIN_EXTSN ()
  10 "JS Watchdog"                    0x00007fff9a164bca in __psynch_cvwait ()
   9 "JS Sour~ Thread"                0x00007fff9a164bca in __psynch_cvwait ()
   8 "JS GC Helper"                   0x00007fff9a164bca in __psynch_cvwait ()
   7 "Hang Monitor"                   0x00007fff9a164bca in __psynch_cvwait ()
   4 "Gecko_IOThread"                 0x00007fff9a1657e6 in kevent ()
   2 "com.apple.libdispatch-manager"  0x00007fff9a1657e6 in kevent ()
   1 "com.apple.main-thread"          0x00000001049966cc in Mark<js::types::TypeObject> (trc=0x7fff5fbfe468, thing=0x1111d61c8, name=0x104ce2250 "type") at /Volumes/data/code/firefox/nightly/js/src/gc/Marking.cpp:150

Comment 1

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

Attachment: Callstack

Crash (built with patch from bug 792175 (Dispatch/"lock" patch).  Crashes without needing to quit; just load into gdb and run.

Comment 2

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

Attachment: Mac crash report from a previous run

Comment 3

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

Upgrading to P1 since it's now crashing without shutting down

Comment 4

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

Assigning to ekr for comment and possible reassignment to someone else to attack

Comment 5

[Eric Rescorla (:ekr)]

I just turned on the logging, loaded the test case, and waited for about 30 seconds. No crash.

Should I do something else?

What does this testcase allegedly do?

Comment 6

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

I had a debug build with the bug 792175 patch applied (and the video config patch).  The testcase sets up an asynchronous reload that will interrupt the call setup at random points (and repeat).

Comment 7

[Eric Rescorla (:ekr)]

I believe this is an artifact of the failure to have sigslot be multithreaded. I.e., that we are trying to fire
the signal during destruction of the target object. At minimum we should start by switching sigslot
to multithreaded and see if this goes away. 

https://bugzilla.mozilla.org/show_bug.cgi?id=782657

Comment 8

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

restesting with a patch for multithreading sigslot didn't crash but we're not cleaning up:

cpr SIPCC-UI_API: ui_mnc_reached: line 51: Max number of calls reached =1 
and it keeps going!  But reports things odd about the number of calls after that (usually 0/0)

So, this is likely a new/different bug having to do with cleanup.  It may already be covered, though probably something more useful should happen when we hit the limit (at least fail things, if it isn't already, and complain more probably)

Comment 9

[Eric Rescorla (:ekr)]

Yeah, this seems like a totally different problem.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Updating summary based on comment 3.

Comment 11

[Maire Reavy [:mreavy]]

Needs retest after recent landings.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

We hit this now on inbound when I pushed the patch to enable crashtests for WebRTC:

https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=a5fee86dec9e

Also we have seen this all the time on Alder. As talked on IRC and a research done by myself shows that this is exactly the bug we are hitting:

http://mxr.mozilla.org/mozilla-central/source/xpcom/build/mozPoisonWriteMac.cpp#90

This blocks us from enabling the crashtests on m-c.

Comment 13

[Eric Rescorla (:ekr)]

Those are pretty old stacks. I expect not to see them any more since they reflect code that has changed.

However, see:
90          MOZ_ASSERT(ok);
(gdb) bt
#0  (anonymous namespace)::ValidWriteAssert (ok=false) at /Users/ekr/dev/mozilla-inbound/xpcom/build/mozPoisonWriteMac.cpp:90
#1  0x000000010388a431 in (anonymous namespace)::AbortOnBadWrite (fd=4, wbuf=0x100384c00, count=889) at /Users/ekr/dev/mozilla-inbound/xpcom/build/mozPoisonWriteMac.cpp:353
#2  0x000000010388b043 in _ZN12_GLOBAL__N_115wrap_write_tempILZNS_10write_dataEEEEliPKvm (fd=4, buf=0x100384c00, count=889) at /Users/ekr/dev/mozilla-inbound/xpcom/build/mozPoisonWriteMac.cpp:213
#3  0x00007fff8a6b1a1b in -[CFXPreferencesPropertyListSource writePlistToDisk] ()
#4  0x00007fff8a6871a0 in -[CFXPreferencesPropertyListSource synchronize] ()
#5  0x00007fff8a6ae90b in CFPreferencesSynchronize ()
#6  0x00007fff85136809 in CACFPreferences::Synchronize ()
#7  0x00007fff85131978 in MIO::DAL::DALDefaultDevice::UpdateDefaultDevice ()
#8  0x00007fff85131bf5 in MIO::DAL::DALDefaultDevice::UpdateDefaultDevices ()
#9  0x00007fff8512f83b in MIO::DAL::System::ObjectsPublishedAndDied ()
#10 0x00007fff8512a5fc in TundraObjectsPublishedAndDied ()
#11 0x0000000130216630 in dyld_stub_vvpowf ()
#12 0x0000000130216a11 in dyld_stub_vvpowf ()
#13 0x00000001302223e0 in AppleDALScreenInputDeviceNewPlugIn ()
#14 0x00007fff8512fe2d in MIO::DAL::PlugIn::Teardown ()
#15 0x00007fff85132cac in MIO::DAL::PlugInManagement::Teardown ()
#16 0x00007fff8512ed34 in MIO::DAL::System::AtExitHandler ()
#17 0x00007fff85131010 in MIO::DAL::AtExit::AtExitHandler ()
#18 0x00007fff8545f37f in __cxa_finalize ()
#19 0x00007fff8545f28c in exit ()
#20 0x0000000100000e4b in start ()

Comment 14

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

We should open a new bug for the AppleDAL PoisonWrite failure; it's a separate bug.  This one was fixed by stopping RTCP from running after we closed down the peerconnection

Comment 15

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

Fixed when we stopped leaking RTCP send contexts