1600331 - MOZ_ASSERT(NS_IsMainThread(), "Should only queue idle runnables on the main thread") called from Gecko cache code

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Emilio Cobos Álvarez [:emilio]]

Just hit this on a local debug build:

#0  0x00007f36b49435a1 in clock_nanosleep@GLIBC_2.2.5 () at /lib64/libc.so.6
#1  0x00007f36b4948f77 in nanosleep () at /lib64/libc.so.6
#2  0x00007f36b4948eae in sleep () at /lib64/libc.so.6
#3  0x00007f36aed85fa5 in ah_crap_handler(int) (signum=11) at /home/emilio/src/moz/gecko-2/toolkit/xre/nsSigHandlers.cpp:95
#4  0x00007f36aed69944 in nsProfileLock::FatalSignalHandler(int, siginfo_t*, void*) (signo=11, info=0x7f3694838ab0, context=0x7f3694838980) at /home/emilio/src/moz/gecko-2/toolkit/profile/nsProfileLock.cpp:178
#5  0x00007f36afec17e2 in WasmTrapHandler(int, siginfo_t*, void*) (signum=11, info=<optimized out>, context=<optimized out>) at /home/emilio/src/moz/gecko-2/js/src/wasm/WasmSignalHandlers.cpp:963
#6  0x00007f36b4db9b20 in <signal handler called> () at /lib64/libpthread.so.0
#7  mozilla::PrioritizedEventQueue::PutEvent(already_AddRefed<nsIRunnable>&&, mozilla::EventQueuePriority, mozilla::BaseAutoLock<mozilla::Mutex&> const&, mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator>*) (this=0x7f36b4661100, aEvent=..., aPriority=<optimized out>, aProofOfLock=..., aDelay=0x0) at /home/emilio/src/moz/gecko-2/xpcom/threads/PrioritizedEventQueue.cpp:68
#8  0x00007f36aab11e90 in mozilla::ThreadEventQueue<mozilla::PrioritizedEventQueue>::PutEventInternal(already_AddRefed<nsIRunnable>&&, mozilla::EventQueuePriority, mozilla::ThreadEventQueue<mozilla::PrioritizedEventQueue>::NestedSink*) (this=0x7f369780c120, aEvent=..., aPriority=mozilla::EventQueuePriority::Idle, aSink=0x0) at /home/emilio/src/moz/gecko-2/xpcom/threads/ThreadEventQueue.cpp:113
#9  0x00007f36aab06787 in nsThread::DispatchToQueue(already_AddRefed<nsIRunnable>, mozilla::EventQueuePriority) (this=<optimized out>, aEvent=..., aQueue=mozilla::EventQueuePriority::Idle) at /home/emilio/src/moz/gecko-2/xpcom/threads/nsThread.cpp:959
#10 0x00007f36aab0a795 in NS_DispatchToThreadQueue(already_AddRefed<nsIRunnable>&&, nsIThread*, mozilla::EventQueuePriority) (aEvent=..., aThread=0x7f3698293200, aQueue=mozilla::EventQueuePriority::Idle) at /home/emilio/src/moz/gecko-2/xpcom/threads/nsThreadUtils.cpp:293
#11 0x00007f36aab0d70e in NS_DispatchToMainThreadQueue(already_AddRefed<nsIRunnable>&&, mozilla::EventQueuePriority) (aEvent=..., aQueue=mozilla::EventQueuePriority::Idle) at /home/emilio/src/moz/gecko-2/xpcom/threads/nsThreadUtils.cpp:315
#12 0x00007f36aafd577c in mozilla::net::nsHttpChannel::PerformBackgroundCacheRevalidation() (this=<optimized out>) at /home/emilio/src/moz/gecko-2/netwerk/protocol/http/nsHttpChannel.cpp:10474
#13 0x00007f36aafd4a64 in mozilla::net::nsHttpChannel::OnCacheEntryCheck(nsICacheEntry*, nsIApplicationCache*, unsigned int*) (this=0x7f368a6f9000, entry=0x7f368a6d23d0, appCache=<optimized out>, aResult=0x7f3694839abc) at /home/emilio/src/moz/gecko-2/netwerk/protocol/http/nsHttpChannel.cpp:4532
#14 0x00007f36aaea0359 in mozilla::net::CacheEntry::InvokeCallback(mozilla::net::CacheEntry::Callback&) (this=0x7f368a80e5e0, aCallback=...) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheEntry.cpp:741
#15 0x00007f36aae9ff72 in mozilla::net::CacheEntry::InvokeCallbacks(bool) (this=<optimized out>, aReadOnly=<optimized out>) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheEntry.cpp:668
#16 0x00007f36aae9e351 in mozilla::net::CacheEntry::InvokeCallbacks() (this=0x7f368a80e5e0) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheEntry.cpp:610
#17 0x00007f36aae9f523 in mozilla::net::CacheEntry::OnFileReady(nsresult, bool) (this=0x7f368a80e5e0, aResult=<optimized out>, aIsNew=<optimized out>) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheEntry.cpp:498
#18 0x00007f36aae9f6df in non-virtual thunk to mozilla::net::CacheEntry::OnFileReady(nsresult, bool) () at /home/emilio/src/moz/gecko-2/obj-debug/dist/bin/libxul.so
#19 0x00007f36aaea9419 in mozilla::net::CacheFile::OnMetadataRead(nsresult) (this=<optimized out>, aResult=nsresult::NS_OK) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheFile.cpp:643
#20 0x00007f36aaea9aa9 in non-virtual thunk to mozilla::net::CacheFile::OnMetadataRead(nsresult) () at /home/emilio/src/moz/gecko-2/obj-debug/dist/bin/libxul.so
#21 0x00007f36aaec9abb in mozilla::net::CacheFileMetadata::OnDataRead(mozilla::net::CacheFileHandle*, char*, nsresult) (this=0x7f368a8994a0, aHandle=<optimized out>, aBuf=<optimized out>, aResult=<optimized out>) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheFileMetadata.cpp:699
#22 0x00007f36aaee036e in mozilla::net::ReadEvent::Run() (this=<optimized out>) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheFileIOManager.cpp:704
#23 0x00007f36aaecd1f8 in mozilla::net::CacheIOThread::LoopOneLevel(unsigned int) (this=0x7f36982040e0, aLevel=4) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheIOThread.cpp:545
#24 0x00007f36aaeccf04 in mozilla::net::CacheIOThread::ThreadFunc() (this=0x7f36982040e0) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheIOThread.cpp:483
#25 0x00007f36aaecc8ba in mozilla::net::CacheIOThread::ThreadFunc(void*) (aClosure=0x7f36b4a3f310 <_IO_stdfile_2_lock>) at /home/emilio/src/moz/gecko-2/netwerk/cache2/CacheIOThread.cpp:424
#26 0x00007f36b3df785f in _pt_root (arg=0x7f36949addc0) at /home/emilio/src/moz/gecko-2/nsprpub/pr/src/pthreads/ptthread.c:201
#27 0x00007f36b4dae482 in start_thread () at /lib64/libpthread.so.0
#28 0x00007f36b497c443 in clone () at /lib64/libc.so.6

Comment 1

[Emilio Cobos Álvarez [:emilio]]

Bug 1597158 introduced the assertion. Bug 1536511 the runnable.

The runnable is this.

ni?ing boris first because the assertion is recent.

Comment 2

[Emilio Cobos Álvarez [:emilio]]

The assert may be wrong, and may want to assert that the target thread is the main thread?

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

Not a security bug (but apparently I can't clear the security flag o_O )
I was hoping that we weren't dispatching to idle queue outside main thread, but apparently we are.

Comment 4

[Emilio Cobos Álvarez [:emilio]]

Yeah, I tagged it as s-s just to be safe, but it looks I can't clear it either... Freddy, halp?

Comment 5

[Boris Zbarsky [:bzbarsky]]

No, the assert is asserting what it means to assert: because of the unlocking the idle stuff does, if the originating thread is not the main thread idle runnables could get delayed significantly if they get queued at just the wrong time. That problem predates bug 1597158, but bug 1597158 added an assert for it.

I'll take a look at the details on Monday.

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

Necko code could just dispatch a normal priority runnable to the main thread which then redispatches the runnable to idle queue.

Comment 7

[Boris Zbarsky [:bzbarsky]]

It could, but that seems annoying...

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

Or main thread itself could wrap the runnable and dispatch to normal priority queue which then dispatches to idle queue.
That might not be too bad - as long as we have the issue with idle dispatching from non-main-thread.

Comment 10

[Boris Zbarsky [:bzbarsky]]

That still seems annoying, in the sense of an idle runnable using up non-idle cycles to handle it... Sorry this is taking so long; I really need to just sit down and figure out whether there are any better solutions. :(

Comment 11

[Michael Froman [:mjf]]

I can repro this fairly reliably going to https://duo.google.com with a Linux debug build from moz-central 69687a23245e.

Comment 12

[Emilio Cobos Álvarez [:emilio]]

Can we turn it into an NS_ASSERTION or such for now? I've also seen it from time to time while browsing on a debug build.

Comment 14

[Bob Clary [:bc] (inactive)]

Bughunter has seen this on 26 urls so far.

Comment 15

[Valentin Gosu [:valentin]]

(In reply to Emilio Cobos Álvarez (:emilio) from comment #12)

Can we turn it into an NS_ASSERTION or such for now? I've also seen it from time to time while browsing on a debug build.

It would be nice to do this.
This will be triggered almost 100% on pages with the Cache-Control: stale-while-revalidate= header. Called from here

Comment 16

[Boris Zbarsky [:bzbarsky]]

OK. I haven't managed to reproduce this yet, but going to post a patch that should fix it...

Comment 17

[Boris Zbarsky [:bzbarsky]]

Attachment: Bug 1600331. When an idle runnable is queued from a background thread, lazily queue it from a non-idle runnable.

Idle runnables do weird things involving unlocking the event queue mutex while
looking for runnables, such that queueing one from off the main thread might
cause it to basically never run if it gets queued during one of those
temporary-unlock periods.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f0f431fa8591
When an idle runnable is queued from a background thread, lazily queue it from a non-idle runnable. r=smaug

Comment 19

[Cristina Coroiu [:ccoroiu]]

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

Comment 20

[Bob Clary [:bc] (inactive)]

fwiw, I retested the 69 urls where bughunter has seen this in the last two months and could not reproduce. Thank you!

Comment 21

[Boris Zbarsky [:bzbarsky]]

Thank you for testing that! It's much appreciated.