1407501 - Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/xpcshell/test_ext_contentscript_scriptCreated.js | Test timed out

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=135988182&repo=autoland

https://queue.taskcluster.net/v1/task/B7eRrttwR_-qQouf3OdzFQ/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

2 failures in 947 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1
* autoland: 1

Platform breakdown:
* windows7-32: 1
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 2

[Intermittent Failures Robot]

17 failures in 864 pushes (0.02 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 5
* autoland: 5
* mozilla-inbound: 4
* try: 3

Platform breakdown:
* windows7-32: 8
* windows10-64: 3
* linux64-qr: 3
* linux64: 2
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

:andym, this hasn't hit the filters of the orangefactor robot, but I saw this in looking at trends and we have 46 failures on this bug in the last week all on debug (heavily weighted for windows):
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&endday=2017-10-26&startday=2017-10-01&tree=trunk

you can see the trend above that this started on October 18th and has been failing a lot since then.

Comment 4

[Bob Silverberg [:bsilverberg]]

I'll add this to my list of intermittents to investigate.

Comment 5

[Intermittent Failures Robot]

46 failures in 196 pushes (0.235 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 31
* mozilla-inbound: 7
* mozilla-central: 7
* try: 1

Platform breakdown:
* windows7-32: 24
* osx-10-10: 14
* windows10-64: 4
* linux64: 2
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-26&endday=2017-10-26&tree=all

Comment 7

[Kris Maglione [:kmag]]

Stealing this. There are some suspicious assertion failures in those logs.

Comment 8

[Intermittent Failures Robot]

42 failures in 151 pushes (0.278 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 20
* mozilla-inbound: 10
* try: 7
* mozilla-central: 5

Platform breakdown:
* windows7-32: 24
* windows10-64: 6
* osx-10-10: 6
* linux64: 4
* linux64-qr: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-27&endday=2017-10-27&tree=all

Comment 9

[Intermittent Failures Robot]

25 failures in 55 pushes (0.455 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 12
* autoland: 7
* mozilla-central: 5
* try: 1

Platform breakdown:
* windows7-32: 16
* osx-10-10: 7
* windows10-64: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-28&endday=2017-10-28&tree=all

Comment 10

[Intermittent Failures Robot]

174 failures in 912 pushes (0.191 failures/push) were associated with this bug in the last 7 days. 

This is the #2 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 88
* mozilla-inbound: 48
* mozilla-central: 29
* try: 9

Platform breakdown:
* windows7-32: 106
* osx-10-10: 36
* windows10-64: 19
* linux64: 7
* linux32: 3
* linux64-qr: 2
* linux64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 11

[Intermittent Failures Robot]

49 failures in 171 pushes (0.287 failures/push) were associated with this bug yesterday.    

** This test has failed more than 200 times in the last 30 days. It should be disabled until it can be fixed. ** 

Repository breakdown:
* mozilla-inbound: 22
* autoland: 20
* mozilla-central: 4
* try: 3

Platform breakdown:
* windows7-32: 25
* windows10-64: 12
* osx-10-10: 12

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-30&endday=2017-10-30&tree=all

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a108409e726a
Disable toolkit/components/extensions/test/xpcshell/test_ext_contentscript_scriptCreated.js on debug for frequent failures. r=me, a=testonly

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

I disabled this test for having >200 failures in the last 30 days, please remember to enable this when testing a fix

Comment 14

[Bob Silverberg [:bsilverberg]]

This has been disabled on all platforms, so should be treated as a high priority to fix and re-enable. It's currently assigned to Kris.

Comment 15

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/a108409e726a

Comment 16

[Intermittent Failures Robot]

27 failures in 169 pushes (0.16 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 11
* try: 6
* mozilla-inbound: 5
* mozilla-central: 5

Platform breakdown:
* windows7-32: 16
* osx-10-10: 8
* windows10-64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-31&endday=2017-10-31&tree=all

Comment 17

[Intermittent Failures Robot]

101 failures in 857 pushes (0.118 failures/push) were associated with this bug in the last 7 days. 

This is the #17 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 41
* mozilla-inbound: 33
* try: 17
* mozilla-central: 9
* mozilla-beta: 1

Platform breakdown:
* windows7-32: 57
* osx-10-10: 24
* windows10-64: 20

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 18

[Intermittent Failures Robot]

1 failures in 702 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1

Platform breakdown:
* linux64-jsdcov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407501&startday=2018-02-05&endday=2018-02-11&tree=all

Comment 19

[Rob Wu [:robwu]]

The timeout was caused by a crashing content process; stack trace pasted below (log from first comment).

The assertion is triggered here:
https://searchfox.org/mozilla-central/rev/f2ac80ab7dbde5400a3400d463e07331194dec94/layout/base/nsDocumentViewer.cpp#1126-1134

Given the unsatisfied conditions, it seems that the document's readyState is at READYSTATE_LOADING
(or somehow the URL is not about:blank, e.g. empty?)


This same assertion is always triggered when I run the test case from bug 1465388 in a debug build of Firefox.

I think that the failure is related to the use of blockParsing, and when content scripts are involved, document.blockParsing is only called when the script is not preloaded yet. So if the test case's child frame is loaded before the content script is loaded, then this assertion would be triggered. This is a racy condition, hence the test failure does not occur 100% of the time.



17:57:08     INFO -  PID 10936 | [Child 13020, Main Thread] ###!!! ASSERTION: Bad readystate: 'mDocument->IsXULDocument() || mDocument->GetReadyStateEnum() == nsIDocument::READYSTATE_INTERACTIVE || (mDocument->GetReadyStateEnum() == nsIDocument::READYSTATE_UNINITIALIZED && NS_IsAboutBlank(mDocument->GetDocumentURI()))', file z:/build/build/src/layout/base/nsDocumentViewer.cpp, line 1030
17:57:21     INFO -  PID 10936 | #01: nsDocShell::EndPageLoad(nsIWebProgress *,nsIChannel *,nsresult) [docshell/base/nsDocShell.cpp:7761]
17:57:21     INFO -  PID 10936 | #02: nsDocShell::OnStateChange(nsIWebProgress *,nsIRequest *,unsigned int,nsresult) [docshell/base/nsDocShell.cpp:7559]
17:57:21     INFO -  PID 10936 | #03: nsDocLoader::DoFireOnStateChange(nsIWebProgress * const,nsIRequest * const,int &,nsresult) [uriloader/base/nsDocLoader.cpp:1320]
17:57:21     INFO -  PID 10936 | #04: nsDocLoader::doStopDocumentLoad(nsIRequest *,nsresult) [uriloader/base/nsDocLoader.cpp:861]
17:57:21     INFO -  PID 10936 | #05: nsDocLoader::DocLoaderIsEmpty(bool) [uriloader/base/nsDocLoader.cpp:752]
17:57:21     INFO -  PID 10936 | #06: nsDocLoader::OnStopRequest(nsIRequest *,nsISupports *,nsresult) [uriloader/base/nsDocLoader.cpp:633]
17:57:21     INFO -  PID 10936 | #07: mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest *,nsISupports *,nsresult) [netwerk/base/nsLoadGroup.cpp:629]
17:57:21     INFO -  PID 10936 | #08: nsBaseChannel::OnStopRequest(nsIRequest *,nsISupports *,nsresult) [netwerk/base/nsBaseChannel.cpp:888]
17:57:21     INFO -  PID 10936 | #09: nsInputStreamPump::OnStateStop() [netwerk/base/nsInputStreamPump.cpp:705]
17:57:21     INFO -  PID 10936 | #10: nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream *) [netwerk/base/nsInputStreamPump.cpp:428]
17:57:21     INFO -  PID 10936 | #11: nsInputStreamReadyEvent::Run() [xpcom/io/nsStreamUtils.cpp:99]
17:57:21     INFO -  PID 10936 | #12: mozilla::SchedulerGroup::Runnable::Run() [xpcom/threads/SchedulerGroup.cpp:396]
17:57:21     INFO -  PID 10936 | #13: nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:1038]
17:57:21     INFO -  PID 10936 | #14: NS_ProcessNextEvent(nsIThread *,bool) [xpcom/threads/nsThreadUtils.cpp:524]
17:57:21     INFO -  PID 10936 | #15: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:97]
17:57:21     INFO -  PID 10936 | #16: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:301]
17:57:21     INFO -  PID 10936 | #17: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:320]
17:57:21     INFO -  PID 10936 | #18: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:300]
17:57:21     INFO -  PID 10936 | #19: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:160]
17:57:21     INFO -  PID 10936 | #20: nsAppShell::Run() [widget/windows/nsAppShell.cpp:232]
17:57:21     INFO -  PID 10936 | #21: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:877]
17:57:21     INFO -  PID 10936 | #22: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:269]
17:57:21     INFO -  PID 10936 | #23: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:320]
17:57:21     INFO -  PID 10936 | #24: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:300]
17:57:21     INFO -  PID 10936 | #25: XRE_InitChildProcess(int,char * * const,XREChildData const *) [toolkit/xre/nsEmbedFunctions.cpp:707]
17:57:21     INFO -  PID 10936 | #26: content_process_main(mozilla::Bootstrap *,int,char * * const) [ipc/contentproc/plugin-container.cpp:64]
17:57:21     INFO -  PID 10936 | #27: NS_internal_main(int,char * *) [ipc/app/MozillaRuntimeMain.cpp:25]
17:57:21     INFO -  PID 10936 | #28: wmain [toolkit/xre/nsWindowsWMain.cpp:114]
17:57:21     INFO -  PID 10936 | #29: __scrt_common_main_seh [f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:253]
17:57:21     INFO -  PID 10936 | #30: KERNEL32.DLL + 0x12774
17:57:21     INFO -  PID 10936 | #31: ntdll.dll + 0x70d61

Comment 20

[Rob Wu [:robwu]]

Locally I managed to reproduce the crash with a different test (see previous comment) and fixed that crash in bug 1465388.
I'll close this bug since I'm not seeing any new intermittents at https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-07-31&endday=2018-09-03&tree=all&bug=1407501