1649493 - Intermittent toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js | run_test - [run_test : 40] null != null

Status: RESOLVED FIXED

(Firefox :: Search, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=308026463&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aAZeBNG9SHKp6mEATcwmVA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-06-30T14:58:53.129Z] 14:58:53 INFO - PID 3140 | console.debug: SearchService: "_loadEnginesLegacy: done using existing cache"
[task 2020-06-30T14:58:53.129Z] 14:58:53 WARNING - TEST-UNEXPECTED-FAIL | xpcshell-legacyconfig.ini:toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js | run_test - [run_test : 40] null != null
[task 2020-06-30T14:58:53.129Z] 14:58:53 INFO - Z:/task_1593524360/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js:run_test:40
[task 2020-06-30T14:58:53.129Z] 14:58:53 INFO - Z:\task_1593524360\build\tests\xpcshell\head.js:_do_main:248
[task 2020-06-30T14:58:53.129Z] 14:58:53 INFO - Z:\task_1593524360\build\tests\xpcshell\head.js:_execute_test:577
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - -e:null:1
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - exiting test
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - _abort_failed_test@Z:\task_1593524360\build\tests\xpcshell\head.js:833:20
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - do_report_result@Z:\task_1593524360\build\tests\xpcshell\head.js:934:5
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - Assert<@Z:\task_1593524360\build\tests\xpcshell\head.js:73:21
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - notEqual@resource://testing-common/Assert.jsm:290:8
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - run_test@Z:/task_1593524360/build/tests/xpcshell/tests/toolkit/components/search/tests/xpcshell/test_remove_profile_engine.js:40:10
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - _do_main@Z:\task_1593524360\build\tests\xpcshell\head.js:248:6
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - _execute_test@Z:\task_1593524360\build\tests\xpcshell\head.js:577:5
[task 2020-06-30T14:58:53.130Z] 14:58:53 INFO - @-e:1:1
[task 2020-06-30T14:58:53.131Z] 14:58:53 INFO - exiting test
[task 2020-06-30T14:58:53.131Z] 14:58:53 INFO - PID 3140 | console.debug: SearchCache: "batchTask: Invalidating engine cache"
[task 2020-06-30T14:58:53.131Z] 14:58:53 INFO - PID 3140 | console.debug: SearchCache: "_buildCache: Writing to cache file."
[task 2020-06-30T14:58:53.131Z] 14:58:53 INFO - PID 3140 | console.debug: SearchCache: "_buildCache: cache file written to disk."
[task 2020-06-30T14:58:53.131Z] 14:58:53 INFO - <<<<<<<
[task 2020-06-30T14:58:53.151Z] 14:58:53 INFO - c:\users\task_1593524360\appdata\local\temp\xpc-profile-zbtqi0 could not be cleaned up.
[task 2020-06-30T14:58:53.151Z] 14:58:53 INFO - INFO | Result summary:
[task 2020-06-30T14:58:53.151Z] 14:58:53 INFO - INFO | Passed: 2158
[task 2020-06-30T14:58:53.151Z] 14:58:53 WARNING - INFO | Failed: 1
[task 2020-06-30T14:58:53.151Z] 14:58:53 WARNING - One or more unittests failed.
[task 2020-06-30T14:58:53.151Z] 14:58:53 INFO - INFO | Todo: 4
[task 2020-06-30T14:58:53.152Z] 14:58:53 INFO - INFO | Retried: 6
[task 2020-06-30T14:58:53.152Z] 14:58:53 INFO - SUITE-END | took 958s
[task 2020-06-30T14:58:53.152Z] 14:58:53 INFO - Node moz-http2 server shutting down ...
[task 2020-06-30T14:58:53.155Z] 14:58:53 INFO - Process stdout
[task 2020-06-30T14:58:53.155Z] 14:58:53 INFO - forked process without handler sent: [object Object]
[task 2020-06-30T14:58:53.155Z] 14:58:53 INFO - Process stderr
[task 2020-06-30T14:58:53.156Z] 14:58:53 INFO - (node:5488) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-06-30T14:58:53.156Z] 14:58:53 INFO - (node:5488) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-06-30T14:58:53.156Z] 14:58:53 INFO - (node:5488) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-06-30T14:58:53.156Z] 14:58:53 INFO - (node:5488) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-06-30T14:58:53.243Z] 14:58:53 ERROR - Return code: 1
[task 2020-06-30T14:58:53.243Z] 14:58:53 INFO - TinderboxPrint: xpcshell-xpcshell<br/>2158/<em class="testfail">1</em>/4
[task 2020-06-30T14:58:53.243Z] 14:58:53 WARNING - # TBPL FAILURE #
[task 2020-06-30T14:58:53.243Z] 14:58:53 WARNING - setting return code to 2
[task 2020-06-30T14:58:53.243Z] 14:58:53 WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE

Comment 1

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

Is this a regression from bug 1647320?

Comment 2

[Mark Banner (:standard8)]

Think I've spotted this. The previous bug made it so that cache updates after init could be delayed.

So I think what was happening in this test, is that it was initialising the search service then adding an engine and waiting for the cache then going through a reInit. The waiting for the cache was catching the first cache update due to init(), but a second one for the engine had been kicked off after (I think), so we didn't properly wait for that. As a result, the reInit happened with an out-of-date cache.

I'm testing this on try at the moment.

Comment 3

[Mark Banner (:standard8)]

Attachment: Bug 1649493 - Fix intermittent failure in test_remove_profile_engine.js - ensure we correctly wait for the cache to save. r?daleharvey!

Comment 4

[Intermittent Failures Robot]

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

This is the #43 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:

• autoland: 23
• mozilla-central: 9
• try: 6
• comm-central: 1

Platform breakdown:

• windows7-32-shippable: 27
• windows7-32: 7
• windows7-32-devedition: 3
• windows10-64-shippable: 2

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

Comment 5

[Intermittent Failures Robot]

15 failures in 849 pushes (0.018 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• try: 1

Platform breakdown:

• windows7-32-shippable: 15

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

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ccd521ebc464
Fix intermittent failure in test_remove_profile_engine.js - ensure we correctly wait for the cache to save. r=daleharvey

Comment 7

[Andreea Pavel [:apavel]]

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

Comment 8

[Intermittent Failures Robot]

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

This is the #36 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:

• autoland: 31
• try: 8
• comm-central: 2
• mozilla-central: 3

Platform breakdown:

• windows7-32-shippable: 37
• windows7-32-devedition: 4
• windows7-32: 3

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