1589568 - Intermittent tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Test timed out -

Status: RESOLVED INVALID

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=271816975&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/VfQaCoy7STiOIGc_V12wVQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/VfQaCoy7STiOIGc_V12wVQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2019-10-18T03:53:10.464Z] 03:53:10     INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | The profiler is not currently active - true == true - 
[task 2019-10-18T03:53:10.464Z] 03:53:10     INFO - Buffered messages logged at 03:50:41
[task 2019-10-18T03:53:10.464Z] 03:53:10     INFO - Wait 100ms so that the tab finishes executing.
[task 2019-10-18T03:53:10.464Z] 03:53:10     INFO - Check that some PreferenceRead profile markers were generated when the feature is enabled.
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - Buffered messages finished
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Test timed out - 
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - GECKO(1159) | MEMORY STAT | vsize 3486MB | residentFast 791MB | heapAllocated 300MB
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - TEST-OK | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | took 155915ms
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Found a tab after previous test timed out: http://example.com/browser/tools/profiler/tests/browser/fixed_height.html - 
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - checking window state
[task 2019-10-18T03:53:10.465Z] 03:53:10     INFO - GECKO(1159) | [Parent 1159, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 673
[task 2019-10-18T03:53:10.466Z] 03:53:10     INFO - GECKO(1159) | ++DOMWINDOW == 11 (0x7f81646a7400) [pid = 1159] [serial = 13] [outer = 0x7f8173296e20]
[task 2019-10-18T03:53:10.466Z] 03:53:10     INFO - GECKO(1159) | ++DOMWINDOW == 12 (0x7f81652d1400) [pid = 1159] [serial = 14] [outer = 0x7f8173296e20]
[task 2019-10-18T03:53:20.091Z] 03:53:20     INFO - GECKO(1159) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ShutdownLeaks: Wait for tabs to finish closing","state":"(none)","filename":"chrome://mochikit/content/browser-test.js","lineNumber":891,"stack":["chrome://mochikit/content/browser-test.js:nextTest/<:891","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805"]}] Barrier: ShutdownLeaks: Wait for cleanup to be finished before checking for leaks
[task 2019-10-18T03:53:23.125Z] 03:53:23     INFO - GECKO(1159) | ++DOCSHELL 0x7f0640861800 == 1 [pid = 1481] [id = {1193b5f2-bca4-4776-9512-6fad2e224756}]
[task 2019-10-18T03:53:23.528Z] 03:53:23     INFO - GECKO(1159) | ++DOMWINDOW == 1 (0x7f0641226f20) [pid = 1481] [serial = 1] [outer = (nil)]
[task 2019-10-18T03:53:35.179Z] 03:53:35     INFO - GECKO(1159) | --DOCSHELL 0x7f2f7e969800 == 0 [pid = 1414] [id = {7f19810f-831c-4298-8ac5-1225a31b1a04}] [url = about:blank]
[task 2019-10-18T03:53:35.296Z] 03:53:35     INFO - GECKO(1159) | --DOCSHELL 0x7f8713d60000 == 0 [pid = 1455] [id = {d72f4953-1a43-46fc-81ba-62e74556f3ba}] [url = http://example.com/browser/tools/profiler/tests/browser/fixed_height.html]
[task 2019-10-18T03:53:35.401Z] 03:53:35     INFO - GECKO(1159) | --DOMWINDOW == 1 (0x7f2f7f35d000) [pid = 1414] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-10-18T03:53:35.403Z] 03:53:35     INFO - GECKO(1159) | --DOMWINDOW == 0 (0x7f2f904c2f20) [pid = 1414] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-10-18T03:53:35.519Z] 03:53:35     INFO - GECKO(1159) | --DOMWINDOW == 1 (0x7f8713d2cf20) [pid = 1455] [serial = 1] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/fixed_height.html]
[task 2019-10-18T03:53:35.528Z] 03:53:35     INFO - GECKO(1159) | --DOMWINDOW == 0 (0x7f87147c5800) [pid = 1455] [serial = 3] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/fixed_height.html]
[task 2019-10-18T03:53:36.216Z] 03:53:36     INFO - GECKO(1159) | --DOCSHELL 0x7f2f06f21800 == 0 [pid = 1234] [id = {0fb5d6ea-6db1-455b-bddb-d4f00efb0ad0}] [url = about:newtab]
[task 2019-10-18T03:53:36.217Z] 03:53:36     INFO - GECKO(1159) | --DOMWINDOW == 1 (0x7f2f06f952e0) [pid = 1234] [serial = 4] [outer = (nil)] [url = about:newtab]
[task 2019-10-18T03:53:36.223Z] 03:53:36     INFO - GECKO(1159) | --DOMWINDOW == 0 (0x7f2f06f45c00) [pid = 1234] [serial = 6] [outer = (nil)] [url = about:newtab]
[task 2019-10-18T03:53:43.520Z] 03:53:43     INFO - GECKO(1159) | --DOMWINDOW == 11 (0x7f81646a7400) [pid = 1159] [serial = 13] [outer = (nil)] [url = about:blank]
[task 2019-10-18T03:53:43.520Z] 03:53:43     INFO - GECKO(1159) | --DOMWINDOW == 10 (0x7f816b4d5400) [pid = 1159] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2019-10-18T03:53:45.732Z] 03:53:45     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1387
[task 2019-10-18T03:53:45.888Z] 03:53:45     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1414
[task 2019-10-18T03:53:45.989Z] 03:53:45     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1353
[task 2019-10-18T03:53:46.090Z] 03:53:46     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1286
[task 2019-10-18T03:53:46.106Z] 03:53:46     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1315
[task 2019-10-18T03:53:46.202Z] 03:53:46     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1455
[task 2019-10-18T03:53:46.378Z] 03:53:46     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1234
[task 2019-10-18T03:53:46.748Z] 03:53:46     INFO - GECKO(1159) | ++DOMWINDOW == 2 (0x7f0641354000) [pid = 1481] [serial = 2] [outer = 0x7f0641226f20]
[task 2019-10-18T03:53:48.213Z] 03:53:48     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1212
[task 2019-10-18T03:53:50.668Z] 03:53:50     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1481
[task 2019-10-18T03:55:57.941Z] 03:55:57     INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-18T03:55:57.941Z] 03:55:57     INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/tools/profiler/tests/browser/browser_test_feature_ipcmessages.js:49 - TypeError: Assert is null
[task 2019-10-18T03:55:57.941Z] 03:55:57     INFO - Stack trace:
[task 2019-10-18T03:55:57.941Z] 03:55:57     INFO - test_profile_feature_ipcmessges/<@chrome://mochitests/content/browser/tools/profiler/tests/browser/browser_test_feature_ipcmessages.js:49:7
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:135:24
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - async*test_profile_feature_ipcmessges@chrome://mochitests/content/browser/tools/profiler/tests/browser/browser_test_feature_ipcmessages.js:30:26
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - Tester_execTest/<@chrome://mochikit/content/browser-test.js:1067:34
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1102:11
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:924:14
[task 2019-10-18T03:55:57.942Z] 03:55:57     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-10-18T03:56:03.984Z] 03:56:03     INFO - GECKO(1159) | Completed ShutdownLeaks collections in process 1159

