Perma JavaScript error: resource://gre/modules/addons/XPIProvider.jsm, line 2600: TypeError: addon is null; can't access its "seen" property when Gecko 65 merges to Beta on 2018-12-03

RESOLVED DUPLICATE of bug 1506310

Status

defect
P5
normal
RESOLVED DUPLICATE of bug 1506310
6 months ago
6 months ago

People

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

Tracking

({intermittent-failure})

Version 3
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr60 unaffected, firefox63 unaffected, firefox64 unaffected, firefox65 affected)

Details

Attachments

(2 attachments)

Reporter

Description

6 months ago
treeherder
Filed by: dluca [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=211092052&repo=try

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

Calling ['/home/cltbld/tasks/task_1541943730/build/venv/bin/python', u'/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.py', u'--test', 'raptor-assorted-dom', u'--binary', '/home/cltbld/tasks/task_1541943730/build/application/firefox/firefox', u'--app', u'firefox', u'--symbolsPath', 'https://queue.taskcluster.net/v1/task/FXpnaBbjSGKJJ5s7R73eZw/artifacts/public/build/target.crashreporter-symbols.zip', u'--log-tbpl-level=debug'] with output_timeout 3600
05:54:51     INFO -  raptor-main raptor-start
05:54:51     INFO -  raptor-main received command line arguments: Namespace(app='firefox', binary='/home/cltbld/tasks/task_1541943730/build/application/firefox/firefox', gecko_profile=False, gecko_profile_entries=None, gecko_profile_interval=None, host='127.0.0.1', is_release_build=False, log_errorsummary=None, log_grouped=None, log_html=None, log_mach=None, log_mach_buffer=None, log_mach_level=None, log_mach_screenshot=None, log_mach_verbose=None, log_raw=None, log_raw_level=None, log_tbpl=None, log_tbpl_buffer=None, log_tbpl_compact=None, log_tbpl_level='debug', log_unittest=None, log_xunit=None, obj_path=None, page_cycles=None, page_timeout=None, run_local=False, symbols_path='https://queue.taskcluster.net/v1/task/FXpnaBbjSGKJJ5s7R73eZw/artifacts/public/build/target.crashreporter-symbols.zip', test='raptor-assorted-dom')
05:54:51     INFO -  raptor-manifest /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.ini
05:54:51     INFO -  raptor-main raptor tests scheduled to run:
05:54:51     INFO -  raptor-main raptor-assorted-dom-firefox
05:54:51     INFO -  raptor-main Merging profile: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/profile_data/base
05:54:51     INFO -  raptor-main Merging profile: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/profile_data/common
05:54:51     INFO -  raptor-main Merging profile: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/profile_data/perf
05:54:51     INFO -  raptor-main Merging profile: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/profile_data/raptor
05:54:51     INFO -  raptor-main creating browser runner using mozrunner
05:54:51     INFO -  raptor-main raptor config: {'binary': '/home/cltbld/tasks/task_1541943730/build/application/firefox/firefox', 'symbols_path': 'https://queue.taskcluster.net/v1/task/FXpnaBbjSGKJJ5s7R73eZw/artifacts/public/build/target.crashreporter-symbols.zip', 'app': 'firefox', 'gecko_profile_entries': None, 'run_local': False, 'platform': 'linux', 'host': '127.0.0.1', 'is_release_build': False, 'gecko_profile_interval': None, 'processor': 'x86_64', 'gecko_profile': False, 'obj_path': None}
05:54:51     INFO -  raptor-control-server raptor control server running on port 34722...
05:54:51     INFO -  raptor-main starting raptor test: raptor-assorted-dom-firefox
05:54:51     INFO -  raptor-main test settings: {'alert_threshold': '2.0', 'gecko_profile_entries': '2000000', 'here': '/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/tests', 'path': '/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/tests/raptor-assorted-dom-firefox', 'gecko_profile_interval': '1', 'unit': 'ms', 'ancestor-manifest': '/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.ini', 'name': 'raptor-assorted-dom-firefox', 'type': 'benchmark', 'page_cycles': '10', 'apps': 'firefox', 'test_url': 'http://<host>:<port>/assorted-dom/assorted/driver.html?raptor', 'manifest': '/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/tests/raptor-assorted-dom.ini', 'page_timeout': '60000', 'expected': 'pass', 'lower_is_better': 'true', 'relpath': 'tests/raptor-assorted-dom-firefox'}
05:54:51     INFO -  raptor-main raptor config: {'binary': '/home/cltbld/tasks/task_1541943730/build/application/firefox/firefox', 'symbols_path': 'https://queue.taskcluster.net/v1/task/FXpnaBbjSGKJJ5s7R73eZw/artifacts/public/build/target.crashreporter-symbols.zip', 'app': 'firefox', 'gecko_profile_entries': None, 'run_local': False, 'platform': 'linux', 'host': '127.0.0.1', 'is_release_build': False, 'gecko_profile_interval': None, 'processor': 'x86_64', 'gecko_profile': False, 'obj_path': None}
05:54:51     INFO -  raptor-benchmark bench_dir contains:
05:54:51     INFO -  raptor-benchmark ['unity-webgl', 'webaudio', 'assorted-dom', 'MotionMark', 'resources', 'wasm-godot', 'six-speed', 'StyleBench', 'wasm-misc', 'ARES-6', 'SunSpider', 'Speedometer']
05:54:51     INFO -  raptor-benchmark writing wptserve headers file
05:54:51     INFO -  raptor-benchmark wrote wpt headers file: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/tests/webkit/PerformanceTests/__dir__.headers
05:54:51     INFO -  raptor-benchmark starting webserver on '127.0.0.1:39185'
05:54:51     INFO -  raptor-benchmark serving benchmarks from here: /home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/tests/webkit/PerformanceTests
05:54:51     INFO -  raptor-gen-test-config writing test settings into background js, so webext can get it
05:54:51     INFO -  raptor-gen-test-config finished writing test config to /home/cltbld/tasks/task_1541943730/build/tests/raptor/webext/raptor/auto_gen_test_config.js
05:54:51     INFO -  raptor-main installing webext /home/cltbld/tasks/task_1541943730/build/tests/raptor/webext/raptor
05:54:51     INFO -  raptor-main starting firefox
05:54:51     INFO -  Application command: /home/cltbld/tasks/task_1541943730/build/application/firefox/firefox -profile /tmp/tmpA84azM.mozrunner
05:54:51     INFO -  PID 3540 | 1541944491632	addons.xpi-utils	WARN	Add-on raptor@mozilla.org is not correctly signed.
05:54:51     INFO -  PID 3540 | 1541944491632	addons.xpi-utils	WARN	Add-on raptor@mozilla.org is not correctly signed.
05:54:51     INFO -  PID 3540 | 1541944491632	addons.xpi-utils	WARN	addMetadata: Add-on raptor@mozilla.org is invalid: Error: Extension raptor@mozilla.org is not correctly signed(resource://gre/modules/addons/XPIDatabase.jsm:2418:17) JS Stack trace: addMetadata@XPIDatabase.jsm:2418:17
05:54:52    ERROR -  PID 3540 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm, line 2600: TypeError: addon is null; can't access its "seen" property
06:05:18     INFO -  raptor-main application timed out after 630 seconds
06:05:34     INFO -  raptor-main removing webext /home/cltbld/tasks/task_1541943730/build/tests/raptor/webext/raptor
06:05:34    ERROR -  Traceback (most recent call last):
06:05:34     INFO -    File "/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.py", line 527, in <module>
06:05:34     INFO -      main()
06:05:34     INFO -    File "/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.py", line 497, in main
06:05:34     INFO -      raptor.run_test(next_test, timeout=int(next_test['page_timeout']))
06:05:34     INFO -    File "/home/cltbld/tasks/task_1541943730/build/tests/raptor/raptor/raptor.py", line 342, in run_test
06:05:34     INFO -      self.profile.addons.remove_addon(webext_id)
06:05:34     INFO -    File "/home/cltbld/tasks/task_1541943730/build/venv/lib/python2.7/site-packages/mozprofile/addons.py", line 329, in remove_addon
06:05:34     INFO -      path = self.get_addon_path(addon_id)
06:05:34     INFO -    File "/home/cltbld/tasks/task_1541943730/build/venv/lib/python2.7/site-packages/mozprofile/addons.py", line 108, in get_addon_path
06:05:34     INFO -      raise IOError('Add-on not found: %s' % addon_id)
06:05:34     INFO -  IOError: Add-on not found: raptor@mozilla.org
06:05:34    ERROR - Return code: 1
06:05:34  WARNING - setting return code to 1
06:05:34 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
06:05:34     INFO - copying raptor results to upload dir:
06:05:34     INFO - /home/cltbld/tasks/task_1541943730/build/blobber_upload_dir/perfherder-data.json
06:05:34     INFO - copying raptor results from /home/cltbld/tasks/task_1541943730/build/raptor.json to /home/cltbld/tasks/task_1541943730/build/blobber_upload_dir/perfherder-data.json
06:05:34 CRITICAL - Error copying results /home/cltbld/tasks/task_1541943730/build/raptor.json to upload dir /home/cltbld/tasks/task_1541943730/build/blobber_upload_dir/perfherder-data.json
06:05:34     INFO - [Errno 2] No such file or directory: u'/home/cltbld/tasks/task_1541943730/build/raptor.json'
06:05:34     INFO - Running post-action listener: _package_coverage_data
06:05:34     INFO - Running post-action listener: _resource_record_post_action
06:05:34     INFO - Running post-action listener: process_java_coverage_data
06:05:34     INFO - Running post-action listener: stop_device
06:05:34     INFO - [mozharness: 2018-11-11 14:05:34.187784Z] Finished run-tests step (success)
06:05:34     INFO - Running post-run listener: _resource_record_post_run
06:05:34     INFO - Total resource usage - Wall time: 653s; CPU: 1.0%; Read bytes: 234856448; Write bytes: 770195456; Read time: 968; Write time: 51144
06:05:34     INFO - TinderboxPrint: CPU usage<br/>0.6%
06:05:34     INFO - TinderboxPrint: I/O read bytes / time<br/>234,856,448 / 968
06:05:34     INFO - TinderboxPrint: I/O write bytes / time<br/>770,195,456 / 51,144
06:05:34     INFO - TinderboxPrint: CPU idle<br/>5,173.3 (99.3%)
06:05:34     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
06:05:34     INFO - install - Wall time: 11s; CPU: 13.0%; Read bytes: 32768; Write bytes: 18292736; Read time: 0; Write time: 56
06:05:34     INFO - run-tests - Wall time: 643s; CPU: 0.0%; Read bytes: 194584576; Write bytes: 751706112; Read time: 920; Write time: 51080
06:05:34  WARNING - returning nonzero exit status 1
Comment hidden (Intermittent Failures Robot)
This is from a central as Beta simulation:

https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=be8f1b86d8a2e95efffcc04bd96a0b7635130b76&selectedJob=211156344

05:55:27     INFO -  PID 3637 | 1541944527500	addons.xpi-utils	WARN	addMetadata: Add-on raptor@mozilla.org is invalid: Error: Extension raptor@mozilla.org is not correctly signed(resource://gre/modules/addons/XPIDatabase.jsm:2418:17) JS Stack trace: addMetadata@XPIDatabase.jsm:2418:17
05:55:28    ERROR -  PID 3637 | JavaScript error: resource://gre/modules/addons/XPIProvider.jsm, line 2600: TypeError: addon is null; can't access its "seen" property
06:05:53     INFO -  raptor-main application timed out after 630 seconds
06:06:09     INFO -  raptor-main removing webext /home/cltbld/tasks/task_1541938782/build/tests/raptor/webext/raptor
06:06:09    ERROR -  Traceback (most recent call last):
06:06:09     INFO -    File "/home/cltbld/tasks/task_1541938782/build/tests/raptor/raptor/raptor.py", line 527, in <module>
06:06:09     INFO -      main()
06:06:09     INFO -    File "/home/cltbld/tasks/task_1541938782/build/tests/raptor/raptor/raptor.py", line 497, in main
06:06:09     INFO -      raptor.run_test(next_test, timeout=int(next_test['page_timeout']))
06:06:09     INFO -    File "/home/cltbld/tasks/task_1541938782/build/tests/raptor/raptor/raptor.py", line 342, in run_test
06:06:09     INFO -      self.profile.addons.remove_addon(webext_id)
06:06:09     INFO -    File "/home/cltbld/tasks/task_1541938782/build/venv/lib/python2.7/site-packages/mozprofile/addons.py", line 329, in remove_addon
06:06:09     INFO -      path = self.get_addon_path(addon_id)
06:06:09     INFO -    File "/home/cltbld/tasks/task_1541938782/build/venv/lib/python2.7/site-packages/mozprofile/addons.py", line 108, in get_addon_path
06:06:09     INFO -      raise IOError('Add-on not found: %s' % addon_id)
06:06:09     INFO -  IOError: Add-on not found: raptor@mozilla.org
06:06:10    ERROR - Return code: 1
06:06:10  WARNING - setting return code to 1
06:06:10 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
06:06:10     INFO - copying raptor results to upload dir:
06:06:10     INFO - /home/cltbld/tasks/task_1541938782/build/blobber_upload_dir/perfherder-data.json
06:06:10     INFO - copying raptor results from /home/cltbld/tasks/task_1541938782/build/raptor.json to /home/cltbld/tasks/task_1541938782/build/blobber_upload_dir/perfherder-data.json
06:06:10 CRITICAL - Error copying results /home/cltbld/tasks/task_1541938782/build/raptor.json to upload dir /home/cltbld/tasks/task_1541938782/build/blobber_upload_dir/perfherder-data.json
06:06:10     INFO - [Errno 2] No such file or directory: u'/home/cltbld/tasks/task_1541938782/build/raptor.json'


Appears to be from bug 1499352,  https://hg.mozilla.org/mozilla-central/rev/7995ad2aa744#l1.102

Bob, can you please take a look?
Blocks: 1499352
Flags: needinfo?(bob)
Summary: JavaScript error: resource://gre/modules/addons/XPIProvider.jsm, line 2600: TypeError: addon is null; can't access its "seen" property → Perma JavaScript error: resource://gre/modules/addons/XPIProvider.jsm, line 2600: TypeError: addon is null; can't access its "seen" property when Gecko 65 merges to Beta on 2018-12-03
Assignee

Comment 3

6 months ago
I see you set the release-type to beta but the patch from bug 1499352 checked config.params['project'] in taskcluster/taskgraph/transforms/tests.py in setup_raptor which may not have been set to mozilla-beta during your push. I don't see it in the try_task_config.json.
Flags: needinfo?(bob)
With 'try' added to the list, there is a new failure message: https://treeherder.mozilla.org/#/jobs?repo=try&revision=efb6a1c6da3e23bcd205a3e781d32315328a0283&selectedJob=211216777
06:41:14     INFO - [mozharness: 2018-11-12 14:41:14.349310Z] Finished run-tests step (failed)
06:41:14    FATAL - Uncaught exception: Traceback (most recent call last):
06:41:14    FATAL -   File "/home/cltbld/tasks/task_1542032483/mozharness/mozharness/base/script.py", line 2089, in run
06:41:14    FATAL -     self.run_action(action)
06:41:14    FATAL -   File "/home/cltbld/tasks/task_1542032483/mozharness/mozharness/base/script.py", line 2028, in run_action
06:41:14    FATAL -     self._possibly_run_method(method_name, error_if_missing=True)
06:41:14    FATAL -   File "/home/cltbld/tasks/task_1542032483/mozharness/mozharness/base/script.py", line 1983, in _possibly_run_method
06:41:14    FATAL -     return getattr(self, method_name)()
06:41:14    FATAL -   File "/home/cltbld/tasks/task_1542032483/mozharness/mozharness/mozilla/testing/raptor.py", line 572, in run_tests
06:41:14    FATAL -     env=env)
06:41:14    FATAL -   File "/home/cltbld/tasks/task_1542032483/mozharness/mozharness/base/script.py", line 1397, in run_command
06:41:14    FATAL -     self.info("Copy/paste: %s" % subprocess.list2cmdline(command))
06:41:14    FATAL -   File "/usr/lib/python2.7/subprocess.py", line 617, in list2cmdline
06:41:14    FATAL -     needquote = (" " in arg) or ("\t" in arg) or not arg
06:41:14    FATAL - TypeError: argument of type 'bool' is not iterable
Assignee

Comment 5

6 months ago
From https://taskcluster-artifacts.net/TCEDiesgQeGHsMdFKk3MjQ/0/public/logs/live_backing.log the command that is being executed looks like:

06:41:14     INFO - Running command: ['/home/cltbld/tasks/task_1542032483/build/venv/bin/python', u'/home/cltbld/tasks/task_1542032483/build/tests/raptor/raptor/raptor.py', u'--test', 'raptor-tp6-1', u'--binary', '/home/cltbld/tasks/task_1542032483/build/application/firefox/firefox', u'--app', u'firefox', u'--is_release_build', True, u'--symbolsPath', 'https://queue.taskcluster.net/v1/task/Bd05jUOTQd2QOUTdIBHlPg/artifacts/public/build/target.crashreporter-symbols.zip', u'--log-tbpl-level=debug'] in /home/cltbld/tasks/task_1542032483/build

two things stand out. The argument was changed from --is-release-build to --is_release_build and it lists the value explicitly:

u'--is_release_build', True

I'll look into the callers to see where this occurred.
Flags: needinfo?(bob)
Assignee

Comment 6

6 months ago
Ok, found it:

https://searchfox.org/mozilla-central/source/testing/mozharness/mozharness/mozilla/testing/raptor.py#336-355

I set kw_options['is_release_build'] = self.config['is_release_build'] but later it does

        for key, value in kw_options.items():
            options.extend(['--%s' % key, value])

which accounts for the two things in comment 5.

I think the "approved" approach to this would be to:

a) not put is_release_build in the kw_options at all, and
b) handle the is_release_build the same way that the code_coverage is handled, that is

        if self.config.get('is_release_build', False):
            options.extend(['--is-release-build'])

rwood: Sound right to you?
Flags: needinfo?(rwood)
Assignee

Comment 7

6 months ago
aryx: I think rwood is off today for Armistice day, but I think this will fix it. Could you do another attempt with this patch to confirm?
Assignee: nobody → bob
Flags: needinfo?(bob) → needinfo?(aryx.bugmail)
Attachment #9024476 - Flags: review?(rwood)
Assignee

Comment 10

6 months ago
aryx: My run was green but yours was orange. I didn't see that you included the patch to force detection of the try project which means it didn't include the --is-release-build argument.

Updated

6 months ago
Attachment #9024476 - Flags: review?(rwood) → review+
(In reply to Bob Clary [:bc:] from comment #6)
> 
> rwood: Sound right to you?

Yep thanks :bc
Flags: needinfo?(rwood)

Comment 12

6 months ago
Pushed by bclary@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ee9695250526
properly handle is_release_build configuration in mozharness.mozilla.testing.raptor.Raptor.raptor_options, r=rwood.

Comment 13

6 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/ee9695250526
Status: NEW → RESOLVED
Last Resolved: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
Assignee

Comment 14

6 months ago
apavel: Can you confirm that we are ok now?
Flags: needinfo?(apavel)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla65 → ---
Assignee

Comment 16

6 months ago
Again I think you are hitting the fact that the code to add the --is-release-build argument only detects the project mozilla-beta. If you add that hack to do the same for try projects it should work I think. We could also try to get the taskcluster folks to support the release_type for us, but that is more involved. Let me know if that is a requirement.
Assignee

Comment 17

6 months ago
I wonder if something like this might help by setting the project in the parameters.
Comment on attachment 9025389 [details] [diff] [review]
try-release.patch

Review of attachment 9025389 [details] [diff] [review]:
-----------------------------------------------------------------

If things want to care about release_type, they should look at that, rather than at project, rather than duplicate release_type as project.
Attachment #9025389 - Flags: review-
This should be addressed by Bug 1506310.
Status: REOPENED → RESOLVED
Last Resolved: 6 months ago6 months ago
Flags: needinfo?(aswan)
Resolution: --- → DUPLICATE
Duplicate of bug: 1506310
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.