Closed Bug 1136780 Opened 10 years ago Closed 9 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
(deleted), 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) (deleted) — 
/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: 9 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: