Closed Bug 471227 Opened 16 years ago Closed 15 years ago

test_Prototype.html intermittently fails

Categories

(Core :: DOM: Core & HTML, defect, P2)

Product:
Core
Component:
DOM: Core & HTML
Platform:
x86
macOS
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla1.9.2a1

People

(Reporter: sgautherie, Assigned: dcamp)

References

Details

(Keywords: fixed1.9.1, intermittent-failure)

Attachments

(2 files, 5 obsolete files)

get better logs for debugging [Checkin: Comment 7]
1.82 KB, patch
Details | Diff | Splinter Review
v3 [Checkin: Comment 35 & 37]
25.24 KB, patch
bzbarsky
: review+
bzbarsky
: superreview+
Details | Diff | Splinter Review 
For example:
{
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1230338221.1230341196.28431.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2008/12/26 16:37:01

*** 31172 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testSynchronousRequest - 2 assertions, 1 failures, 1 errors
*** 31173 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testAsynchronousRequest - 1 assertions, 0 failures, 1 errors
*** 31174 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testUpdater - 3 assertions, 2 failures, 0 errors
*** 31175 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponders - 7 assertions, 3 failures, 0 errors
*** 31176 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testEvalResponseShouldBeCalledBeforeOnComplete - 1 assertions, 2 failures, 1 errors
}
Flags: wanted1.9.1?
Just checked in an update to the prototype test suite in bug 424814.  Maybe it will help.
Still there:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1234634595.1234638028.17962.gz
Linux mozilla-1.9.1 unit test on 2009/02/14 10:03:15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1234634595.1234639635.20441.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/02/14 10:03:15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235239496.1235243538.13915.gz
WINNT 5.2 mozilla-1.9.1 unit test on 2009/02/21 10:04:56

*** 31231 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testPeriodicalExecuterStop - 0 assertions, 1 failures, 0 errors
Failure: assertEqual: expected "3", actual "2" Line #141
Depends on: 478581
Looks like something's failing with the xhr requests in this file, but we're not getting the right exceptions logged. If you look at the failed logs, we're getting a lot of:

undefined: undefined([object Object])

in the failed tests.  The onException handler takes the wrong args.  The attached patch fixes that, and makes sure the onException handler is set for testSynchronousRequest and testAsynchronousRequest, two of the simpler tests to debug here.

This patch (or something like it) should go upstream to the prototype folks, but I'd like to check it in asap to get more information on the test failures.
Attachment #363780 - Attachment is patch: true
Attachment #363780 - Attachment mime type: application/octet-stream → text/plain
Comment on attachment 363780 [details] [diff] [review]
get better logs for debugging
[Checkin: Comment 7]


http://hg.mozilla.org/mozilla-central/rev/72f3109517bc
Attachment #363780 - Attachment description: get better logs for debugging → get better logs for debugging [Checkin: Comment 7]
(In reply to comment #6)
> get better logs for debugging

See new log at:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1235432389.1235439081.19972.gz
WINNT 5.2 mozilla-central unit test on 2009/02/23 15:39:49
OK, so anything synchronous is failing with NS_ERROR_FAILURE from nsXMLHttpRequest::Send(), anything asynchronous is dying from what would presumably be the xhr request not succeeding, and a few tests are failing because prototype doesn't properly update activeRequestCount when a request fails.

So something is causing these requests (and apparently only these requests) to fail during the request...
I just landed this spew to help narrow down what's failing in the request.  I'll back it out once we have a failure with a log.

http://hg.mozilla.org/mozilla-central/rev/920e3f7dfd49
Not sure if I'm meant to report this or not but I just saw this on my console:

(Bug 471227): XHR failed for http://1.channel21.facebook.com/x/2210732379/false/p_286106589=1: status: 804b0002, appcache: (nil)

Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.2a1pre) Gecko/20090224 Minefield/3.2a1pre
Assignee: nobody → dcamp
Attached patch more spew [Backout: Comment 13] (obsolete) — — Splinter Review 
It looks from the previous patch that we're getting an application cache associated somehow with ajax_test.html's document.  That doesn't make a whole lot of sense, adding a bit more spew to try to figure out where that's happening.

Landed as http://hg.mozilla.org/mozilla-central/rev/d69abaa8188b
Got logs:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1235546553.1235550815.627.gz&fulltext=1

At first glance it looks like a leftover cache update is associating with a new document.  Not sure why that's happening, will take a closer look tomorrow.

I backed out patches 2 and 3 (the debug spew).
Landed another round of logging as http://hg.mozilla.org/mozilla-central/rev/39a65a31eb93
FWIW, this test failed today on 1.9.1 branch:

OS X 10.5.2 mozilla-1.9.1 unit test on 2009/02/26 12:54:30
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235681670.1235688993.32650.gz&fulltext=1
another one on the 1.9.1 branch

WINNT 5.2 mozilla-1.9.1 unit test on 2009/02/27 14:48:14
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1235774894.1235780160.32337.gz&fulltext=1
We know 1.9.1 has this bug too ... but the debugging logs are (done) on trunk only...
This is happening pretty frequently right now - 3 times consecutively on 1.9.1, and once on trunk.

mozilla-central:
http://tinderbox.mozilla.org/showlog.cgi?tree=Firefox&errorparser=unittest&logfile=1236083065.1236090608.4800.gz&buildtime=1236083065&buildname=WINNT%205.2%20mozilla-central%20unit%20test&fulltext=1

1.9.1:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1236080286.1236087131.30927.gz&fulltext=1

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1236073086.1236079774.6555.gz&fulltext=1

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.1/1236065886.1236069350.17918.gz&fulltext=1


Seemingly-relevant snippet from the mozilla-central log:

