788001 - ABORT: index corruption: 'mStreamTransactionHash.Count() == mStreamIDHash.Count()'

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Bob Clary [:bc] (inactive)]

1. Install Spider
   http://bclary.com/projects/spider/spider/spider.xpi

2. firefox -spider -start -quit -url http://friendfans.blogspot.com/feeds/posts/default

3. ABORT: index corruption: 'mStreamTransactionHash.Count() == mStreamIDHash.Count()', file c:/work/mozilla/builds/beta/mozilla/netwerk/protocol/http/SpdySession3.cpp, line 1901 during shutdown.

Appears to require Spider. It does not happen (for me) just loading the browser and shutting down so this might be invalid.

Beta/16, Aurora/17, Nightly/18 all platforms at least.

most stacks look like

NS_DebugBreak_P | mozilla::net::SpdySession3::Close(unsigned int) nsHttpConnection::CloseTransaction(nsAHttpTransaction*, unsigned int) nsHttpConnection::OnInputStreamReady(nsIAsyncInputStream*) nsSocketInputStream::OnSocketReady(unsigned int) nsSocketTransport::OnSocketReady(PRFileDesc*, short)

though a couple look like

mozalloc_abort | NS_DebugBreak_P | mozilla::DeadlockDetector<mozilla::BlockingResourceBase::DeadlockDetectorEntry>::PRAutoLock::~PRAutoLock mozilla::DeadlockDetector<mozilla::BlockingResourceBase::DeadlockDetectorEntry>::CheckAcquisition mozilla::DeadlockDetector<mozilla::BlockingResourceBase::DeadlockDetectorEntry>::PRAutoLock::~PRAutoLock

Comment 1

[Patrick McManus [:mcmanus]]

Thanks bob. I'll take a look.

Comment 2

[Patrick McManus [:mcmanus]]

Hi Bob - spider doesn't seem to be running for me on nightly.. any ideas?

JavaScript strict warning: chrome://spider/content/utils.js, line 543: reference to undefined property netscape.security.PrivilegeManager
JavaScript strict warning: chrome://spider/content/utils.js, line 57: assignment to undeclared variable gOutput
checkChromePrivs: Several features such as cross domain access, error logging, 
or http logging require security privileges to operate.
Please see Help for more details.JavaScript strict warning: chrome://spider/content/utils.js, line 543: reference to undefined property netscape.security.PrivilegeManager
WARNING: Unable to test style tree integrity -- no content node: file ../../../scratch/layout/base/nsCSSFrameConstructor.cpp, line 8227
WARNING: OpenGL-accelerated layers are not supported on this system.: file ../../../scratch/widget/xpwidgets/nsBaseWidget.cpp, line 806
WARNING: OpenGL-accelerated layers are not supported on this system.: file ../../../scratch/widget/xpwidgets/nsBaseWidget.cpp, line 806
JavaScript strict warning: chrome://spider/content/spider.js, line 1282: reference to undefined property netscape.security.PrivilegeManager
JavaScript error: , line 0: uncaught exception: CHTTPResponseObserver.register: privilege failure TypeError: netscape.security.PrivilegeManager is undefined
Spider: Start: -url "http://friendfans.blogspot.com/feeds/posts/default" -depth 0 -timeout 0 -wait 0 -start -quit 
Spider: Begin loading http://friendfans.blogspot.com/feeds/posts/default

Comment 3

[Bob Clary [:bc] (inactive)]

mcmanus: sorry, I had posted a link to the old version. Try downloading and reinstalling it. It should show version 0.0.5.0 from August 29, 2012 in the bottom of the window.

Comment 4

[Patrick McManus [:mcmanus]]

bob this is wfm right now (linux64). can you reconfirm with latest and if so any thoughts on what might be different?

Comment 5

[Bob Clary [:bc] (inactive)]

I can't reproduce the ABORT at the moment after loading the url 30 times on OSX and Linux though I do see some really slow shutdowns and currently have a hung process on Linux:

#0  0x00b13424 in __kernel_vsyscall ()
#1  0x00a3b2bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
#2  0x00cd9a4b in PR_WaitCondVar (cvar=0x8e90258, timeout=4294967295)
    at /work/mozilla/builds/nightly/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:385
#3  0x00cda23c in PR_Wait (mon=0x8e90298, timeout=4294967295)
    at /work/mozilla/builds/nightly/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:582
#4  0x02edf118 in mozilla::ReentrantMonitor::Wait (this=0x8e8fa9c, interval=
    4294967295)
    at /work/mozilla/builds/nightly/mozilla/firefox-debug/xpcom/build/BlockingResourceBase.cpp:312
