1331919 - Intermittent ts_paint,ts_paint_webext | Multiple matches for __startTimestamp,__endTimestamp after TypeError: winData is undefined after BROWSER FAILED TO GENERATE MOZAFTERPAINT IN 5 SECONDS

Status: RESOLVED INCOMPLETE

(Testing :: Talos, defect)

Description

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

https://treeherder.mozilla.org/logviewer.html#?job_id=69907325&repo=autoland

03:12:07     INFO -  PROCESS | 3380 | __startTimestamp1484737927020__endTimestamp
03:12:08     INFO -  TEST-INFO | 3380: exit 0
03:12:08     INFO -  Running cycle 19/20 for ts_paint test...
03:12:08     INFO -  TEST-INFO | started process 76 (C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpmu9jwv\profile http://localhost:49276/startup_test/tspaint_test.html)
03:12:09     INFO -  PROCESS | 76 | __start_report943__end_report
03:12:09     INFO -  PROCESS | 76 |
03:12:09     INFO -  PROCESS | 76 | __startTimestamp1484737929311__endTimestamp
03:12:10     INFO -  TEST-INFO | 76: exit 0
03:12:10     INFO -  Running cycle 20/20 for ts_paint test...
03:12:10     INFO -  TEST-INFO | started process 3376 (C:\slave\test\build\application\firefox\firefox -profile c:\users\cltbld~1.t-w\appdata\local\temp\tmpmu9jwv\profile http://localhost:49276/startup_test/tspaint_test.html)
03:12:12     INFO -  PROCESS | 3376 | __start_report981__end_report
03:12:12     INFO -  PROCESS | 3376 |
03:12:15     INFO -  PROCESS | 3376 | __startTimestamp1484737935712__endTimestamp
03:12:17     INFO -  PROCESS | 3376 | BROWSER FAILED TO GENERATE MOZAFTERPAINT IN 5 SECONDS__startTimestamp1484737937739__endTimestamp
03:12:17     INFO -  PROCESS | 3376 | *************************
03:12:17     INFO -  PROCESS | 3376 | A coding exception was thrown and uncaught in a Task.
03:12:17     INFO -  PROCESS | 3376 |
03:12:17    ERROR -  PROCESS | 3376 | Full message: TypeError: winData is undefined
03:12:17     INFO -  PROCESS | 3376 | Full stack: ssi_collectWindowData@resource:///modules/sessionstore/SessionStore.jsm:3106:9
03:12:17     INFO -  PROCESS | 3376 | SessionStoreInternal.flushAllWindowsAsync<@resource:///modules/sessionstore/SessionStore.jsm:1650:7
03:12:17     INFO -  PROCESS | 3376 | TaskImpl_run@resource://gre/modules/Task.jsm:319:42
03:12:17     INFO -  PROCESS | 3376 | process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
03:12:17     INFO -  PROCESS | 3376 | walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
03:12:17     INFO -  PROCESS | 3376 | Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
03:12:17     INFO -  PROCESS | 3376 | schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
03:12:17     INFO -  PROCESS | 3376 | Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:450:5
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:777:9
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:503:5
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:440:7
03:12:17     INFO -  PROCESS | 3376 | ssi_onQuitApplicationGranted@resource:///modules/sessionstore/SessionStore.jsm:1574:7
03:12:17     INFO -  PROCESS | 3376 | ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:725:9
03:12:17     INFO -  PROCESS | 3376 | canQuitApplication@http://localhost:49276/tests/quit.js:67:3
03:12:17     INFO -  PROCESS | 3376 | goQuitApplication@http://localhost:49276/tests/quit.js:109:8
03:12:17     INFO -  PROCESS | 3376 | dumpConsoleAndQuit/<@http://localhost:49276/startup_test/tspaint_test.html:59:5
03:12:17     INFO -  PROCESS | 3376 | observe@resource://gre/modules/AsyncShutdown.jsm:550:9
03:12:17     INFO -  PROCESS | 3376 | canQuitApplication@http://localhost:49276/tests/quit.js:67:3
03:12:17     INFO -  PROCESS | 3376 | goQuitApplication@http://localhost:49276/tests/quit.js:109:8
03:12:17     INFO -  PROCESS | 3376 | dumpConsoleAndQuit/<@http://localhost:49276/startup_test/tspaint_test.html:59:5
03:12:17     INFO -  PROCESS | 3376 | setTimeout handler*dumpConsoleAndQuit@http://localhost:49276/startup_test/tspaint_test.html:55:3
03:12:17     INFO -  PROCESS | 3376 | painted/<@http://localhost:49276/startup_test/tspaint_test.html:29:5
03:12:17     INFO -  PROCESS | 3376 | promise callback*painted@http://localhost:49276/startup_test/tspaint_test.html:22:3
03:12:17     INFO -  PROCESS | 3376 | EventListener.handleEvent*@http://localhost:49276/startup_test/tspaint_test.html:64:1
03:12:17     INFO -  PROCESS | 3376 |
03:12:17     INFO -  PROCESS | 3376 | *************************
03:12:17     INFO -  PROCESS | 3376 | WARNING: A blocker encountered an error while we were waiting.
03:12:17     INFO -  PROCESS | 3376 |           Blocker:  SessionStore: flushing all windows
03:12:17     INFO -  PROCESS | 3376 |           Phase: quit-application-granted
03:12:17     INFO -  PROCESS | 3376 |           State: {"total":1,"current":0}
03:12:17    ERROR -  PROCESS | 3376 | WARNING: TypeError: winData is undefined
03:12:17     INFO -  PROCESS | 3376 | WARNING: ssi_collectWindowData@resource:///modules/sessionstore/SessionStore.jsm:3106:9
03:12:17     INFO -  PROCESS | 3376 | SessionStoreInternal.flushAllWindowsAsync<@resource:///modules/sessionstore/SessionStore.jsm:1650:7
03:12:17     INFO -  PROCESS | 3376 | TaskImpl_run@resource://gre/modules/Task.jsm:319:42
03:12:17     INFO -  PROCESS | 3376 | process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
03:12:17     INFO -  PROCESS | 3376 | walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
03:12:17     INFO -  PROCESS | 3376 | Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
03:12:17     INFO -  PROCESS | 3376 | schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
03:12:17     INFO -  PROCESS | 3376 | Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:450:5
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:777:9
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:503:5
03:12:17     INFO -  PROCESS | 3376 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:440:7
03:12:17     INFO -  PROCESS | 3376 | ssi_onQuitApplicationGranted@resource:///modules/sessionstore/SessionStore.jsm:1574:7
03:12:17     INFO -  PROCESS | 3376 | ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:725:9
03:12:17     INFO -  PROCESS | 3376 | canQuitApplication@http://localhost:49276/tests/quit.js:67:3
03:12:17     INFO -  PROCESS | 3376 | goQuitApplication@http://localhost:49276/tests/quit.js:109:8
03:12:17     INFO -  PROCESS | 3376 | dumpConsoleAndQuit/<@http://localhost:49276/startup_test/tspaint_test.html:59:5
03:12:17     INFO -  PROCESS | 3376 | observe@resource://gre/modules/AsyncShutdown.jsm:550:9
03:12:17     INFO -  PROCESS | 3376 | canQuitApplication@http://localhost:49276/tests/quit.js:67:3
03:12:17     INFO -  PROCESS | 3376 | goQuitApplication@http://localhost:49276/tests/quit.js:109:8
03:12:17     INFO -  PROCESS | 3376 | dumpConsoleAndQuit/<@http://localhost:49276/startup_test/tspaint_test.html:59:5
03:12:17     INFO -  PROCESS | 3376 | setTimeout handler*dumpConsoleAndQuit@http://localhost:49276/startup_test/tspaint_test.html:55:3
03:12:17     INFO -  PROCESS | 3376 | painted/<@http://localhost:49276/startup_test/tspaint_test.html:29:5
03:12:17     INFO -  PROCESS | 3376 | promise callback*painted@http://localhost:49276/startup_test/tspaint_test.html:22:3
03:12:17     INFO -  PROCESS | 3376 | EventListener.handleEvent*@http://localhost:49276/startup_test/tspaint_test.html:64:1
03:12:17     INFO -  PROCESS | 3376 |
03:12:20     INFO -  TEST-INFO | 3376: exit 0
03:12:21     INFO -  TEST-UNEXPECTED-ERROR | ts_paint | Multiple matches for __startTimestamp,__endTimestamp
03:12:21    ERROR -  Traceback (most recent call last):
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\run_tests.py", line 202, in run_tests
03:12:21     INFO -      talos_results.add(mytest.runTest(browser_config, test))
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\ttest.py", line 70, in runTest
03:12:21     INFO -      return self._runTest(browser_config, test_config, setup)
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\ttest.py", line 232, in _runTest
03:12:21     INFO -      else None)
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\results.py", line 94, in add
03:12:21     INFO -      global_counters=self.global_counters
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\results.py", line 311, in __init__
03:12:21     INFO -      self.parse()
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\results.py", line 344, in parse
03:12:21     INFO -      value, _last_token = self.get_single_token(*tokens)
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\results.py", line 375, in get_single_token
03:12:21     INFO -      self.error("Multiple matches for %s,%s" % (start_token, end_token))
03:12:21     INFO -    File "C:\slave\test\build\tests\talos\talos\results.py", line 322, in error
03:12:21     INFO -      raise utils.TalosError(message)
03:12:21     INFO -  TalosError: Multiple matches for __startTimestamp,__endTimestamp
03:12:21     INFO -  TEST-INFO took 62819ms
03:12:21     INFO -  SUITE-END | took 174s

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

no instances in the last 2 months.

Comment 2

[Intermittent Failures Robot]

1 failures in 720 pushes (0.001 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1331919&startday=2017-07-10&endday=2017-07-16&tree=all

Comment 3

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

https://treeherder.mozilla.org/logviewer.html#?job_id=154983972&repo=mozilla-central

Comment 4

[Intermittent Failures Robot]

2 failures in 788 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1
* mozilla-central: 1

Platform breakdown:
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1331919&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures in 747 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1331919&startday=2018-03-05&endday=2018-03-11&tree=all