*** 31571 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/offline/test_updatingManifest.html | we have associated application cache and update is pending (4)
*** 31572 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/offline/test_updatingManifest.html | we have associated application cache (4)
(Bug 471227) Processing manifest for document >0666F12C< (http://localhost:8888/tests/dom/tests/mochitest/ajax/offline/updatingIframe.sjs) which was loaded from app cache 05BE83B8 (http://localhost:8888/tests/dom/tests/mochitest/ajax/offline/updatingManifest.sjs)
(Bug 471227) Scheduling an update.
*** 31573 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/offline/test_updatingManifest.html | IFrame version 2
*** 31575 INFO Running /tests/dom/tests/mochitest/ajax/offline/test_xhtmlManifest.xhtml...
(Bug 471227) Processing manifest for document >05C8D78C< (http://localhost:8888/tests/dom/tests/mochitest/ajax/offline/test_xhtmlManifest.xhtml) which was loaded from app cache 00000000 ()
(Bug 471227) No permission.
(Bug 471227) Processing manifest for document >0626DB44< (http://localhost:8888/tests/dom/tests/mochitest/ajax/offline/test_xhtmlManifest.xhtml) which was loaded from app cache 00000000 ()
(Bug 471227) Scheduling an update.
(Bug 471227) Associating documents from Finish()
(Bug 471227) Associating app cache 059003E8 (http%3A//localhost%3A8888/tests/dom/tests/mochitest/ajax/offline/simpleManifest.cacheManifest|0000001236089169|50) to document >0626DB44< (http://localhost:8888/tests/dom/tests/mochitest/ajax/offline/test_xhtmlManifest.xhtml)
*** 31576 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/offline/test_xhtmlManifest.xhtml | Application cache updated.
*** 31578 INFO Running /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html...
(Bug 471227) Associating documents from Finish()
(Bug 471227) Associating app cache 0593C700 (http%3A//localhost%3A8888/tests/dom/tests/mochitest/ajax/offline/updatingManifest.sjs|0000001236089170|51) to document >0666F12C< (http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/test/unit/tmp/ajax_test.html)
NEXT ERROR *** 31579 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testSynchronousRequest - 2 assertions, 0 failures, 1 errors
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
NEXT ERROR *** 31580 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testAsynchronousRequest - 1 assertions, 0 failures, 1 errors
TypeError: h2 is null(TypeError: h2 is null)
NEXT ERROR *** 31581 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testUpdater - 3 assertions, 1 failures, 0 errors
Failure: assertEqual
expected <'pack my box with <em>five dozen</em> liquor jugs! oh, how <strong>quickly</strong> daft jumping zebras vex...'>, actual: <''> ajax_test.js: Line #55
NEXT ERROR *** 31582 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testUpdaterWithInsertion - 0 assertions, 2 failures, 0 errors
Failure: assertEqual
expected <'pack my box with <em>five dozen</em> liquor jugs! oh, how <strong>quickly</strong> daft jumping zebras vex...'>, actual: <''> ajax_test.js: Line #80
Failure: assertEqual
expected <'five dozen'>, actual: <''> ajax_test.js: Line #85
*** 31583 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testUpdaterOptions
NEXT ERROR *** 31584 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponders - 7 assertions, 3 failures, 0 errors
Failure: assertEqual
expected <0>, actual: <2> ajax_test.js: Line #129
Failure: assertEqual
expected <1>, actual: <3> ajax_test.js: Line #132
Failure: assertEqual
expected <0>, actual: <2> ajax_test.js: Line #136
*** 31585 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testEvalResponseShouldBeCalledBeforeOnComplete
*** 31586 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testContentTypeSetForSimulatedVerbs
NEXT ERROR *** 31587 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testOnCreateCallback - 1 assertions, 0 failures, 1 errors
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
NEXT ERROR *** 31588 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testEvalJS - 0 assertions, 0 failures, 1 errors
Info: You must be running your tests from rake to test this feature.
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
*** 31589 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testCallbacks - 1 assertions, 0 failures, 1 errors
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
*** 31590 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponseText - 0 assertions, 0 failures, 1 errors
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
*** 31591 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponseXML
*** 31592 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponseJSON - 0 assertions, 0 failures, 1 errors
Info: You must be running your tests from rake to test this feature.
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]([Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXMLHttpRequest.send]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: http://localhost:8888/tests/dom/tests/mochitest/ajax/prototype/dist/prototype.js :: anonymous :: line 1291"  data: no])
*** 31593 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testHeaderJSON
*** 31594 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testGetHeader
*** 31595 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testParametersCanBeHash
So an update is being scheduled for updatingIFrame.sjs, and is completed while ajax_test.html is running.  ajax_test.html and updatingIFrame.sjs seem to have the same document object (or at least the same document object pointer).
You mean that a document mapping is not properly removed from nsOfflineCacheUpdateService::mDocUpdates? That actually nsOfflineCacheUpdateService::OnStateChange doesn't get STATE_STOP or we fail to get the document pointer from aWebProgress?
Attached patch v1 (obsolete) — — Splinter Review 
So there are two problems here:  first, we attach to the docloader service to get notification of documents loading, which doesn't always get stop notifications.  Second, we're using a hash of pointers to documents to identify when a given stop item is one we care about.  So what's happening is that we're leaving a pending update sitting around until another update with the same pointer (often ajax_test.html) happens to complete, and then we're scheduling/attaching it.

The attached patch attaches the web progress listener to the document's docshell, which is more reliable than the global service.  And rather than a hash of pending updates, it just attaches a new listener per document (I basically converted the PendingUpdate document to implement nsIWebProgressListener).
Attachment #365351 - Flags: review?(bzbarsky)
(patch also reverts the debug spew used to track down this problem)
Flags: blocking1.9.1?
(In reply to comment #21)
> Created an attachment (id=365351) [details]
> "until another update with the same pointer"

You probably wanted to say "until another DOCUMENT with the same pointer".
What are the two test changes about?
(In reply to comment #23)
> You probably wanted to say "until another DOCUMENT with the same pointer".

Err, yeah.

(In reply to comment #24)
> What are the two test changes about?


The first test was relying on applicationCache.status being UNCACHED to detect
that it was not associated with a cache, which was breaking because this change
causes updates to fire slightly earlier.  This is actually the wrong fix though
- we shouldn't be returning a cache status of CHECKING/DOWNLOADING until we're
associated with a cache.  New patch fixes that (and updates the tests to
reflect this).

The second test wasn't expecting a second noupdate event (which it previously
wasn't getting because the update was never scheduled), so was rerunning step 3
of its tests, unsuccessfully.  This just disconnects from the noupdate event
after step 3 starts the first time.
Attached patch v2 (obsolete) — — Splinter Review 

        Attachment #365351 -
        Attachment is obsolete: true

        Attachment #365444 -
        Flags: review?(bzbarsky)

        Attachment #365351 -
        Flags: review?(bzbarsky)

        Attachment #365444 -
        Flags: review?(bzbarsky) → review+

    
    

    
  
Comment on attachment 365444 [details] [diff] [review]
v2

>+class nsOfflineCachePendingUpdate : public nsIWebProgressListener
>+    nsCOMPtr<nsIDOMDocument> mDocument;

Would it be reasonable to make that an nsWeakPtr, so that in the unlikely case this class leaks we don't leak the document?

>@@ -2313,21 +2398,29 @@ nsOfflineCacheUpdateService::ScheduleOnD
>+    nsCOMPtr<nsIDocument> doc = do_QueryInterface(aDocument);
>+    nsCOMPtr<nsISupports> container = doc->GetContainer();
>+    nsCOMPtr<nsIWebProgress> progress = do_QueryInterface(container);
>+    nsresult rv = progress->AddProgressListener

Are you guaranteed that this document lives inside a docshell?

r=bzbarsky if so.  Either way on the mDocument strong ref.

    
    

    
  
(In reply to comment #31)
> >@@ -2313,21 +2398,29 @@ nsOfflineCacheUpdateService::ScheduleOnD
> >+    nsCOMPtr<nsIDocument> doc = do_QueryInterface(aDocument);
> >+    nsCOMPtr<nsISupports> container = doc->GetContainer();
> >+    nsCOMPtr<nsIWebProgress> progress = do_QueryInterface(container);
> >+    nsresult rv = progress->AddProgressListener
> 
> Are you guaranteed that this document lives inside a docshell?

I don't think we are, but we probably should be.  I don't think it makes sense to be dealing with the cache selection/update process for documents that aren't loaded in docshells.

I'll attach a new patch that errors out of ScheduleOnDocumentStop() if the container doesn't support nsIWebProgress, and bails out of nsContentSink if the document in question doesn't belong to a docshell.

> r=bzbarsky if so.  Either way on the mDocument strong ref.

    
    

    
  

      
      
      
      

        Attached patch
          
          
        v3 interdiff (obsolete)
        — 
          — Splinter Review
      

    


  

    
    

    
  


  
guarantee a docshell, use a weakref for the doc.  interdiff attached.

        Attachment #365444 -
        Attachment is obsolete: true

        Attachment #365500 -
        Flags: superreview?(bzbarsky)

        Attachment #365500 -
        Flags: review?(bzbarsky)

        Attachment #365500 -
        Flags: superreview?(bzbarsky)

        Attachment #365500 -
        Flags: superreview+

        Attachment #365500 -
        Flags: review?(bzbarsky)

        Attachment #365500 -
        Flags: review+

    
    

    
  
http://hg.mozilla.org/mozilla-central/rev/91cc17772818
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → FIXED

    
    

    
  
Let's get this on 191 when we re-open for b4. Thanks, Dave!
Flags: blocking1.9.1? → blocking1.9.1+
Priority: -- → P2

    
  

        Attachment #365500 -
        Attachment description: v3 → v3
[Checkin: Comment 35 & 37]

    
  

        Attachment #364042 -
        Attachment description: more spew → more spew
[Backout: Comment 13]

    
  

        Attachment #363842 -
        Attachment description: temporary spew → temporary spew
[Backout: Comment 13]

    
  

        Attachment #364042 -
        Attachment is obsolete: true

    
  

        Attachment #363842 -
        Attachment is obsolete: true

    
  

        Attachment #365498 -
        Attachment is obsolete: true

    
  
Flags: wanted1.9.1? → in-testsuite+
Whiteboard: [fixed1.9.1b3]
Target Milestone: --- → mozilla1.9.2a1
Version: 1.9.1 Branch → Trunk
Whiteboard: [fixed1.9.1b3] → [orange]

    
  
Blocks: 452706

    
    

    
  
(In reply to comment #18)
> NEXT ERROR *** 31584 ERROR TEST-UNEXPECTED-FAIL |
> /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testResponders
> - 7 assertions, 3 failures, 0 errors

BTW, this "testResponders" failure is apparently still broken -- I've filed Bug 502646 on it.

    
  
Blocks: 502646

    
    

    
      
  

    
    

    
      
  
Whiteboard: [orange]
Depends on: CVE-2013-5597
Component: DOM → DOM: Core & HTML

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: