Closed Bug 1136780 Opened 10 years ago Closed 10 years ago

Intermittent test_fetch_event.html | should be controlled | load should be successful | load should have synthesized response etc...

Categories

(Core :: DOM: Workers, defect)

Product:
Core
Component:
DOM: Workers
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla40
Tracking Flags:
Tracking Status
firefox38 --- unaffected
firefox39 --- disabled
firefox40 --- disabled
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: ehsan.akhgari)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Re-enable test_fetch_event.html now that bug 1156771 has been fixed
861 bytes, patch
nsm
: review+
Details | Diff | Splinter Review
22:55:51 INFO - 119 INFO TEST-START | dom/workers/test/serviceworkers/test_fetch_event.html 22:55:51 INFO - 120 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | should be controlled - expected PASS 22:55:51 INFO - 121 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | load should be successful - expected PASS 22:55:51 INFO - 122 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | load should have synthesized response - expected PASS 22:55:51 INFO - 123 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should be uninterrupted 22:55:51 INFO - 124 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | XHR load should not complete successfully - expected PASS 22:55:51 INFO - 125 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | XHR load should not complete successfully - expected PASS 22:55:51 INFO - 126 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | XHR load should not complete successfully - expected PASS 22:55:51 INFO - 127 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | load should be successful - expected PASS 22:55:51 INFO - 128 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | request header checks should have passed - expected PASS 22:55:51 INFO - 129 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | SCRIPT load should complete successfully - expected PASS 22:55:51 INFO - 130 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | LINK load should complete successfully - expected PASS 22:55:51 INFO - 131 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | IMG load should complete successfully - expected PASS 22:55:51 INFO - 132 INFO TEST-UNEXPECTED-FAIL | dom/workers/test/serviceworkers/test_fetch_event.html | iframe load should be intercepted - expected PASS 22:55:51 INFO - 133 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | worker load intercepted 22:55:51 INFO - 134 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | worker imported script should be intercepted 22:55:51 INFO - 135 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should be successful 22:55:51 INFO - 136 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should have synthesized response 22:55:51 INFO - 137 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should not complete 22:55:51 INFO - 138 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should be uninterrupted 22:55:51 INFO - 139 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should not complete 22:55:51 INFO - 140 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should not complete 22:55:51 INFO - 141 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | load should be successful 22:55:51 INFO - 142 INFO TEST-PASS | dom/workers/test/serviceworkers/test_fetch_event.html | request header checks should have passed 22:55:51 INFO - 143 INFO TEST-OK | dom/workers/test/serviceworkers/test_fetch_event.html | took 33174ms
The new gzip tests are failing relatively frequently :<
Flags: needinfo?(nsm.nikhil)
Hmm, I expected Bug 1110814's 'fully initialize Response' patch to fix them. I'll take a look.
Assignee: nobody → nsm.nikhil
Flags: needinfo?(nsm.nikhil)
Sorry, but this is too frequent and widespread to leave the test enabled. I'm planning to disable tomorrow if there isn't a fix landed before then.
Flags: needinfo?(nsm.nikhil)
Disabled. https://hg.mozilla.org/mozilla-central/rev/dc1ada58ef9d
status-firefox38: --- → unaffected
status-firefox39: --- → affected
status-firefox40: --- → disabled
status-firefox-esr31: --- → unaffected
Flags: needinfo?(nsm.nikhil)
Whiteboard: [test disabled]
Attached file MozReview Request: bz://1136780/mt (obsolete) —
/r/6415 - Bug 1136780 - Disable test_fetch_event.html for frequent failures on all platforms. a=me /r/6417 - Bug 996238 - Reformat gtest_utils.h, r=ekr /r/6419 - Bug 996238 - ALPN support for WebRTC, r=ekr /r/6421 - Bug 996238 - Adding test for asymmetric media isolation across PC, r=ekr /r/6423 - Bug 996238 - Move more of the test code to promises, r=jib Pull down these commits: hg pull -r 9dac340bb2db8d3cd8d3420ef5c6736df29b539f https://reviewboard-hg.mozilla.org/gecko/
Comment on attachment 8586428 [details] MozReview Request: bz://1136780/mt Oops, unnoticed rebase snafu.
Attachment #8586428 - Attachment is obsolete: true
Flags: needinfo?(ehsan)
Depends on: 1156432
I investigated this today. Here are my findings so far: 1. This is trivial to reproduce locally, at least on OSX debug, by applying the patches that I will soon attach to bug 1156432 and running this under --run-until-failure. 2. This happens with hello-after-extracting.gz, not with hello.js. 3. Here is the failure condition: this can only fail when there is a cache entry for hello-after-extracting.gz. Sometimes when that happens, we get to this code <https://dxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#2787> and try to open the cache entry. While doing that, we get to <https://dxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#2890> but the call to GetMetaDataElement fails because CacheFileMetadata::mBuf is null. Here is the call stack at this point: * frame #0: 0x0000000102b407c4 XUL`mozilla::net::nsHttpChannel::OnCacheEntryCheck(this=0x0000000126c62000, entry=0x0000000124715900, appCache=0x0000000000000000, aResult=0x00007fff5fbfbcd4) + 820 at nsHttpChannel.cpp:2925 frame #1: 0x0000000102b430ff XUL`non-virtual thunk to mozilla::net::nsHttpChannel::OnCacheEntryCheck(this=0x0000000126c62448, entry=0x0000000124715900, appCache=0x0000000000000000, aResult=0x00007fff5fbfbcd4) + 63 at nsHttpChannel.cpp:3279 frame #2: 0x00000001029d14f5 XUL`mozilla::net::CacheEntry::InvokeCallback(this=0x0000000124715900, aCallback=0x00007fff5fbfbd50) + 645 at CacheEntry.cpp:681 frame #3: 0x00000001029d11e3 XUL`mozilla::net::CacheEntry::InvokeCallbacks(this=0x0000000124715900, aReadOnly=false) + 899 at CacheEntry.cpp:616 frame #4: 0x00000001029ced3c XUL`mozilla::net::CacheEntry::InvokeCallbacks(this=0x0000000124715900) + 92 at CacheEntry.cpp:570 frame #5: 0x00000001029cdd69 XUL`mozilla::net::CacheEntry::Open(this=0x0000000124715900, aCallback=0x00007fff5fbfbe60, aTruncate=false, aPriority=false, aBypassIfBusy=true) + 249 at CacheEntry.cpp:310 frame #6: 0x00000001029cdc11 XUL`mozilla::net::CacheEntry::AsyncOpen(this=0x0000000124715900, aCallback=0x0000000126c62448, aFlags=24) + 561 at CacheEntry.cpp:284 frame #7: 0x0000000102a35b1a XUL`mozilla::net::CacheStorage::AsyncOpenURI(this=0x0000000124388f10, aURI=0x000000011b103900, aIdExtension=0x00007fff5fbfc438, aFlags=24, aCallback=0x0000000126c62448) + 2730 at CacheStorage.cpp:107 frame #8: 0x0000000102b313fb XUL`mozilla::net::nsHttpChannel::OpenCacheEntry(this=0x0000000126c62000, isHttps=false) + 4843 at nsHttpChannel.cpp:2816 frame #9: 0x0000000102af15c1 XUL`mozilla::net::InterceptedChannelChrome::FinishSynthesizedResponse(this=0x000000011b3ac760) + 849 at InterceptedChannel.cpp:207 frame #10: 0x0000000105c22ecf XUL`mozilla::dom::workers::(anonymous namespace)::FinishResponse::Run(this=0x0000000129dda910) + 879 at ServiceWorkerEvents.cpp:129 frame #11: 0x000000010271394f XUL`nsThread::ProcessNextEvent(this=0x0000000100633310, aMayWait=false, aResult=0x00007fff5fbfc9c3) + 2095 at nsThread.cpp:866 frame #12: 0x00000001027701da XUL`NS_ProcessPendingEvents(aThread=0x0000000100633310, aTimeout=20) + 154 at nsThreadUtils.cpp:207 frame #13: 0x0000000105ef39a9 XUL`nsBaseAppShell::NativeEventCallback(this=0x000000011881c7a0) + 201 at nsBaseAppShell.cpp:98 frame #14: 0x0000000105f70d9d XUL`nsAppShell::ProcessGeckoEvents(aInfo=0x000000011881c7a0) + 445 at nsAppShell.mm:377 frame #15: 0x00007fff83251a01 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17 frame #16: 0x00007fff83243b8d CoreFoundation`__CFRunLoopDoSources0 + 269 frame #17: 0x00007fff832431bf CoreFoundation`__CFRunLoopRun + 927 frame #18: 0x00007fff83242bd8 CoreFoundation`CFRunLoopRunSpecific + 296 frame #19: 0x00007fff8d5bd56f HIToolbox`RunCurrentEventLoopInMode + 235 frame #20: 0x00007fff8d5bd2ea HIToolbox`ReceiveNextEventCommon + 431 frame #21: 0x00007fff8d5bd12b HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71 frame #22: 0x00007fff865469bb AppKit`_DPSNextEvent + 978 frame #23: 0x00007fff86545f68 AppKit`-[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 346 frame #24: 0x0000000105f6f8b7 XUL`-[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:](self=0x0000000118815430, _cmd=0x00007fff86e62808, mask=18446744073709551615, expiration=0x422d63c37f00000d, mode=0x00007fff71d96040, flag='\x01') + 119 at nsAppShell.mm:118 frame #25: 0x00007fff8653bbf3 AppKit`-[NSApplication run] + 594 frame #26: 0x0000000105f7176c XUL`nsAppShell::Run(this=0x000000011881c7a0) + 172 at nsAppShell.mm:651 frame #27: 0x0000000106ea48a1 XUL`nsAppStartup::Run(this=0x0000000118857c40) + 161 at nsAppStartup.cpp:281 frame #28: 0x0000000106f55d5d XUL`XREMain::XRE_mainRun(this=0x00007fff5fbfe940) + 6157 at nsAppRunner.cpp:4157 frame #29: 0x0000000106f566a2 XUL`XREMain::XRE_main(this=0x00007fff5fbfe940, argc=5, argv=0x00007fff5fbff248, aAppData=0x00007fff5fbfebc8) + 1010 at nsAppRunner.cpp:4237 frame #30: 0x0000000106f56b62 XUL`XRE_main(argc=5, argv=0x00007fff5fbff248, aAppData=0x00007fff5fbfebc8, aFlags=0) + 98 at nsAppRunner.cpp:4456 frame #31: 0x000000010000237e firefox`do_main(argc=5, argv=0x00007fff5fbff248, xreDirectory=0x000000010060e100) + 1870 at nsBrowserApp.cpp:294 frame #32: 0x0000000100001735 firefox`main(argc=5, argv=0x00007fff5fbff248) + 293 at nsBrowserApp.cpp:667 frame #33: 0x00000001000011b4 firefox`start + 52 Also, here is the dumps for some of these objects: (lldb) p *((mozilla::net::CacheEntry *)entry) (mozilla::net::CacheEntry) $2 = { mRefCnt = { mValue = { mozilla::detail::AtomicBaseIncDec<unsigned long, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned long, mozilla::MemoryOrdering> = (mValue = 9) } } } _mOwningThread = (mThread = 0x000000010069c070) mFrecency = 0 mSortingExpirationTime = { mozilla::detail::AtomicBaseIncDec<unsigned int, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned int, mozilla::MemoryOrdering> = (mValue = 4294967295) } } mService = { mRawPtr = 0x000000012972ba60 } mLock = { mozilla::OffTheBooksMutex = { mozilla::BlockingResourceBase = { mChainPrev = 0x0000000000000000 mName = 0x0000000108b8659f "CacheEntry" mType = eMutex mAcquired = false } mLock = 0x0000000129133b80 } } mHandlesCount = { mValue = { mozilla::detail::AtomicBaseIncDec<unsigned long, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned long, mozilla::MemoryOrdering> = (mValue = 4) } } } mCallbacks = {} mDoomCallback = (mRawPtr = 0x0000000000000000) mFile = { mRawPtr = 0x000000012795b3c0 } mFileStatus = { mozilla::detail::AtomicBase<nsresult, mozilla::MemoryOrdering> = (mValue = NS_OK) } mURI = (mRawPtr = 0x0000000124715400) mEnhanceID = { nsACString_internal = "u" } mStorageID = { nsACString_internal = "" } mUseDisk = false mIsDoomed = false mSecurityInfoLoaded = false mPreventCallbacks = false mHasData = true mState = READY mRegistration = REGISTERED mOutputStream = (mRawPtr = 0x0000000000000000) mWriter = 0x0000000000000000 mBackgroundOperations = (mFlags = 0) mSecurityInfo = { nsCOMPtr_base = (mRawPtr = 0x0000000000000000) } mPredictedDataSize = 0 mLoadStart = (mValue = 243261124143658) mUseCount = 0 mReleaseThread = (mRawPtr = 0x0000000100633310) } (lldb) p *((mozilla::net::CacheFile *)(*((mozilla::net::CacheEntry *)entry)).mFile.mRawPtr) (mozilla::net::CacheFile) $4 = { mRefCnt = { mValue = { mozilla::detail::AtomicBaseIncDec<unsigned long, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned long, mozilla::MemoryOrdering> = (mValue = 2) } } } _mOwningThread = (mThread = 0x000000010069c070) mLock = { mozilla::OffTheBooksMutex = { mozilla::BlockingResourceBase = { mChainPrev = 0x0000000000000000 mName = 0x0000000108b873db "CacheFile.mLock" mType = eMutex mAcquired = false } mLock = 0x0000000129133c40 } } mOpeningFile = false mReady = true mMemoryOnly = true mOpenAsMemoryOnly = true mPriority = false mDataAccessed = true mDataIsDirty = false mWritingMetadata = false mPreloadWithoutInputStreams = false mPreloadChunkCount = 4 mStatus = NS_OK mDataSize = 0 mKey = { nsACString_internal = "~u,:http://mochi.test:8888/tests/dom/workers/test/serviceworkers/fetch/hello-after-extracting.gz" } mHandle = { mRawPtr = 0x0000000000000000 } mMetadata = { mRawPtr = 0x000000012e1cf5e0 } mListener = (mRawPtr = 0x0000000000000000) mDoomAfterOpenListener = (mRawPtr = 0x0000000000000000) mChunks = { nsBaseHashtable<nsUint32HashKey, nsRefPtr<mozilla::net::CacheFileChunk>, mozilla::net::CacheFileChunk *> = { nsTHashtable<nsBaseHashtableET<nsUint32HashKey, nsRefPtr<mozilla::net::CacheFileChunk> > > = { mTable = { mOps = 0x000000010b7fbbf0 mHashShift = 29 mEntrySize = 16 mEntryCount = 0 mRemovedCount = 0 mGeneration = 0 mEntryStore = 0x0000000000000000 mRecursionLevel = { mozilla::detail::AtomicBaseIncDec<unsigned int, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned int, mozilla::MemoryOrdering> = (mValue = 0) } } } } } } mChunkListeners = { nsBaseHashtable<nsUint32HashKey, nsAutoPtr<mozilla::net::ChunkListeners>, mozilla::net::ChunkListeners *> = { nsTHashtable<nsBaseHashtableET<nsUint32HashKey, nsAutoPtr<mozilla::net::ChunkListeners> > > = { mTable = { mOps = 0x000000010b7fbbc8 mHashShift = 29 mEntrySize = 16 mEntryCount = 0 mRemovedCount = 0 mGeneration = 0 mEntryStore = 0x0000000000000000 mRecursionLevel = { mozilla::detail::AtomicBaseIncDec<unsigned int, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned int, mozilla::MemoryOrdering> = (mValue = 0) } } } } } } mCachedChunks = { nsBaseHashtable<nsUint32HashKey, nsRefPtr<mozilla::net::CacheFileChunk>, mozilla::net::CacheFileChunk *> = { nsTHashtable<nsBaseHashtableET<nsUint32HashKey, nsRefPtr<mozilla::net::CacheFileChunk> > > = { mTable = { mOps = 0x000000010b7fbbf0 mHashShift = 29 mEntrySize = 16 mEntryCount = 0 mRemovedCount = 0 mGeneration = 0 mEntryStore = 0x0000000000000000 mRecursionLevel = { mozilla::detail::AtomicBaseIncDec<unsigned int, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned int, mozilla::MemoryOrdering> = (mValue = 0) } } } } } } mInputs = {} mOutput = 0x00000001298fca90 mObjsToRelease = {} } (lldb) p *((mozilla::net::CacheFileMetadata *)(*((mozilla::net::CacheFile *)(*((mozilla::net::CacheEntry *)entry)).mFile.mRawPtr)).mMetadata.mRawPtr) (mozilla::net::CacheFileMetadata) $7 = { mozilla::net::CacheMemoryConsumer = (mReportedMemoryConsumption = 0, mFlags = 1) mRefCnt = { mValue = { mozilla::detail::AtomicBaseIncDec<unsigned long, mozilla::MemoryOrdering> = { mozilla::detail::AtomicBase<unsigned long, mozilla::MemoryOrdering> = (mValue = 1) } } } _mOwningThread = (mThread = 0x000000010069c070) mHandle = { mRawPtr = 0x0000000000000000 } mKey = { nsACString_internal = "~u,:http://mochi.test:8888/tests/dom/workers/test/serviceworkers/fetch/hello-after-extracting.gz" } mHashArray = 0x0000000000000000 mHashArraySize = 0 mHashCount = 0 mOffset = 0 mBuf = 0x0000000000000000 mBufSize = 0 mWriteBuf = 0x0000000000000000 mMetaHdr = { mVersion = 1 mFetchCount = 0 mLastFetched = 0 mLastModified = 0 mFrecency = 0 mExpirationTime = 4294967295 mKeySize = 96 } mElementsSize = 0 mIsDirty = true mAnonymous = false mInBrowser = false mAllocExactSize = false mFirstRead = true mReadStart = (mValue = 0) mAppId = 0 mListener = (mRawPtr = 0x0000000000000000) } I'm still not familiar enough with how things are supposed to work here, but a couple of questions for now from Josh: * Does the above help you determine what could be happening here? * Is it intentional that we store synthesized responses in the memory cache? That is surprising to me.
Flags: needinfo?(ehsan) → needinfo?(josh)
Also, I forgot to mention that the reason for the test failure is that we fail to intercept, the request ends up going to the network, and we get a 404.
Another interesting fact is that if you put the browser in offline mode during the test, the failure goes away, which confirms my suspicious of this having to do with the entry stored in the memory cache, since the offline status check bypasses the usage of local cache altogether.
Hmm, I wonder if this is the collision discussed in bug 1156771? We're performing the same requests in the main page and in the worker, and the tests are written to be as concurrent as possible.
Flags: needinfo?(josh)
(In reply to Josh Matthews [:jdm] from comment #275) > Hmm, I wonder if this is the collision discussed in bug 1156771? We're > performing the same requests in the main page and in the worker, and the > tests are written to be as concurrent as possible. That is very possible. I will investigate. Thanks!
(In reply to :Ehsan Akhgari (not reading bugmail, needinfo? me!) from comment #276) > (In reply to Josh Matthews [:jdm] from comment #275) > > Hmm, I wonder if this is the collision discussed in bug 1156771? We're > > performing the same requests in the main page and in the worker, and the > > tests are written to be as concurrent as possible. > > That is very possible. I will investigate. Thanks! Yes, this seems to be the cause. I'll submit a fix for bug 1156771 and test the fix on try in the mean time.
Assignee: nsm.nikhil → ehsan
Depends on: 1156771
Whiteboard: [test disabled]
https://hg.mozilla.org/mozilla-central/rev/5496344c05e9
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: