1506460 - 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

Status: RESOLVED DUPLICATE of bug 1506310

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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 [e-mail] is not correctly signed.
05:54:51     INFO -  PID 3540 | 1541944491632	addons.xpi-utils	WARN	Add-on [e-mail] is not correctly signed.
05:54:51     INFO -  PID 3540 | 1541944491632	addons.xpi-utils	WARN	addMetadata: Add-on [e-mail] is invalid: Error: Extension [e-mail] is not correctly signed(resource://gre/modules/addons/XPIDatabase.jsm:2418:17) JS Stack trace: [e-mail]: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: [e-mail]
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 1

[Intermittent Failures Robot]

136 failures in 3007 pushes (0.045 failures/push) were associated with this bug in the last 7 days.

This is the #2 most frequent failure this week.

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

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

Repository breakdown:
* try: 136

Platform breakdown:
* osx-10-10: 18
* windows10-64-qr: 18
* linux64: 32
* windows10-64: 18
* linux64-qr: 32
* windows7-32: 18

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

Comment 2

[Andreea Pavel [:apavel]]

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 [e-mail] is invalid: Error: Extension [e-mail] is not correctly signed(resource://gre/modules/addons/XPIDatabase.jsm:2418:17) JS Stack trace: [e-mail]: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: [e-mail]
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?

Comment 3

[Bob Clary [:bc] (inactive)]

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.

Comment 4

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

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

Comment 5

[Bob Clary [:bc] (inactive)]

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.

Comment 6

[Bob Clary [:bc] (inactive)]

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?

Comment 7

[Bob Clary [:bc] (inactive)]

Attachment: bug-1506460-mozharness-raptor-command.patch

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?

Comment 8

[Bob Clary [:bc] (inactive)]

Hopefully this is a sufficient test: <https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&group_state=expanded&revision=676eeeb37e74f79607154c8ac784880b62a64c38>

Comment 9

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

https://treeherder.mozilla.org/#/jobs?repo=try&revision=14ffeafdeac8f3faf2eaede4dd367f38514e557e

Comment 10

[Bob Clary [:bc] (inactive)]

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.

Comment 11

[Robert Wood [:rwood]]

(In reply to Bob Clary [:bc:] from comment #6)
> 
> rwood: Sound right to you?

Yep thanks :bc

Comment 12

[Pulsebot]

Pushed by [e-mail]:
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

[Arthur Iakab [arthur_iakab]]

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

Comment 14

[Bob Clary [:bc] (inactive)]

apavel: Can you confirm that we are ok now?

Comment 15

[Cosmin Sabou [:CosminS]]

Hi! These kind of failures are still happening on today's beta-sim: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception&revision=a1e29fb19e352ef3395d6a8f788dab7edae8dbe9&searchStr=raptor&selectedJob=211959002

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=211959043&repo=try&lineNumber=601

This time it looks to be a regression from Bug 1500265 https://hg.mozilla.org/integration/mozilla-inbound/rev/5861cb42b71dce8baf91679b75f4eb5b4a891cef

Andrew, could you take a look over this? Thank you.

Comment 16

[Bob Clary [:bc] (inactive)]

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.

Comment 17

[Bob Clary [:bc] (inactive)]

Attachment: try-release.patch

I wonder if something like this might help by setting the project in the parameters.

Comment 18

[Tom Prince [:tomprince]]

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.

Comment 19

[Tom Prince [:tomprince]]

This should be addressed by Bug 1506310.

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 12

Platform breakdown:
* osx-10-10: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1506460&startday=2018-11-12&endday=2018-11-18&tree=all