Closed Bug 1220362 Opened 9 years ago Closed 3 years ago

Intermittent TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]

Categories

(Testing :: Talos, defect, P5)

Product:
Testing
Component:
Talos
Type:
defect

Tracking

(firefox49 wontfix, firefox50 wontfix, firefox51 fixed, firefox52 fixed, firefox-esr78 unaffected, firefox88 wontfix, firefox89 wontfix, firefox90 fixed)

Status:
RESOLVED FIXED
Milestone:
90 Branch
Tracking Flags:
Tracking Status
firefox49 --- wontfix
firefox50 --- wontfix
firefox51 --- fixed
firefox52 --- fixed
firefox-esr78 --- unaffected
firefox88 --- wontfix
firefox89 --- wontfix
firefox90 --- fixed

People

(Reporter: philor, Assigned: beth)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell disabled][stockwell unknown])

Attachments

(3 files, 1 obsolete file)

Bug 1220362 - retry on dlopen.c errors.
58 bytes, text/x-review-board-request
gbrown
: review+
Details
Bug 1220362 - Disable talos startup_about_home_paint_cached
47 bytes, text/x-phabricator-request
Details | Review
Bug 1220362 - Ensure first browser window is available before finishing sessionrestore_no_autorestore Talos test. r?sparky!
48 bytes, text/x-phabricator-request
Details | Review
I see many recent failures have "JavaScript error: chrome://browser/content/tabbrowser.xml, line 3083: TypeError: this.tabs is undefined", which looks different from bug 1304005. Has this bug morphed?
Flags: needinfo?(jmaher)
I believe that tab error is in all talos tests, if you look for dl-open.c, you see the assertion and the same pattern of the test terminating right after the assertion.
Flags: needinfo?(jmaher)
I see that now. Thanks/sorry.
one thought I had here was to try and detect the dl-open.c crash from stderr and if we get that force the job to retry (return/exit code of 4 I believe: http://docs.buildbot.net/latest/developer/results.html ) Alison, is this a bug you would be interested in hacking on? It seems like a reasonable approach to detect this and force a retry- it would reduce our failures and allow us to get more data.
Flags: needinfo?(ashiue)
to test this we would need push to try with linux64 pgo: https://wiki.mozilla.org/ReleaseEngineering/TryChooser#What_if_I_want_PGO_for_my_build and the try syntax would be: try: -b o -p linux64 -u none -t all --rebuild 3 outside of that, we need to look for an error that matches this line: Inconsistency detected by ld.so: dl-open.c: 667: _dl_open: Assertion `_dl_debug_initialize (0, args.nsid)->r_state == RT_CONSISTENT' failed! maybe something smaller would be easier to find, specifically ".*_dl_open: Assertion.*" this would be easy to figure out on try as this reproduces pretty much on every pgo set of tests.
yes, please, keep the ni for reminding.
hmm, this seemed to sort of fix itself on Oct 26th- the rate has dropped to a slow trickle. I think we should put this fix in- I did a try push with what I think would be the fix: https://treeherder.mozilla.org/#/jobs?repo=try&revision=4d6f8caecf1512d08772e0605d93b21e18539d14 but no retries and no failures- so possibly we need to wait until this happens again so we can test the fix- I will do more retriggers to see if I can get an instance to fail.
There are still a few instances each day, like https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=6015343#L1154. Your patch looks good to me - let's land it.
Flags: needinfo?(ashiue)
Comment on attachment 8806863 [details] Bug 1220362 - retry on dlopen.c errors. https://reviewboard.mozilla.org/r/90150/#review89814
Attachment #8806863 - Flags: review?(gbrown) → review+
Pushed by jmaher@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/18db98d0503b retry on dlopen.c errors. r=gbrown
https://hg.mozilla.org/mozilla-central/rev/18db98d0503b
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
status-firefox45: affected → ---
status-firefox49: --- → wontfix
status-firefox50: --- → wontfix
status-firefox51: --- → affected
Whiteboard: [checkin-needed-aurora]
Assignee: nobody → jmaher
thanks for mentioning this- I will wait to see if this happens more frequently and what the pattern is.
Flags: needinfo?(jmaher)
Over the last 7 days there are 47 failures present on this bug. These happen on windows10-64, windows7-32, osx-10-10, linux64-qr. Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=180536556&repo=mozilla-inbound&lineNumber=1073 14:29:43 INFO - TEST-UNEXPECTED-ERROR | tp5n | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 14:29:43 ERROR - Traceback (most recent call last): 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\run_tests.py", line 296, in run_tests 14:29:43 INFO - talos_results.add(mytest.runTest(browser_config, test)) 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\ttest.py", line 63, in runTest 14:29:43 INFO - return self._runTest(browser_config, test_config, setup) 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\ttest.py", line 270, in _runTest 14:29:43 INFO - else None) 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\results.py", line 95, in add 14:29:43 INFO - global_counters=self.global_counters 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\results.py", line 326, in __init__ 14:29:43 INFO - self.parse() 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\results.py", line 353, in parse 14:29:43 INFO - % self.report_tokens) 14:29:43 INFO - File "Z:\task_1527517030\build\tests\talos\talos\results.py", line 337, in error 14:29:43 INFO - raise utils.TalosError(message) 14:29:43 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 14:29:43 INFO - TEST-INFO took 3519ms 14:29:43 INFO - SUITE-END | took 3s 14:29:43 ERROR - Return code: 2 14:29:43 WARNING - setting return code to 2 14:29:43 ERROR - # TBPL FAILURE #
Flags: needinfo?(rwood)
the spike here is related to bug 1464428 which was backed out, then landed again with a proper fix.
there is 4 failures outside of yesterday- I assume 100% of yesterday is invalid.
Flags: needinfo?(rwood)
Whiteboard: [stockwell disable-recommended] → [stockwell unknown]
Whiteboard: [stockwell disable-recommended] → [stockwell unknown]
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:backout]
Over the last 7 days there are 31 failuree on this bug. These happen on linux64-qr, windows10-64-nightly Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=181993137&repo=mozilla-central&lineNumber=2477 00:11:56 INFO - TEST-UNEXPECTED-ERROR | ts_paint | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 00:11:56 ERROR - Traceback (most recent call last): 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\run_tests.py", line 297, in run_tests 00:11:56 INFO - talos_results.add(mytest.runTest(browser_config, test)) 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\ttest.py", line 63, in runTest 00:11:56 INFO - return self._runTest(browser_config, test_config, setup) 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\ttest.py", line 270, in _runTest 00:11:56 INFO - else None) 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\results.py", line 95, in add 00:11:56 INFO - global_counters=self.global_counters 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\results.py", line 326, in __init__ 00:11:56 INFO - self.parse() 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\results.py", line 353, in parse 00:11:56 INFO - % self.report_tokens) 00:11:56 INFO - File "C:\Users\task_1528243536\build\tests\talos\talos\results.py", line 337, in error 00:11:56 INFO - raise utils.TalosError(message) 00:11:56 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 00:11:56 INFO - TEST-INFO took 80944ms 00:11:56 INFO - SUITE-END | took 97s 00:11:57 ERROR - Return code: 2 00:11:57 WARNING - setting return code to 2 00:11:57 ERROR - # TBPL FAILURE #
Flags: needinfo?(rwood)
This intermittent is too general - if you look at the failures it is across all kinds of different tests, and the failure cause is completely different across many instances. The above example in comment 128 is just one of many different failures - it's not really possible to fix this intermittent, IMO it is invalid.
Flags: needinfo?(rwood)
The only option where invalid is one of your choices is if you mark all talos tests as tier-3 first. This is the only line of output in the logs which is marked in a way that Treeherder can parse as a failure, and you don't get to tell Treeherder that a line is a failure and then expect sheriffs to ignore that failure and instead read the log and somehow guess what the actual failure was and manually search for a bug and star the job as that instead.
Over the last 7 days there are 31 failures on this bug. These happen on linux64, linux64-nightly, linux64-qr, macosx64-nightly, windows10-64-nightly, windows7-32. Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=186248064&repo=autoland&lineNumber=831 12:00:37 INFO - ExceptionHandler::GenerateDump cloned child 1193 12:00:37 INFO - ExceptionHandler::SendContinueSignalToChild sent continue signal to child 12:00:37 INFO - ExceptionHandler::WaitForContinueSignal waiting for continue signal... 12:00:47 INFO - JavaScript error: chrome://global/content/browser-child.js, line 352: NS_ERROR_MALFORMED_URI: Component returned failure code: 0x804b000a (NS_ERROR_MALFORMED_URI) [nsIWebNavigation.loadURIWithOptions] 12:00:47 ERROR - JavaScript error: resource:///modules/NetErrorContent.jsm, line 449: TypeError: docShell.failedChannel is null 12:00:47 INFO - [Parent 933, Gecko_IOThread] WARNING: waitpid failed pid:1050 errno:10: file /builds/worker/workspace/build/src/ipc/chromium/src/base/process_util_posix.cc, line 256 12:00:47 INFO - ExceptionHandler::GenerateDump cloned child 1247
Flags: needinfo?(jmaher)
this seems to be mostly linux64-qr failures with a few other random failures mixed in. Looking at some logs I see a lot of tps failures with this: 2:00:27 INFO - [GFX1-]: Failed to compile shader: cs_clip_image 12:00:27 INFO - ERROR 2018-07-03T19:00:27Z: webrender::device::gl: Failed to compile shader: cs_clip_image 12:00:27 INFO - [GFX1-]: wr_renderer_render: Shader(Compilation("cs_clip_image", "")) 12:00:27 INFO - [GFX1-]: Failed to compile shader: cs_clip_image 12:00:27 INFO - ERROR 2018-07-03T19:00:27Z: webrender::device::gl: Failed to compile shader: cs_clip_image 12:00:27 INFO - [GFX1-]: wr_renderer_render: Shader(Compilation("cs_clip_image", "")) 12:00:27 INFO - [GFX1-]: Failed to compile shader: cs_clip_image 12:00:27 INFO - ERROR 2018-07-03T19:00:27Z: webrender::device::gl: Failed to compile shader: cs_clip_image 12:00:27 INFO - [GFX1-]: wr_renderer_render: Shader(Compilation("cs_clip_image", "")) 12:00:28 INFO - [GFX1-]: Compositors might be mixed (5,2) most other tests have similar messages, but this is a consistent one which might be easier to pinpoint and fix. :kats, do these errors concern you much? Is there a way to work around this or fix it?
Flags: needinfo?(jmaher) → needinfo?(bugmail)
It is somewhat concerning, yes. I'm not sure what could cause this, but we have bug 1462777 on file for these random shader compilation failures. I'll see if somebody has cycles to investigate.
Depends on: 1462777
Flags: needinfo?(bugmail)
Update: There have been 36 failures in the last week. Failures platform and build type: - linux64-qr / opt: 28 - windows7-32 / opt & pgo: 6 - windows7-32-msvc / opt: 1 - windows10-64 / opt: 1 Recent relevant log: https://treeherder.mozilla.org/logviewer.html#?job_id=198202781&repo=mozilla-central&lineNumber=1870 Summary: Intermittent TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] I see that from September 6th the number of failures started to increase. :jmaher, I've seen that you commented on this before, could you please have another look?
Flags: needinfo?(jmaher)
interesting, the majority of the failures are linux64-qr, and looking at some logs [1] I see many messages about failed to compile shader04:09:48 INFO - PID 15851 | ATTENTION: default value of option force_s3tc_enable overridden by environment. 04:09:48 INFO - PID 15851 | ATTENTION: default value of option force_s3tc_enable overridden by environment. 04:10:07 INFO - PID 15851 | [GFX1-]: Failed to compile shader: cs_clip_rectangle 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | ERROR 2018-09-08T11:10:07Z: webrender::device::gl: Failed to compile shader: cs_clip_rectangle 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | [GFX1-]: Failed to compile shader: cs_blur 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | ERROR 2018-09-08T11:10:07Z: webrender::device::gl: Failed to compile shader: cs_blur 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | [GFX1-]: Failed to compile shader: cs_blur 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | ERROR 2018-09-08T11:10:07Z: webrender::device::gl: Failed to compile shader: cs_blur 04:10:07 INFO - PID 15851 | 04:10:07 INFO - PID 15851 | [GFX1-]: Failed to compile shader: cs_border_solid ... I don't know if we need to adjust settings on the OS config, browser setup, or the tests. :mattwoodrow, would you know who to talk to on the graphics team regarding these errors? [1] https://taskcluster-artifacts.net/ZnZNX0DTQvyvlRB3Jji-Pw/0/public/logs/live_backing.log
Flags: needinfo?(jmaher) → needinfo?(matt.woodrow)
I can't think of any reason that shader compiling would be intermittent. It even looks like we're falling back to normal accelerated compositing (non-WebRender) and that fails too. Is it possible that we're getting different hardware for different runs? It seems like we'd have to get something without decent OpenGL drivers for this to fail. Adding ni?gw in case he has any other ideas.
Flags: needinfo?(matt.woodrow) → needinfo?(gwatson)
It does seem likely that we just end up in a situation where the gfx driver isn't working at all, given what you've written above. I can't think of any other obvious causes for an intermittent shader compilation failure. Do we have any information in the logs on the reported gfx hardware / driver version in between runs, even though that does seem unlikely?
Flags: needinfo?(gwatson)
:fubar, (:dhouse is on PTO, maybe you know or can redirect) these are linux boxes- do you think we could have secondary graphics drivers being used or some pool of machines with a different configuration?
Flags: needinfo?(klibby)
It's a bit difficult to see because of the error message being so generic that a huge bunch of other things are mixed in, but if you look at https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-09-03&endday=2018-09-09&tree=all&bug=1220362 and sort by the Machine Name column and find the t-linux64-ms-* among them, I'd say that this particular part of the problem is that we have some t-linux64-ms-* machines that are broken and need to be quarantined. I did that for t-linux64-ms-346, t-linux64-ms-353, and t-linux64-ms-538, but interestingly enough, despite https://tools.taskcluster.net/provisioners/releng-hardware/worker-types/gecko-t-linux-talos/workers/mdc1/t-linux64-ms-004 having been failing -qr jobs just a couple of days ago, according to that it's all better now. The one thing in my faded memory that fits with that sort of thing, "accelerated graphics consistently didn't work on a machine for a while, and then suddenly it got all better," has been times when we had a class of machines where we didn't set a resolution and enforce it, so a particular job or a particular cosmic ray or whatever could suddenly set the machine to 800x600, where we can't do accel, and then it would stay there until some other particular job or cosmic ray would set it back to a usable resolution.
Well, 353 has also cured itself, which I somehow failed to notice, but I'll leave it quarantined just to teach it a lesson.
And I rather doubt my resolution theory, since 346 ran test-linux64-qr/opt-talos-g1-e10s and failed, ran the non-qr test-linux64/opt-talos-tps-e10s and passed, then ran the qr test-linux64-qr/opt-talos-dromaeojs-e10s and passed it, then ran two more non-qr jobs and passed them, then a qr job and failed it. Even though a person pushing a resolution theory does have one ace up their sleeve, "oh, that must have been a reboot after which it was okay until it was rebroken," that much rebreakage wouldn't fit with just a few machines being broken.
(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #156) > :fubar, (:dhouse is on PTO, maybe you know or can redirect) these are linux > boxes- do you think we could have secondary graphics drivers being used or > some pool of machines with a different configuration? Dave's back tomorrow, but Dragos could dig into this, too, since he was involved in the early setup. All of the hosts should be consistent except for the staging nodes where we're testing new firmware. ISTR Dave fixing either driver or resolution issues ages ago, but nothing recent.
Flags: needinfo?(klibby) → needinfo?(dcrisan)
Bug 1493427 got backed out so I'll address that there.
Flags: needinfo?(dkeeler)
The high occurrence rate in Comment 164 is for TEST-UNEXPECTED-ERROR | tresize | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] and could actually be related to bug 1493867 which was landed before bug 1493427, but something in that bug caused them to almost perma-fail on tier1. This appeared on central tier2 here, bug 1494573 Comment 1: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=success,testfailed,busted,exception,usercancel,runnable&searchStr=windows7-32-msvc,opt,talos,performance,tests,with,e10s,test-windows7-32-msvc%2Fopt-talos-chrome-e10s,t-e10s(c)&revision=024521c589d28744b5c4a6c01127fa35edef2c53&selectedJob=201868926 Aryx can you please take a look at this and help with continuing the investigation? Should we file a specific bug here to track this issue or maybe edit the bug Marga made (1494573)? How should we proceed? ***i did not see any other talos failures of this sort in the past days that had a different test failing than tresize. Backing out Bug 1493427 indeed seems to have decreased the failure rate: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success,testfailed,busted,exception&fromchange=f8d681cc1d4cdd5095853077c0acc95576baa6dd&searchStr=windows,7,opt,talos,performance,tests,with,e10s,test-windows7-32%2Fopt-talos-chrome-e10s,t-e10s(c)&selectedJob=202505271
Flags: needinfo?(aryx.bugmail)
See Also: → 1494573, 1493867
Failure level is back to lower volume.
Flags: needinfo?(aryx.bugmail)
Migrated linux workers from taskcluster-worker to generic-worker. Let's keep an eye and see if this error still happen.
Flags: needinfo?(dcrisan)
There are 25 failures in the last 7 days, all of them on qr platforms, 21 windows10-64-qr and 4 linux64-qr. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-11-30&endday=2018-12-07&tree=all&bug=1220362 In the last 30 days there are 72 failures, 51 on linux64-qr and 21 on windows10-64-qr. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-11-07&endday=2018-12-07&tree=all&bug=1220362
Assignee: jmaher → nobody

When you read the log there is clearly the following line at the top:

PID 800 | FATAL ERROR: Non-local network connections are disabled and a connection attempt to ping.ie.sogou.com (211.159.235.146) was made.

So that should actually be the line which should be classified. I filed bug 1554570 for that.

Depends on: 1554570
Flags: needinfo?(hskupin)

Over the last 7 days there are 39 failures present on this bug. These happen on windows7-32-shippable, windows7-32, windows10-aarch64, windows10-64-shippable-qr, windows10-64-qr, windows10-64, macosx1014-64-shippable, linux64-shippable-qr, linux64-shippable, linux64-qr, linux64

Here is the most recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=250055888&repo=mozilla-inbound&lineNumber=1265

Flags: needinfo?(rwood)

(In reply to Stefan Hindli [:stefan_hindli] from comment #212)

Here is the most recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=250055888&repo=mozilla-inbound&lineNumber=1265

This is not Raptor but Talos. And this specific failure seems to be related to the recently fixed bug 1554570. So maybe this problem is caused when Firefox crashes before a report is available.

Flags: needinfo?(rwood)
Priority: -- → P3
Priority: P3 → P5

(In reply to Alexandru Michis [:malexandru] from comment #235)

Henrik, two talos jobs started permafailing on central and I think the culprit is https://hg.mozilla.org/mozilla-central/rev/7dee76ec48c47302bb18148f7fda7dbdb52ad1cf landed.

Could you please take a look?

This is Mike Conley's patch. So forwarding the needinfo to him. Do you have an idea Mike?

Flags: needinfo?(hskupin) → needinfo?(mconley)
See Also: → 1615727

Responded in bug 1615727 comment 5.

Flags: needinfo?(mconley)

Bugbug thinks this bug is a regression, but please revert this change in case of error.

Keywords: regression

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 8 years ago → 4 years ago
Resolution: --- → INCOMPLETE

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

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Whiteboard: [stockwell fixed:backout] → [stockwell fixed:backout] [perftest:triage]
Whiteboard: [stockwell fixed:backout] [perftest:triage] → [stockwell fixed:backout]
See Also: → 1648918

This test has failed 100+ times in the last week, see :apavel's comment here for more info on when the perma-fails might have started: https://bugzilla.mozilla.org/show_bug.cgi?id=1648918#c13

Flags: needinfo?(fstrugariu)

Looking at the history of the failure I have found that it first failed on:

https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=opt-talos-other-e10s%2Co&tochange=fa0afb4328103e7e61b98b3b2706891334eb2926&fromchange=419a897d7e4b9489ad51b51044f154e5bcbb605e&selectedTaskRun=BCYo38McTTCgZ7kjcxTUwg.0

Ran some retriggers but failed to reproduce the issue.
Ran the test locally a few times with no luck.

Sylvestre do you think your patch might affect this test?

Flags: needinfo?(fstrugariu) → needinfo?(sledru)

(::) I saw you investigated a similar issue in the past any ideas what might have caused this?

The stacktrace is:

 TEST-START | sessionrestore
[task 2020-06-17T19:57:21.186Z] 19:57:21     INFO -  Initialising browser for sessionrestore test...
[task 2020-06-17T19:57:21.186Z] 19:57:21     INFO -  Cloning profile located at C:\Users\task_1592416915\build\tests\talos\talos\startup_test\sessionrestore\profile
[task 2020-06-17T19:57:21.186Z] 19:57:21     INFO -  Merging profile: C:\Users\task_1592416915\build\tests\talos\talos\profile_data\base
[task 2020-06-17T19:57:21.187Z] 19:57:21     INFO -  Merging profile: C:\Users\task_1592416915\build\tests\talos\talos\profile_data\common
[task 2020-06-17T19:57:21.187Z] 19:57:21     INFO -  Merging profile: C:\Users\task_1592416915\build\tests\talos\talos\profile_data\perf
[task 2020-06-17T19:57:21.191Z] 19:57:21     INFO -  Installing Add-ons:
[task 2020-06-17T19:57:21.191Z] 19:57:21     INFO -  ['C:\\Users\\task_1592416915\\build\\tests\\talos\\talos/talos-powers', 'C:\\Users\\task_1592416915\\build\\tests\\talos\\talos/startup_test/sessionrestore/addon']
[task 2020-06-17T19:57:21.200Z] 19:57:21     INFO -  Installing Webextensions:
[task 2020-06-17T19:57:21.200Z] 19:57:21     INFO -  Application command: C:\Users\task_1592416915\build\application\firefox\firefox -wait-for-browser -no-deelevate http://127.0.0.1:49781/getInfo.html --wait-for-browser -profile c:\users\task_1592416915\appdata\local\temp\tmpfm9t1e\profile
[task 2020-06-17T19:57:21.200Z] 19:57:21     INFO -  TEST-INFO | started process 580 (C:\Users\task_1592416915\build\application\firefox\firefox -wait-for-browser -no-deelevate http://127.0.0.1:49781/getInfo.html --wait-for-browser)
[task 2020-06-17T19:57:22.788Z] 19:57:22     INFO -  console.error: SearchCache: "_readCacheFile: Error reading cache file:" (new Error("", "(unknown module)"))
[task 2020-06-17T19:57:22.957Z] 19:57:22     INFO -  __metrics
[task 2020-06-17T19:57:22.957Z] 19:57:22     INFO -  	Screen width/height: 1024/768
[task 2020-06-17T19:57:22.957Z] 19:57:22     INFO -  	colorDepth: 24
[task 2020-06-17T19:57:22.957Z] 19:57:22     INFO -  	Browser inner width/height: 1012/688
[task 2020-06-17T19:57:22.957Z] 19:57:22     INFO -  __metrics
[task 2020-06-17T19:57:23.038Z] 19:57:23     INFO -  JavaScript warning: resource://gre/modules/Troubleshoot.jsm, line 628: WebGL context was lost.
[task 2020-06-17T19:57:23.038Z] 19:57:23     INFO -  JavaScript warning: resource://gre/modules/Troubleshoot.jsm, line 628: WebGL context was lost.
[task 2020-06-17T19:57:23.065Z] 19:57:23     INFO -  about:support	{"application":{"name":"Firefox","osVersion":"Windows_NT 10.0 15063","version":"79.0a1","buildID":"20200617175652","distributionID":"","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:79.0) Gecko/20100101 Firefox/79.0","safeMode":false,"updateChannel":"nightly-autoland","supportURL":"https://support.mozilla.org/1/firefox/79.0a1/WINNT/en-US/","numTotalWindows":1,"numRemoteWindows":1,"launcherProcessState":0,"remoteAutoStart":true,"autoStartStatus":1,"policiesStatus":0,"keyLocationServiceGoogleFound":true,"keySafebrowsingGoogleFound":true,"keyMozillaFound":true},"securitySoftware":{"registeredAntiVirus":"","registeredAntiSpyware":"","registeredFirewall":""},"processes":{"remoteTypes":{"web":2,"extension":1,"gpu":1},"maxWebContentProcesses":8},"modifiedPreferences":{"browser.cache.disk.filesystem_reported":1,"browser.cache.disk.smart_size.enabled":false,"browser.contentblocking.category":"custom","browser.link.open_newwindow":2,"browser.search.region":"US","browser.startup.homepage_override.mstone":"79.0a1","browser.startup.homepage_override.buildID":"20200617175652","browser.startup.page":3,"browser.tabs.remote.autostart":true,"browser.tabs.unloadOnLowMemory":false,"dom.forms.autocomplete.formautofill":true,"dom.allow_scripts_to_close_windows":true,"dom.disable_open_during_load":false,"dom.disable_window_flip":true,"dom.disable_window_move_resize":true,"dom.max_chrome_script_run_time":0,"dom.max_script_run_time":0,"dom.push.connection.enabled":false,"dom.send_after_paint_to_content":true,"extensions.checkCompatibility":false,"extensions.lastAppVersion":"79.0a1","general.useragent.updates.enabled":false,"gfx.crash-guard.wmfvpxvideo.deviceID":"0x193a","gfx.crash-guard.status.wmfvpxvideo":2,"gfx.crash-guard.wmfvpxvideo.driverVersion":"22.20.16.4815","gfx.crash-guard.wmfvpxvideo.appVersion":"79.0a1","gfx.webrender.all.qualified":false,"idle.lastDailyNotification":-1,"layers.mlgpu.sanity-test-failed":false,"media.gmp.storage.version.observed":1,"media.allowed-to-play.enabled":true,"media.autoplay.ask-permission":false,"media.autoplay.block-webaudio":false,"media.autoplay.blocking_policy":0,"media.autoplay.default":0,"media.block-autoplay-until-in-foreground":false,"media.capturestream_hints.enabled":true,"media.geckoview.autoplay.request":false,"media.gmp-manager.updateEnabled":false,"media.gmp-manager.url":"http://127.0.0.1/gmpmanager-dummy/update.xml","media.hardware-video-decoding.failed":false,"media.libavcodec.allow-obsolete":true,"media.navigator.enabled":true,"media.navigator.permission.disabled":true,"media.peerconnection.enabled":true,"media.peerconnection.mtransport_process":false,"network.http.speculative-parallel-limit":0,"network.process.enabled":false,"places.history.expiration.transient_current_max_pages":112348,"places.database.lastMaintenance":2147483647,"plugin.state.flash":0,"plugins.flashBlock.enabled":false,"privacy.sanitize.pending":"[{\"id\":\"newtab-container\",\"itemsToClear\":[],\"options\":{}}]","privacy.reduceTimerPrecision":false,"privacy.trackingprotection.annotate_channels":false,"privacy.trackingprotection.enabled":false,"privacy.trackingprotection.introURL":"http://127.0.0.1/trackingprotection/tour","privacy.trackingprotection.pbmode.enabled":false,"security.certerrors.mitm.priming.enabled":false,"security.enable_java":false,"security.fileuri.strict_origin_policy":false,"security.sandbox.content.tempDirSuffix":"{485a5271-ea36-4526-984c-7646bf599458}","security.sandbox.plugin.tempDirSuffix":"{79fb2c13-c8ce-40ac-ac40-cbebe54da2cb}","security.turn_off_all_security_so_that_viruses_can_take_over_this_computer":true,"services.sync.engine.addresses.available":true},"lockedPreferences":{"dom.ipc.processCount.webIsolated":1},"media":{"currentAudioBackend":"(remote error)","currentMaxAudioChannels":0,"currentPreferredSampleRate":44100,"audioOutputDevices":[],"audioInputDevices":[]},"accessibility":{"isActive":false,"forceDisabled":0,"handlerUsed":false,"instantiator":""},"startupCache":{"DiskCachePath":"C:\\Users\\task_1592416915\\AppData\\Local\\Temp\\tmpfm9t1e\\profile\\startupCache\\startupCache.8.little","IgnoreDiskCache":false,"FoundDiskCacheOnInit":false,"WroteToDiskCache":false},"libraryVersions":{"NSPR":{"minVersion":"4.26 Beta","version":"4.26 Beta"},"NSS":{"minVersion":"3.54 Beta","version":"3.54 Beta"},"NSSUTIL":{"minVersion":"3.54 Beta","version":"3.54 Beta"},"NSSSSL":{"minVersion":"3.54 Beta","version":"3.54 Beta"},"NSSSMIME":{"minVersion":"3.54 Beta","version":"3.54 Beta"}},"userJS":{"exists":true},"intl":{"localeService":{"requested":["en-US"],"available":["en-US"],"supported":["en-US"],"regionalPrefs":["en-US"],"defaultLocale":"en-US"},"osPrefs":{"systemLocales":["en-US"],"regionalPrefsLocales":["en-US"]}},"crashes":{"submitted":[],"pending":0},"sandbox":{"contentSandboxLevel":6,"effectiveContentSandboxLevel":6},"remoteAgent":{"listening":false,"url":""},"graphics":{"numTotalWindows":1,"numAcceleratedWindows":1,"windowLayerManagerType":"Direct3D 11","windowLayerManagerRemote":true,"windowUsingAdvancedLayers":true,"adapterDescription":"Intel(R) Iris(R) Pro Graphics P580","adapterVendorID":"0x8086","adapterDeviceID":"0x193a","adapterSubsysID":"18a9103c","adapterRAM":0,"adapterDrivers":"igdumdim64 igd10iumd64 igd10iumd64 igd12umd64 igdumdim32 igd10iumd32 igd10iumd32 igd12umd32","driverVendor":"","driverVersion":"22.20.16.4815","driverDate":"9-26-2017","adapterDescription2":"","adapterVendorID2":"","adapterDeviceID2":"","adapterSubsysID2":"","adapterRAM2":0,"adapterDrivers2":"","driverVendor2":"","driverVersion2":"","driverDate2":"","isGPU2Active":false,"direct2DEnabled":true,"directWriteEnabled":true,"directWriteVersion":"10.0.15063.0","clearTypeParameters":"Gamma: 1.8 Pixel Structure: RGB ClearType Level: 100 Enhanced Contrast: 50 ","usesTiling":false,"contentUsesTiling":false,"offMainThreadPaintEnabled":true,"offMainThreadPaintWorkerCount":4,"targetFrameRate":60,"webgl1Renderer":"Google Inc. -- ANGLE (Intel(R) Iris(R) Pro Graphics P580 Direct3D11 vs_5_0 ps_5_0)","webgl1Version":"OpenGL ES 2.0.0 (ANGLE 2.1.0.eabf2a79aac3)","webgl1DriverExtensions":"GL_ANGLE_client_arrays GL_ANGLE_depth_texture GL_ANGLE_explicit_context GL_ANGLE_explicit_context_gles1 GL_ANGLE_framebuffer_blit GL_ANGLE_framebuffer_multisample GL_ANGLE_instanced_arrays GL_ANGLE_lossy_etc_decode GL_ANGLE_memory_size GL_ANGLE_multi_draw GL_ANGLE_multiview_multisample GL_ANGLE_pack_reverse_row_order GL_ANGLE_program_cache_control GL_ANGLE_provoking_vertex GL_ANGLE_request_extension GL_ANGLE_robust_client_memory GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_ANGLE_texture_usage GL_ANGLE_translated_shader_source GL_CHROMIUM_bind_generates_resource GL_CHROMIUM_bind_uniform_location GL_CHROMIUM_color_buffer_float_rgb GL_CHROMIUM_color_buffer_float_rgba GL_CHROMIUM_copy_compressed_texture GL_CHROMIUM_copy_texture GL_CHROMIUM_lose_context GL_CHROMIUM_sync_query GL_EXT_blend_func_extended GL_EXT_blend_minmax GL_EXT_color_buffer_half_float GL_EXT_debug_marker GL_EXT_discard_framebuffer GL_EXT_disjoint_timer_query GL_EXT_draw_buffers GL_EXT_float_blend GL_EXT_frag_depth GL_EXT_instanced_arrays GL_EXT_map_buffer_range GL_EXT_occlusion_query_boolean GL_EXT_read_format_bgra GL_EXT_robustness GL_EXT_sRGB GL_EXT_shader_texture_lod GL_EXT_texture_compression_bptc GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_s3tc_srgb GL_EXT_texture_filter_anisotropic GL_EXT_texture_format_BGRA8888 GL_EXT_texture_rg GL_EXT_texture_storage GL_EXT_unpack_subimage GL_KHR_debug GL_KHR_parallel_shader_compile GL_KHR_robust_buffer_access_behavior GL_NV_EGL_stream_consumer_external GL_NV_fence GL_NV_pack_subimage GL_NV_pixel_buffer_object GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_depth24 GL_OES_depth32 GL_OES_element_index_uint GL_OES_get_program_binary GL_OES_mapbuffer GL_OES_packed_depth_stencil GL_OES_rgb8_rgba8 GL_OES_standard_derivatives GL_OES_surfaceless_context GL_OES_texture_3D GL_OES_texture_border_clamp GL_OES_texture_float GL_OES_texture_float_linear GL_OES_texture_half_float GL_OES_texture_half_float_linear GL_OES_texture_npot GL_OES_vertex_array_object OES_compressed_EAC_R11_signed_texture OES_compressed_EAC_R11_unsigned_texture OES_compressed_EAC_RG11_signed_texture OES_compressed_EAC_RG11_unsigned_texture OES_compressed_ETC2_RGB8_texture OES_compressed_ETC2_RGBA8_texture OES_compressed_ETC2_punchthroughA_RGBA8_texture OES_compressed_ETC2_punchthroughA_sRGB8_alpha_texture OES_compressed_ETC2_sRGB8_alpha8_texture OES_compressed_ETC2_sRGB8_texture ","webgl1Extensions":"ANGLE_instanced_arrays EXT_blend_minmax EXT_color_buffer_half_float EXT_float_blend EXT_frag_depth EXT_shader_texture_lod EXT_sRGB EXT_texture_compression_bptc EXT_texture_filter_anisotropic MOZ_debug OES_element_index_uint OES_standard_derivatives OES_texture_float OES_texture_float_linear OES_texture_half_float OES_texture_half_float_linear OES_vertex_array_object WEBGL_color_buffer_float WEBGL_compressed_texture_s3tc WEBGL_compressed_texture_s3tc_srgb WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_depth_texture WEBGL_draw_buffers WEBGL_lose_context","webgl1WSIInfo":"EGL_VENDOR: Google Inc. (adapter LUID: 0000000000004d6e)\nEGL_VERSION: 1.4 (ANGLE 2.1.0.eabf2a79aac3)\nEGL_EXTENSIONS: EGL_EXT_create_context_robustness EGL_ANGLE_d3d_share_handle_client_buffer EGL_ANGLE_d3d_texture_client_buffer EGL_ANGLE_surface_d3d_texture_2d_share_handle EGL_ANGLE_query_surface_pointer EGL_ANGLE_window_fixed_size EGL_ANGLE_keyed_mutex EGL_ANGLE_surface_orientation EGL_ANGLE_direct_composition EGL_NV_post_sub_buffer EGL_KHR_create_context EGL_EXT_device_query EGL_KHR_image EGL_KHR_image_base EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_KHR_get_all_proc_addresses EGL_KHR_stream EGL_KHR_stream_consumer_gltexture EGL_NV_stream_consumer_gltexture_yuv EGL_ANGLE_flexible_surface_compatibility EGL_ANGLE_stream_producer_d3d_texture EGL_ANGLE_create_context_webgl_compatibility EGL_CHROMIUM_create_context_bind_generates_resource EGL_CHROMIUM_sync_control EGL_EXT_pixel_format_float EGL_KHR_surfaceless_context EGL_ANGLE_display_texture_share_group EGL_ANGLE_create_context_client_arrays EGL_ANGLE_program_cache_control EGL_ANGLE_robust_resource_initialization EGL_ANGLE_create_context_extensions_enabled EGL_ANDROID_blob_cache EGL_ANDROID_recordable EGL_ANGLE_image_d3d11_texture EGL_ANGLE_create_context_backwards_compatible \nEGL_EXTENSIONS(nullptr): EGL_EXT_client_extensions EGL_EXT_platform_base EGL_EXT_platform_device EGL_ANGLE_platform_angle EGL_ANGLE_platform_angle_d3d EGL_ANGLE_device_creation EGL_ANGLE_device_creation_d3d11 EGL_ANGLE_experimental_present_path EGL_KHR_client_get_all_proc_addresses EGL_KHR_debug EGL_ANGLE_explicit_context EGL_ANGLE_feature_control ","webgl2Renderer":"Google Inc. -- ANGLE (Intel(R) Iris(R) Pro Graphics P580 Direct3D11 vs_5_0 ps_5_0)","webgl2Version":"OpenGL ES 3.0.0 (ANGLE 2.1.0.eabf2a79aac3)","webgl2DriverExtensions":"GL_ANGLE_client_arrays GL_ANGLE_copy_texture_3d GL_ANGLE_depth_texture GL_ANGLE_explicit_context GL_ANGLE_explicit_context_gles1 GL_ANGLE_framebuffer_blit GL_ANGLE_framebuffer_multisample GL_ANGLE_instanced_arrays GL_ANGLE_lossy_etc_decode GL_ANGLE_memory_size GL_ANGLE_multi_draw GL_ANGLE_multiview_multisample GL_ANGLE_pack_reverse_row_order GL_ANGLE_program_cache_control GL_ANGLE_provoking_vertex GL_ANGLE_request_extension GL_ANGLE_robust_client_memory GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_ANGLE_texture_multisample GL_ANGLE_texture_usage GL_ANGLE_translated_shader_source GL_CHROMIUM_bind_generates_resource GL_CHROMIUM_bind_uniform_location GL_CHROMIUM_color_buffer_float_rgb GL_CHROMIUM_color_buffer_float_rgba GL_CHROMIUM_copy_compressed_texture GL_CHROMIUM_copy_texture GL_CHROMIUM_lose_context GL_CHROMIUM_sync_query GL_EXT_blend_func_extended GL_EXT_blend_minmax GL_EXT_color_buffer_float GL_EXT_color_buffer_half_float GL_EXT_debug_marker GL_EXT_discard_framebuffer GL_EXT_disjoint_timer_query GL_EXT_draw_buffers GL_EXT_float_blend GL_EXT_frag_depth GL_EXT_instanced_arrays GL_EXT_map_buffer_range GL_EXT_occlusion_query_boolean GL_EXT_read_format_bgra GL_EXT_robustness GL_EXT_sRGB GL_EXT_shader_texture_lod GL_EXT_texture_compression_bptc GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_s3tc_srgb GL_EXT_texture_filter_anisotropic GL_EXT_texture_format_BGRA8888 GL_EXT_texture_norm16 GL_EXT_texture_rg GL_EXT_texture_storage GL_EXT_unpack_subimage GL_KHR_debug GL_KHR_parallel_shader_compile GL_KHR_robust_buffer_access_behavior GL_NV_EGL_stream_consumer_external GL_NV_fence GL_NV_pack_subimage GL_NV_pixel_buffer_object GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_EGL_image_external_essl3 GL_OES_depth24 GL_OES_depth32 GL_OES_element_index_uint GL_OES_get_program_binary GL_OES_mapbuffer GL_OES_packed_depth_stencil GL_OES_rgb8_rgba8 GL_OES_standard_derivatives GL_OES_surfaceless_context GL_OES_texture_3D GL_OES_texture_border_clamp GL_OES_texture_float GL_OES_texture_float_linear GL_OES_texture_half_float GL_OES_texture_half_float_linear GL_OES_texture_npot GL_OES_vertex_array_object GL_OVR_multiview GL_OVR_multiview2 OES_compressed_EAC_R11_signed_texture OES_compressed_EAC_R11_unsigned_texture OES_compressed_EAC_RG11_signed_texture OES_compressed_EAC_RG11_unsigned_texture OES_compressed_ETC2_RGB8_texture OES_compressed_ETC2_RGBA8_texture OES_compressed_ETC2_punchthroughA_RGBA8_texture OES_compressed_ETC2_punchthroughA_sRGB8_alpha_texture OES_compressed_ETC2_sRGB8_alpha8_texture OES_compressed_ETC2_sRGB8_texture ","webgl2Extensions":"EXT_color_buffer_float EXT_float_blend EXT_texture_compression_bptc EXT_texture_filter_anisotropic MOZ_debug OES_texture_float_linear OVR_multiview2 WEBGL_compressed_texture_s3tc WEBGL_compressed_texture_s3tc_srgb WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_lose_context","webgl2WSIInfo":"EGL_VENDOR: Google Inc. (adapter LUID: 0000000000004d6e)\nEGL_VERSION: 1.4 (ANGLE 2.1.0.eabf2a79aac3)\nEGL_EXTENSIONS: EGL_EXT_create_context_robustness EGL_ANGLE_d3d_share_handle_client_buffer EGL_ANGLE_d3d_texture_client_buffer EGL_ANGLE_surface_d3d_texture_2d_share_handle EGL_ANGLE_query_surface_pointer EGL_ANGLE_window_fixed_size EGL_ANGLE_keyed_mutex EGL_ANGLE_surface_orientation EGL_ANGLE_direct_composition EGL_NV_post_sub_buffer EGL_KHR_create_context EGL_EXT_device_query EGL_KHR_image EGL_KHR_image_base EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_gl_renderbuffer_image EGL_KHR_get_all_proc_addresses EGL_KHR_stream EGL_KHR_stream_consumer_gltexture EGL_NV_stream_consumer_gltexture_yuv EGL_ANGLE_flexible_surface_compatibility EGL_ANGLE_stream_producer_d3d_texture EGL_ANGLE_create_context_webgl_compatibility EGL_CHROMIUM_create_context_bind_generates_resource EGL_CHROMIUM_sync_control EGL_EXT_pixel_format_float EGL_KHR_surfaceless_context EGL_ANGLE_display_texture_share_group EGL_ANGLE_create_context_client_arrays EGL_ANGLE_program_cache_control EGL_ANGLE_robust_resource_initialization EGL_ANGLE_create_context_extensions_enabled EGL_ANDROID_blob_cache EGL_ANDROID_recordable EGL_ANGLE_image_d3d11_texture EGL_ANGLE_create_context_backwards_compatible \nEGL_EXTENSIONS(nullptr): EGL_EXT_client_extensions EGL_EXT_platform_base EGL_EXT_platform_device EGL_ANGLE_platform_angle EGL_ANGLE_platform_angle_d3d EGL_ANGLE_device_creation EGL_ANGLE_device_creation_d3d11 EGL_ANGLE_experimental_present_path EGL_KHR_client_get_all_proc_addresses EGL_KHR_debug EGL_ANGLE_explicit_context EGL_ANGLE_feature_control ","info":{"AzureCanvasBackend (UI Process)":"skia","AzureFallbackCanvasBackend (UI Process)":"none","AzureContentBackend (UI Process)":"skia","AzureCanvasBackend":"direct2d 1.1","AzureContentBackend":"direct2d 1.1","ApzWheelInput":1,"ApzDragInput":1,"ApzKeyboardInput":1,"ApzAutoscrollInput":1,"CMSOutputProfile":"AAAMSExpbm8CEAAAbW50clJHQiBYWVogB84AAgAJAAYAMQAAYWNzcE1TRlQAAAAASUVDIHNSR0IAAAAAAAAAAAAAAAAAAPbWAAEAAAAA0y1IUCAgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAARY3BydAAAAVAAAAAzZGVzYwAAAYQAAABsd3RwdAAAAfAAAAAUYmtwdAAAAgQAAAAUclhZWgAAAhgAAAAUZ1hZWgAAAiwAAAAUYlhZWgAAAkAAAAAUZG1uZAAAAlQAAABwZG1kZAAAAsQAAACIdnVlZAAAA0wAAACGdmlldwAAA9QAAAAkbHVtaQAAA/gAAAAUbWVhcwAABAwAAAAkdGVjaAAABDAAAAAMclRSQwAABDwAAAgMZ1RSQwAABDwAAAgMYlRSQwAABDwAAAgMdGV4dAAAAABDb3B5cmlnaHQgKGMpIDE5OTggSGV3bGV0dC1QYWNrYXJkIENvbXBhbnkAAGRlc2MAAAAAAAAAEnNSR0IgSUVDNjE5NjYtMi4xAAAAAAAAAAAAAAASc1JHQiBJRUM2MTk2Ni0yLjEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFhZWiAAAAAAAADzUQABAAAAARbMWFlaIAAAAAAAAAAAAAAAAAAAAABYWVogAAAAAAAAb6IAADj1AAADkFhZWiAAAAAAAABimQAAt4UAABjaWFlaIAAAAAAAACSgAAAPhAAAts9kZXNjAAAAAAAAABZJRUMgaHR0cDovL3d3dy5pZWMuY2gAAAAAAAAAAAAAABZJRUMgaHR0cDovL3d3dy5pZWMuY2gAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAZGVzYwAAAAAAAAAuSUVDIDYxOTY2LTIuMSBEZWZhdWx0IFJHQiBjb2xvdXIgc3BhY2UgLSBzUkdCAAAAAAAAAAAAAAAuSUVDIDYxOTY2LTIuMSBEZWZhdWx0IFJHQiBjb2xvdXIgc3BhY2UgLSBzUkdCAAAAAAAAAAAAAAAAAAAAAAAAAAAAAGRlc2MAAAAAAAAALFJlZmVyZW5jZSBWaWV3aW5nIENvbmRpdGlvbiBpbiBJRUM2MTk2Ni0yLjEAAAAAAAAAAAAAACxSZWZlcmVuY2UgVmlld2luZyBDb25kaXRpb24gaW4gSUVDNjE5NjYtMi4xAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAB2aWV3AAAAAAATpP4AFF8uABDPFAAD7cwABBMLAANcngAAAAFYWVogAAAAAABMCVYAUAAAAFcf521lYXMAAAAAAAAAAQAAAAAAAAAAAAAAAAAAAAAAAAKPAAAAAnNpZyAAAAAAQ1JUIGN1cnYAAAAAAAAEAAAAAAUACgAPABQAGQAeACMAKAAtADIANwA7AEAARQBKAE8AVABZAF4AYwBoAG0AcgB3AHwAgQCGAIsAkACVAJoAnwCkAKkArgCyALcAvADBAMYAywDQANUA2wDgAOUA6wDwAPYA+wEBAQcBDQETARkBHwElASsBMgE4AT4BRQFMAVIBWQFgAWcBbgF1AXwBgwGLAZIBmgGhAakBsQG5AcEByQHRAdkB4QHpAfIB+gIDAgwCFAIdAiYCLwI4AkECSwJUAl0CZwJxAnoChAKOApgCogKsArYCwQLLAtUC4ALrAvUDAAMLAxYDIQMtAzgDQwNPA1oDZgNyA34DigOWA6IDrgO6A8cD0wPgA+wD+QQGBBMEIAQtBDsESARVBGMEcQR+BIwEmgSoBLYExATTBOEE8AT+BQ0FHAUrBToFSQVYBWcFdwWGBZYFpgW1BcUF1QXlBfYGBgYWBicGNwZIBlkGagZ7BowGnQavBsAG0QbjBvUHBwcZBysHPQdPB2EHdAeGB5kHrAe/B9IH5Qf4CAsIHwgyCEYIWghuCIIIlgiqCL4I0gjnCPsJEAklCToJTwlkCXkJjwmkCboJzwnlCfsKEQonCj0KVApqCoEKmAquCsUK3ArzCwsLIgs5C1ELaQuAC5gLsAvIC+EL+QwSDCoMQwxcDHUMjgynDMAM2QzzDQ0NJg1ADVoNdA2ODakNww3eDfgOEw4uDkkOZA5/DpsOtg7SDu4PCQ8lD0EPXg96D5YPsw/PD+wQCRAmEEMQYRB+EJsQuRDXEPURExExEU8RbRGMEaoRyRHoEgcSJhJFEmQShBKjEsMS4xMDEyMTQxNjE4MTpBPFE+UUBhQnFEkUahSLFK0UzhTwFRIVNBVWFXgVmxW9FeAWAxYmFkkWbBaPFrIW1hb6Fx0XQRdlF4kXrhfSF/cYGxhAGGUYihivGNUY+hkgGUUZaxmRGbcZ3RoEGioaURp3Gp4axRrsGxQbOxtjG4obshvaHAIcKhxSHHscoxzMHPUdHh1HHXAdmR3DHeweFh5AHmoelB6+HukfEx8+H2kflB+/H+ogFSBBIGwgmCDEIPAhHCFIIXUhoSHOIfsiJyJVIoIiryLdIwojOCNmI5QjwiPwJB8kTSR8JKsk2iUJJTglaCWXJccl9yYnJlcmhya3JugnGCdJJ3onqyfcKA0oPyhxKKIo1CkGKTgpaymdKdAqAio1KmgqmyrPKwIrNitpK50r0SwFLDksbiyiLNctDC1BLXYtqy3hLhYuTC6CLrcu7i8kL1ovkS/HL/4wNTBsMKQw2zESMUoxgjG6MfIyKjJjMpsy1DMNM0YzfzO4M/E0KzRlNJ402DUTNU01hzXCNf02NzZyNq426TckN2A3nDfXOBQ4UDiMOMg5BTlCOX85vDn5OjY6dDqyOu87LTtrO6o76DwnPGU8pDzjPSI9YT2hPeA+ID5gPqA+4D8hP2E/oj/iQCNAZECmQOdBKUFqQaxB7kIwQnJCtUL3QzpDfUPARANER0SKRM5FEkVVRZpF3kYiRmdGq0bwRzVHe0fASAVIS0iRSNdJHUljSalJ8Eo3Sn1KxEsMS1NLmkviTCpMcky6TQJNSk2TTdxOJU5uTrdPAE9JT5NP3VAnUHFQu1EGUVBRm1HmUjFSfFLHUxNTX1OqU/ZUQlSPVNtVKFV1VcJWD1ZcVqlW91dEV5JX4FgvWH1Yy1kaWWlZuFoHWlZaplr1W0VblVvlXDVchlzWXSddeF3JXhpebF69Xw9fYV+zYAVgV2CqYPxhT2GiYfViSWKcYvBjQ2OXY+tkQGSUZOllPWWSZedmPWaSZuhnPWeTZ+loP2iWaOxpQ2maafFqSGqfavdrT2una/9sV2yvbQhtYG25bhJua27Ebx5veG/RcCtwhnDgcTpxlXHwcktypnMBc11zuHQUdHB0zHUodYV14XY+dpt2+HdWd7N4EXhueMx5KnmJeed6RnqlewR7Y3vCfCF8gXzhfUF9oX4BfmJ+wn8jf4R/5YBHgKiBCoFrgc2CMIKSgvSDV4O6hB2EgITjhUeFq4YOhnKG14c7h5+IBIhpiM6JM4mZif6KZIrKizCLlov8jGOMyo0xjZiN/45mjs6PNo+ekAaQbpDWkT+RqJIRknqS45NNk7aUIJSKlPSVX5XJljSWn5cKl3WX4JhMmLiZJJmQmfyaaJrVm0Kbr5wcnImc951kndKeQJ6unx2fi5/6oGmg2KFHobaiJqKWowajdqPmpFakx6U4pammGqaLpv2nbqfgqFKoxKk3qamqHKqPqwKrdavprFys0K1ErbiuLa6hrxavi7AAsHWw6rFgsdayS7LCszizrrQltJy1E7WKtgG2ebbwt2i34LhZuNG5SrnCuju6tbsuu6e8IbybvRW9j74KvoS+/796v/XAcMDswWfB48JfwtvDWMPUxFHEzsVLxcjGRsbDx0HHv8g9yLzJOsm5yjjKt8s2y7bMNcy1zTXNtc42zrbPN8+40DnQutE80b7SP9LB00TTxtRJ1MvVTtXR1lXW2Ndc1+DYZNjo2WzZ8dp22vvbgNwF3IrdEN2W3hzeot8p36/gNuC94UThzOJT4tvjY+Pr5HPk/OWE5g3mlucf56noMui86Ubp0Opb6uXrcOv77IbtEe2c7ijutO9A78zwWPDl8XLx//KM8xnzp/Q09ML1UPXe9m32+/eK+Bn4qPk4+cf6V/rn+3f8B/yY/Sn9uv5L/tz/bf//","DisplayCount":1,"Display0":"1024x768@60Hz "},"featureLog":{"features":[{"name":"HW_COMPOSITING","description":"Compositing","status":"available","log":[{"type":"default","status":"available"}]},{"name":"D3D11_COMPOSITING","description":"Direct3D11 Compositing","status":"available","log":[{"type":"default","status":"available"}]},{"name":"DIRECT2D","description":"Direct2D","status":"available","log":[{"type":"default","status":"available"}]},{"name":"D3D11_HW_ANGLE","description":"Direct3D11 hardware ANGLE","status":"available","log":[{"type":"default","status":"available"}]},{"name":"GPU_PROCESS","description":"GPU Process","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBRENDER","description":"WebRender","status":"opt-in","log":[{"type":"default","status":"opt-in","message":"WebRender is an opt-in feature"}]},{"name":"WEBRENDER_QUALIFIED","description":"WebRender qualified","status":"denied","log":[{"type":"default","status":"available"},{"type":"env","status":"denied","message":"Not on allowlist"}]},{"name":"WEBRENDER_COMPOSITOR","description":"WebRender native compositor","status":"unavailable","log":[{"type":"default","status":"available"},{"type":"runtime","status":"unavailable","message":"No DirectComposition usage"}]},{"name":"WEBRENDER_ANGLE","description":"WebRender ANGLE","status":"opt-in","log":[{"type":"default","status":"opt-in","message":"WebRender ANGLE is an opt-in feature"}]},{"name":"WEBRENDER_DCOMP_PRESENT","description":"WebRender DirectComposition","status":"opt-in","log":[{"type":"default","status":"opt-in","message":"WebRender DirectComposition is an opt-in feature"}]},{"name":"OMTP","description":"Off Main Thread Painting","status":"available","log":[{"type":"default","status":"available"}]},{"name":"ADVANCED_LAYERS","description":"Advanced Layers","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBGPU","description":"WebGPU","status":"disabled","log":[{"type":"default","status":"disabled","message":"Disabled by default"}]}],"fallbacks":[]},"crashGuards":[]},"extensions":[{"name":"Session Restore Startup Performance Test","version":"2.1","isActive":true,"id":"session-restore-test-2@mozilla.org"},{"name":"Talos Powers","version":"1.1","isActive":true,"id":"talos-powers@mozilla.org"}],"features":[{"name":"DoH Roll-Out","version":"1.3.0","id":"doh-rollout@mozilla.org"},{"name":"Firefox Screenshots","version":"39.0.0","id":"screenshots@mozilla.org"},{"name":"Form Autofill","version":"1.0","id":"formautofill@mozilla.org"},{"name":"Web Compat","version":"11.0.0","id":"webcompat@mozilla.org"},{"name":"WebCompat Reporter","version":"1.3.0","id":"webcompat-reporter@mozilla.org"}]}
[task 2020-06-17T19:57:23.349Z] 19:57:23    ERROR -  JavaScript error: resource://gre/modules/sessionstore/PrivacyFilter.jsm, line 121: TypeError: can't access property "isPrivate", tab is undefined
[task 2020-06-17T19:57:23.408Z] 19:57:23     INFO -  JavaScript error: moz-extension://a77f127f-d8f1-4eb8-86f9-6497b1785dfe/chrome/talos-powers-content.js, line 19: NS_ERROR_NOT_INITIALIZED:
[task 2020-06-17T19:57:23.512Z] 19:57:23     INFO -  *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run
[task 2020-06-17T19:57:23.529Z] 19:57:23     INFO -  JavaScript error: resource:///modules/Discovery.jsm, line 104: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsICookieManager.remove]
Flags: needinfo?(mconley)

Justin maybe you have a idea on what's causing this error

Flags: needinfo?(dolske)

This is a permafailure now so it would need immediate attention can you help investigate it.

Also if we don't get any support on this test we will need to disable the test.

Flags: needinfo?(dothayer)

Sounds unlikely that it is coming from a rust coding style change :)

Flags: needinfo?(sledru)

Florin, can the test be disabled or is there anything else left to be done before that?

Flags: needinfo?(fstrugariu)
Assignee: nobody → fstrugariu

Hopefully when the Project Shirley crunch ends, I'll find some time to re-enable this.

(In reply to Mike Conley (:mconley) (:⚙️) from comment #267)

Hopefully when the Project Shirley crunch ends, I'll find some time to re-enable this.

Thanks for the update :mconley. We're strapped for time/resources in perftest as well but I'm going to try to push for some work on these failures (talos-svgr is another one) in the coming sprints.

Attachment #9169423 - Attachment description: Bug 1220362 Dissable talos startup_about_home_paint_cached → Bug 1220362 - Disable talos startup_about_home_paint_cached
Flags: needinfo?(jdinbox)
Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/a0b9da32637e Disable talos startup_about_home_paint_cached r=perftest-reviewers,sparky DONTBUILD
Keywords: leave-open
Whiteboard: [stockwell fixed:backout] → [stockwell disabled]

test disabled removing ni?

Flags: needinfo?(fstrugariu)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INACTIVE

This is still happening:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=319631038&repo=autoland&lineNumber=940

INFO -  TEST-INFO | started process 3928 (C:\Users\task_1603528065\build\application\firefox\firefox -wait-for-browser -no-deelevate -profile c:\users\task_1603528065\appdata\local\temp\tmpscpwz2\profile)
[task 2020-10-24T09:15:56.740Z] 09:15:56     INFO -  PID 3928 | Can't find symbol 'eglSwapBuffersWithDamageEXT'.
[task 2020-10-24T09:15:56.740Z] 09:15:56     INFO -  PID 3928 | Can't find symbol 'eglSetDamageRegionKHR'.
[task 2020-10-24T09:16:07.934Z] 09:16:07     INFO -  PID 3928 | Failed to get timestamps.about_home_topsites_first_paint scalar probe in time.
[task 2020-10-24T09:16:08.218Z] 09:16:08     INFO -  TEST-INFO | 3928: exit 0
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -  mozcrash checking c:\users\task_1603528065\appdata\local\temp\tmpscpwz2\profile\minidumps for minidumps...
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -  TEST-UNEXPECTED-ERROR | startup_about_home_paint_realworld_webextensions | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2020-10-24T09:16:08.275Z] 09:16:08    ERROR -  Traceback (most recent call last):
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\run_tests.py", line 315, in run_tests
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\ttest.py", line 64, in runTest
[task 2020-10-24T09:16:08.275Z] 09:16:08     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\ttest.py", line 280, in _runTest
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -      else None)
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\results.py", line 95, in add
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -      global_counters=self.global_counters
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\results.py", line 326, in __init__
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -      self.parse()
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\results.py", line 353, in parse
[task 2020-10-24T09:16:08.276Z] 09:16:08     INFO -      % self.report_tokens)
[task 2020-10-24T09:16:08.277Z] 09:16:08     INFO -    File "C:\Users\task_1603528065\build\tests\talos\talos\results.py", line 337, in error
[task 2020-10-24T09:16:08.277Z] 09:16:08     INFO -      raise utils.TalosError(message)
[task 2020-10-24T09:16:08.277Z] 09:16:08     INFO -  TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2020-10-24T09:16:08.277Z] 09:16:08     INFO -  TEST-INFO took 15790ms
[task 2020-10-24T09:16:08.277Z] 09:16:08     INFO -  SUITE-END | took 15s
[task 2020-10-24T09:16:08.438Z] 09:16:08     INFO -  127.0.0.1 - - [24/Oct/2020 09:16:02] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03P\r=\x17\xb9J\xc5\x86\xac\x7f|\xcc\xe8W\x8c0\xbf|\x14O\xa5\x90\x8d\xe3z\x0eW&\xc5\xf0\xc7\xf7 \xaa\xb7\xf4\x0b\xc4\x0e\xd3Y\x05\x84\x00\xcc\xb4\x0b\x97\xc7\x86\x02\x16e')
[task 2020-10-24T09:16:08.438Z] 09:16:08     INFO -  127.0.0.1 - - [24/Oct/2020 09:16:02] "
Status: RESOLVED → REOPENED
Resolution: INACTIVE → ---
Assignee: fstrugariu → nobody
Whiteboard: [stockwell disabled] → [stockwell disabled][perftest:triage]
Whiteboard: [stockwell disabled][perftest:triage] → [stockwell disabled]

In the last 7 days there have been 24 occurrences on macosx1014-64-shippable-qr opt.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=330628074&repo=mozilla-central&lineNumber=4653

[task 2021-02-20T23:39:31.464Z] 23:39:31     INFO -  TEST-INFO | started process 2257 (/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmp2IfP9m/profile)
[task 2021-02-20T23:39:32.856Z] 23:39:32     INFO -  PID 2257 | __start_report1159__end_report
[task 2021-02-20T23:39:32.856Z] 23:39:32     INFO -  PID 2257 |
[task 2021-02-20T23:39:32.856Z] 23:39:32     INFO -  PID 2257 | __startTimestamp1047.694641__endTimestamp
[task 2021-02-20T23:39:33.284Z] 23:39:33     INFO -  TEST-INFO | 2257: exit 0
[task 2021-02-20T23:39:33.354Z] 23:39:33     INFO -  mozcrash checking /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmp2IfP9m/profile/minidumps for minidumps...
[task 2021-02-20T23:39:33.354Z] 23:39:33     INFO -  TEST-OK | startup_about_home_paint | took 55169ms
[task 2021-02-20T23:39:33.354Z] 23:39:33     INFO -  TEST-START | pdfpaint
[task 2021-02-20T23:39:33.354Z] 23:39:33     INFO -  Initialising browser for pdfpaint test...
[task 2021-02-20T23:39:33.354Z] 23:39:33     INFO -  Cloning profile located at /Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/base_profile
[task 2021-02-20T23:39:33.355Z] 23:39:33     INFO -  Merging profile: /Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/profile_data/base
[task 2021-02-20T23:39:33.355Z] 23:39:33     INFO -  Merging profile: /Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/profile_data/common
[task 2021-02-20T23:39:33.355Z] 23:39:33     INFO -  Merging profile: /Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/profile_data/perf
[task 2021-02-20T23:39:33.368Z] 23:39:33     INFO -  Installing Add-ons:
[task 2021-02-20T23:39:33.368Z] 23:39:33     INFO -  ['/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/talos-powers', '/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/pageloader']
[task 2021-02-20T23:39:33.373Z] 23:39:33     INFO -  Installing Webextensions:
[task 2021-02-20T23:39:33.373Z] 23:39:33     INFO -  Application command: /Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS/firefox http://127.0.0.1:50059/getInfo.html -foreground -profile /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile
[task 2021-02-20T23:39:33.382Z] 23:39:33     INFO -  TEST-INFO | started process 2263 (/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS/firefox http://127.0.0.1:50059/getInfo.html)
[task 2021-02-20T23:39:34.834Z] 23:39:34     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2021-02-20T23:39:35.026Z] 23:39:35     INFO -  __metrics
[task 2021-02-20T23:39:35.026Z] 23:39:35     INFO -  	Screen width/height: 1280/1024
[task 2021-02-20T23:39:35.026Z] 23:39:35     INFO -  	colorDepth: 24
[task 2021-02-20T23:39:35.026Z] 23:39:35     INFO -  	Browser inner width/height: 1280/927
[task 2021-02-20T23:39:35.026Z] 23:39:35     INFO -  __metrics
[task 2021-02-20T23:39:35.145Z] 23:39:35     INFO -  JavaScript warning: resource://gre/modules/Troubleshoot.jsm, line 691: WebGL context was lost.
[task 2021-02-20T23:39:35.146Z] 23:39:35     INFO -  JavaScript warning: resource://gre/modules/Troubleshoot.jsm, line 691: WebGL context was lost.
[task 2021-02-20T23:39:35.221Z] 23:39:35     INFO -  about:support	{"application":{"name":"Firefox","osVersion":"Darwin 18.6.0 Darwin Kernel Version 18.6.0: Thu Apr 25 23:16:27 PDT 2019; root:xnu-4903.261.4~2/RELEASE_X86_64","version":"87.0a1","buildID":"20210220213332","distributionID":"","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:87.0) Gecko/20100101 Firefox/87.0","safeMode":false,"updateChannel":"nightly","supportURL":"https://support.mozilla.org/1/firefox/87.0a1/Darwin/en-US/","rosetta":false,"numTotalWindows":1,"numFissionWindows":0,"numRemoteWindows":1,"fissionAutoStart":false,"fissionDecisionStatus":"disabledByDefault","remoteAutoStart":true,"policiesStatus":0,"keyLocationServiceGoogleFound":true,"keySafebrowsingGoogleFound":true,"keyMozillaFound":true},"securitySoftware":{"registeredAntiVirus":"","registeredAntiSpyware":"","registeredFirewall":""},"processes":{"remoteTypes":{"extension":1,"web":1},"maxWebContentProcesses":8},"environmentVariables":{"MOZ_CRASHREPORTER":"1","MOZ_AUTOMATION":"1","MOZ_UPLOAD_DIR":"/Users/cltbld/tasks/task_1613859502/build/blobber_upload_dir","MOZ_NODE_PATH":"/usr/local/bin/node","MOZ_FETCHES_DIR":"/Users/cltbld/tasks/task_1613859502/fetches","MOZ_NO_REMOTE":"1","MOZ_SCM_LEVEL":"3","MOZ_DISABLE_NONLOCAL_CONNECTIONS":"1","MOZ_FETCHES":"[{\"artifact\": \"public/build/fix-stacks.tar.xz\", \"extract\": true, \"task\": \"EUMXXpnmTsWHSdt3Q2fkuQ\"}, {\"artifact\": \"public/build/minidump_stackwalk.tar.xz\", \"extract\": true, \"task\": \"esQGLSWSRg2_2C82FceOXg\"}]","XRE_NO_WINDOWS_CRASH_DIALOG":"1","MOZ_CRASHREPORTER_NO_REPORT":"1","MOZ_CRASHREPORTER_EVENTS_DIRECTORY":"/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile/crashes/events","MOZ_CRASHREPORTER_RESTART_ARG_0":"/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS/firefox","MOZ_CRASHREPORTER_RESTART_ARG_1":"http://127.0.0.1:50059/getInfo.html","MOZ_CRASHREPORTER_RESTART_ARG_2":"-foreground","MOZ_CRASHREPORTER_RESTART_ARG_3":"-profile","MOZ_CRASHREPORTER_RESTART_ARG_4":"/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile","MOZ_CRASHREPORTER_RESTART_ARG_5":"","MOZ_CRASHREPORTER_DATA_DIRECTORY":"/Users/cltbld/Library/Application Support/Firefox/Crash Reports","MOZ_CRASHREPORTER_PING_DIRECTORY":"/Users/cltbld/Library/Application Support/Firefox/Pending Pings","MOZ_CRASHREPORTER_STRINGS_OVERRIDE":"/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/Resources/browser/crashreporter-override.ini","MOZ_LAUNCHED_CHILD":"","XRE_PROFILE_PATH":"","XRE_PROFILE_LOCAL_PATH":"","XRE_START_OFFLINE":"","XRE_BINARY_PATH":"","XRE_RESTARTED_BY_PROFILE_MANAGER":""},"modifiedPreferences":{"browser.cache.disk.smart_size.enabled":false,"browser.contentblocking.category":"custom","browser.link.open_newwindow":2,"browser.search.region":"US","browser.startup.homepage_override.mstone":"87.0a1","browser.startup.homepage_override.buildID":"20210220213332","browser.tabs.remote.autostart":true,"browser.tabs.unloadOnLowMemory":false,"doh-rollout.balrog-migration-done":true,"doh-rollout.doneFirstRun":true,"dom.allow_scripts_to_close_windows":true,"dom.disable_open_during_load":false,"dom.disable_window_flip":true,"dom.disable_window_move_resize":true,"dom.forms.autocomplete.formautofill":true,"dom.max_chrome_script_run_time":0,"dom.max_script_run_time":0,"dom.push.connection.enabled":false,"dom.send_after_paint_to_content":true,"extensions.checkCompatibility":false,"extensions.lastAppVersion":"87.0a1","font.internaluseonly.changed":true,"general.useragent.updates.enabled":false,"gfx.webrender.all.qualified":false,"gfx.webrender.software":true,"idle.lastDailyNotification":-1,"layers.d3d11.enable-blacklist":false,"media.gmp.storage.version.observed":1,"media.allowed-to-play.enabled":true,"media.autoplay.ask-permission":false,"media.autoplay.block-webaudio":false,"media.autoplay.blocking_policy":0,"media.autoplay.default":0,"media.block-autoplay-until-in-foreground":false,"media.capturestream_hints.enabled":true,"media.geckoview.autoplay.request":false,"media.gmp-manager.updateEnabled":false,"media.gmp-manager.url":"http://127.0.0.1/gmpmanager-dummy/update.xml","media.libavcodec.allow-obsolete":true,"media.navigator.enabled":true,"media.navigator.permission.disabled":true,"media.peerconnection.enabled":true,"media.peerconnection.mtransport_process":false,"network.http.speculative-parallel-limit":0,"network.process.enabled":false,"places.database.lastMaintenance":2147483647,"plugin.state.flash":0,"plugins.flashBlock.enabled":false,"privacy.sanitize.pending":"[{\"id\":\"newtab-container\",\"itemsToClear\":[],\"options\":{}}]","privacy.reduceTimerPrecision":false,"privacy.trackingprotection.annotate_channels":false,"privacy.trackingprotection.enabled":false,"privacy.trackingprotection.introURL":"http://127.0.0.1/trackingprotection/tour","privacy.trackingprotection.pbmode.enabled":false,"security.certerrors.mitm.priming.enabled":false,"security.enable_java":false,"security.fileuri.strict_origin_policy":false,"security.sandbox.content.tempDirSuffix":"c1812690-8d6c-d34c-a0f4-01dba4d1956e","security.sandbox.plugin.tempDirSuffix":"3604ff94-88e4-1341-bdb4-16265117261c","security.turn_off_all_security_so_that_viruses_can_take_over_this_computer":true,"services.sync.engine.addresses.available":true},"lockedPreferences":{"fission.autostart.session":false},"printingPreferences":{},"media":{"currentAudioBackend":"audiounit-rust","currentMaxAudioChannels":2,"currentPreferredSampleRate":44100,"audioOutputDevices":[{"name":"Internal Speakers","groupId":"builtin-internal-mic|spk","vendor":"Apple Inc.","type":2,"state":2,"preferred":15,"supportedFormat":12336,"defaultFormat":4096,"maxChannels":2,"defaultRate":44100,"maxRate":96000,"minRate":44100,"maxLatency":4736,"minLatency":654}],"audioInputDevices":[]},"accessibility":{"isActive":false,"forceDisabled":0,"handlerUsed":false,"instantiator":""},"startupCache":{"DiskCachePath":"/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile/startupCache/startupCache.8.little","IgnoreDiskCache":false,"FoundDiskCacheOnInit":false,"WroteToDiskCache":false},"libraryVersions":{"NSPR":{"minVersion":"4.29","version":"4.29"},"NSS":{"minVersion":"3.62","version":"3.62"},"NSSUTIL":{"minVersion":"3.62","version":"3.62"},"NSSSSL":{"minVersion":"3.62","version":"3.62"},"NSSSMIME":{"minVersion":"3.62","version":"3.62"}},"userJS":{"exists":true},"intl":{"localeService":{"requested":["en-US"],"available":["en-US"],"supported":["en-US"],"regionalPrefs":["en"],"defaultLocale":"en-US"},"osPrefs":{"systemLocales":["en"],"regionalPrefsLocales":["en"]}},"crashes":{"submitted":[],"pending":0},"sandbox":{"contentSandboxLevel":3,"effectiveContentSandboxLevel":3},"remoteAgent":{"listening":false,"url":""},"graphics":{"numTotalWindows":1,"numAcceleratedWindows":1,"windowLayerManagerType":"WebRender (Software)","windowLayerManagerRemote":true,"windowUsingAdvancedLayers":false,"adapterDescription":"","adapterVendorID":"0x8086","adapterDeviceID":"0x0a2e","adapterRAM":0,"adapterDrivers":"","driverVendor":"","driverVersion":"","driverDate":"","usesTiling":true,"contentUsesTiling":true,"offMainThreadPaintEnabled":true,"offMainThreadPaintWorkerCount":3,"targetFrameRate":60,"webgl1Renderer":"Intel Inc. -- Intel Iris OpenGL Engine","webgl1Version":"4.1 INTEL-12.9.22","webgl1DriverExtensions":"GL_ARB_blend_func_extended GL_ARB_draw_buffers_blend GL_ARB_draw_indirect GL_ARB_ES2_compatibility GL_ARB_explicit_attrib_location GL_ARB_gpu_shader_fp64 GL_ARB_gpu_shader5 GL_ARB_instanced_arrays GL_ARB_internalformat_query GL_ARB_occlusion_query2 GL_ARB_sample_shading GL_ARB_sampler_objects GL_ARB_separate_shader_objects GL_ARB_shader_bit_encoding GL_ARB_shader_subroutine GL_ARB_shading_language_include GL_ARB_tessellation_shader GL_ARB_texture_buffer_object_rgb32 GL_ARB_texture_cube_map_array GL_ARB_texture_gather GL_ARB_texture_query_lod GL_ARB_texture_rgb10_a2ui GL_ARB_texture_storage GL_ARB_texture_swizzle GL_ARB_timer_query GL_ARB_transform_feedback2 GL_ARB_transform_feedback3 GL_ARB_vertex_attrib_64bit GL_ARB_vertex_type_2_10_10_10_rev GL_ARB_viewport_array GL_EXT_debug_label GL_EXT_debug_marker GL_EXT_framebuffer_multisample_blit_scaled GL_EXT_texture_compression_s3tc GL_EXT_texture_filter_anisotropic GL_EXT_texture_sRGB_decode GL_APPLE_client_storage GL_APPLE_container_object_shareable GL_APPLE_flush_render GL_APPLE_object_purgeable GL_APPLE_rgb_422 GL_APPLE_row_bytes GL_APPLE_texture_range GL_ATI_texture_mirror_once GL_NV_texture_barrier","webgl1Extensions":"ANGLE_instanced_arrays EXT_blend_minmax EXT_color_buffer_half_float EXT_float_blend EXT_frag_depth EXT_shader_texture_lod EXT_sRGB EXT_texture_compression_rgtc EXT_texture_filter_anisotropic MOZ_debug OES_element_index_uint OES_fbo_render_mipmap OES_standard_derivatives OES_texture_float OES_texture_float_linear OES_texture_half_float OES_texture_half_float_linear OES_vertex_array_object WEBGL_color_buffer_float WEBGL_compressed_texture_s3tc WEBGL_compressed_texture_s3tc_srgb WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_depth_texture WEBGL_draw_buffers WEBGL_lose_context","webgl1WSIInfo":"CGL\nIsWebglOutOfProcessEnabled: 1","webgl2Renderer":"Intel Inc. -- Intel Iris OpenGL Engine","webgl2Version":"4.1 INTEL-12.9.22","webgl2DriverExtensions":"GL_ARB_blend_func_extended GL_ARB_draw_buffers_blend GL_ARB_draw_indirect GL_ARB_ES2_compatibility GL_ARB_explicit_attrib_location GL_ARB_gpu_shader_fp64 GL_ARB_gpu_shader5 GL_ARB_instanced_arrays GL_ARB_internalformat_query GL_ARB_occlusion_query2 GL_ARB_sample_shading GL_ARB_sampler_objects GL_ARB_separate_shader_objects GL_ARB_shader_bit_encoding GL_ARB_shader_subroutine GL_ARB_shading_language_include GL_ARB_tessellation_shader GL_ARB_texture_buffer_object_rgb32 GL_ARB_texture_cube_map_array GL_ARB_texture_gather GL_ARB_texture_query_lod GL_ARB_texture_rgb10_a2ui GL_ARB_texture_storage GL_ARB_texture_swizzle GL_ARB_timer_query GL_ARB_transform_feedback2 GL_ARB_transform_feedback3 GL_ARB_vertex_attrib_64bit GL_ARB_vertex_type_2_10_10_10_rev GL_ARB_viewport_array GL_EXT_debug_label GL_EXT_debug_marker GL_EXT_framebuffer_multisample_blit_scaled GL_EXT_texture_compression_s3tc GL_EXT_texture_filter_anisotropic GL_EXT_texture_sRGB_decode GL_APPLE_client_storage GL_APPLE_container_object_shareable GL_APPLE_flush_render GL_APPLE_object_purgeable GL_APPLE_rgb_422 GL_APPLE_row_bytes GL_APPLE_texture_range GL_ATI_texture_mirror_once GL_NV_texture_barrier","webgl2Extensions":"EXT_color_buffer_float EXT_float_blend EXT_texture_compression_rgtc EXT_texture_filter_anisotropic MOZ_debug OES_texture_float_linear WEBGL_compressed_texture_s3tc WEBGL_compressed_texture_s3tc_srgb WEBGL_debug_renderer_info WEBGL_debug_shaders WEBGL_lose_context","webgl2WSIInfo":"CGL\nIsWebglOutOfProcessEnabled: 1","info":{"AzureCanvasBackend":"skia","AzureFallbackCanvasBackend":"none","AzureContentBackend":"skia","ApzWheelInput":1,"ApzDragInput":1,"ApzKeyboardInput":1,"ApzAutoscrollInput":1,"ApzZoomingInput":1,"TileHeight":512,"TileWidth":512,"CMSOutputProfile":"AAA.......//KM8xnzp/Q09ML1UPXe9m32+/eK+Bn4qPk4+cf6V/rn+3f8B/yY/Sn9uv5L/tz/bf//","DisplayCount":1,"Display0":"1280x1024 scale:1.000000"},"featureLog":{"features":[{"name":"HW_COMPOSITING","description":"Compositing","status":"available","log":[{"type":"default","status":"available"}]},{"name":"OPENGL_COMPOSITING","description":"OpenGL Compositing","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBRENDER","description":"WebRender","status":"disabled","log":[{"type":"default","status":"available"},{"type":"user","status":"disabled","message":"User force-enabled software WR"}]},{"name":"WEBRENDER_QUALIFIED","description":"WebRender qualified","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBRENDER_COMPOSITOR","description":"WebRender native compositor","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBRENDER_OPTIMIZED_SHADERS","description":"WebRender optimized shaders","status":"unavailable","log":[{"type":"default","status":"available"},{"type":"runtime","status":"unavailable","message":"WebRender disabled"}]},{"name":"WEBRENDER_ANGLE","description":"WebRender ANGLE","status":"unavailable","log":[{"type":"default","status":"available"},{"type":"env","status":"unavailable","message":"OS not supported"}]},{"name":"WEBRENDER_DCOMP_PRESENT","description":"WebRender DirectComposition","status":"unavailable","log":[{"type":"default","status":"available"},{"type":"user","status":"disabled","message":"User disabled via pref"},{"type":"env","status":"unavailable","message":"Requires Windows 10 or later"},{"type":"runtime","status":"unavailable","message":"Requires ANGLE"}]},{"name":"WEBRENDER_SOFTWARE","description":"WebRender software fallback","status":"force_enabled","log":[{"type":"default","status":"available"},{"type":"user","status":"force_enabled","message":"Force enabled by pref"}]},{"name":"OMTP","description":"Off Main Thread Painting","status":"available","log":[{"type":"default","status":"available"}]},{"name":"WEBGPU","description":"WebGPU","status":"disabled","log":[{"type":"default","status":"disabled","message":"Disabled by default"}]}],"fallbacks":[]},"crashGuards":[]},"addons":[{"name":"PageLoader extension","type":"extension","version":"1.1","isActive":true,"id":"pageloader@mozilla.org"},{"name":"Talos Powers","type":"extension","version":"1.1","isActive":true,"id":"talos-powers@mozilla.org"}],"features":[{"name":"DoH Roll-Out","version":"2.0.0","id":"doh-rollout@mozilla.org"},{"name":"Firefox Screenshots","version":"39.0.0","id":"screenshots@mozilla.org"},{"name":"Form Autofill","version":"1.0","id":"formautofill@mozilla.org"},{"name":"Web Compatibility Interventions","version":"20.1.0","id":"webcompat@mozilla.org"},{"name":"WebCompat Reporter","version":"1.4.0","id":"webcompat-reporter@mozilla.org"}],"normandy":{"addonStudies":[],"prefRollouts":[],"prefStudies":[]},"experimentalFeatures":[["experimental-features-abouthome-startup-cache","browser.startup.homepage.abouthome_cache.enabled",true],["experimental-features-cookie-samesite-lax-by-default2","network.cookie.sameSite.laxByDefault",true],["experimental-features-cookie-samesite-none-requires-secure2","network.cookie.sameSite.noneRequiresSecure",true],["experimental-features-cookie-samesite-schemeful","network.cookie.sameSite.schemeful",true],["experimental-features-css-constructable-stylesheets","layout.css.constructable-stylesheets.enabled",false],["experimental-features-css-masonry2","layout.css.grid-template-masonry-value.enabled",true],["experimental-features-devtools-color-scheme-simulation","devtools.inspector.color-scheme-simulation.enabled",true],["experimental-features-devtools-compatibility-panel","devtools.inspector.compatibility.enabled",true],["experimental-features-devtools-execution-context-selector","devtools.webconsole.input.context",true],["experimental-features-devtools-serviceworker-debugger-support","devtools.debugger.features.windowless-service-workers",false],["experimental-features-fission","fission.autostart",false],["experimental-features-http3","network.http.http3.enabled",false],["experimental-features-multi-pip","media.videocontrols.picture-in-picture.allow-multiple",true],["experimental-features-ime-search","browser.urlbar.keepPanelOpenDuringImeComposition",false],["experimental-features-web-api-inputmode","dom.forms.inputmode",true],["experimental-features-web-gpu2","dom.webgpu.enabled",false],["experimental-features-webrtc-global-mute-toggles","privacy.webrtc.globalMuteToggles",false]]}
[task 2021-02-20T23:39:36.547Z] 23:39:36     INFO -  TEST-INFO | 2263: exit 0
[task 2021-02-20T23:39:36.547Z] 23:39:36     INFO -  Browser initialized.
[task 2021-02-20T23:39:36.547Z] 23:39:36     INFO -  Fission enabled: False
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -  Running cycle 1/1 for pdfpaint test...
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -  Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.8rGEPS6kTO/Render',
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -   'EXTRA_MOZHARNESS_CONFIG': '{"installer_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XptwVGT6SDqmrKjTFfnlUA/artifacts/public/build/target.dmg", "test_packages_url": "https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XptwVGT6SDqmrKjTFfnlUA/artifacts/public/build/target.test_packages.json"}',
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -   'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central',
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -   'GECKO_HEAD_REV': '0796575658504e4a433be6041a3f29ef4fd0b5a4',
[task 2021-02-20T23:39:36.908Z] 23:39:36     INFO -   'HOME': '/Users/cltbld',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'JSGC_DISABLE_POISONING': '1',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'LANG': 'en_US.UTF-8',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'LC_ALL': 'en_US.UTF-8',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'LD_LIBRARY_PATH': '/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'LOGNAME': 'cltbld',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'MINIDUMP_SAVE_PATH': '/Users/cltbld/tasks/task_1613859502/build/blobber_upload_dir',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'MINIDUMP_STACKWALK': '/Users/cltbld/tasks/task_1613859502/fetches/minidump_stackwalk/minidump_stackwalk',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'MOZ_ACCELERATED': '1',
[task 2021-02-20T23:39:36.909Z] 23:39:36     INFO -   'MOZ_AUTOMATION': '1',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_CRASHREPORTER': '1',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_CRASHREPORTER_NO_REPORT': '1',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_FETCHES': '[{"artifact": "public/build/fix-stacks.tar.xz", "extract": true, "task": "EUMXXpnmTsWHSdt3Q2fkuQ"}, {"artifact": "public/build/minidump_stackwalk.tar.xz", "extract": true, "task": "esQGLSWSRg2_2C82FceOXg"}]',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_FETCHES_DIR': '/Users/cltbld/tasks/task_1613859502/fetches',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_NODE_PATH': '/usr/local/bin/node',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_SCM_LEVEL': '3',
[task 2021-02-20T23:39:36.910Z] 23:39:36     INFO -   'MOZ_UPLOAD_DIR': '/Users/cltbld/tasks/task_1613859502/build/blobber_upload_dir',
[task 2021-02-20T23:39:36.911Z] 23:39:36     INFO -   'MOZ_USE_PAGELOADER': '1',
[task 2021-02-20T23:39:36.911Z] 23:39:36     INFO -   'MOZ_WEBRENDER': '1',
[task 2021-02-20T23:39:36.911Z] 23:39:36     INFO -   'NO_EM_RESTART': '1',
[task 2021-02-20T23:39:36.911Z] 23:39:36     INFO -   'PATH': '/Users/cltbld/tasks/task_1613859502/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin',
[task 2021-02-20T23:39:36.911Z] 23:39:36     INFO -   'PWD': '/Users/cltbld',
[task 2021-02-20T23:39:36.912Z] 23:39:36     INFO -   'PYTHONPATH': '/Users/cltbld/tasks/task_1613859502/build/tests/talos',
[task 2021-02-20T23:39:36.912Z] 23:39:36     INFO -   'RUST_BACKTRACE': 'full',
[task 2021-02-20T23:39:36.912Z] 23:39:36     INFO -   'SCCACHE_DISABLE': '1',
[task 2021-02-20T23:39:36.912Z] 23:39:36     INFO -   'SHELL': '/bin/bash',
[task 2021-02-20T23:39:36.912Z] 23:39:36     INFO -   'SHLVL': '1',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.5kf16L427c/Listeners',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'STYLO_FORCE_ENABLED': '1',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'TASK_ID': 'cL7C5OlSTP6l4eavgzUa6A',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'TMPDIR': '/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/',
[task 2021-02-20T23:39:36.917Z] 23:39:36     INFO -   'USER': 'cltbld',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   'VIRTUAL_ENV': '/Users/cltbld/tasks/task_1613859502/build/venv',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   'XPC_FLAGS': '0x0',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   'XPC_SERVICE_NAME': '0',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   '_': '/usr/local/bin/generic-worker',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   '__CF_USER_TEXT_ENCODING': '0x27:0:0',
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -   '__PYVENV_LAUNCHER__': '/usr/local/bin/python3'}
[task 2021-02-20T23:39:36.918Z] 23:39:36     INFO -  TEST-INFO | started process 2273 (/Users/cltbld/tasks/task_1613859502/build/application/Firefox Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile)
[task 2021-02-20T23:39:40.199Z] 23:39:40     INFO -  PID 2273 | Cycle 1(1): loaded http://127.0.0.1:50059/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50059/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-20T23:39:41.295Z] 23:39:41     INFO -  PID 2273 | Error: Expected page 1 got 2
[task 2021-02-20T23:39:41.777Z] 23:39:41     INFO -  Terminating psutil.Process(pid=2273, name='firefox', started='23:39:36')
[task 2021-02-20T23:39:41.777Z] 23:39:41     INFO -  TEST-INFO | 2273: exit 0
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -  mozcrash checking /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpvcjZkH/profile/minidumps for minidumps...
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -  TEST-UNEXPECTED-ERROR | pdfpaint | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2021-02-20T23:39:41.815Z] 23:39:41    ERROR -  Traceback (most recent call last):
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/run_tests.py", line 337, in run_tests
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/ttest.py", line 65, in runTest
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/ttest.py", line 275, in _runTest
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -      counter_management.results() if counter_management else None
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/results.py", line 95, in add
[task 2021-02-20T23:39:41.815Z] 23:39:41     INFO -      global_counters=self.global_counters,
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/results.py", line 346, in __init__
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -      self.parse()
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/results.py", line 373, in parse
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -      "Could not find report in browser output: %s" % self.report_tokens
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -    File "/Users/cltbld/tasks/task_1613859502/build/tests/talos/talos/results.py", line 357, in error
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -      raise utils.TalosError(message)
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -  TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -  TEST-INFO took 8455ms
[task 2021-02-20T23:39:41.816Z] 23:39:41     INFO -  SUITE-END | took 430s
[task 2021-02-20T23:39:42.102Z] 23:39:42    ERROR - Return code: 2
[task 2021-02-20T23:39:42.102Z] 23:39:42  WARNING - setting return code to 2
[task 2021-02-20T23:39:42.102Z] 23:39:42    ERROR - # TBPL FAILURE #
[task 2021-02-20T23:39:42.103Z] 23:39:42     INFO - Running post-action listener: _package_coverage_data
[task 2021-02-20T23:39:42.103Z] 23:39:42     INFO - Running post-action listener: _resource_record_post_action
[task 2021-02-20T23:39:42.103Z] 23:39:42     INFO - Running post-action listener: process_java_coverage_data
[task 2021-02-20T23:39:42.103Z] 23:39:42     INFO - [mozharness: 2021-02-20 23:39:42.103170Z] Finished run-tests step (success)
[task 2021-02-20T23:39:42.103Z] 23:39:42     INFO - Running post-run listener: _resource_record_post_run
[task 2021-02-20T23:39:42.240Z] 23:39:42     INFO - Total resource usage - Wall time: 461s; CPU: 25.0%; Read bytes: 161054720; Write bytes: 1996410880; Read time: 5508; Write time: 13573
[task 2021-02-20T23:39:42.240Z] 23:39:42     INFO - TinderboxPrint: CPU usage<br/>25.1%

Sparky, does this require attention?

Flags: needinfo?(gmierz2)

Yes, this needs attention. It seems like the big issue is coming from the talos-other-* tests on the macosx1014-64-shippable-qr platform.

Here's an interesting line from there. It looks like the test itself is failing: https://treeherder.mozilla.org/logviewer?job_id=330514646&repo=autoland&lineNumber=4623

Excerpt from a failing test:

[task 2021-02-19T12:35:08.481Z] 12:35:08     INFO -   '__PYVENV_LAUNCHER__': '/usr/local/bin/python3'}
[task 2021-02-19T12:35:08.481Z] 12:35:08     INFO -  TEST-INFO | started process 1582 (/Users/cltbld/tasks/task_1613737584/build/application/Firefox Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/jg/kqc5xp8532z79s1bjhkhqx84000017/T/tmpnXFk_4/profile)
[task 2021-02-19T12:35:11.073Z] 12:35:11     INFO -  PID 1582 | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "http://127.0.0.1:50158"
[task 2021-02-19T12:35:11.392Z] 12:35:11     INFO -  PID 1582 | Cycle 1(1): loaded http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:35:12.919Z] 12:35:12     INFO -  PID 1582 | Cycle 1(2): loaded http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:35:13.663Z] 12:35:13     INFO -  PID 1582 | Cycle 1(3): loaded http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:35:14.522Z] 12:35:14     INFO -  PID 1582 | Cycle 1(4): loaded http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:35:15.769Z] 12:35:15     INFO -  PID 1582 | Cycle 1(5): loaded http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:50158/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:35:16.855Z] 12:35:16     INFO -  PID 1582 | Error: Expected page 1 got 2
[task 2021-02-19T12:35:17.240Z] 12:35:17     INFO -  Terminating psutil.Process(pid=1582, name='firefox', started='12:35:08')
[task 2021-02-19T12:35:17.240Z] 12:35:17     INFO -  TEST-INFO | 1582: exit 0

Excerpt from a passing test:

[task 2021-02-19T12:15:35.631Z] 12:15:35     INFO -  TEST-INFO | started process 1602 (/Users/cltbld/tasks/task_1613736100/build/application/Firefox Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/bc/pst9drxx23s9b4sfr94whfg8000017/T/tmpmEB_Ij/profile)
[task 2021-02-19T12:15:39.248Z] 12:15:39     INFO -  PID 1602 | Cycle 1(1): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:40.356Z] 12:15:40     INFO -  PID 1602 | Cycle 1(2): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:41.565Z] 12:15:41     INFO -  PID 1602 | Cycle 1(3): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:42.860Z] 12:15:42     INFO -  PID 1602 | Cycle 1(4): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:44.141Z] 12:15:44     INFO -  PID 1602 | Cycle 1(5): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:45.118Z] 12:15:45     INFO -  PID 1602 | Cycle 1(6): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:46.318Z] 12:15:46     INFO -  PID 1602 | Cycle 1(7): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:47.355Z] 12:15:47     INFO -  PID 1602 | Cycle 1(8): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:48.633Z] 12:15:48     INFO -  PID 1602 | Cycle 1(9): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:50.180Z] 12:15:50     INFO -  PID 1602 | Cycle 1(10): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:51.467Z] 12:15:51     INFO -  PID 1602 | Cycle 1(11): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:52.328Z] 12:15:52     INFO -  PID 1602 | Cycle 1(12): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:53.327Z] 12:15:53     INFO -  PID 1602 | Cycle 1(13): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:54.137Z] 12:15:54     INFO -  PID 1602 | Cycle 1(14): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:55.645Z] 12:15:55     INFO -  PID 1602 | Cycle 1(15): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:57.048Z] 12:15:57     INFO -  PID 1602 | Cycle 1(16): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:58.088Z] 12:15:58     INFO -  PID 1602 | Cycle 1(17): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:15:59.006Z] 12:15:59     INFO -  PID 1602 | Cycle 1(18): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:16:00.227Z] 12:16:00     INFO -  PID 1602 | Cycle 1(19): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)
[task 2021-02-19T12:16:01.053Z] 12:16:01     INFO -  PID 1602 | Cycle 1(20): loaded http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf (next: http://127.0.0.1:49985/tests/pdfpaint/tracemonkey.pdf)

:bdahl, since you're listed as the owner for the pdfpaint talos tests, could you look into this issue or find someone that could?

Flags: needinfo?(bdahl)

I've opened bug 1694189 to look into the pdfpaint issue.

Flags: needinfo?(bdahl)
Depends on: 1694189

Thanks :bdahl!

Flags: needinfo?(gmierz2)
See Also: → 1695502
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]

