Closed Bug 1633363 Opened 5 years ago Closed 5 years ago

Intermittent xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 265] A promise chain failed to handle a rejection: `webext_storage::teardown` didn't run on the background thread - stack: handleError@ExtensionSto

Categories

(WebExtensions :: Storage, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1633943

People

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

Details

(Keywords: intermittent-failure)

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


[task 2020-04-27T09:36:33.779Z] 09:36:33     INFO -  TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_proxy_socks.js
[task 2020-04-27T09:36:33.779Z] 09:36:33     INFO -  TEST-SKIP | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_ext_proxy_socks.js | took 0ms
[task 2020-04-27T09:36:33.787Z] 09:36:33     INFO -  TEST-START | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_upgrade.js
[task 2020-04-27T09:36:34.521Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_upgrade.js | took 734ms
[task 2020-04-27T09:36:34.525Z] 09:36:34     INFO -  Retrying tests that failed when run in parallel.
[task 2020-04-27T09:36:34.532Z] 09:36:34     INFO -  TEST-START | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js
[task 2020-04-27T09:36:34.660Z] 09:36:34  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | xpcshell return code: 0
[task 2020-04-27T09:36:34.661Z] 09:36:34     INFO -  TEST-INFO took 128ms
[task 2020-04-27T09:36:34.662Z] 09:36:34     INFO -  >>>>>>>
[task 2020-04-27T09:36:34.662Z] 09:36:34     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-04-27T09:36:34.662Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  running event loop
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | Starting check_remote
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - false == false
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | check_remote - [check_remote : 1] testing from extension process - true == true
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | Starting test_storage_sync_service
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test test_storage_sync_service pending (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-04-27T09:36:34.663Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 46] `set` should notify listeners about changes - [{"bye":{"newValue":"\\"adiós\\""},"hi":{"newValue":"\\"hello! 💖\\""}}] deepEqual [{"hi":{"newValue":"\\"hello! 💖\\""},"bye":{"newValue":"\\"adiós\\""}}]
[task 2020-04-27T09:36:34.665Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 60] `set` should not return a value - true == true
[task 2020-04-27T09:36:34.666Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 69] `get` should not notify listeners - [] deepEqual []
[task 2020-04-27T09:36:34.667Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 70] `get` with key should return value - {"hi":"hello! 💖"} deepEqual {"hi":"hello! 💖"}
[task 2020-04-27T09:36:34.667Z] 09:36:34     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 79] `get` without a key should return all values - {"bye":"adiós","hi":"hello! 💖"} deepEqual {"hi":"hello! 💖","bye":"adiós"}
[task 2020-04-27T09:36:34.668Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2020-04-27T09:36:34.668Z] 09:36:34     INFO -  (xpcshell/head.js) | test test_storage_sync_service finished (2)
[task 2020-04-27T09:36:34.668Z] 09:36:34     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (1)
[task 2020-04-27T09:36:34.668Z] 09:36:34     INFO -  exiting test
[task 2020-04-27T09:36:34.668Z] 09:36:34     INFO -  PID 23687 | WARNING: A blocker encountered an error while we were waiting.
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 |           Blocker:  StorageSyncService: shutdown
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 |           Phase: profile-change-teardown
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 |           State: (none)
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 | WARNING: [Exception... "`webext_storage::teardown` didn't run on the background thread"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://gre/modules/ExtensionStorageComponents.jsm :: handleError :: line 106"  data: no]
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 | WARNING: handleError@resource://gre/modules/ExtensionStorageComponents.jsm:106:31
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 | observe@resource://gre/modules/AsyncShutdown.jsm:554:16
[task 2020-04-27T09:36:34.669Z] 09:36:34     INFO -  PID 23687 | _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:655:19
[task 2020-04-27T09:36:34.670Z] 09:36:34     INFO -  PID 23687 | @-e:1:1
[task 2020-04-27T09:36:34.670Z] 09:36:34     INFO -  PID 23687 | JavaScript error: resource://gre/modules/ExtensionStorageComponents.jsm, line 106: NS_ERROR_UNEXPECTED: `webext_storage::teardown` didn't run on the background thread
[task 2020-04-27T09:36:34.674Z] 09:36:34  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/components/extensions/test/xpcshell/test_StorageSyncService.js | test_storage_sync_service - [test_storage_sync_service : 265] A promise chain failed to handle a rejection: `webext_storage::teardown` didn't run on the background thread - stack: handleError@resource://gre/modules/ExtensionStorageComponents.jsm:106:31
[task 2020-04-27T09:36:34.674Z] 09:36:34     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:554:16
[task 2020-04-27T09:36:34.675Z] 09:36:34     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:655:19
[task 2020-04-27T09:36:34.675Z] 09:36:34     INFO -  @-e:1:1
[task 2020-04-27T09:36:34.676Z] 09:36:34     INFO -  Rejection date: Mon Apr 27 2020 09:36:34 GMT+0000 (Coordinated Universal Time) - false == true
[task 2020-04-27T09:36:34.677Z] 09:36:34     INFO -  resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-04-27T09:36:34.678Z] 09:36:34     INFO -  /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:664
[task 2020-04-27T09:36:34.678Z] 09:36:34     INFO -  -e:null:1
[task 2020-04-27T09:36:34.678Z] 09:36:34     INFO -  exiting test
[task 2020-04-27T09:36:34.678Z] 09:36:34     INFO -  PID 23687 | JavaScript error: /builds/worker/workspace/build/tests/xpcshell/head.js, line 787: NS_ERROR_ABORT:
[task 2020-04-27T09:36:34.679Z] 09:36:34     INFO -  <<<<<<<
[task 2020-04-27T09:36:34.679Z] 09:36:34     INFO -  INFO | Result summary:
[task 2020-04-27T09:36:34.679Z] 09:36:34     INFO -  INFO | Passed: 1141
[task 2020-04-27T09:36:34.680Z] 09:36:34  WARNING -  INFO | Failed: 1
[task 2020-04-27T09:36:34.680Z] 09:36:34  WARNING -  One or more unittests failed.
[task 2020-04-27T09:36:34.680Z] 09:36:34     INFO -  INFO | Todo: 4
[task 2020-04-27T09:36:34.681Z] 09:36:34     INFO -  INFO | Retried: 1
[task 2020-04-27T09:36:34.681Z] 09:36:34     INFO -  SUITE-END | took 482s
[task 2020-04-27T09:36:34.681Z] 09:36:34     INFO -  Node moz-http2 server shutting down ...
[task 2020-04-27T09:36:34.685Z] 09:36:34     INFO -  Process stdout
[task 2020-04-27T09:36:34.685Z] 09:36:34     INFO -  forked process without handler sent: [object Object]
[task 2020-04-27T09:36:34.686Z] 09:36:34     INFO -  Process stderr
[task 2020-04-27T09:36:34.686Z] 09:36:34     INFO -  (node:1131) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-04-27T09:36:34.687Z] 09:36:34     INFO -  (node:1131) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-04-27T09:36:34.687Z] 09:36:34     INFO -  (node:1131) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-04-27T09:36:34.688Z] 09:36:34     INFO -  (node:1131) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 window_update listeners added. Use emitter.setMaxListeners() to increase limit
[task 2020-04-27T09:36:34.688Z] 09:36:34     INFO -  http3Server server shutting down ...
[task 2020-04-27T09:36:34.845Z] 09:36:34    ERROR - Return code: 1
[task 2020-04-27T09:36:34.846Z] 09:36:34     INFO - TinderboxPrint: xpcshell-xpcshell<br/>1141/<em class="testfail">1</em>/4
[task 2020-04-27T09:36:34.846Z] 09:36:34  WARNING - # TBPL FAILURE #
[task 2020-04-27T09:36:34.846Z] 09:36:34  WARNING - setting return code to 2
[task 2020-04-27T09:36:34.846Z] 09:36:34  WARNING - The xpcshell suite: xpcshell ran with return status: FAILURE
[task 2020-04-27T09:36:34.846Z] 09:36:34     INFO - Running post-action listener: _package_coverage_data
[task 2020-04-27T09:36:34.847Z] 09:36:34     INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-27T09:36:34.847Z] 09:36:34     INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-27T09:36:34.847Z] 09:36:34     INFO - [mozharness: 2020-04-27 09:36:34.847702Z] Finished run-tests step (success)
[task 2020-04-27T09:36:34.848Z] 09:36:34     INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-27T09:36:34.909Z] 09:36:34     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2020-04-27T09:36:34.913Z] 09:36:34     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 93.21042510121457}, {"name": "io_write_bytes", "value": 13699842048}, {"name": "io.read_bytes", "value": 109850624}, {"name": "io_write_time", "value": 858916}, {"name": "io_read_time", "value": 1172}], "extraOptions": ["e10s", "taskcluster-m5.large"], "name": "xpcshell.xpcshell.overall"}, {"subtests": [{"name": "time", "value": 0.028561830520629883}], "name": "xpcshell.xpcshell.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 10.36299180984497}, {"name": "cpu_percent", "value": 50.44444444444444}], "name": "xpcshell.xpcshell.install"}, {"subtests": [{"name": "time", "value": 0.016371965408325195}], "name": "xpcshell.xpcshell.stage-files"}, {"subtests": [{"name": "time", "value": 484.6385622024536}, {"name": "cpu_percent", "value": 94.19989648033128}], "name": "xpcshell.xpcshell.run-tests"}]}
[task 2020-04-27T09:36:34.914Z] 09:36:34     INFO - Total resource usage - Wall time: 495s; CPU: 94.0%; Read bytes: 109850624; Write bytes: 13699842048; Read time: 1172; Write time: 858916
[task 2020-04-27T09:36:34.915Z] 09:36:34     INFO - TinderboxPrint: CPU usage<br/>94.2%
[task 2020-04-27T09:36:34.915Z] 09:36:34     INFO - TinderboxPrint: I/O read bytes / time<br/>109,850,624 / 1,172
[task 2020-04-27T09:36:34.916Z] 09:36:34     INFO - TinderboxPrint: I/O write bytes / time<br/>13,699,842,048 / 858,916
[task 2020-04-27T09:36:34.916Z] 09:36:34     INFO - TinderboxPrint: CPU idle<br/>63.1 (6.4%)
[task 2020-04-27T09:36:34.916Z] 09:36:34     INFO - TinderboxPrint: CPU system<br/>197.9 (20.0%)
[task 2020-04-27T09:36:34.917Z] 09:36:34     INFO - TinderboxPrint: CPU user<br/>719.0 (72.8%)
[task 2020-04-27T09:36:34.917Z] 09:36:34     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-04-27T09:36:34.918Z] 09:36:34     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-27T09:36:34.918Z] 09:36:34     INFO - install - Wall time: 10s; CPU: 50.0%; Read bytes: 2330624; Write bytes: 18919424; Read time: 28; Write time: 12936
[task 2020-04-27T09:36:34.918Z] 09:36:34     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-27T09:36:34.920Z] 09:36:34     INFO - run-tests - Wall time: 485s; CPU: 94.0%; Read bytes: 55001088; Write bytes: 13673349120; Read time: 656; Write time: 840860
[task 2020-04-27T09:36:34.987Z] 09:36:34  WARNING - returning nonzero exit status 2
Assignee: nobody → lina
Status: NEW → ASSIGNED
Component: General → Storage

I think this was fixed by bug 1633943, which got rid of the extra Arc::clone call in teardown! \o/

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.