Comment 1

[BugBot [:suhaib / :marco]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2019-10-14&endday=2019-10-20&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2019-11-04&endday=2019-11-10&tree=all

Comment 4

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 5

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293015627&repo=mozilla-central&lineNumber=6189

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform breakdown:

• windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-03-09&endday=2020-03-15&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform breakdown:

• windows10-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 9

[Intermittent Failures Robot]

14 failures in 5015 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• autoland: 11
• try: 1

Platform breakdown:

• windows10-64: 14

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-03-30&endday=2020-04-05&tree=all

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5
• mozilla-beta: 2
• try: 1

Platform breakdown:

• windows10-64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 11

[Intermittent Failures Robot]

16 failures in 803 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 15
• mozilla-central: 1

Platform breakdown:

• windows10-64: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-16&endday=2020-04-16&tree=all

Comment 12

[Cristina Coroiu [:ccoroiu]]

This bug has 35 failures in the last 7 days, on windows10-64 platform, asan build type.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=298101272&repo=autoland&lineNumber=5738

Log snippet:
[task 2020-04-17T14:43:58.602Z] 14:43:58 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | IPC profile markers were recorded for the content process' main thread when the IPCMessages feature was turned on. - 316 > 0 -
[task 2020-04-17T14:43:58.602Z] 14:43:58 INFO - Now open a tab without profiling IPC messages.
[task 2020-04-17T14:43:58.602Z] 14:43:58 INFO - Buffered messages logged at 14:30:28
[task 2020-04-17T14:43:58.602Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 9
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Buffered messages logged at 14:31:58
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 8
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Buffered messages logged at 14:33:28
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 7
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Buffered messages logged at 14:34:58
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 6
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Buffered messages logged at 14:36:28
[task 2020-04-17T14:43:58.603Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 5
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Buffered messages logged at 14:37:58
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 4
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Buffered messages logged at 14:39:28
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Buffered messages logged at 14:40:58
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Buffered messages logged at 14:42:28
[task 2020-04-17T14:43:58.604Z] 14:43:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - Buffered messages finished
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Test timed out -
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - GECKO(676) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - GECKO(676) | MEMORY STAT | vsize 19406055MB | vsizeMaxContiguous 66751250MB | residentFast 1503MB
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - TEST-OK | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | took 900326ms
[task 2020-04-17T14:43:58.605Z] 14:43:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-17T14:43:58.606Z] 14:43:58 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Found a tab after previous test timed out: about:blank -
[task 2020-04-17T14:43:58.606Z] 14:43:58 INFO - checking window state

Gerald, can you please take a look at this? Thank you

Comment 13

[Intermittent Failures Robot]

41 failures in 4528 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #37 most frequent failure this week.

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

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

Repository breakdown:

• try: 2
• autoland: 32
• mozilla-central: 6
• mozilla-beta: 1

Platform breakdown:

• windows10-64: 41

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 14

[Andreea Pavel [:apavel]]

There are 57 total failures in the last 7 days on windows10-64 asan

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=298936578&repo=autoland&lineNumber=10052

[task 2020-04-22T23:53:27.684Z] 23:53:27 INFO - TEST-START | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js
[task 2020-04-23T00:08:15.273Z] 00:08:15 INFO - JavaScript error: resource://gre/modules/PlacesExpiration.jsm, line 894: TypeError: can't access property "createAsyncStatement", this._db is undefined
[task 2020-04-23T00:08:27.807Z] 00:08:27 INFO - TEST-INFO | started process screenshot
[task 2020-04-23T00:08:27.999Z] 00:08:27 INFO - TEST-INFO | screenshot: exit 0
[task 2020-04-23T00:08:28.000Z] 00:08:27 INFO - Buffered messages logged at 23:53:27
[task 2020-04-23T00:08:28.000Z] 00:08:28 INFO - Entering test bound test_profile_feature_ipcmessges
[task 2020-04-23T00:08:28.000Z] 00:08:28 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | The profiler is not currently active - true == true -
[task 2020-04-23T00:08:28.001Z] 00:08:28 INFO - Open a tab while profiling IPC messages.
[task 2020-04-23T00:08:28.001Z] 00:08:28 INFO - Buffered messages logged at 23:54:57
[task 2020-04-23T00:08:28.002Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 9
[task 2020-04-23T00:08:28.002Z] 00:08:28 INFO - Buffered messages logged at 23:56:27
[task 2020-04-23T00:08:28.003Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 8
[task 2020-04-23T00:08:28.003Z] 00:08:28 INFO - Buffered messages logged at 23:57:47
[task 2020-04-23T00:08:28.004Z] 00:08:28 INFO - Console message: [JavaScript Error: "Unknown Collection "main/messaging-experiments"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 137}]
[task 2020-04-23T00:08:28.004Z] 00:08:28 INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:137:5
[task 2020-04-23T00:08:28.004Z] 00:08:28 INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:373:13
[task 2020-04-23T00:08:28.005Z] 00:08:28 INFO - asyncget@resource://services-settings/RemoteSettingsClient.jsm:315:22
[task 2020-04-23T00:08:28.005Z] 00:08:28 INFO - asyncupdateRecipes@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:141:49
[task 2020-04-23T00:08:28.005Z] 00:08:28 INFO - setTimer/<@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:188:18
[task 2020-04-23T00:08:28.005Z] 00:08:28 INFO - TM_notify/</<@resource://gre/modules/UpdateTimerManager.jsm:257:36
[task 2020-04-23T00:08:28.005Z] 00:08:28 INFO - ChromeUtils::IdleDispatch handler*TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:255:25
[task 2020-04-23T00:08:28.006Z] 00:08:28 INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:290:7
[task 2020-04-23T00:08:28.006Z] 00:08:28 INFO -
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Buffered messages logged at 23:57:57
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 7
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Buffered messages logged at 23:59:27
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 6
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Buffered messages logged at 00:00:57
[task 2020-04-23T00:08:28.007Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 5
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Buffered messages logged at 00:02:27
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 4
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Buffered messages logged at 00:03:57
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Buffered messages logged at 00:05:27
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Buffered messages logged at 00:06:57
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - Buffered messages finished
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Test timed out -
[task 2020-04-23T00:08:28.008Z] 00:08:28 INFO - GECKO(11328) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2020-04-23T00:08:28.009Z] 00:08:28 INFO - GECKO(11328) | MEMORY STAT | vsize 19406052MB | vsizeMaxContiguous 69104525MB | residentFast 1502MB
[task 2020-04-23T00:08:28.009Z] 00:08:28 INFO - TEST-OK | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | took 900304ms
[task 2020-04-23T00:08:28.009Z] 00:08:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-23T00:08:28.009Z] 00:08:28 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Found a tab after previous test timed out: about:blank -

Gerald are there updates here?

Comment 15

[Intermittent Failures Robot]

16 failures in 1127 pushes (0.014 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16

Platform breakdown:

• windows10-64: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-22&endday=2020-04-22&tree=all

Comment 16

[Intermittent Failures Robot]

17 failures in 999 pushes (0.017 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• try: 2
• mozilla-central: 1

Platform breakdown:

• windows10-64: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-23&endday=2020-04-23&tree=all

Comment 17

[Intermittent Failures Robot]

60 failures in 5582 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #33 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-beta: 3
• autoland: 54
• try: 2
• mozilla-central: 1

Platform breakdown:

• windows10-64: 60

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 18

[Julien Wajsberg [:julienw]]

The relevant error from the initial comment seems to be:

[task 2019-10-18T03:55:57.941Z] 03:55:57 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_ipcmessages.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/tools/profiler/tests/browser/browser_test_feature_ipcmessages.js:49 - TypeError: Assert is null

However we don't see this in the recent logs I looked at, so I think this is a red herring.
Instead we usually see a timeout for the second part of the test, where we restart the profiler with different features. I don't know why because we don't have many more error logs.

There's an error about Places:
[task 2020-04-25T12:00:37.947Z] 12:00:37 INFO - JavaScript error: resource://gre/modules/PlacesExpiration.jsm, line 894: TypeError: can't access property "createAsyncStatement", this._db is undefined
It doesn't seem related to our problem, I think, but it triggers a screenshot, and as a result we don't have a screenshot for our timeout sadly.

Something else I realized: when one test fails, the profiler isn't stopped, which has an impact on the following tests. Should we register a cleanup task to always stop it at the end of a test?

NI Greg who might have more ideas.
Also NI Marco for the Places issue: it would help us tremendously if this could be fixed!

Comment 19

[Greg Tatum [:gregtatum]]

Putting something to stop the profiler would probably be good, although I'm not sure the desired behavior on having 1 failing test in the suite, that should probably stop the rest of the run, right? So it may not matter that it doesn't clean up after itself.

As far as the error in the log, this is a bug happening not in our code, triggering a failure in our test because it was executed next. At least, that's how I read it.

Comment 20

[Marco Bonardo [:mak]]

I suspect something is initializing Places, that initializes PlacesExpiration, that starts up its timer https://searchfox.org/mozilla-central/rev/7fd1c1c34923ece7ad8c822bee062dd0491d64dc/toolkit/components/places/PlacesExpiration.jsm#484
When the timer notifies, it tries to use this._db, because it's the first consumer it will try to start the lazy getter. Likely at this point shutdown has begun and the getter fails and returns null?
I'd suggest to check this._shuttingDown in PEX_timerCallback before invoking this._getPagesStats and see what happens.

Comment 21

[Intermittent Failures Robot]

38 failures in 5423 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #44 most frequent failure this week.

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

Repository breakdown:

• autoland: 36
• mozilla-central: 2

Platform breakdown:

• windows10-64: 38

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 22

[Cosmin Sabou [:CosminS]]

Julien, any updates here? This is now on the disabled recommended list with 39 total failures in the last 7 days https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-27&endday=2020-05-04&tree=trunk&bug=1589568
and 161 total failures in the last 30 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-04&endday=2020-05-04&tree=trunk&bug=1589568
It fails only windows10-64 asan, can we disable on that platform until a fix is in place?

Comment 23

[Julien Wajsberg [:julienw]]

Putting something to stop the profiler would probably be good, although I'm not sure the desired behavior on having 1 failing test in the suite, that should probably stop the rest of the run, right? So it may not matter that it doesn't clean up after itself.

That's not what happens, other test files are run and they all fail because the profiler is still running. It's not a big deal by itself (the failure cause is clear) but it's not so clean :-)

Hey Cosmin, I'll invest some time today. I'd rather not disable the test for now. Thanks for pinging me!

Comment 24

[Julien Wajsberg [:julienw]]

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

I suspect something is initializing Places, that initializes PlacesExpiration, that starts up its timer https://searchfox.org/mozilla-central/rev/7fd1c1c34923ece7ad8c822bee062dd0491d64dc/toolkit/components/places/PlacesExpiration.jsm#484
When the timer notifies, it tries to use this._db, because it's the first consumer it will try to start the lazy getter. Likely at this point shutdown has begun and the getter fails and returns null?
I'd suggest to check this._shuttingDown in PEX_timerCallback before invoking this._getPagesStats and see what happens.

Ah, it would be surprising because the timer is canceled in https://searchfox.org/mozilla-central/rev/7fd1c1c34923ece7ad8c822bee062dd0491d64dc/toolkit/components/places/PlacesExpiration.jsm#499-502 though.
Oh, I have an idea: the timer is created in https://searchfox.org/mozilla-central/rev/7fd1c1c34923ece7ad8c822bee062dd0491d64dc/toolkit/components/places/PlacesExpiration.jsm#479-485
This means it's possible that we create the timer after we try to cancel it, if shutting down happens right away.

But here I doubt this is the reason: it appears after a few minutes after the start of the test...

Also this is surprising the problem appears only with our test :-)

Still looking..

Comment 25

[Julien Wajsberg [:julienw]]

Here is a try with some more diagnostics in the failing test: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d10e8656ba8ad413e94e8d302c56d2d0a420e903

Comment 26

[Marco Bonardo [:mak]]

(In reply to Julien Wajsberg [:julienw] from comment #24)

Ah, it would be surprising because the timer is canceled in https://searchfox.org/mozilla-central/rev/7fd1c1c34923ece7ad8c822bee062dd0491d64dc/toolkit/components/places/PlacesExpiration.jsm#499-502 though.

That's a good point. I pointed that out because in the past we had other cases of services running things after shutdown started.

But here I doubt this is the reason: it appears after a few minutes after the start of the test...

Places is initialized lazily at the first use (that maybe a visit or some other UI trying to figure out something about history), on init it fires a notification that initializes other components like expiration, so it's not necessarily impossible.

The other possibility would be that we just can't open the db, but that would mean either the profile folder is non accessible or somehow broken... that sounds less likely, but of course not impossible.

Comment 27

[Julien Wajsberg [:julienw]]

Attachment: Bug 1589568 - Always stop the profiler after browser tests

Comment 28

[Julien Wajsberg [:julienw]]

Attachment: Bug 1589568 - Add some more logs in an intermittent profiler test

Comment 29

[Julien Wajsberg [:julienw]]

Thanks Marco, I filed Bug 1635388 about that, with some more information about my latest thoughts after looking at the code.

I still think this is orthogonal to this problem, that's why I've opened another bug -- but I'm not sure...

Also I couldn't make it fail in the try, even with a lot of repeats. So I pushed a patch adding some more logs to the test, and I guess we'll see better when more intermittents come.

Comment 30

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/08110af8b1d4
Always stop the profiler after browser tests r=gregtatum
https://hg.mozilla.org/integration/autoland/rev/8fd0ee723ae1
Add some more logs in an intermittent profiler test r=gregtatum

Comment 31

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/08110af8b1d4
https://hg.mozilla.org/mozilla-central/rev/8fd0ee723ae1

Comment 32

[Julien Wajsberg [:julienw]]

From the new logs I see the problem is with opening a new tab. Not sure what's happening :/
We still see the error with Places (including for the next test that seems to times out too) but I don't know if that's a red herring or a real clue.

Comment 33

[Intermittent Failures Robot]

24 failures in 5276 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 15
• mozilla-central: 6
• try: 3

Platform breakdown:

• windows10-64: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-05-04&endday=2020-05-10&tree=all

Comment 34

[Intermittent Failures Robot]

23 failures in 5488 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 21
• mozilla-release: 1
• mozilla-central: 1

Platform breakdown:

• windows10-64: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 35

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1
• autoland: 2

Platform breakdown:

• windows10-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-05-18&endday=2020-05-24&tree=all

Comment 36

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 1
• mozilla-release: 2

Platform breakdown:

• windows10-64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 37

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1
• autoland: 4
• mozilla-beta: 2
• mozilla-central: 1

Platform breakdown:

• windows10-64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-06-01&endday=2020-06-07&tree=all

Comment 38

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 1
• autoland: 4
• mozilla-beta: 1
• mozilla-central: 1

Platform breakdown:

• windows10-64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-06-08&endday=2020-06-14&tree=all

Comment 39

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-release: 2
• mozilla-beta: 2

Platform breakdown:

• windows10-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-06-15&endday=2020-06-21&tree=all

Comment 40

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 2
• autoland: 6
• mozilla-central: 2

Platform breakdown:

• windows10-64: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-06-22&endday=2020-06-28&tree=all

Comment 41

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 2
• autoland: 2

Platform breakdown:

• windows10-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-06-29&endday=2020-07-05&tree=all

Comment 42

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5

Platform breakdown:

• windows10-64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 43

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6
• mozilla-central: 1

Platform breakdown:

• windows10-64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-07-13&endday=2020-07-19&tree=all

Comment 44

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• try: 1
• mozilla-esr78: 1
• mozilla-release: 1

Platform breakdown:

• windows10-64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-07-20&endday=2020-07-26&tree=all

Comment 45

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 2

Platform breakdown:

• windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 46

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-09-28&endday=2020-10-04&tree=all

Comment 47

[Julien Wajsberg [:julienw]]

This became very quiet. Recent failures are only in ESR78, and they're very few, so I'm inclined to think this has been fixed.

Tentatively closing this.

Comment 48

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1589568&startday=2020-11-02&endday=2020-11-08&tree=all

Comment 49

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1589568&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 50

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1589568&startday=2020-12-07&endday=2020-12-13&tree=all

Comment 51

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1589568&startday=2021-01-04&endday=2021-01-10&tree=all