Looks like the changes in https://bugzilla.mozilla.org/show_bug.cgi?id=1649606#c5 made this bug to have frequent failures on macOS talos-other-e10s jobs. Backfills.
Failure log: https://treeherder.mozilla.org/logviewer?job_id=338425547&repo=autoland
Barret, could you have a look over these failures? Thank you.

Flags: needinfo?(brennie)

Greg, should we use this one to classify recent talos failures with Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] or should we open new bugs for each talos TEST-UNEXPECTED-ERROR ? Thanks.

Flags: needinfo?(gmierz2)

Let's classify them against this one for now - thanks for checking!

Flags: needinfo?(gmierz2)

There are 48 total failures in the last 7 days on

[task 2021-05-09T10:14:20.997Z] 10:14:20 INFO - TEST-INFO | started process 2244 (C:\Users\task_1620551343\build\application\firefox\firefox -wait-for-browser -no-deelevate -profile C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile about:home)
[task 2021-05-09T10:14:21.495Z] 10:14:21 INFO - PID 2244 | console.error: "Profiler could not init with object: {}"
[task 2021-05-09T10:14:21.498Z] 10:14:21 INFO - PID 2244 | __start_report507__end_report
[task 2021-05-09T10:14:21.499Z] 10:14:21 INFO - PID 2244 |
[task 2021-05-09T10:14:21.499Z] 10:14:21 INFO - PID 2244 | __startTimestamp336.35538231007376__endTimestamp
[task 2021-05-09T10:14:21.499Z] 10:14:21 INFO - PID 2244 |
[task 2021-05-09T10:14:21.522Z] 10:14:21 INFO - PID 2244 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\search.json.mozlz4", (void 0), 575))
[task 2021-05-09T10:14:21.670Z] 10:14:21 INFO - PID 2244 | console.log: "RemoteSettingsWorker error: Error: Can't import when we've started shutting down."
[task 2021-05-09T10:14:21.673Z] 10:14:21 INFO - PID 2244 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: region-update-timer
[task 2021-05-09T10:14:21.705Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine google@search.mozilla.org: AbortError: IOUtils.profileBeforeChange getter: IOUtils: profileBeforeChange phase has already finished"
[task 2021-05-09T10:14:21.734Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine amazondotcom@search.mozilla.org: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: callInstallListeners :: line 1519" data: no]"
[task 2021-05-09T10:14:21.736Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine wikipedia@search.mozilla.org: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: installBuiltinAddon :: line 2536" data: no]"
[task 2021-05-09T10:14:21.737Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine bing@search.mozilla.org: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: installBuiltinAddon :: line 2536" data: no]"
[task 2021-05-09T10:14:21.738Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine ddg@search.mozilla.org: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: installBuiltinAddon :: line 2536" data: no]"
[task 2021-05-09T10:14:21.739Z] 10:14:21 INFO - PID 2244 | console.error: "Could not load engine ebay@search.mozilla.org: [Exception... "AddonManager is not initialized" nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)" location: "JS frame :: resource://gre/modules/AddonManager.jsm :: installBuiltinAddon :: line 2536" data: no]"
[task 2021-05-09T10:14:21.740Z] 10:14:21 INFO - PID 2244 | console.warn: SearchService: "_init: abandoning init due to shutting down"
[task 2021-05-09T10:14:21.741Z] 10:14:21 INFO - PID 2244 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run
[task 2021-05-09T10:14:22.303Z] 10:14:22 INFO - TEST-INFO | 2244: exit 0
[task 2021-05-09T10:14:22.556Z] 10:14:22 INFO - mozcrash checking C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\minidumps for minidumps...
[task 2021-05-09T10:14:22.557Z] 10:14:22 INFO - Running cycle 2/10 for sessionrestore_no_auto_restore test...
[task 2021-05-09T10:14:22.557Z] 10:14:22 INFO - Reinstalling C:\Users\task_1620551343\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionstore.jsonlz4 on top of C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\sessionstore.jsonlz4
[task 2021-05-09T10:14:22.558Z] 10:14:22 INFO - Reinstalling C:\Users\task_1620551343\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionstore.js on top of C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\sessionstore.js
[task 2021-05-09T10:14:22.559Z] 10:14:22 INFO - Reinstalling C:\Users\task_1620551343\build\tests\talos\talos/startup_test/sessionrestore/profile\sessionCheckpoints.json on top of C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\sessionCheckpoints.json
[task 2021-05-09T10:14:22.561Z] 10:14:22 INFO - Using env: {'ALLUSERSPROFILE': 'C:\ProgramData',
[task 2021-05-09T10:14:22.561Z] 10:14:22 INFO - 'APPDATA': 'C:\Users\task_1620551343\AppData\Roaming',
[task 2021-05-09T10:14:22.561Z] 10:14:22 INFO - 'COMMONPROGRAMFILES': 'C:\Program Files\Common Files',
[task 2021-05-09T10:14:22.562Z] 10:14:22 INFO - 'COMMONPROGRAMFILES(X86)': 'C:\Program Files (x86)\Common Files',
[task 2021-05-09T10:14:22.562Z] 10:14:22 INFO - 'COMMONPROGRAMW6432': 'C:\Program Files\Common Files',
[task 2021-05-09T10:14:22.562Z] 10:14:22 INFO - 'COMPUTERNAME': 'T-W1064-MS-126',
[task 2021-05-09T10:14:22.563Z] 10:14:22 INFO - 'COMSPEC': 'C:\windows\system32\cmd.exe',
[task 2021-05-09T10:14:22.563Z] 10:14:22 INFO - 'DRIVERDATA': 'C:\Windows\System32\Drivers\DriverData',
[task 2021-05-09T10:14:22.563Z] 10:14:22 INFO - 'EXTRA_MOZHARNESS_CONFIG': '{"installer_url": '
[task 2021-05-09T10:14:22.564Z] 10:14:22 INFO - '"https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CIgg_BUNSdKEACzeFF327g/artifacts/public/build/target.zip", '
[task 2021-05-09T10:14:22.564Z] 10:14:22 INFO - '"test_packages_url": '
[task 2021-05-09T10:14:22.565Z] 10:14:22 INFO - '"https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CIgg_BUNSdKEACzeFF327g/artifacts/public/build/target.test_packages.json"}',
[task 2021-05-09T10:14:22.565Z] 10:14:22 INFO - 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central',
[task 2021-05-09T10:14:22.566Z] 10:14:22 INFO - 'GECKO_HEAD_REV': 'ca56a49fd420516b7200d4d680ea83b8d118c175',
[task 2021-05-09T10:14:22.566Z] 10:14:22 INFO - 'HG_CACHE': 'C:\tooltool-cache',
[task 2021-05-09T10:14:22.566Z] 10:14:22 INFO - 'HOMEDRIVE': 'C:',
[task 2021-05-09T10:14:22.566Z] 10:14:22 INFO - 'HOMEPATH': '\Users\task_1620551343',
[task 2021-05-09T10:14:22.567Z] 10:14:22 INFO - 'LD_LIBRARY_PATH': 'C:\Users\task_1620551343\build\application\firefox',
[task 2021-05-09T10:14:22.567Z] 10:14:22 INFO - 'LOCALAPPDATA': 'C:\Users\task_1620551343\AppData\Local',
[task 2021-05-09T10:14:22.568Z] 10:14:22 INFO - 'LOGONSERVER': '\\T-W1064-MS-126',
[task 2021-05-09T10:14:22.568Z] 10:14:22 INFO - 'MINIDUMP_SAVE_PATH': 'C:\Users\task_1620551343\build\blobber_upload_dir',
[task 2021-05-09T10:14:22.568Z] 10:14:22 INFO - 'MINIDUMP_STACKWALK': 'C:/Users/task_1620551343/fetches\minidump_stackwalk\minidump_stackwalk.exe',
[task 2021-05-09T10:14:22.569Z] 10:14:22 INFO - 'MOZILLABUILD': 'C:\mozilla-build',
[task 2021-05-09T10:14:22.569Z] 10:14:22 INFO - 'MOZ_ACCELERATED': '1',
[task 2021-05-09T10:14:22.569Z] 10:14:22 INFO - 'MOZ_AUTOMATION': '1',
[task 2021-05-09T10:14:22.569Z] 10:14:22 INFO - 'MOZ_CRASHREPORTER': '1',
[task 2021-05-09T10:14:22.570Z] 10:14:22 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1',
[task 2021-05-09T10:14:22.570Z] 10:14:22 INFO - 'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2021-05-09T10:14:22.570Z] 10:14:22 INFO - 'MOZ_FETCHES': '[{"artifact": "public/build/fix-stacks.tar.bz2", "extract": '
[task 2021-05-09T10:14:22.571Z] 10:14:22 INFO - 'true, "task": "Lhs91AvoT-28yyuTcna2Gw"}, {"artifact": '
[task 2021-05-09T10:14:22.571Z] 10:14:22 INFO - '"public/build/minidump_stackwalk.tar.xz", "extract": true, '
[task 2021-05-09T10:14:22.571Z] 10:14:22 INFO - '"task": "eJff2_1VTrWWmPPvPfuitQ"}]',
[task 2021-05-09T10:14:22.572Z] 10:14:22 INFO - 'MOZ_FETCHES_DIR': 'C:/Users/task_1620551343/fetches',
[task 2021-05-09T10:14:22.572Z] 10:14:22 INFO - 'MOZ_SCM_LEVEL': '3',
[task 2021-05-09T10:14:22.572Z] 10:14:22 INFO - 'MOZ_UPLOAD_DIR': 'C:\Users\task_1620551343\build\blobber_upload_dir',
[task 2021-05-09T10:14:22.572Z] 10:14:22 INFO - 'MOZ_WEBRENDER': '1',
[task 2021-05-09T10:14:22.573Z] 10:14:22 INFO - 'NO_EM_RESTART': '1',
[task 2021-05-09T10:14:22.573Z] 10:14:22 INFO - 'NUMBER_OF_PROCESSORS': '8',
[task 2021-05-09T10:14:22.573Z] 10:14:22 INFO - 'ONEDRIVE': 'C:\Users\task_1620551343\OneDrive',
[task 2021-05-09T10:14:22.573Z] 10:14:22 INFO - 'OS': 'Windows_NT',
[task 2021-05-09T10:14:22.574Z] 10:14:22 INFO - 'PATH': 'C:\Users\task_1620551343\build\venv\Scripts;C:\windows\system32;C:\windows;C:\windows\System32\Wbem;C:\windows\System32\WindowsPowerShell\v1.0\;C:\windows\System32\OpenSSH\;C:\Program '
[task 2021-05-09T10:14:22.574Z] 10:14:22 INFO - 'Files\Puppet Labs\Puppet\bin;C:\Program '
[task 2021-05-09T10:14:22.575Z] 10:14:22 INFO - 'Files\Mellanox\MLNX_VPI\IB\Tools;C:\Program '
[task 2021-05-09T10:14:22.575Z] 10:14:22 INFO - 'Files\Mellanox\MLNX_CIMProvider\lib\mft;C:\Program '
[task 2021-05-09T10:14:22.575Z] 10:14:22 INFO - 'Files\Git\cmd;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program '
[task 2021-05-09T10:14:22.576Z] 10:14:22 INFO - 'Files\Mercurial\;C:\Program '
[task 2021-05-09T10:14:22.576Z] 10:14:22 INFO - 'Files\Mercurial;C:\mozilla-build\bin;C:\mozilla-build\kdiff;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\nsis-3.01;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\Program '
[task 2021-05-09T10:14:22.576Z] 10:14:22 INFO - 'Files (x86)\Windows Kits\10\Windows Performance '
[task 2021-05-09T10:14:22.577Z] 10:14:22 INFO - 'Toolkit\;C:\Users\task_1620551343\AppData\Local\Microsoft\WindowsApps',
[task 2021-05-09T10:14:22.577Z] 10:14:22 INFO - 'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC',
[task 2021-05-09T10:14:22.577Z] 10:14:22 INFO - 'PIP_DOWNLOAD_CACHE': 'C:\pip-cache',
[task 2021-05-09T10:14:22.578Z] 10:14:22 INFO - 'PROCESSOR_ARCHITECTURE': 'AMD64',
[task 2021-05-09T10:14:22.578Z] 10:14:22 INFO - 'PROCESSOR_IDENTIFIER': 'Intel64 Family 6 Model 94 Stepping 3, GenuineIntel',
[task 2021-05-09T10:14:22.578Z] 10:14:22 INFO - 'PROCESSOR_LEVEL': '6',
[task 2021-05-09T10:14:22.578Z] 10:14:22 INFO - 'PROCESSOR_REVISION': '5e03',
[task 2021-05-09T10:14:22.579Z] 10:14:22 INFO - 'PROGRAMDATA': 'C:\ProgramData',
[task 2021-05-09T10:14:22.579Z] 10:14:22 INFO - 'PROGRAMFILES': 'C:\Program Files',
[task 2021-05-09T10:14:22.579Z] 10:14:22 INFO - 'PROGRAMFILES(X86)': 'C:\Program Files (x86)',
[task 2021-05-09T10:14:22.580Z] 10:14:22 INFO - 'PROGRAMW6432': 'C:\Program Files',
[task 2021-05-09T10:14:22.580Z] 10:14:22 INFO - 'PROMPT': '$P$G',
[task 2021-05-09T10:14:22.580Z] 10:14:22 INFO - 'PSMODULEPATH': '%ProgramFiles%\WindowsPowerShell\Modules;C:\windows\system32\WindowsPowerShell\v1.0\Modules;C:\Program '
[task 2021-05-09T10:14:22.580Z] 10:14:22 INFO - 'Files\Mellanox\MLNX_VPI\Tools\WMI\Modules;C:\Program '
[task 2021-05-09T10:14:22.581Z] 10:14:22 INFO - 'Files\Mellanox\MLNX_CIMProvider\WMI\Modules',
[task 2021-05-09T10:14:22.581Z] 10:14:22 INFO - 'PUBLIC': 'C:\Users\Public',
[task 2021-05-09T10:14:22.581Z] 10:14:22 INFO - 'PYTHON': 'c:\mozilla-build\python3\python3.exe',
[task 2021-05-09T10:14:22.581Z] 10:14:22 INFO - 'PYTHONPATH': 'C:\Users\task_1620551343\build\tests\talos',
[task 2021-05-09T10:14:22.582Z] 10:14:22 INFO - 'RUST_BACKTRACE': 'full',
[task 2021-05-09T10:14:22.582Z] 10:14:22 INFO - 'SCCACHE_DISABLE': '1',
[task 2021-05-09T10:14:22.582Z] 10:14:22 INFO - 'STYLO_FORCE_ENABLED': '1',
[task 2021-05-09T10:14:22.582Z] 10:14:22 INFO - 'SYSTEMDRIVE': 'C:',
[task 2021-05-09T10:14:22.583Z] 10:14:22 INFO - 'SYSTEMROOT': 'C:\windows',
[task 2021-05-09T10:14:22.583Z] 10:14:22 INFO - 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2021-05-09T10:14:22.583Z] 10:14:22 INFO - 'TASK_ID': 'Y9niZ7M7Sbm3Sle0nkP7rA',
[task 2021-05-09T10:14:22.583Z] 10:14:22 INFO - 'TASK_STOP_TIME': '1620554794',
[task 2021-05-09T10:14:22.583Z] 10:14:22 INFO - 'TEMP': 'C:\Users\task_1620551343\AppData\Local\Temp',
[task 2021-05-09T10:14:22.584Z] 10:14:22 INFO - 'TMP': 'C:\Users\task_1620551343\AppData\Local\Temp',
[task 2021-05-09T10:14:22.584Z] 10:14:22 INFO - 'TOOLTOOL_CACHE': 'C:\builds\tooltool_cache',
[task 2021-05-09T10:14:22.584Z] 10:14:22 INFO - 'USERDOMAIN': 'T-W1064-MS-126',
[task 2021-05-09T10:14:22.584Z] 10:14:22 INFO - 'USERDOMAIN_ROAMINGPROFILE': 'T-W1064-MS-126',
[task 2021-05-09T10:14:22.584Z] 10:14:22 INFO - 'USERNAME': 'task_1620551343',
[task 2021-05-09T10:14:22.585Z] 10:14:22 INFO - 'USERPROFILE': 'C:\Users\task_1620551343',
[task 2021-05-09T10:14:22.585Z] 10:14:22 INFO - 'VIRTUAL_ENV': 'C:\Users\task_1620551343\build\venv',
[task 2021-05-09T10:14:22.585Z] 10:14:22 INFO - 'WINDIR': 'C:\windows'}
[task 2021-05-09T10:14:22.586Z] 10:14:22 INFO - TEST-INFO | started process 3500 (C:\Users\task_1620551343\build\application\firefox\firefox -wait-for-browser -no-deelevate -profile C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile about:home)
[task 2021-05-09T10:14:22.855Z] 10:14:22 ERROR - PID 3500 | SessionRestoreTalosTest: error TypeError: can't access property "arguments", win is null
[task 2021-05-09T10:14:22.856Z] 10:14:22 INFO - PID 3500 | finishProfiling@file:///C:/Users/task_1620551343/AppData/Local/Temp/tmpd8ijlsj8/profile/extensions/session-restore-test-2@mozilla.org/api.js:53:16
[task 2021-05-09T10:14:22.856Z] 10:14:22 INFO - PID 3500 |
[task 2021-05-09T10:14:23.099Z] 10:14:23 INFO - PID 3500 |
[task 2021-05-09T10:14:23.100Z] 10:14:23 INFO - PID 3500 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-09T10:14:23.100Z] 10:14:23 INFO - PID 3500 |
[task 2021-05-09T10:14:23.537Z] 10:14:23 INFO - TEST-INFO | 3500: exit 0
[task 2021-05-09T10:14:23.585Z] 10:14:23 INFO - mozcrash checking C:\Users\task_1620551343\AppData\Local\Temp\tmpd8ijlsj8\profile\minidumps for minidumps...
[task 2021-05-09T10:14:23.586Z] 10:14:23 INFO - TEST-UNEXPECTED-ERROR | sessionrestore_no_auto_restore | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2021-05-09T10:14:23.586Z] 10:14:23 ERROR - Traceback (most recent call last):
[task 2021-05-09T10:14:23.586Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\run_tests.py", line 337, in run_tests
[task 2021-05-09T10:14:23.586Z] 10:14:23 INFO - talos_results.add(mytest.runTest(browser_config, test))
[task 2021-05-09T10:14:23.587Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\ttest.py", line 65, in runTest
[task 2021-05-09T10:14:23.587Z] 10:14:23 INFO - return self._runTest(browser_config, test_config, setup)
[task 2021-05-09T10:14:23.587Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\ttest.py", line 274, in _runTest
[task 2021-05-09T10:14:23.588Z] 10:14:23 INFO - counter_management.results() if counter_management else None
[task 2021-05-09T10:14:23.588Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\results.py", line 95, in add
[task 2021-05-09T10:14:23.588Z] 10:14:23 INFO - global_counters=self.global_counters,
[task 2021-05-09T10:14:23.588Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\results.py", line 346, in init
[task 2021-05-09T10:14:23.589Z] 10:14:23 INFO - self.parse()
[task 2021-05-09T10:14:23.589Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\results.py", line 373, in parse
[task 2021-05-09T10:14:23.589Z] 10:14:23 INFO - "Could not find report in browser output: %s" % self.report_tokens
[task 2021-05-09T10:14:23.590Z] 10:14:23 INFO - File "C:\Users\task_1620551343\build\tests\talos\talos\results.py", line 357, in error
[task 2021-05-09T10:14:23.590Z] 10:14:23 INFO - raise utils.TalosError(message)
[task 2021-05-09T10:14:23.590Z] 10:14:23 INFO - talos.utils.TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2021-05-09T10:14:23.591Z] 10:14:23 INFO - TEST-INFO took 5091ms
[task 2021-05-09T10:14:23.591Z] 10:14:23 INFO - SUITE-END | took 250s
[task 2021-05-09T10:14:23.802Z] 10:14:23 ERROR - Return code: 2
[task 2021-05-09T10:14:23.802Z] 10:14:23 WARNING - setting return code to 2
[task 2021-05-09T10:14:23.802Z] 10:14:23 ERROR - # TBPL FAILURE #
[task 2021-05-09T10:14:23.802Z] 10:14:23 INFO - Running post-action listener: _package_coverage_data
[task 2021-05-09T10:14:23.802Z] 10:14:23 INFO - Running post-action listener: _resource_record_post_action
[task 2021-05-09T10:14:23.802Z] 10:14:23 INFO - Running post-action listener: process_java_coverage_data
[task 2021-05-09T10:14:23.803Z] 10:14:23 INFO - [mozharness: 2021-05-09 10:14:23.802135Z] Finished run-tests step (success)
[task 2021-05-09T10:14:23.803Z] 10:14:23 INFO - Running post-run listener: _resource_record_post_run
[task 2021-05-09T10:14:23.896Z] 10:14:23 INFO - Total resource usage - Wall time: 252s; CPU: 14%; Read bytes: 84631552; Write bytes: 567294464; Read time: 1; Write time: 4
[task 2021-05-09T10:14:23.896Z] 10:14:23 INFO - TinderboxPrint: CPU usage<br/>13.8%
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - TinderboxPrint: I/O read bytes / time<br/>84,631,552 / 1
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - TinderboxPrint: I/O write bytes / time<br/>567,294,464 / 4
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - TinderboxPrint: CPU idle<br/>1,738.3 (86.2%)
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - TinderboxPrint: CPU system<br/>80.2 (4.0%)
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - TinderboxPrint: CPU user<br/>197.9 (9.8%)
[task 2021-05-09T10:14:23.897Z] 10:14:23 INFO - install - Wall time: 2s; CPU: 13%; Read bytes: 110592; Write bytes: 1925120; Read time: 0; Write time: 0
[task 2021-05-09T10:14:23.900Z] 10:14:23 INFO - run-tests - Wall time: 251s; CPU: 14%; Read bytes: 84020224; Write bytes: 422636032; Read time: 1; Write time: 4
[task 2021-05-09T10:14:23.968Z] 10:14:23 WARNING - returning nonzero exit status 2

Barret, did you get a chance to take a look at this?

Flags: needinfo?(brennie)
Flags: needinfo?(brennie)

From what I understand, the talos tests are failing due to win.arguments being null here (log) which is the case when BrowserWindowTracker.getTopWindow() cannot find a top window and returns null and so we never report to talos that we are finished.

As for why this is happening, I don't know. I also am unclear as to why bug 1649606 made this more.

:kashav I know you've been working on session store, could you perhaps take a look at this?

Flags: needinfo?(brennie) → needinfo?(kmadan)

It seems that the regressing patch changed stuff with the addon manager, so it'd be more likely that something is going wrong with the talos webextension, rather than Session Store itself.

I haven't touched this code in the past, so going to dump everything I find here:

Maybe the regressing patch introduced some weird interaction between SessionFile and how the talos webextension reads the file? Will probably need some more logs to figure out what's going wrong here, but it appears to not be related to Session Store.

Flags: needinfo?(kmadan)
Flags: needinfo?(brennie)

I've pushed a patch with extra logging to try to get more information.

Assignee: nobody → brennie

:sparky This should prevent the talos test failures, but I dont know if this will skew talos results because his will cause reports to complete when the test misbehaves.

Flags: needinfo?(brennie) → needinfo?(gmierz2)

Commented in the patch; we should take a look at a try run with many retriggers and see what it looks like.

Flags: needinfo?(gmierz2)

Hello, you are listed as an owner of the sessionrestore tests for Talos here: https://wiki.mozilla.org/TestEngineering/Performance/Talos/Tests#sessionrestore

Could either of you look the issues that we're having here or find someone that can? See the comments above for additional information on the failure, essentially, the browser window seems to be missing by the time the test reaches here: https://searchfox.org/mozilla-central/source/testing/talos/talos/startup_test/sessionrestore/addon/api.js#52-53

Here's a recent try run with the failures: https://treeherder.mozilla.org/jobs?repo=try&revision=6fa6ce8ad3b104657694f5621a89dd8f1fc98de4&selectedTaskRun=RgV_Hdj3TR-pAV-08VYIYA.0

This is a high-frequency failure and we'll have to disable it on macosx in the next 2-3 weeks if there's no action taken.

Flags: needinfo?(mdeboer)
Flags: needinfo?(mconley)
Flags: needinfo?(felipc)
Flags: needinfo?(dothayer)

See comment above.

Flags: needinfo?(mconley)
Attachment #9222211 - Attachment is obsolete: true

I'm about to go on a week of PTO, but I think I found a solution here, and wanted to get it off my plate before I went AFK. Anybody, feel free to commandeer this if there's follow-up work to do.

Flags: needinfo?(mdeboer)
Flags: needinfo?(mconley)
Flags: needinfo?(felipc)

Thanks a lot for fixing this :mconley! Patch is landing.

Pushed by gmierz2@outlook.com: https://hg.mozilla.org/integration/autoland/rev/e1fec3843185 Ensure first browser window is available before finishing sessionrestore_no_autorestore Talos test. r=sparky,perftest-reviewers

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

Status: REOPENED → RESOLVED
Closed: 4 years ago → 3 years ago
status-firefox90: --- → fixed
Resolution: --- → FIXED
Target Milestone: mozilla52 → 90 Branch

Hi Greg, this is still happening https://treeherder.mozilla.org/logviewer?job_id=340987006&repo=mozilla-central&lineNumber=2129
Should we file a different bug?

Flags: needinfo?(gmierz2)

Hi Andreea, thanks for checking! Yes, I think we should file a new bug now, this one is getting too big. Could you add this bug to the See also field of the new one?

Flags: needinfo?(gmierz2)
See Also: → 1713226

(In reply to Greg Mierzwinski [:sparky] from comment #319)

Hi Andreea, thanks for checking! Yes, I think we should file a new bug now, this one is getting too big. Could you add this bug to the See also field of the new one?

Yes, thank you!

See Also: → 1579683
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: