Closed Bug 1519538 Opened 1 year ago Closed 1 year ago

Intermittent tier2 browser/components/urlbar/tests/legacy/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(Firefox :: Address Bar, defect, P5)

defect

Tracking

()

RESOLVED FIXED
Firefox 67
Tracking Status
firefox67 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered] [stockwell needswork])

Attachments

(1 file)

Filed by: nerli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=221368032&repo=mozilla-central

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

19:56:07 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | Visible action - "Visit" == "Visit" -
19:56:07 INFO - Leaving test bound injectJSON
19:56:07 INFO - Entering test bound losslessDecode
19:56:07 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | The string displayed in the textbox should not be escaped - "example.com/アイウエオ" == "example.com/アイウエオ" -
19:56:07 INFO - Leaving test bound losslessDecode
19:56:07 INFO - Entering test bound actionURILosslessDecode
19:56:07 INFO - Disable popup animation. Change dontAnimate value from true to true.
19:56:07 INFO - Buffered messages logged at 19:56:07
19:56:07 INFO - Restore popup dontAnimate value to true
19:56:07 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | visiturl action URI should be in the urlbar - "visiturl" == "visiturl" -
19:56:07 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | The string displayed in the textbox should not be escaped - "example.com/アイウエオ" == "example.com/アイウエオ" -
19:56:07 INFO - Leaving test bound actionURILosslessDecode
19:56:07 INFO - Buffered messages finished
19:56:07 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/urlbar/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
19:56:07 INFO - GECKO(4068) | MEMORY STAT | vsize 2352MB | vsizeMaxContiguous 131589872MB | residentFast 457MB | heapAllocated 100MB
19:56:07 INFO - TEST-OK | browser/base/content/test/urlbar/browser_urlbarDecode.js | took 194085ms
19:56:07 INFO - GECKO(4068) | ++DOCSHELL 000001996F077000 == 1 [pid = 3608] [id = {b9128b05-d003-4cf3-a3da-7fb416ed33fc}]
19:56:07 INFO - GECKO(4068) | ++DOMWINDOW == 1 (000001996F0A7000) [pid = 3608] [serial = 121] [outer = 0000000000000000]
19:56:07 INFO - GECKO(4068) | ++DOMWINDOW == 2 (000001996F0D6000) [pid = 3608] [serial = 122] [outer = 000001996F0A7000]
19:56:07 INFO - GECKO(4068) | ++DOMWINDOW == 3 (00000199732B3C00) [pid = 3608] [serial = 123] [outer = 000001996F0A7000]
19:56:07 INFO - checking window state

This started https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&selectedJob=221368032&searchStr=windows%2C10%2Cx64%2Cccov%2Cdebug%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows10-64-ccov%2Fdebug-mochitest-browser-chrome-e10s-4%2Cm-e10s%28bc4%29&tochange=2a99e348fde3d1674296bb82c5f3881e696e8fb6&fromchange=8e746f670f430ceb0cb85fa8eebfe97cbe42ff01

There are 16 total failures in the last 7 days on windows10-64-ccov debug.
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=221632021&repo=mozilla-central&lineNumber=9577

23:33:53 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | Visible action - "Visit" == "Visit" -
23:33:53 INFO - Leaving test bound injectJSON
23:33:53 INFO - Entering test bound losslessDecode
23:33:53 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | The string displayed in the textbox should not be escaped - "example.com/アイウエオ" == "example.com/アイウエオ" -
23:33:53 INFO - Leaving test bound losslessDecode
23:33:53 INFO - Entering test bound actionURILosslessDecode
23:33:53 INFO - Buffered messages logged at 23:33:51
23:33:53 INFO - Disable popup animation. Change dontAnimate value from true to true.
23:33:53 INFO - Buffered messages logged at 23:33:53
23:33:53 INFO - Restore popup dontAnimate value to true
23:33:53 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | visiturl action URI should be in the urlbar - "visiturl" == "visiturl" -
23:33:53 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_urlbarDecode.js | The string displayed in the textbox should not be escaped - "example.com/アイウエオ" == "example.com/アイウエオ" -
23:33:53 INFO - Leaving test bound actionURILosslessDecode
23:33:53 INFO - Buffered messages finished
23:33:53 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/urlbar/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
23:33:53 INFO - GECKO(5692) | MEMORY STAT | vsize 2393MB | vsizeMaxContiguous 130603721MB | residentFast 490MB | heapAllocated 117MB
23:33:53 INFO - TEST-OK | browser/base/content/test/urlbar/browser_urlbarDecode.js | took 189447ms
23:33:53 INFO - GECKO(5692) | ++DOCSHELL 000001C424475800 == 1 [pid = 8324] [id = {9c8f7d44-78fd-425a-8272-bded8bda2b94}]
23:33:53 INFO - GECKO(5692) | ++DOMWINDOW == 1 (000001C4244C9400) [pid = 8324] [serial = 121] [outer = 0000000000000000]
23:33:53 INFO - GECKO(5692) | ++DOMWINDOW == 2 (000001C4244CD000) [pid = 8324] [serial = 122] [outer = 000001C4244C9400]
23:33:53 INFO - checking window state

Whiteboard: [retriggered]

There are 38 failures in the last 7 days. All of them on windows10-64-ccov -> debug.
As I can see, it could be caused by the landing of Bug 1513241 or Bug 1514664.

Marco, could you please take a look?

Flags: needinfo?(mak77)
Whiteboard: [retriggered] → [retriggered] [stockwell needswork]
Duplicate of this bug: 1522985
Flags: needinfo?(mak77)
Summary: Intermittent Perma tier2 browser/base/content/test/urlbar/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - → Intermittent Perma tier2 browser/components/urlbar/tests/legacy/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
Assignee: nobody → mak77
Status: NEW → ASSIGNED
Summary: Intermittent Perma tier2 browser/components/urlbar/tests/legacy/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - → Intermittent tier2 browser/components/urlbar/tests/legacy/browser_urlbarDecode.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

There are 44 failures in the last 7 days.
They occur on windows10-64-ccov debug.
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=224904031&repo=mozilla-central&lineNumber=13045
mak: Hi, Do you have any updates on this? Thank you!

From the log
17:29:00 INFO - TEST-START | browser/base/content/test/urlbar/browser_urlbarDecode.js

17:32:18 INFO - Entering test bound injectJSON
^ This is the first test, we spent 3 minutes just to START executing the first test.

17:32:18 INFO - Leaving test bound actionURILosslessDecode
^ Here we exit from the LAST test.

Globally the test took less than 1 second, so apparently this is not a problem with the test, it's the test harness that for some reason takes a long time to setup, or something else is happening in the meanwhile.

In that amount of time there isn't much logged, I see some telemetry probes, a vacuum manager call trying to vacuum Places, something in dom quota, some GC.
Off-hand it looks like idle-daily hit us, based on the VacuumManager failure... That could mean something broke our special setting of "idle.lastDailyNotification" that we do here:
https://searchfox.org/mozilla-central/rev/9eb30227b21e0aa40d51d9f9b08bb0b113c5fadb/testing/mochitest/runtests.py#1882

Maybe we started running tests differently, or we run tests differently for ccov? I don't know, maybe Marco Castelluccio knows if we take a different path for these tests?
I don't have much to suggest here, we should figure out why idle-daily is hitting us

Flags: needinfo?(mcastelluccio)

Maybe we should move those prefs to testing/profiles/perf/user.js or testing/profiles/unittest-required/user.js ? Oh, there is also testing/profiles/common/user.js.

Wes, what's the right location today for setting a pref for xpcshell and mochitests?

Flags: needinfo?(wkocher)

what's the difference between common and unittest-required?

Standard8 made me notice the only documentation we have is also completely out of date: https://developer.mozilla.org/en-US/docs/Mozilla/QA/Automated_testing#Need_to_set_preferences_for_test-suites

(In reply to Marco Bonardo [::mak] from comment #13)

what's the difference between common and unittest-required?

You can see which profiles apply to which test suites by inspecting testing/profiles/profiles.json. The current structure isn't very well organized, and is mostly the way it is to get all the test harnesses using it. We should really go through and audit all the prefs and try to group them into more logical profile by function (e.g one profile to disable network connections, one profile to turn off background tasks, etc).

Anyway, if you want to set these prefs for mochitest+xpcshell and only mochitest+xpcshell, I'd recommend adding them to both 'unittest-required' and 'xpcshell' for now.

Flags: needinfo?(wkocher)

Unfortunately the idle daily pref only accepts numbers between 0 and now, so it's hard to disable it from user.js, because we can't set a time in the future. It could even make sense, if the user's time is bogus we don't want to skip this work.
runtests.py sets the time to now (in seconds), I wonder if it's possible due to timers resolution that python time ends up being > then PR_NOW().
So there are 2 possibile solutions:

  1. allow to use a negative value to disable idle-daily
  2. Change python to subtract a few seconds (or even 1 hour for possible DST problems) to the time, to exclude timers.

Since it looks like the will is to move more prefs to specific user.js files, solution 1 sounds good. The likelihook we or the user sets a negative value here is quite low. and anyway I can add the idle. prefs to about:support

Flags: needinfo?(mcastelluccio)
Pushed by mak77@bonardo.net:
https://hg.mozilla.org/integration/autoland/rev/bac51381060d
Disable idle-daily notifications in tests through user.js files. r=Standard8

Apparently nor pushing nor mozreview run pylint...

Flags: needinfo?(mak77)
Pushed by mak77@bonardo.net:
https://hg.mozilla.org/integration/autoland/rev/58b16c9dabfd
Disable idle-daily notifications in tests through user.js files. r=Standard8
Backout by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3d8811e611d9
Backed out 2 changesets for linting failures. CLOSED TREE
Pushed by mak77@bonardo.net:
https://hg.mozilla.org/integration/autoland/rev/b9fad54bae14
Disable idle-daily notifications in tests through user.js files. r=Standard8
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 67
You need to log in before you can comment on or make changes to this bug.