#5  0x015c6920 in mozilla::ReentrantMonitorAutoEnter::Wait (this=0xbff49228, 
    interval=4294967295)
    at ../../../dist/include/mozilla/ReentrantMonitor.h:192
#6  0x015c76b4 in nsHttpConnectionMgr::Shutdown (this=0x8e8fa90)
    at /work/mozilla/builds/nightly/mozilla/netwerk/protocol/http/nsHttpConnectionMgr.cpp:150
#7  0x015e7f62 in nsHttpHandler::Observe (this=0x8e8d428, subject=0x8dca678, 
    topic=0x3f836f7 "profile-change-net-teardown", data=0x3f83940)
    at /work/mozilla/builds/nightly/mozilla/netwerk/protocol/http/nsHttpHandler.cpp:1572

I'll bisect and look for a fix or mask to the condition. more new at ...

Comment 6

[Bob Clary [:bc] (inactive)]

I can no longer reproduce even with a 9/3 build. :-(. Content change ?

Comment 7

[Patrick McManus [:mcmanus]]

(In reply to Bob Clary [:bc:] from comment #5)
>
> OSX and Linux though I do see some really slow shutdowns and currently have
> a hung process on Linux:
>

that could be a dup of 729536

I'm going to mark this wfm for the moment and refile/reopen if we have something to work with. Sorry I couldn't jump on it as soon as it was filed.

Comment 8

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

I've seen this fatal assertion twice in the past week, while browsing, both times I think while on Google properties.

Comment 9

[Bob Clary [:bc] (inactive)]

sorry, i missed that this was also reproducible on https://plus.google.com/107950851093654625603/posts on Windows XP and Windows 7.

Comment 10

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

On January 18, I crashed while running a debug build that I started on January 12 (so it was probably built within a few days prior to January 12).  I saw this assertion:

###!!! ASSERTION: Appended stream not at beginning.: 'SeekableStreamAtBeginning(aStream)', file /home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/io/nsMultiplexInputStream.cpp, line 107
nsHttpTransaction::Init(unsigned int, nsHttpConnectionInfo*, nsHttpRequestHead*, nsIInputStream*, bool, nsIEventTarget*, nsIInterfaceRequestor*, nsITransportEventSink*, nsIAsyncInputStream**) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpTransaction.cpp:295)
mozilla::net::nsHttpChannel::SetupTransaction() (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:861)
mozilla::net::nsHttpChannel::DoAuthRetry(nsAHttpConnection*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:5538)
mozilla::net::nsHttpChannel::OnStopRequest(nsIRequest*, nsISupports*, tag_nsresult) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:4997)
nsInputStreamPump::OnStateStop() (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/src/nsInputStreamPump.cpp:553)
nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/src/nsInputStreamPump.cpp:375)
nsInputStreamReadyEvent::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/io/nsStreamUtils.cpp:83)
nsThread::ProcessNextEvent(bool, bool*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:627)
NS_ProcessNextEvent_P(nsIThread*, bool) (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/xpcom/build/nsThreadUtils.cpp:238)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/glue/MessagePump.cpp:83)
MessageLoop::RunInternal() (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:216)
~AutoRunState (/home/dbaron/builds/ssd/mozilla-central/mozilla/ipc/chromium/src/base/message_loop.cc:502)
nsBaseAppShell::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/widget/xpwidgets/nsBaseAppShell.cpp:165)
nsAppStartup::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/components/startup/nsAppStartup.cpp:289)
XREMain::XRE_mainRun() (/home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:3827)
XREMain::XRE_main(int, char**, nsXREAppData const*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:3893)
XRE_main (/home/dbaron/builds/ssd/mozilla-central/mozilla/toolkit/xre/nsAppRunner.cpp:4096)
do_main (/home/dbaron/builds/ssd/mozilla-central/mozilla/browser/app/nsBrowserApp.cpp:195)
~ScopedLogging (/home/dbaron/builds/ssd/mozilla-central/mozilla/browser/app/nsBrowserApp.cpp:102)
__libc_start_main (/build/buildd/eglibc-2.15/csu/libc-start.c:258)
_start (/home/dbaron/bin/running-firefox/firefox)


followed within a few seconds, I think, by this abort:

###!!! ABORT: index corruption: 'mStreamTransactionHash.Count() == mStreamIDHash.Count()', file /home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/SpdySession2.cpp, line 1876
nsHttpConnectionMgr::TimeoutTickCB(nsACString_internal const&, nsAutoPtr<nsHttpConnectionMgr::nsConnectionEntry>&, void*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpConnectionMgr.cpp:2303)
PL_DHashTableEnumerate (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/xpcom/build/pldhash.cpp:718)
nsBaseHashtable<nsCStringHashKey, nsAutoPtr<nsHttpConnectionMgr::nsConnectionEntry>, nsHttpConnectionMgr::nsConnectionEntry*>::Enumerate(PLDHashOperator (*)(nsACString_internal const&, nsAutoPtr<nsHttpConnectionMgr::nsConnectionEntry>&, void*), void*) (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/netwerk/protocol/http/../../../dist/include/nsBaseHashtable.h:224)
nsHttpConnectionMgr::Observe(nsISupports*, char const*, unsigned short const*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/protocol/http/nsHttpConnectionMgr.cpp:252)
nsTimerImpl::Fire() (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsTimerImpl.cpp:497)
~nsRefPtr (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/xpcom/threads/../../dist/include/nsAutoPtr.h:875)
nsThread::ProcessNextEvent(bool, bool*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:627)
NS_ProcessNextEvent_P(nsIThread*, bool) (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/xpcom/build/nsThreadUtils.cpp:238)
nsSocketTransportService::Run() (/home/dbaron/builds/ssd/mozilla-central/mozilla/netwerk/base/src/nsSocketTransportService2.cpp:650)
nsThread::ProcessNextEvent(bool, bool*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:627)
NS_ProcessNextEvent_P(nsIThread*, bool) (/home/dbaron/builds/ssd/mozilla-central/obj/firefox-debugopt/xpcom/build/nsThreadUtils.cpp:238)
nsThread::ThreadFunc(void*) (/home/dbaron/builds/ssd/mozilla-central/mozilla/xpcom/threads/nsThread.cpp:264)
_pt_root (/home/dbaron/builds/ssd/mozilla-central/mozilla/nsprpub/pr/src/pthreads/ptthread.c:159)
start_thread (/build/buildd/eglibc-2.15/nptl/pthread_create.c:308)
clone (/build/buildd/eglibc-2.15/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:114)



The https: URLs (I'm saying this since the ABORT was in SPDY code) that I was interacting with at the very end of my session (based on its stdout, which is augmented by some printfs I have locally) were:

nsDocShell(0x6b862960)::LoadURI(https://tbpl.mozilla.org/php/getParsedLog.php?id=18917909&tree=Mozilla-Inbound)
--DOMWINDOW == 1313 (0x6b3d8c80) [serial = 19497] [outer = (nil)] [url = https://hg.mozilla.org/integration/mozilla-inbound/rev/0238a6bf8f85]
--DOMWINDOW == 1312 (0x5971b5d0) [serial = 19505] [outer = 0xdaf11b0] [url = https://tbpl.mozilla.org/php/getParsedLog.php?id=18917909&tree=Mozilla-Inbound]
--DOMWINDOW == 1311 (0xdaf11b0) [serial = 19503] [outer = (nil)] [url = https://tbpl.mozilla.org/php/getParsedLog.php?id=18917909&tree=Mozilla-Inbound]
nsDocShell(0x6b068260)::LoadURI(https://tbpl.mozilla.org/?tree=Mozilla-Inbound)


Maybe related to bug 829120???

Comment 11

[Patrick McManus [:mcmanus]]

As the author of this assert, I can say "This assert is bogus".

The assert is saying that when the session is marked closed that the 2 transaction indicies have the same # of entries.. while that is true most of the time - there is a window between when a transaction is added (and goes into the transaction index) and when it is assigned an ID (and goes into the ID index). A close is legitimate between those events, and it looks like the code deals with that case correctly (i.e. the streams are still reset appropriately because they are in the transaction hash).

There was a time when the ID was assigned in sync with the transaction hash, but that had to change to be asyncronous in order to guarantee monotonically increasing SYN_STREAM ids.

the fix here is just to remove the assert because it does not state an invariant anymore.

Comment 12

[Patrick McManus [:mcmanus]]

Attachment: patch 0

deletes the incorrect NS_ABORT_IF_FALSE in question and reduces another redundant one from two asserts() to one.

Comment 13

[Patrick McManus [:mcmanus]]

Attachment: patch 1

forgot the spdy 2 version the first time.

Comment 14

[Honza Bambas (:mayhemer)]

Comment on attachment 723772 [details] [diff] [review]
patch 1

Review of attachment 723772 [details] [diff] [review]:
-----------------------------------------------------------------

r+ based on comment 11.

I cannot confirm this is OK by actually inspecting the code, since spdy implementation is a total labyrinth to me.

Comment 15

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3bf16356ae8b

Comment 16

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/3bf16356ae8b