Closed Bug 1391823 Opened 7 years ago Closed 2 years ago

Intermittent dom/security/test/mixedcontentblocker/test_frameNavigation.html | called finish() multiple times

Categories

(Core :: DOM: Security, defect, P3)

Product:
Core
Component:
DOM: Security
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
firefox60 --- affected
firefox61 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [domsecurity-backlog1])

Attachments

(3 files, 2 obsolete files)

Bug 1391823 - Fixed finish() called multiple times
45 bytes, text/x-phabricator-request
ckerschb
: review+
Details | Review
Disable_bug1391823.patch
936 bytes, patch
jmaher
: review+
Details | Diff | Splinter Review
Disabled on OSX platform
967 bytes, patch
jmaher
: review-
Details | Diff | Splinter Review
Whiteboard: [domsecurity-intermittent]
37 total failures in the last week

Ocurrences on platforms: 
- 18 on windows10-64
- 8 on linux32-stylo-disable
- 8 on windows7-32-stylo-disabled
- 3 on Windows 7

The most affect build type is debug and there are also 2 failures on opt.

Here is a recent relevant log file: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=145303050&lineNumber=7410
and a snippet from it:
13:20:03     INFO -  Buffered messages logged at 13:20:03
7405
13:20:03     INFO -  344 INFO TEST-PASS | dom/security/test/mixedcontentblocker/test_frameNavigation.html | couldn't open an http link in a new window from a secure page
7406
13:20:03     INFO -  345 INFO TEST-PASS | dom/security/test/mixedcontentblocker/test_frameNavigation.html | navigated to insecure iframe on secure page
7407
13:20:03     INFO -  346 INFO TEST-PASS | dom/security/test/mixedcontentblocker/test_frameNavigation.html | couldn't open an http link in a new window from a secure page
7408
13:20:03     INFO -  347 ERROR [SimpleTest.finish()] this test already called finish!
7409
13:20:03     INFO -  Buffered messages finished
7410
13:20:03    ERROR -  348 INFO TEST-UNEXPECTED-ERROR | dom/security/test/mixedcontentblocker/test_frameNavigation.html | called finish() multiple times
7411
13:20:03     INFO -  TEST-INFO took 6806ms
7412
13:20:03     INFO -  349 INFO TEST-OK | dom/security/test/mixedcontentblocker/test_frameNavigation.html
7413
13:20:03     INFO -  GECKO(5752) | ++DOMWINDOW == 49 (000001728A741800) [pid = 6972] [serial = 91] [outer = 000001728924F800]
7414
13:20:03     INFO -  350 INFO None351 INFO TEST-START | dom/security/test/mixedcontentblocker/test_main.html


:ckerschb, would you please take a look at this?
Flags: needinfo?(ckerschb)
Whiteboard: [domsecurity-intermittent] → [stockwell needswork]
(In reply to Tiberius Oros[:tiberius_oros] from comment #15)
> :ckerschb, would you please take a look at this?

Vino, can you please have a look?
Assignee: nobody → cegvinoth
Flags: needinfo?(ckerschb) → needinfo?(cegvinoth)
Whiteboard: [stockwell needswork] → [stockwell needswork][domsecurity-active]
Not able to reproduce this bug in my local Mac OS build. Is there any other way to replicate this bug ?
Flags: needinfo?(cegvinoth)
(In reply to Vinothkumar Nagasayanan [:vinoth] from comment #18)
> Not able to reproduce this bug in my local Mac OS build. Is there any other
> way to replicate this bug ?

Hey Vino, that is the problem with intermittent failures in our infra. It seems that finish() is called multiple times in some cases. What we could do is add some logging to the test and land that debugging information which then might dump some helpful information to the console. E.g. within checkTestsCompleted().
Flags: needinfo?(cegvinoth)
:vinoth - Any updates? Please let us know if you are able to work on this.
(In reply to Dorel Luca [:dluca] from comment #21)
> :vinoth - Any updates? Please let us know if you are able to work on this.

Since I am not able to reproduce the bug locally, I am working on adding more logs and trying to re-trigger the test in try server.
Flags: needinfo?(cegvinoth)
Update:

Added logs and a additional flag to test_frameNavigation.html
pushed to try server and re triggering the tests in different platforms and checking if the error still persists.

Try server link,
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8d147396c403935cc298abac1d6d8a34583524d6

Code change link,
https://hg.mozilla.org/try/rev/84477ea65804ca7ef7c2a75312def06ab6afd199
Comment on attachment 8940086 [details]
Bug 1391823 - Logs added and multiple calls to finish() fixed

https://reviewboard.mozilla.org/r/210370/#review216626

Hey Vino, I don't understand what we are trying to accomplish with this patch. Isn't 'flag' the same as 'counter'? Ulitmately we don't want to call finish only if counter == 1 but we need to find out why counter > 1 happens multiple times.
Attachment #8940086 - Flags: review?(ckerschb) → review-
There are 28 failures in the last 7 days. Most of the failures happen on Windows10-64 debug (15) & Windows 7 debug (9). The failure rate has increased in the last 2 days.

Most recent failure log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=160290823&lineNumber=7546

::ckerschb Could you please take a look at this? Thank you.
Flags: needinfo?(ckerschb)
(In reply to Cosmin Sabou [:cosmin_s] from comment #35)
> ::ckerschb Could you please take a look at this? Thank you.

Vino is still on it. I'll check if I can give that bug some more momentum.
Flags: needinfo?(ckerschb)
Priority: P5 → P2
Status: NEW → ASSIGNED
Attachment #8940086 - Attachment is obsolete: true
Attachment #8949645 - Flags: review?(ckerschb)
https://dxr.mozilla.org/mozilla-central/source/dom/security/test/mixedcontentblocker/file_frameNavigation_blankTarget.html#22

> var observer = {
>    observe: function(subject, topic, data) {
>      if(topic == "content-document-global-created" && data =="http://example.com") {
>         parent.parent.postMessage({"test": "blankTarget", "msg": "opened an http link with target=_blank from a secure page"}, > "http://mochi.test:8888");
>         SpecialPowers.removeAsyncObserver(observer, "content-document-global-created");
>      }
>    }

Before this "SpecialPowers.removeAsyncObserver" is completed, Asynchronously this observer function is called multiple times. Which causes "parent.parent.postMessage" to be called multiple times.

All the failed cases contain this test being called thrice instead of twice. And instead of 8 test case passes, 9 test cases were passed.
Which can be seen here,
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=160290823&lineNumber=7543

This additional flag will make sure this test is called only twice(for secure and insecure testcase).
>    observe: function(subject, topic, data) {
>      if(topic == "content-document-global-created" && data == "http://example.com") {
>         parent.parent.postMessage({"test": "blankTarget", "msg": "opened an http link with target=_blank from a secure page"}, >"http://mochi.test:8888");
>         SpecialPowers.removeAsyncObserver(observer, "content-document-global-created");
>      }

I am only guessing here, but maybe we should only check for a more specific data. Probably worth printing the 'data' and push to try, maybe the problem is that this test interfers with something else and hence the observer fires. (As I said, only guessing here).
(In reply to Christoph Kerschbaumer [:ckerschb] from comment #41)
> >    observe: function(subject, topic, data) {
> >      if(topic == "content-document-global-created" && data == "http://example.com") {
> >         parent.parent.postMessage({"test": "blankTarget", "msg": "opened an http link with target=_blank from a secure page"}, >"http://mochi.test:8888");
> >         SpecialPowers.removeAsyncObserver(observer, "content-document-global-created");
> >      }
> 
> I am only guessing here, but maybe we should only check for a more specific
> data. Probably worth printing the 'data' and push to try, maybe the problem
> is that this test interfers with something else and hence the observer
> fires. (As I said, only guessing here).

Yes you are right, we need to check for more specific subject(window object) location here. 
After printing the data, Observer is fired for the following cases, 

subject: about:blank, topic: content-document-global-created, data: null
subject: about:blank, topic: content-document-global-created, data: https://example.com
subject: about:blank, topic: content-document-global-created, data: null
subject: about:blank, topic: content-document-global-created, data: https://example.com
subject: http://example.com/tests/dom/security/test/mixedcontentblocker/file_frameNavigation_innermost.html?blankTarget, topic: content-document-global-created, data: http://example.com

So I made changes to check only for specific subject with location "http://example.com/tests/dom/security/test/mixedcontentblocker/file_frameNavigation_innermost.html?blankTarget"

I pushed the changes to the the try server.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7a69a04ecf246e102aab989e3f888c74f22ff252

Latest code change can be found here,
https://phabricator.services.mozilla.com/D562
Flags: needinfo?(ckerschb)
(In reply to Vinothkumar Nagasayanan [:vinoth] from comment #42)
> (In reply to Christoph Kerschbaumer [:ckerschb] from comment #41)
> > >    observe: function(subject, topic, data) {
> > >      if(topic == "content-document-global-created" && data == "http://example.com") {
> > >         parent.parent.postMessage({"test": "blankTarget", "msg": "opened an http link with target=_blank from a secure page"}, >"http://mochi.test:8888");
> > >         SpecialPowers.removeAsyncObserver(observer, "content-document-global-created");
> > >      }
> > 
> > I am only guessing here, but maybe we should only check for a more specific
> > data. Probably worth printing the 'data' and push to try, maybe the problem
> > is that this test interfers with something else and hence the observer
> > fires. (As I said, only guessing here).
> 
> Yes you are right, we need to check for more specific subject(window object)
> location here. 
> After printing the data, Observer is fired for the following cases, 
> 
> subject: about:blank, topic: content-document-global-created, data: null
> subject: about:blank, topic: content-document-global-created, data:
> https://example.com
> subject: about:blank, topic: content-document-global-created, data: null
> subject: about:blank, topic: content-document-global-created, data:
> https://example.com
> subject:
> http://example.com/tests/dom/security/test/mixedcontentblocker/
> file_frameNavigation_innermost.html?blankTarget, topic:
> content-document-global-created, data: http://example.com
> 
> So I made changes to check only for specific subject with location
> "http://example.com/tests/dom/security/test/mixedcontentblocker/
> file_frameNavigation_innermost.html?blankTarget"
> 
> I pushed the changes to the the try server.
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=7a69a04ecf246e102aab989e3f888c74f22ff252
> 
> Latest code change can be found here,
> https://phabricator.services.mozilla.com/D562

Try server test is completed, but it throws test timeout error.
https://treeherder.mozilla.org/logviewer.html#?job_id=162633344&repo=try&lineNumber=1842

I will look into it.
(In reply to Vinothkumar Nagasayanan [:vinoth] from comment #43)
> Try server test is completed, but it throws test timeout error.
> https://treeherder.mozilla.org/logviewer.
> html#?job_id=162633344&repo=try&lineNumber=1842
> 
> I will look into it.

Please re-trigger the test couple times on each platform (Franziskus can help in case you don't know how to do that). It seems it's only failing on Windows, right? If so, I think that is already an improvement. Anyway, maybe we can figure out the actual problem - thanks!
Flags: needinfo?(ckerschb)
Comment on attachment 8949645 [details]
Bug 1391823 - Fixed finish() called multiple times

Clearing the r? for now.
Attachment #8949645 - Flags: review?(ckerschb)
In the last 7 days we have 66 failures.
They occur mostly on 	windows10-64 (debug) and the rest of them on Linux x64 (debug, pgo), linux32-stylo-disabled (debug), linux64-ccov (opt), linux64-stylo-disabled (debug, opt), OS X 10.10 (debug),Windows 7 (debug).

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=164762793&lineNumber=8566
:vinoth, can you please have a look at this?
Flags: needinfo?(cegvinoth)
Whiteboard: [domsecurity-active][stockwell unknown] → [domsecurity-active][stockwell needswork]
Attached patch disable_bug1391823.patch (obsolete) — — Splinter Review 
I've made a patch to disable this test that is failing frequently on Linux, OS X and Windows (because it has more than 5 failures on each platform for the last 7 days).

Please let me know if "skip-if = true" was the best decision here.

Thanks,
Attachment #8955756 - Flags: review?(jmaher)
Comment on attachment 8955756 [details] [diff] [review]
disable_bug1391823.patch

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

I would be more specific here to skip on linux/debug and windows/debug- this leaves it running on osx and linux/win opt.

Also, you removed the previous comments from the skip-if line, please append your bug number to the existing comment.
Attachment #8955756 - Flags: review?(jmaher) → review-
Thank you for your input, it really helps. Here's the new updated patch.
Attachment #8955756 - Attachment is obsolete: true
Attachment #8955765 - Flags: review?(jmaher)
Comment on attachment 8955765 [details] [diff] [review]
Disable_bug1391823.patch

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

thanks!
Attachment #8955765 - Flags: review?(jmaher) → review+
Pushed by cbrindusan@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/59bfbf50c86d
Disable dom/security/test/mixedcontentblocker/test_frameNavigation.html for frequent failures. r=jmaher
let see how this does, possibly the osx failures will require a disabling
Whiteboard: [domsecurity-active][stockwell disable-recommended] → [domsecurity-active][stockwell disabled]
we should disable this on osx as well the failure rate is really high the last few days.
Whiteboard: [domsecurity-active][stockwell disabled] → [domsecurity-active][stockwell disabled-recommended]
Comment on attachment 8957613 [details] [diff] [review]
Disabled on OSX platform

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

now we skip on all debug platforms, lets make it easier to read

::: dom/security/test/mixedcontentblocker/mochitest.ini
@@ +24,4 @@
>  [test_bug803225.html]
>  skip-if = toolkit == 'android' || (os=='linux' && bits==32) || headless #Android: TIMED_OUT; Linux32:bug 1324870; Headless:bug 1405870
>  [test_frameNavigation.html]
> +skip-if = (toolkit == 'android') || webrender || (debug && (os == 'linux' || os == 'win' || os == 'mac')) # Android: TIMED_OUT; webrender: bug 1424752 # Bug 1391823

in this case we can just simplify this to:
kip-if = (toolkit == 'android') || webrender || debug # Android: TIMED_OUT; webrender: bug 1424752, debug: Bug 1391823
Attachment #8957613 - Flags: review?(jmaher) → review-
Flags: needinfo?(cegvinoth)
Attachment #8949645 - Flags: review?(ckerschb)
Changes have been pushed to try server and the test runs without the "called finish() multiple times" error.
Results can be found here,
https://treeherder.mozilla.org/#/jobs?repo=try&revision=062a7173cb6a95473dd01bcb595fc9e9bd25bb4b
Comment on attachment 8949645 [details]
Bug 1391823 - Fixed finish() called multiple times

Christoph Kerschbaumer [:ckerschb] has approved the revision.

https://phabricator.services.mozilla.com/D562
Attachment #8949645 - Flags: review+
Attachment #8949645 - Flags: review?(ckerschb)
Pushed by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/mozilla-inbound/rev/70a6977ab6c0
Don't run |finish() called multiple times| for dom/security/test/mixedcontentblocker/test_frameNavigation.html. r=ckerschb
Keywords: checkin-needed
What's the status of this bug? It would appear we landed a hopeful fix on m-c but never re-enabled the test on the platforms where it had been disabled?
status-firefox60: --- → affected
status-firefox61: --- → affected
Flags: needinfo?(cegvinoth)
Keywords: leave-open
:gbrown could you please take a look at Ryan's comment(Comment 73)?
Flags: needinfo?(gbrown)
I will take a look and get back on this.
Flags: needinfo?(cegvinoth)
Flags: needinfo?(gbrown)
According to orangefactor this bug hasn't had any occurrences in the last 30 days, removing disable-recommended. 

:vinoth do you have any updates regarding Ryan's question in comment 73?
Flags: needinfo?(cegvinoth)
Whiteboard: [domsecurity-active][stockwell disabled-recommended] → [domsecurity-active]
Assignee: cegvinoth → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(cegvinoth)
Priority: P2 → P3
Whiteboard: [domsecurity-active] → [domsecurity-backlog1]

Haven't seen any reports of this in a long long time.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: