Closed Bug 450450 Opened 16 years ago Closed 14 years ago

mochitest-plain: test_loadflags.html intermittently fails, missing 1 header/cookie

Categories

(Core :: Networking: Cookies, defect)

Product:
Core
Component:
Networking: Cookies
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla1.9.2b1

People

(Reporter: sgautherie, Assigned: tnikkel)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but not be fixed yet] )

Attachments

(2 files, 2 obsolete files)

(Av2) Call |window.removeEventListener()| ++ [Checkin: See comment 18 & 19]
8.52 KB, patch
dwitte
: review+
Details | Diff | Splinter Review
(Bv1a) Make it more serial, explicit and documented [Checkin: Comment 27 & 28]
9.57 KB, patch
dwitte
: review+
Details | Diff | Splinter Review 
(I had noticed this previously...)

<http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1218631417.1218635037.28019.gz&fulltext=1>
{{
Win2k3 comm-central dep unit test on 2008/08/13 05:43:37

*** 29167 INFO Running /tests/extensions/cookie/test/test_loadflags.html...
*** 29168 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | cookie wasn't inited
search "file" not found - skipping.
*** 29169 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | cookie wasn't sent
*** 29170 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | cookie wasn't sent
Document http://example.org/tests/extensions/cookie/test/file_loadflags_inner.html loaded successfully
*** 29171 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | wrong event type
*** 29172 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of cookies
*** 29173 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of request headers
}}

<http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1218636691.1218640318.11441.gz>
{{
Win2k3 comm-central dep unit test on 2008/08/13 07:11:31

*** 29167 INFO Running /tests/extensions/cookie/test/test_loadflags.html...
*** 29168 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | cookie wasn't inited
search "file" not found - skipping.
*** 29169 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | cookie wasn't sent
Document http://example.org/tests/extensions/cookie/test/file_loadflags_inner.html loaded successfully
*** 29170 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | wrong event type
*** 29171 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of cookies - got 4, expected 5
*** 29172 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of request headers - got 1, expected 2
}}

