Open Bug 1237028 Opened 8 years ago Updated 2 years ago

browser_save_link-perwindowpb.js fails 25% in multi core docker containers and doesn't in single core

Tracking

()

Status:

NEW

People

(Reporter: jmaher, Unassigned)

References

(Blocks 1 open bug)

Details

Joel Maher ( :jmaher ) (UTC -8)

Reporter

Description

•

8 years ago

in comparing a single core vs multi core docker container for running tests, we find a few tests which have different behaviors (bug 1237024).  In this case I care about:
TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_save_link-perwindowpb.js | Test timed out
https://public-artifacts.taskcluster.net/acyFqo7RSrOp0d5SqGYN-Q/0/public/logs/live_backing.log

this is an small clip from the log file above:
14:30:54     INFO -  551 INFO TEST-START | browser/base/content/test/general/browser_save_link-perwindowpb.js
14:30:54     INFO -  ++DOCSHELL 0x7f32da83e000 == 39 [pid = 1213] [id = 897]
14:30:54     INFO -  ++DOMWINDOW == 70 (0x7f32d9ae7400) [pid = 1213] [serial = 2417] [outer = (nil)]
14:30:54     INFO -  ++DOMWINDOW == 71 (0x7f32d9ae8c00) [pid = 1213] [serial = 2418] [outer = 0x7f32d9ae7400]
14:30:55     INFO -  ++DOCSHELL 0x7f32e0402800 == 40 [pid = 1213] [id = 898]
14:30:55     INFO -  ++DOMWINDOW == 72 (0x7f32da33dc00) [pid = 1213] [serial = 2419] [outer = (nil)]
14:30:55     INFO -  ++DOCSHELL 0x7f32e0404800 == 41 [pid = 1213] [id = 899]
14:30:55     INFO -  ++DOMWINDOW == 73 (0x7f32da3eac00) [pid = 1213] [serial = 2420] [outer = (nil)]
14:30:55     INFO -  ++DOMWINDOW == 74 (0x7f32da3f0800) [pid = 1213] [serial = 2421] [outer = 0x7f32da3eac00]
14:30:55     INFO -  ++DOCSHELL 0x7f32e117d000 == 42 [pid = 1213] [id = 900]
14:30:55     INFO -  ++DOMWINDOW == 75 (0x7f32da33d400) [pid = 1213] [serial = 2422] [outer = (nil)]
14:30:55     INFO -  ++DOMWINDOW == 76 (0x7f32e0288800) [pid = 1213] [serial = 2423] [outer = 0x7f32da33d400]
14:30:55     INFO -  ++DOMWINDOW == 77 (0x7f32e0535c00) [pid = 1213] [serial = 2424] [outer = 0x7f32da33dc00]
14:30:55     INFO -  ++DOMWINDOW == 78 (0x7f32e0536400) [pid = 1213] [serial = 2425] [outer = 0x7f32da3eac00]
14:30:55     INFO -  ++DOMWINDOW == 79 (0x7f32e0ad6400) [pid = 1213] [serial = 2426] [outer = 0x7f32da33d400]
14:30:56     INFO -  ++DOMWINDOW == 80 (0x7f32da4bac00) [pid = 1213] [serial = 2427] [outer = 0x7f32da33d400]
14:30:56     INFO -  [1213] WARNING: attempt to modify an immutable nsStandardURL: file /home/worker/workspace/build/src/netwerk/base/nsStandardURL.cpp, line 1302
14:30:56     INFO -  ++DOMWINDOW == 81 (0x7f32e448b400) [pid = 1213] [serial = 2428] [outer = 0x7f32da33d400]
14:30:58     INFO -  [1213] WARNING: no triggering principal available via loadInfo, assuming load is cross-origin: file /home/worker/workspace/build/src/netwerk/protocol/http/HttpBaseChannel.cpp, line 1388
14:30:58     INFO -  [1213] WARNING: NS_ENSURE_TRUE(window) failed: file /home/worker/workspace/build/src/uriloader/exthandler/nsExternalHelperAppService.cpp, line 2560
14:30:58     INFO -  [1213] WARNING: The dialog should nullify the dialog progress listener: file /home/worker/workspace/build/src/uriloader/exthandler/nsExternalHelperAppService.cpp, line 2166
14:30:58     INFO -  [1213] WARNING: NS_ENSURE_TRUE(mDoneSetup) failed: file /home/worker/workspace/build/src/editor/composer/nsEditingSession.cpp, line 1330
14:30:58     INFO -  ++DOCSHELL 0x7f32dab7d000 == 43 [pid = 1213] [id = 901]
14:30:58     INFO -  ++DOMWINDOW == 82 (0x7f32daef8400) [pid = 1213] [serial = 2429] [outer = (nil)]
14:30:58     INFO -  ++DOMWINDOW == 83 (0x7f32e0530800) [pid = 1213] [serial = 2430] [outer = 0x7f32daef8400]
14:30:59     INFO -  ++DOCSHELL 0x7f32e3f11800 == 44 [pid = 1213] [id = 902]
14:30:59     INFO -  ++DOMWINDOW == 84 (0x7f32dadeb400) [pid = 1213] [serial = 2431] [outer = (nil)]
14:30:59     INFO -  ++DOCSHELL 0x7f32e3f14000 == 45 [pid = 1213] [id = 903]
14:30:59     INFO -  ++DOMWINDOW == 85 (0x7f32dadef400) [pid = 1213] [serial = 2432] [outer = (nil)]
14:30:59     INFO -  ++DOMWINDOW == 86 (0x7f32d980c400) [pid = 1213] [serial = 2433] [outer = 0x7f32dadef400]
14:30:59     INFO -  ++DOCSHELL 0x7f32e44ae000 == 46 [pid = 1213] [id = 904]
14:30:59     INFO -  ++DOMWINDOW == 87 (0x7f32dadeb000) [pid = 1213] [serial = 2434] [outer = (nil)]
14:30:59     INFO -  ++DOMWINDOW == 88 (0x7f32e4592000) [pid = 1213] [serial = 2435] [outer = 0x7f32dadeb000]
14:30:59     INFO -  ++DOMWINDOW == 89 (0x7f32e5252c00) [pid = 1213] [serial = 2436] [outer = 0x7f32dadeb400]
14:30:59     INFO -  ++DOMWINDOW == 90 (0x7f32e5254000) [pid = 1213] [serial = 2437] [outer = 0x7f32dadef400]
14:30:59     INFO -  ++DOMWINDOW == 91 (0x7f32e5257800) [pid = 1213] [serial = 2438] [outer = 0x7f32dadeb000]
14:31:00     INFO -  ++DOMWINDOW == 92 (0x7f32e5c2f400) [pid = 1213] [serial = 2439] [outer = 0x7f32dadeb000]
14:31:00     INFO -  [1213] WARNING: NS_ENSURE_TRUE(aSecondURI) failed: file /home/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 97
14:31:00     INFO -  [1213] WARNING: NS_ENSURE_TRUE(aSecondURI) failed: file /home/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 97
14:31:00     INFO -  ++DOMWINDOW == 93 (0x7f32e5c2fc00) [pid = 1213] [serial = 2440] [outer = 0x7f32dadeb000]
14:31:04     INFO -  --DOMWINDOW == 92 (0x7f32d9a6f800) [pid = 1213] [serial = 2155] [outer = (nil)] [url = about:blank]
14:31:04     INFO -  --DOMWINDOW == 91 (0x7f32e1720800) [pid = 1213] [serial = 2211] [outer = (nil)] [url = about:blank]
14:31:07     INFO -  --DOMWINDOW == 90 (0x7f32dabae400) [pid = 1213] [serial = 2375] [outer = (nil)] [url = about:blank]
14:31:07     INFO -  --DOMWINDOW == 89 (0x7f32e0287800) [pid = 1213] [serial = 2377] [outer = (nil)] [url = about:blank]
14:31:07     INFO -  --DOMWINDOW == 88 (0x7f32e17ed400) [pid = 1213] [serial = 2387] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 87 (0x7f32e0bc4800) [pid = 1213] [serial = 2381] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 86 (0x7f32dad34000) [pid = 1213] [serial = 2397] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 85 (0x7f32da72e400) [pid = 1213] [serial = 2395] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 84 (0x7f32e1966800) [pid = 1213] [serial = 2383] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 83 (0x7f32e2adcc00) [pid = 1213] [serial = 2385] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 82 (0x7f32dabb3000) [pid = 1213] [serial = 2376] [outer = (nil)] [url = about:blank]
14:31:07     INFO -  --DOMWINDOW == 81 (0x7f32e053b000) [pid = 1213] [serial = 2378] [outer = (nil)] [url = about:blank]
14:31:07     INFO -  --DOMWINDOW == 80 (0x7f32daeba400) [pid = 1213] [serial = 2399] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 79 (0x7f32e05d5400) [pid = 1213] [serial = 2379] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 78 (0x7f32d9807c00) [pid = 1213] [serial = 2393] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:07     INFO -  --DOMWINDOW == 77 (0x7f32e38b4c00) [pid = 1213] [serial = 2389] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:14     INFO -  --DOCSHELL 0x7f32e0402800 == 45 [pid = 1213] [id = 898]
14:31:14     INFO -  --DOCSHELL 0x7f32e0404800 == 44 [pid = 1213] [id = 899]
14:31:14     INFO -  --DOCSHELL 0x7f32e117d000 == 43 [pid = 1213] [id = 900]
14:31:14     INFO -  --DOCSHELL 0x7f32da83e000 == 42 [pid = 1213] [id = 897]
14:31:14     INFO -  --DOMWINDOW == 76 (0x7f32daef5400) [pid = 1213] [serial = 2400] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 75 (0x7f32e05d6c00) [pid = 1213] [serial = 2380] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 74 (0x7f32d9810c00) [pid = 1213] [serial = 2394] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 73 (0x7f32e2ade400) [pid = 1213] [serial = 2386] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 72 (0x7f32e4497c00) [pid = 1213] [serial = 2257] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 71 (0x7f32e2adf000) [pid = 1213] [serial = 2388] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 70 (0x7f32e0bc6c00) [pid = 1213] [serial = 2382] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 69 (0x7f32dad82800) [pid = 1213] [serial = 2398] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 68 (0x7f32da730000) [pid = 1213] [serial = 2396] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 67 (0x7f32e1968c00) [pid = 1213] [serial = 2384] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 66 (0x7f32e1414800) [pid = 1213] [serial = 2195] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 65 (0x7f32e277f800) [pid = 1213] [serial = 2236] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 64 (0x7f32e38b5c00) [pid = 1213] [serial = 2390] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 63 (0x7f32e0536400) [pid = 1213] [serial = 2425] [outer = 0x7f32da3eac00] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 62 (0x7f32da3f0800) [pid = 1213] [serial = 2421] [outer = 0x7f32da3eac00] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 61 (0x7f32e0535c00) [pid = 1213] [serial = 2424] [outer = 0x7f32da33dc00] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 60 (0x7f32d980c400) [pid = 1213] [serial = 2433] [outer = 0x7f32dadef400] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 59 (0x7f32da33dc00) [pid = 1213] [serial = 2419] [outer = (nil)] [url = about:blank]
14:31:14     INFO -  --DOMWINDOW == 58 (0x7f32da3eac00) [pid = 1213] [serial = 2420] [outer = (nil)] [url = about:blank]
14:31:17     INFO -  --DOMWINDOW == 57 (0x7f32e448b400) [pid = 1213] [serial = 2428] [outer = (nil)] [url = http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html]
14:31:17     INFO -  --DOMWINDOW == 56 (0x7f32e0ad6400) [pid = 1213] [serial = 2426] [outer = (nil)] [url = about:blank]
14:31:17     INFO -  --DOMWINDOW == 55 (0x7f32e0288800) [pid = 1213] [serial = 2423] [outer = (nil)] [url = about:blank]
14:31:17     INFO -  --DOMWINDOW == 54 (0x7f32e5257800) [pid = 1213] [serial = 2438] [outer = (nil)] [url = about:blank]
14:31:17     INFO -  --DOMWINDOW == 53 (0x7f32e4592000) [pid = 1213] [serial = 2435] [outer = (nil)] [url = about:blank]
14:31:17     INFO -  --DOMWINDOW == 52 (0x7f32e38aa400) [pid = 1213] [serial = 2272] [outer = (nil)] [url = chrome://browser/content/browser.xul]
14:31:17     INFO -  --DOMWINDOW == 51 (0x7f32d92f8c00) [pid = 1213] [serial = 2391] [outer = (nil)] [url = chrome://browser/content/sanitize.xul]
14:31:17     INFO -  --DOMWINDOW == 50 (0x7f32da33d400) [pid = 1213] [serial = 2422] [outer = (nil)] [url = http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html]
14:31:17     INFO -  --DOMWINDOW == 49 (0x7f32da4bac00) [pid = 1213] [serial = 2427] [outer = (nil)] [url = about:home]
14:31:17     INFO -  --DOMWINDOW == 48 (0x7f32e5c2f400) [pid = 1213] [serial = 2439] [outer = (nil)] [url = about:privatebrowsing]
14:31:22     INFO -  --DOMWINDOW == 47 (0x7f32e3f71400) [pid = 1213] [serial = 2273] [outer = (nil)] [url = about:blank]
14:31:22     INFO -  --DOMWINDOW == 46 (0x7f32d986b000) [pid = 1213] [serial = 2392] [outer = (nil)] [url = about:blank]
14:31:40     INFO -  TEST-INFO | started process screentopng
14:31:40     INFO -  TEST-INFO | screentopng: exit 0
14:31:40     INFO -  552 INFO checking window state
14:31:40     INFO -  553 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
14:31:40     INFO -  554 INFO Start the test
14:31:40     INFO -  555 INFO testOnWindow(undefined)
14:31:40     INFO -  556 INFO got [object ChromeWindow]
14:31:40     INFO -  557 INFO whenDelayedStartupFinished
14:31:40     INFO -  558 INFO whenDelayedStartupFinished, got topic: browser-delayed-startup-finished, got subject: [object ChromeWindow], waiting for [object ChromeWindow]
14:31:40     INFO -  559 INFO whenDelayedStartupFinished found our window
14:31:40     INFO -  560 INFO started triggerSave
14:31:40     INFO -  561 INFO observer called with http-on-modify-request
14:31:40     INFO -  562 INFO onModifyRequest with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  563 INFO observer called with http-on-examine-response
14:31:40     INFO -  564 INFO onExamineResponse with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  565 INFO returning
14:31:40     INFO -  566 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://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html" line: 0}]
14:31:40     INFO -  567 INFO got pageshow with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  568 INFO found our page!
14:31:40     INFO -  569 INFO must wait for focus
14:31:40     INFO -  570 INFO register to handle popupshown
14:31:40     INFO -  571 INFO link: http://mochi.test:8888/browser/browser/base/content/test/general/bug792517.sjs
14:31:40     INFO -  572 INFO right clicked!
14:31:40     INFO -  573 INFO contextMenuOpened
14:31:40     INFO -  574 INFO create testsavedir!
14:31:40     INFO -  575 INFO return from createTempSaveDir: /tmp/testsavedir
14:31:40     INFO -  576 INFO saveLinkCommand: [object XULElement]
14:31:40     INFO -  577 INFO popup hidden
14:31:40     INFO -  578 INFO observer called with http-on-modify-request
14:31:40     INFO -  579 INFO onModifyRequest with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517.sjs
14:31:40     INFO -  580 INFO onModifyRequest caught NOTAVAIL[Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIHttpChannel.getRequestHeader]"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/general/browser_save_link-perwindowpb.js :: onModifyRequest :: line 159"  data: no]
14:31:40     INFO -  581 INFO observer called with http-on-examine-response
14:31:40     INFO -  582 INFO onExamineResponse with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517.sjs
14:31:40     INFO -  583 INFO TEST-PASS | browser/base/content/test/general/browser_save_link-perwindowpb.js | Cookie should be foopy=1 -
14:31:40     INFO -  584 INFO gNumSet = 1
14:31:40     INFO -  585 INFO showCallback
14:31:40     INFO -  586 INFO fileName: bug792517.sjs
14:31:40     INFO -  587 INFO done showCallback
14:31:40     INFO -  588 INFO mockTransferCallback
14:31:40     INFO -  589 INFO TEST-PASS | browser/base/content/test/general/browser_save_link-perwindowpb.js | Link should have been downloaded successfully -
14:31:40     INFO -  590 INFO TEST-PASS | browser/base/content/test/general/browser_save_link-perwindowpb.js | Destination dir should be removed -
14:31:40     INFO -  591 INFO TEST-PASS | browser/base/content/test/general/browser_save_link-perwindowpb.js | Destination file should be removed -
14:31:40     INFO -  592 INFO done mockTransferCallback
14:31:40     INFO -  593 INFO TEST-PASS | browser/base/content/test/general/browser_save_link-perwindowpb.js | 1 cookie should be set -
14:31:40     INFO -  594 INFO testOnWindow([object Object])
14:31:40     INFO -  595 INFO got [object ChromeWindow]
14:31:40     INFO -  596 INFO whenDelayedStartupFinished
14:31:40     INFO -  597 INFO whenDelayedStartupFinished, got topic: browser-delayed-startup-finished, got subject: [object ChromeWindow], waiting for [object ChromeWindow]
14:31:40     INFO -  598 INFO whenDelayedStartupFinished found our window
14:31:40     INFO -  599 INFO started triggerSave
14:31:40     INFO -  600 INFO observer called with http-on-modify-request
14:31:40     INFO -  601 INFO onModifyRequest with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  602 INFO observer called with http-on-examine-response
14:31:40     INFO -  603 INFO onExamineResponse with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  604 INFO returning
14:31:40     INFO -  605 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://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html" line: 0}]
14:31:40     INFO -  606 INFO got pageshow with http://mochi.test:8888/browser/browser/base/content/test/general/bug792517-2.html
14:31:40     INFO -  607 INFO found our page!
14:31:40     INFO -  608 INFO must wait for focus
14:31:40     INFO -  609 INFO register to handle popupshown
14:31:40     INFO -  610 INFO link: http://mochi.test:8888/browser/browser/base/content/test/general/bug792517.sjs
14:31:40     INFO -  611 INFO right clicked!
14:31:40     INFO -  612 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_save_link-perwindowpb.js | Test timed out -
14:31:40     INFO -  613 INFO Running the cleanup code
14:31:40     INFO -  614 INFO Finished running the cleanup code
14:31:40     INFO -  MEMORY STAT | vsize 1991MB | residentFast 502MB | heapAllocated 142MB
14:31:40     INFO -  615 INFO TEST-OK | browser/base/content/test/general/browser_save_link-perwindowpb.js | took 45257ms
14:31:40     INFO -  ++DOCSHELL 0x7f32da3c7000 == 43 [pid = 1213] [id = 905]
14:31:40     INFO -  ++DOMWINDOW == 47 (0x7f32d98ea800) [pid = 1213] [serial = 2441] [outer = (nil)]
14:31:40     INFO -  ++DOMWINDOW == 48 (0x7f32d994d000) [pid = 1213] [serial = 2442] [outer = 0x7f32d98ea800]
14:31:40     INFO -  Not taking screenshot here: see the one that was previously logged
14:31:40     INFO -  616 INFO checking window state
14:31:40     INFO -  617 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_save_link-perwindowpb.js | Found a browser window after previous test timed out -
14:31:40     INFO -  must wait for focus
14:31:40     INFO -  618 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]
14:31:40     INFO -  [1213] WARNING: NS_ENSURE_TRUE(mDoneSetup) failed: file /home/worker/workspace/build/src/editor/composer/nsEditingSession.cpp, line 1330


I am not sure why this is the case, but I think this might be something worth looking into how we can make this test more reliable or maybe private browsing has a bug in it.  This has no differences in normal vs e10s, same pattern of failure/pass.

Josh Matthews [:jdm]

Comment 1

•

8 years ago

According to the log, the second right click does not end up triggering the popupshown event that causes contextMenuOpened to execute, thus the test times out. Mysterious.

Mark Hammond [:markh] [:mhammond]

Comment 2

•

8 years ago

(In reply to Josh Matthews [:jdm] from comment #1)
> According to the log, the second right click does not end up triggering the
> popupshown event that causes contextMenuOpened to execute, thus the test
> times out. Mysterious.

It looks even stranger than that to me if I'm reading the timestamps correctly. Snipping some of the lines from that output:

14:30:54     INFO -  551 INFO TEST-START | browser/base/content/test/general/browser_save_link-perwindowpb.js
so the test runner seems to think it has started the test.
14:31:40     INFO -  TEST-INFO | started process screentopng
14:31:40     INFO -  TEST-INFO | screentopng: exit 0

I'm not sure why the test runner is taking screenshot here? The previous test passed, and note that this test is yet to dump any output it produces, and it's ~46 seconds since it was reported the test started.

14:31:40     INFO -  552 INFO checking window state
14:31:40     INFO -  553 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}]

The lines above also imply the test runner thinks it is between tests.

14:31:40     INFO -  554 INFO Start the test

This is the first line of output from the test itself (from the first line of its |test()| function) - which seems to run fine until:

14:31:40     INFO -  611 INFO right clicked!
14:31:40     INFO -  612 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/general/browser_save_link-perwindowpb.js | Test timed out -
...
14:31:40     INFO -  615 INFO TEST-OK | browser/base/content/test/general/browser_save_link-perwindowpb.js | took 45257ms

So it was killed after taking 45 seconds, but it seems the test didn't actually start until then. If this is one of the only tests with these symptoms, it may be that some of the top-level code in that test could have caused the timeout (ie, before that |test()| method was called), but nothing leaps out at me. It's a pity there are no print/dump calls at the top of the test.

Joel Maher ( :jmaher ) (UTC -8)

Reporter

Comment 3

•

8 years ago

is there some logging we can try out to get more information here.  I could run this in the same environment and compare single core vs multi core.

Mark Hammond [:markh] [:mhammond]

Comment 4

•

8 years ago

(In reply to Joel Maher (:jmaher) from comment #3)
> is there some logging we can try out to get more information here.  I could
> run this in the same environment and compare single core vs multi core.

If comment 2 isn't missing the point, then I'd suggest we add a dump() as the first line of that test file and re-run. If we still see 45 seconds from the harness reporting the test starting and that dump appearing, then I guess it would point at a harness issue. If the dump appears immediately, then I guess a few more dumps so we can see what part of the initialization code in that test is causing the hang would make sense - this test only does 2 "global" things of interest:

* Uses SpecialPowers to create a mocked object:
> var MockFilePicker = SpecialPowers.MockFilePicker;
> MockFilePicker.init(window);

* Imports a module:
> Cc["@mozilla.org/moz/jssubscript-loader;1"]
>   .getService(Ci.mozIJSSubScriptLoader)
>   .loadSubScript("chrome://mochitests/content/browser/toolkit/content/tests/browser/common/mockTransfer.js",
>                  this);

BMO Automation

Updated

•

2 years ago

Severity: normal → S3

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

Bugzilla

Quick Search

browser_save_link-perwindowpb.js fails 25% in multi core docker containers and doesn't in single core

Categories

(Firefox :: Private Browsing, defect)

Tracking

()

People

(Reporter: jmaher, Unassigned)

References

(Blocks 1 open bug)

Details

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Updated