Closed Bug 1445837 Opened 4 years ago Closed 4 years ago

Intermittent toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have recovery content. - "" == "Failed to load article from page" -

Categories

(Toolkit :: Printing, defect, P5)

Product:
Toolkit
Component:
Printing
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox60 --- fixed
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mlongaray)

References

Details

Attachments

(1 file)

Bug 1445837 - Fix race condition in toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js.
59 bytes, text/x-review-board-request
mconley
: review+
Details 
Filed by: toros [at] mozilla.com

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

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

[task 2018-03-14T20:36:41.719Z] 20:36:41     INFO - TEST-START | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js
[task 2018-03-14T20:36:41.761Z] 20:36:41     INFO - GECKO(1045) | Waiting for browser load
[task 2018-03-14T20:36:41.800Z] 20:36:41     INFO - GECKO(1045) | Saw state f0001 and status 0
[task 2018-03-14T20:36:41.858Z] 20:36:41     INFO - GECKO(1045) | Saw state c0010 and status 0
[task 2018-03-14T20:36:41.859Z] 20:36:41     INFO - GECKO(1045) | Browser loaded http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html
[task 2018-03-14T20:36:42.097Z] 20:36:42     INFO - GECKO(1045) | JavaScript error: resource:///modules/ContentMetaHandler.jsm, line 155: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]
[task 2018-03-14T20:36:42.692Z] 20:36:42     INFO - GECKO(1045) | JavaScript error: chrome://global/content/browser-content.js, line 665: TypeError: content.document.head is null
[task 2018-03-14T20:36:42.757Z] 20:36:42     INFO - TEST-INFO | started process screentopng
[task 2018-03-14T20:36:43.744Z] 20:36:43     INFO - TEST-INFO | screentopng: exit 0
[task 2018-03-14T20:36:43.745Z] 20:36:43     INFO - Buffered messages logged at 20:36:41
[task 2018-03-14T20:36:43.750Z] 20:36:43     INFO - Entering test bound set_simplify_and_reader_pref
[task 2018-03-14T20:36:43.750Z] 20:36:43     INFO - Leaving test bound set_simplify_and_reader_pref
[task 2018-03-14T20:36:43.750Z] 20:36:43     INFO - Entering test bound switch_print_preview_browsers
[task 2018-03-14T20:36:43.753Z] 20:36:43     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html" line: 0}]
[task 2018-03-14T20:36:43.753Z] 20:36:43     INFO - Buffered messages logged at 20:36:42
[task 2018-03-14T20:36:43.757Z] 20:36:43     INFO - Console message: [JavaScript Error: "NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]" {file: "resource:///modules/ContentMetaHandler.jsm" line: 155}]
[task 2018-03-14T20:36:43.758Z] 20:36:43     INFO - TEST-PASS | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have initial content. - "Non article title" == "Non article title" - 
[task 2018-03-14T20:36:43.760Z] 20:36:43     INFO - Console message: [JavaScript Error: "TypeError: content.document.head is null" {file: "chrome://global/content/browser-content.js" line: 665}]
[task 2018-03-14T20:36:43.760Z] 20:36:43     INFO - TEST-PASS | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have simplify page option checked - 
[task 2018-03-14T20:36:43.763Z] 20:36:43     INFO - Buffered messages finished
[task 2018-03-14T20:36:43.764Z] 20:36:43     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have recovery content. - "" == "Failed to load article from page" - 
[task 2018-03-14T20:36:43.765Z] 20:36:43     INFO - Stack trace:
[task 2018-03-14T20:36:43.766Z] 20:36:43     INFO - resource://testing-common/content-task.js line 50 > eval:null:4
[task 2018-03-14T20:36:43.767Z] 20:36:43     INFO - TEST-PASS | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have simplified print preview browser selected - 
[task 2018-03-14T20:36:43.768Z] 20:36:43     INFO - TEST-PASS | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should not have default print preview browser selected - 
[task 2018-03-14T20:36:43.768Z] 20:36:43     INFO - Leaving test bound switch_print_preview_browsers
[task 2018-03-14T20:36:43.769Z] 20:36:43     INFO - GECKO(1045) | MEMORY STAT | vsize 2125MB | residentFast 322MB | heapAllocated 115MB
[task 2018-03-14T20:36:43.770Z] 20:36:43     INFO - TEST-OK | toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | took 1204ms
[task 2018-03-14T20:36:43.770Z] 20:36:43     INFO - checking window state
[task 2018-03-14T20:36:43.771Z] 20:36:43     INFO - GECKO(1045) | JavaScript error: resource:///modules/ContentMetaHandler.jsm, line 155: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]
[task 2018-03-14T20:36:44.387Z] 20:36:44     INFO - Console message: [JavaScript Error: "NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]" {file: "resource:///modules/ContentMetaHandler.jsm" line: 155}]
[task 2018-03-14T20:36:45.074Z] 20:36:45     INFO - GECKO(1045) | Completed ShutdownLeaks collections in process 1201
[task 2018-03-14T20:36:45.216Z] 20:36:45     INFO - GECKO(1045) | Completed ShutdownLeaks collections in process 1101
[task 2018-03-14T20:36:45.236Z] 20:36:45     INFO - GECKO(1045) | Completed ShutdownLeaks collections in process 1172
[task 2018-03-14T20:36:45.325Z] 20:36:45     INFO - GECKO(1045) | Completed ShutdownLeaks collections in process 1150
[task 2018-03-14T20:36:45.556Z] 20:36:45     INFO - GECKO(1045) | Completed ShutdownLeaks collections in process 1045
[task 2018-03-14T20:36:45.557Z] 20:36:45     INFO - TEST-START | Shutdown
[task 2018-03-14T20:36:45.558Z] 20:36:45     INFO - Browser Chrome Test Summary
[task 2018-03-14T20:36:45.559Z] 20:36:45     INFO - Passed:  19
[task 2018-03-14T20:36:45.561Z] 20:36:45     INFO - Failed:  1
[task 2018-03-14T20:36:45.563Z] 20:36:45     INFO - Todo:    0
[task 2018-03-14T20:36:45.565Z] 20:36:45     INFO - Mode:    e10s
[task 2018-03-14T20:36:45.567Z] 20:36:45     INFO - *** End BrowserChrome Test Results ***
[task 2018-03-14T20:36:45.827Z] 20:36:45     INFO - GECKO(1045) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2018-03-14T20:36:45.864Z] 20:36:45     INFO - GECKO(1045) | 1521059805848	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-03-14T20:36:45.865Z] 20:36:45     INFO - GECKO(1045) | 1521059805848	Marionette	DEBUG	New connections will no longer be accepted
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - TEST-INFO | Main app process: exit 0
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - runtests.py | Application ran for: 0:00:12.737128
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - zombiecheck | Reading PID log: /tmp/tmpLeO3yipidlog
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - ==> process 1045 launched child process 1068
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - ==> process 1045 launched child process 1101
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - ==> process 1045 launched child process 1150
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - ==> process 1045 launched child process 1172
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - ==> process 1045 launched child process 1201
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - zombiecheck | Checking for orphan process with PID: 1172
[task 2018-03-14T20:36:46.186Z] 20:36:46     INFO - zombiecheck | Checking for orphan process with PID: 1068
[task 2018-03-14T20:36:46.187Z] 20:36:46     INFO - zombiecheck | Checking for orphan process with PID: 1101
[task 2018-03-14T20:36:46.187Z] 20:36:46     INFO - zombiecheck | Checking for orphan process with PID: 1150
[task 2018-03-14T20:36:46.187Z] 20:36:46     INFO - zombiecheck | Checking for orphan process with PID: 1201
[task 2018-03-14T20:36:46.190Z] 20:36:46     INFO - Stopping web server
[task 2018-03-14T20:36:46.211Z] 20:36:46     INFO - Stopping web socket server
[task 2018-03-14T20:36:46.212Z] 20:36:46     INFO - Stopping ssltunnel
[task 2018-03-14T20:36:46.248Z] 20:36:46  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-03-14T20:36:46.252Z] 20:36:46     INFO - runtests.py | Running tests: end.
[task 2018-03-14T20:36:46.268Z] 20:36:46     INFO - Buffered messages finished
[task 2018-03-14T20:36:46.269Z] 20:36:46     INFO -  TEST-INFO | checking window state
[task 2018-03-14T20:36:46.270Z] 20:36:46     INFO -  Browser Chrome Test Summary
[task 2018-03-14T20:36:46.271Z] 20:36:46     INFO -  	Passed: 19
[task 2018-03-14T20:36:46.272Z] 20:36:46     INFO -  	Failed: 1
[task 2018-03-14T20:36:46.273Z] 20:36:46     INFO -  	Todo: 0
[task 2018-03-14T20:36:46.274Z] 20:36:46     INFO -  	Mode: e10s
[task 2018-03-14T20:36:46.275Z] 20:36:46     INFO -  *** End BrowserChrome Test Results ***
Flags: needinfo?(mconley)
Hey mlongaray, it looks like the test that was added in bug 1440638 is a tad race-y. The code that injects the error text is not guaranteed to be there (we're racing with the ReaderMode worker).

Can you modify the test to poll for the title being updated instead? I suspect that's probably simplest, rather than firing some event or something when the parse and render is done.

Here's where I think we need to poll:

https://searchfox.org/mozilla-central/rev/6e96a3f1e44e286ddae5fdafab737709741d237a/toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js#68

You can poll using ContentTaskUtils.waitForCondition:

https://searchfox.org/mozilla-central/rev/6e96a3f1e44e286ddae5fdafab737709741d237a/browser/base/content/test/about/browser_aboutHome_input.js#76
Blocks: 1440638
Flags: needinfo?(mconley) → needinfo?(mlongaray)
Summary: Perma-failing toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have recovery content. - "" == "Failed to load article from page" - → Intermittent toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js | Should have recovery content. - "" == "Failed to load article from page" -
Yes Mike, let's modify the test, thanks for the info! I can probably get the cycles for it this week. If not, next week is certain.
Flags: needinfo?(mlongaray)
Great, thanks, mlongaray.
Assignee: nobody → mlongaray
Comment on attachment 8960221 [details]
Bug 1445837 - Fix race condition in toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js.

https://reviewboard.mozilla.org/r/228980/#review234722

Looks good, thanks!
Attachment #8960221 - Flags: review?(mconley) → review+
Pushed by mconley@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d2c963c50225
Fix race condition in toolkit/components/printing/tests/browser_preview_print_simplify_non_article.js. r=mconley
https://hg.mozilla.org/mozilla-central/rev/d2c963c50225
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox61: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
You need to log in before you can comment on or make changes to this bug.