Same with
<http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1218640095.1218643700.21145.gz>
"Win2k3 comm-central dep unit test on 2008/08/13 08:08:15"
Again:
<http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1219255689.1219259438.29082.gz>
"Win2k3 comm-central dep unit test on 2008/08/20 11:08:09"
i commented briefly on this in https://bugzilla.mozilla.org/show_bug.cgi?id=421494#c37 - feel free to disable the test if it continues to fail.
(In reply to comment #2)
> i commented briefly on this in

Bug 421494 comment 36:
{{
Robert Strong [:rs] (do not email)   2008-08-17 13:36:47 PDT

test_loadflags.html had a test failure on "WINNT 5.2 mozilla-central
qm-win2k3-unittest-hw dep unit test"

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

Can this test be made more robust?
}}

Could you add a (= one) comment here if it happens again on Firefox ?

> https://bugzilla.mozilla.org/show_bug.cgi?id=421494#c37 - feel free to disable

CC: Robert, if he has a preference.

> the test if it continues to fail.

It really does:

<http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1219332694.1219336456.21647.gz>
"Win2k3 comm-central dep unit test on 2008/08/21 08:31:34"
Blocks: 421494
Summary: <test_loadflags.html> intermittently fails, on "Win2k3 comm-central dep unit test" → <test_loadflags.html> intermittently fails, on SeaMonkey "Win2k3 comm-central dep unit test"
I'd prefer if the reason the test is failing was debugged and fixed...
(In reply to comment #3)
> Could you add a (= one) comment here if it happens again on Firefox ?

<http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1219356345.1219360758.26214.gz>
"WINNT 5.2 mozilla-central qm-win2k3-unittest-hw dep unit test on 2008/08/21 15:05:45"

Not SeaMonkey specific, then.

(NB: That was still before the (current) TraceMonkey landing.)
Flags: wanted1.9.1?
Summary: <test_loadflags.html> intermittently fails, on SeaMonkey "Win2k3 comm-central dep unit test" → <test_loadflags.html> intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central"
(In reply to comment #4)
> I'd prefer if the reason the test is failing was debugged and fixed...

of course; i don't have time to do so at the moment unfortunately, so barring someone else from stepping up (give it a week or so?), we should just disable it. i can look into it after i'm done graduating.
(SeaMonkey) Linux can have it too:

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1219583153.1219587427.4898.gz
Linux comm-central dep unit test on 2008/08/24 06:05:53
[
*** 31838 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of cookies - got 4, expected 5
*** 31839 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | incorrect number of request headers - got 1, expected 2
]
OS: Windows Server 2003 → All
Summary: <test_loadflags.html> intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central" → <test_loadflags.html> intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central" (and SM Linux too)
Given the number of regressions from bug 421494, we desperately need these tests enabled. Serge: have you looked at this test? Is there anything obviously broken about it?
Flags: wanted1.9.1? → wanted1.9.1+
"My" part from bug 454857 comment 4.

Iiuc, this won't help this test, but it should "help" the ones which follow it.
Attachment #345630 - Flags: review?(mconnor)
Attachment #345630 - Flags: review?(mconnor)
Depends on: 454857
Blocks: 454717
[Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.1b2pre) Gecko/20081031 Minefield/3.1b2pre] (home, optim default) (W2Ksp4)

*removeEventListener() should "help" following tests;
 and the first test/listener "could" have been disturbing the second one...
*(unrelated) Some code/text rewrites.
*Reenable the second test.
 (So we can learn what the new/current behavior is.)
Assignee: nobody → sgautherie.bz
Attachment #345630 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #345655 - Flags: review?(mconnor)
Severity: minor → normal
Flags: in-testsuite+
Hardware: PC → All
Target Milestone: --- → mozilla1.9.1b2
thanks serge!
Was this checked in? Is this fixed? It's true that we should never leave event listeners on windows as they will (try to) fire on all following tests as well, which is obviously a bad idea.
(In reply to comment #13)

Not checked in: waiting for review(er).!.
Not actually fixed: only can't happen, as the test is currently disabled :->
Whiteboard: [orange]
Attachment #345655 - Flags: review?(mconnor) → review?(dwitte)
(In reply to comment #11)
> *removeEventListener() should "help" following tests;
>  and the first test/listener "could" have been disturbing the second one...

Per bug 454717, this should not be needed ... but this patch is 7.5 months old and it can't hurt, at least.

The one (and only) thing which may actually make a difference is the (2) added |return;|!
dwitte, ping for review ?
Comment on attachment 345655 [details] [diff] [review]
(Av2) Call |window.removeEventListener()| ++
[Checkin: See comment 18 & 19]

Thanks for the patch - I'm not sure if it'll help, but it's worth a try, and if you're willing to watch out for intermittent orange after landing then go for it.

I'd note that if the problem is indeed event listeners from previous tests (including these) that weren't removed, perhaps we shouldn't fail on receiving the wrong event type. We could use a unique message string for each test, and just continue listening if we get something different.
Attachment #345655 - Flags: review?(dwitte) → review+
Comment on attachment 345655 [details] [diff] [review]
(Av2) Call |window.removeEventListener()| ++
[Checkin: See comment 18 & 19]


http://hg.mozilla.org/mozilla-central/rev/a460bfd4f1df
(Av2a) Call |window.removeEventListener()| ++

Av2, with sorting the file names in Makefile.in

(Sorry, forgot to update the checkin summary.)
Attachment #345655 - Attachment description: (Av2) Call |window.removeEventListener()| ++ → (Av2) Call |window.removeEventListener()| ++ [Checkin: See comment 18]
Whiteboard: [orange] → [test disabled on m-1.9.1] [orange]
Comment on attachment 345655 [details] [diff] [review]
(Av2) Call |window.removeEventListener()| ++
[Checkin: See comment 18 & 19]


http://hg.mozilla.org/releases/mozilla-1.9.1/rev/7e630f5d110a
Attachment #345655 - Attachment description: (Av2) Call |window.removeEventListener()| ++ [Checkin: See comment 18] → (Av2) Call |window.removeEventListener()| ++ [Checkin: See comment 18 & 19]
Not reported to fail after comment 18 check-in, so assuming it's fixed,
thought we don't know whether the issue was in Core or in the test.
Status: ASSIGNED → RESOLVED
Closed: 15 years ago
status1.9.1: --- → .2-fixed
Resolution: --- → FIXED
Whiteboard: [test disabled on m-1.9.1] [orange] → [orange]
Summary: <test_loadflags.html> intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central" (and SM Linux too) → mochitest-plain: test_loadflags.html intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central" (and SM Linux too)
What is the best/simplest way for QA to verify this bug?
(In reply to comment #21)
> What is the best/simplest way for QA to verify this bug?

The only thing which can be "easily" checked (somewhat) is that the test does not randomly fail anymore:
to achieve this, one has to check logs/reports from all (orange/red) tests run since the comment 19.
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1249120707.1249127328.25821.gz&fulltext=1
WINNT 5.2 comm-1.9.1 unit test on 2009/08/01 02:58:27
{
... | number of cookies - got 4, expected 5
... | number of request headers - got 1, expected 2
}

Bug still there, unchanged, on 1.9.1.
status1.9.1: .2-fixed → ---
Whiteboard: [orange] → [fixed1.9.1.2: Av2, but not fixed] [orange]
From the log, it looks like the header (and its cookie) to load image1.png is missed somehow.

Source code is
{
file_loadflags_inner.html

<img src="http://example.org/tests/extensions/cookie/test/image1.png" onload="runTest()" />
}
Note that onload= is actually run yet.

***

Fwiw, I found on the web:
{
http://www.htmlcodetutorial.com/images/_IMG_onLoad.html

Unfortunately, onLoad is not a very reliable event handler. Netscape particularly has trouble firing onLoad when the image is malformed in some way or if the image is loaded from cache instead of freshly downloaded from the net.
}
but I would guess this is not relevant (here).
Summary: mochitest-plain: test_loadflags.html intermittently fails, on Firefox "mozilla-central qm-win2k3-unittest-hw" and SeaMonkey "Win2k3 comm-central" (and SM Linux too) → mochitest-plain: test_loadflags.html intermittently fails, missing 1 header/cookie
Whiteboard: [fixed1.9.1.2: Av2, but not fixed] [orange] → [See comment 24] [fixed1.9.1.2: Av2, but not fixed] [orange]
New expected success log is
{
ok - number of cookies for domain example.org
ok - cookie 'oh=hai' is in header for http://example.org/tests/extensions/cookie/test/file_loadflags_inner.html
ok - cookie 'oh=hai' is in header for http://example.org/tests/extensions/cookie/test/image1.png
ok - message data received from popup
ok - number of observed request headers
ok - total number of cookies
}

*****

(In reply to comment #17)
> perhaps we shouldn't fail on receiving the wrong event type.

The type is "message / MessageEvent": it would be very odd to receive another type than the one asked for.
I removed the (useless) check for this.

> We could use a unique message string for each test,

I changed the data string, fwiw.

> and just continue listening if we get something different.

I disagree: something would be very wrong and we should abort this test asap.

*****

As with patch Av2, I'm not sure this will fix the issue (which I never reproduced), but it should at least help reading the code and the logs.
Attachment #392093 - Flags: review?(dwitte)
Bv1, without an unwanted line.
Attachment #392093 - Attachment is obsolete: true
Attachment #392095 - Flags: review?(dwitte)
Attachment #392093 - Flags: review?(dwitte)
Attachment #392095 - Flags: review?(dwitte) → review+
Comment on attachment 392095 [details] [diff] [review]
(Bv1a) Make it more serial, explicit and documented
[Checkin: Comment 27 & 28]


http://hg.mozilla.org/mozilla-central/rev/9281246909f0
Attachment #392095 - Attachment description: (Bv1a) Make it more serial, explicit and documented → (Bv1a) Make it more serial, explicit and documented [Checkin: Comment 27]
Target Milestone: mozilla1.9.1b2 → mozilla1.9.2b1
Comment on attachment 392095 [details] [diff] [review]
(Bv1a) Make it more serial, explicit and documented
[Checkin: Comment 27 & 28]


http://hg.mozilla.org/releases/mozilla-1.9.1/rev/1cb9bec9a965
Attachment #392095 - Attachment description: (Bv1a) Make it more serial, explicit and documented [Checkin: Comment 27] → (Bv1a) Make it more serial, explicit and documented [Checkin: Comment 27 & 28]
No longer blocks: 454717
status1.9.1: --- → .3-fixed
Whiteboard: [See comment 24] [fixed1.9.1.2: Av2, but not fixed] [orange] → [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but may not be fixed yet] [orange]
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250142781.1250149793.20557.gz
WINNT 5.2 comm-1.9.1 unit test on 2009/08/12 22:53:01
{
... | number of observed request headers - got 1, expected 2
... | total number of cookies - got 4, expected 5
}

Confirming (comment 24 and comment 25):
{
... | cookie 'oh=hai' is in header for
http://example.org/tests/extensions/cookie/test/image1.png
}
is missing :-/
Status: RESOLVED → REOPENED
status1.9.1: .3-fixed → ---
Keywords: helpwanted
Resolution: FIXED → ---
Whiteboard: [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but may not be fixed yet] [orange] → [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but not be fixed yet] [orange]
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey2.0/1250137300.1250145549.7075.gz
OS X 10.5 comm-1.9.1 unit test on 2009/08/12 21:21:40
Status: REOPENED → NEW
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1250504961.1250507733.7809.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/08/17 03:29:21
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5-Unittest/1250530280.1250533017.15931.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2009/08/17 10:31:20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1253186727.1253195358.5813.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/09/17 04:25:27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1253688214.1253698514.4258.gz
WINNT 5.2 mozilla-central unit test on 2009/09/22 23:43:34
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257977127.1257981052.23192.gz
Linux mozilla-central debug test mochitests-3/5 on 2009/11/11 14:05:27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1264182020.1264184763.618.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2010/01/22 09:40:20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1264231965.1264233555.30805.gz
Linux mozilla-central debug test mochitests-3/5 on 2010/01/22 23:32:45
s: moz2-linux-slave06
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265163740.1265165687.28422.gz
WINNT 5.2 mozilla-central debug test mochitests-3/5 on 2010/02/02 18:22:20
s: win32-slave36
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1265643897.1265646031.7169.gz
Linux mozilla-central debug test mochitests-3/5 on 2010/02/08 07:44:57
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267370918.1267373370.23892.gz
WINNT 5.2 mozilla-central debug test mochitests-3/5 on 2010/02/28 07:28:38
s: win32-slave22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267345249.1267347412.1264.gz
WINNT 5.2 mozilla-central debug test mochitests-3/5 on 2010/02/28 00:20:49
s: win32-slave22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1267407732.1267409177.30181.gz
Linux mozilla-central debug test mochitests-3/5 on 2010/02/28 17:42:12
s: moz2-linux-slave16
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1270071391.1270074133.8935.gz
OS X 10.5.2 mozilla-1.9.1 test mochitests on 2010/03/31 14:36:31
Assignee: sgautherie.bz → nobody
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1274775241.1274776557.4782.gz
WINNT 5.2 mozilla-central debug test mochitests-4/5 on 2010/05/25 01:14:01

s: win32-slave35
17 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | number of observed request headers - got 1, expected 2
18 ERROR TEST-UNEXPECTED-FAIL | /tests/extensions/cookie/test/test_loadflags.html | total number of cookies - got 4, expected 5
Landed some debugging output to try to figure out what is going on here
http://hg.mozilla.org/mozilla-central/rev/ccf3b452d0f4
To try to find out when the load event for the page file_loadflags_inner.html happens (in relation to the load of the image) I made the test wait for the load event of the page as well and log it. So there is a chance the above changeset might fix (or reduce) the random orange here.
The onload for the image is fired, but we don't get the http-on-modify-request observer notification. I wonder if this could be because we don't open an http channel for the image because it is cached already from the other tests that use the same image? Is that the expected behaviour if the image is cached?
I landed some more debug stuff to see if the cookie for the image was already set and we delete it when we remove all cookies at the start of the test and to see if maybe we get a really late http request for the image by delaying the test end by 5 seconds.
http://hg.mozilla.org/mozilla-central/rev/fbea64d46081
Hmm. For both image1.png and image2.png we specify a 'Cache-Control: no-cache' header. So caching shouldn't be happening. biesi, is that correct?

Perhaps the load is occurring before we register the observer?

To test the caching theory, you could use different images for each test. Just copy the image (and the corresponding ^headers^ file) and rename it.
You should really use Cache-Control: no-store if you never want to reuse the image. That said... for this case this shouldn't make a difference. Get a log with nsHttp:5 and imgRequest:5?
11520 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | setupTest uri: http://example.org/tests/extensions/cookie/test/file_loadflags_inner.html domain: example.org cookies: 5 loads: 2 headers: 2
11521 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | we are going to remove these cookies
11522 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | 0 cookies
11523 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | number of cookies for domain example.org - 1 should equal 1
11524 INFO TEST-PASS | /tests/extensions/cookie/test/test_loadflags.html | adding observer

Looks like there aren't any cookies removed at the beginning of the test. Timothy, you agree?

I'll switch the Cache-Control to no-store...
Yeah, I agree. Thanks for taking this up.
Switched to no-store: http://hg.mozilla.org/mozilla-central/rev/d261faaa483a

Added new images to guarantee cache circumvention: http://hg.mozilla.org/mozilla-central/rev/70175407282a

Hopefully those (or rather, the latter) should fix this.
I *think* this is fixed on trunk. Assigning to :tn, since he did most of the legwork here.

tn, feel free to backport this to 3.6 if you want. ;)
Assignee: nobody → tnikkel
Status: NEW → RESOLVED
Closed: 15 years ago → 14 years ago
Keywords: helpwanted
Resolution: --- → FIXED
Whiteboard: [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but not be fixed yet] [orange] → [See comment 24] [fixed1.9.1.2: Av2; fixed1.9.1.3: Bv1a; but not be fixed yet]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: