794178 - Write poisoning seems to not be compatible with NSPR logging

Status: RESOLVED INVALID

(Core :: XPCOM, defect)

Description

[Boris Zbarsky [:bzbarsky]]

Every time I shut my browser down while running with NSPR logging, write poisoning kills it.  The stack looks like so:

#0  (anonymous namespace)::ValidWriteAssert (ok=false) at mozPoisonWriteMac.cpp:54
#1  0x00000001048ed924 in (anonymous namespace)::AbortOnBadWrite (fd=4, wbuf=0x10056b000, count=134) at mozPoisonWriteMac.cpp:283
#2  0x00000001048ee033 in _ZN12_GLOBAL__N_115wrap_write_tempILZNS_10write_dataEEEEliPKvm (fd=4, buf=0x10056b000, count=134) at mozPoisonWriteMac.cpp:169
#3  0x0000000100636884 in pt_Write (fd=0x100505ee0, buf=0x10056b000, amount=134) at ptio.c:1315
#4  0x00000001006050c6 in PR_Write (fd=0x100505ee0, buf=0x10056b000, amount=134) at priometh.c:114
#5  0x0000000100608c60 in PR_LogFlush () at prlog.c:530
#6  0x0000000100609549 in PR_LogPrint (fmt=0x1055d24a6 "%s") at prlog.c:522
#7  0x0000000104982783 in NS_DebugBreak_P (aSeverity=0, aStr=0x1057904a9 "NS_ENSURE_TRUE(mMainThread) failed", aExpr=0x0, aFile=0x105790401 "../../../mozilla/xpcom/threads/nsThreadManager.cpp", aLine=250) at nsDebugImpl.cpp:341
#8  0x0000000104971016 in nsThreadManager::GetMainThread (this=0x106848bb8, result=0x7fff5fbfe070) at nsThreadManager.cpp:250
#9  0x00000001048d833d in NS_GetMainThread_P (result=0x7fff5fbfe070) at nsThreadUtils.cpp:88
#10 0x00000001048d8449 in NS_DispatchToMainThread_P (event=0x100505520, dispatchFlags=0) at nsThreadUtils.cpp:142
#11 0x0000000103480935 in DOMGCSliceCallback (aRt=0x10c823000, aProgress=js::GC_CYCLE_END, aDesc=@0x7fff5fbfe238) at nsJSEnvironment.cpp:3500
#12 0x0000000101437e23 in js::gcstats::Statistics::endSlice (this=0x10c8233a0) at Statistics.cpp:596
#13 0x0000000101117d9f in js::gcstats::AutoGCSlice::~AutoGCSlice (this=0x7fff5fbfe330) at Statistics.h:163
#14 0x0000000101117d75 in js::gcstats::AutoGCSlice::~AutoGCSlice (this=0x7fff5fbfe330) at Statistics.h:163
#15 0x00000001010fe5d9 in Collect (rt=0x10c823000, incremental=false, budget=0, gckind=js::GC_NORMAL, reason=js::gcreason::DESTROY_CONTEXT) at jsgc.cpp:4659
#16 0x00000001010fc5bc in js::GC (rt=0x10c823000, gckind=js::GC_NORMAL, reason=js::gcreason::DESTROY_CONTEXT) at jsgc.cpp:4666

Basically, we're doing GC on shutdown, we call the DOM slice callback (because GC logging is enabled?), which tries to post an event to the event loop.  But when we try to get the thread pointer we hit this code:

  NS_ENSURE_TRUE(mMainThread, NS_ERROR_NOT_INITIALIZED);

which writes out a warning using PR_LOG.  And since I'm trying to log something else, that warning tries to go into my log file.  But then write poisoning steps in and kills me off, because it thinks I shouldn't be writing to file here...

Comment 1

[Boris Zbarsky [:bzbarsky]]

This is sort of interfering with me trying to debug things, unfortunately.  :(

Comment 2

[Nathan Froyd [:froydnj]]

Oh, ugh, the fix that got applied for other writes would require reaching into the guts of NSPR.  And *that's* not going to happen, so we need to find some other way to do it...

Comment 3

[Terrence Cole [:terrence]]

Attachment: wip0: don't fire the endSlice callback from the Shutdown GC.

I'm not sure if we want to solve this problem in the GC or in the endSlice callback itself.  We already specialize the shutdown GC in a bunch of other ways, so I don't think this is unreasonable.

Does this at least fix the crash?

Comment 4

[Boris Zbarsky [:bzbarsky]]

That doesn't fix the crash.  See stack above: the relevant gc is gcreason::DESTROY_CONTEXT as we tear down the XPCOM JS component loader...

Comment 6

[Terrence Cole [:terrence]]

Comment on attachment 664591 [details] [diff] [review]
wip0: don't fire the endSlice callback from the Shutdown GC.

You are quite correct.  I forgot that we do indeed GC after the 3 shutdown GC's *and* I didn't read carefully enough.  Mea culpa.  I asked Bill more about this and it seems that we cannot solve this fully from the JS side in any case.  Sorry for the noise!

Comment 7

[Boris Zbarsky [:bzbarsky]]

Hey, no need to be sorry.  Thank you for trying to fix!

Here's a proposal.  How about we stop dumping warnings and asserts to the NSPR log while logging?  That's always annoyed me anyway...

Comment 8

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Fine with me.

Comment 9

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

Might bug 811764 be related to that one?

Comment 10

[Nathan Froyd [:froydnj]]

(In reply to Henrik Skupin (:whimboo) from comment #9)
> Might bug 811764 be related to that one?

Almost certainly.

Comment 11

[Nathan Froyd [:froydnj]]

Attachment: don't use NSPR logging for warning/debug messages

Trivial patch.  Not sure who the correct reviewer is here; going with dbaron
because bz asked for his feelings on the changes.

Comment 12

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 697077 [details] [diff] [review]
don't use NSPR logging for warning/debug messages

Ordinarily I'd say this is to broad a response to this problem.  However, I think I've heard the sentiment before that assertions shouldn't appear in NSPR logs... and I even thought I'd reviewed a patch before to change that.

That said, I think you should announce this change to dev-platform and see if people have objections.

But I'm fine with it.

Comment 13

[Nathan Froyd [:froydnj]]

This bug was fixed in a different way by Ehsan in a no-bug commit.

Comment 14

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

This no-bug commit (where?) seems to have broken WebRTC shutdown on mac!  Any place I can find info on the commit?  (I'll ping Ehsan)

Comment 15

[(no longer active)]

(In reply to comment #13)
> This bug was fixed in a different way by Ehsan in a no-bug commit.

Sorry, I don't remember at all what I landed to fix this.  Also looked through the hg log a bit but couldn't find anything.

Comment 16

[(no longer active)]

Oh, this is the commit Nathan mentioned: https://hg.mozilla.org/mozilla-central/rev/8755061452d9

But I don't think it fixes this bug.

Comment 17

[Marcela (Please NI request to Brindusa Tot)]

Since this issue hasn't had any updates in the past years and Firefox has changed deeply, I'll close this bug as Resolved - Invalid.

Comment 18

[Andrew McCreight [:mccr8]]

Looks like the specific code in the patch has been deleted.