Closed Bug 1547943 Opened 2 years ago Closed 9 months ago

Intermittent mozrunner.errors.RunnerNotStartedError: returncode accessed before runner started

Categories

(Testing :: Raptor, defect, P5)

Version 3
defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 unaffected, firefox67 unaffected, firefox68 wontfix, firefox69 wontfix, firefox70 wontfix, firefox71 fixed)

RESOLVED INCOMPLETE
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox67 --- unaffected
firefox68 --- wontfix
firefox69 --- wontfix
firefox70 --- wontfix
firefox71 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=243534707&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/DiMYkWDrTnykFjq0MHHHRQ/runs/0/artifacts/public/logs/live_backing.log


07:56:52 INFO - mozproxy Starting mitmproxy playback using command: C:\Users\task_1556608865\testing\mozproxy\mitmdump --replay-kill-extra --script ""C:\\Users\\task_1556608865\\build\\tests\\raptor\\raptor\\playback\\alternate-server-replay-2.0.2.py C:\\Users\\task_1556608865\\testing\\mozproxy\\reddit.mp""
07:57:41 INFO - mozproxy Aborting: Mitmproxy process did not startup
07:57:41 INFO - mozproxy Stopping mitmproxy playback, killing process 1728
07:57:41 INFO - mozproxy Mitmproxy exited with error code 572
07:57:41 INFO - raptor-control-server shutting down control server
07:57:41 INFO - raptor-main finished
07:57:41 ERROR - Traceback (most recent call last):
07:57:41 INFO - File "C:\Users\task_1556608865\build\tests\raptor\raptor\raptor.py", line 964, in <module>
07:57:41 INFO - main()
07:57:41 INFO - File "C:\Users\task_1556608865\build\tests\raptor\raptor\raptor.py", line 927, in main
07:57:41 INFO - raptor.run_test(next_test, timeout=int(next_test['page_timeout']))
07:57:41 INFO - File "C:\Users\task_1556608865\build\tests\raptor\raptor\raptor.py", line 457, in run_test
07:57:41 INFO - self.run_test_teardown()
07:57:41 INFO - File "C:\Users\task_1556608865\build\tests\raptor\raptor\raptor.py", line 462, in run_test_teardown
07:57:41 INFO - if self.runner.is_running():
07:57:41 INFO - File "C:\Users\task_1556608865\build\venv\lib\site-packages\mozrunner\base\runner.py", line 176, in is_running
07:57:41 INFO - return self.returncode is None
07:57:41 INFO - File "C:\Users\task_1556608865\build\venv\lib\site-packages\mozrunner\base\runner.py", line 92, in returncode
07:57:41 INFO - raise RunnerNotStartedError("returncode accessed before runner started")
07:57:41 INFO - mozrunner.errors.RunnerNotStartedError: returncode accessed before runner started
07:57:42 ERROR - Return code: 1
07:57:42 WARNING - setting return code to 1
07:57:42 CRITICAL - PERFHERDER_DATA was seen 0 times, expected 1.
07:57:42 INFO - copying raptor results to upload dir:
07:57:42 INFO - C:\Users\task_1556608865\build\blobber_upload_dir\perfherder-data.json
07:57:42 INFO - copying raptor results from C:\Users\task_1556608865\build\raptor.json to C:\Users\task_1556608865\build\blobber_upload_dir\perfherder-data.json
07:57:42 CRITICAL - Error copying results C:\Users\task_1556608865\build\raptor.json to upload dir C:\Users\task_1556608865\build\blobber_upload_dir\perfherder-data.json

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE

Can we take a look over this issue and make sure we return the proper error...
From the log it looks like mitmproxy failed to start but the error is from raptor:

[task 2019-09-08T00:26:21.904Z] 00:26:21     INFO -  mozproxy downloading mitmproxy pageset
[task 2019-09-08T00:26:30.054Z] 00:26:30     INFO -  mozproxy INFO - File mitm4-linux-firefox-google-search.zip retrieved from local cache C:\builds\tooltool_cache
[task 2019-09-08T00:26:30.064Z] 00:26:30     INFO -  mozproxy INFO - unzipping "mitm4-linux-firefox-google-search.zip"
[task 2019-09-08T00:26:30.171Z] 00:26:30     INFO -  mozproxy mitmdump path: C:\Users\task_1567899972\testing\mozproxy\mitmdump-4.0.4\mitmdump
[task 2019-09-08T00:26:30.171Z] 00:26:30     INFO -  mozproxy browser path: C:\Users\task_1567899972\build\application\firefox\firefox.exe
[task 2019-09-08T00:26:30.172Z] 00:26:30     INFO -  mozproxy Starting mitmproxy playback using env path: C:\Users\task_1567899972\build\application\firefox;C:\Users\task_1567899972\build\venv\Scripts;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\WINDOWS\System32\OpenSSH\;C:\Program Files\Puppet Labs\Puppet\bin;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program Files\Mercurial\;C:\Program 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 Files (x86)\Windows Kits\10\Windows Performance Toolkit\;C:\Program Files\Git\cmd;C:\Users\task_1567899972\AppData\Local\Microsoft\WindowsApps
[task 2019-09-08T00:26:30.172Z] 00:26:30     INFO -  mozproxy Starting mitmproxy playback using command: C:\Users\task_1567899972\testing\mozproxy\mitmdump-4.0.4\mitmdump -v --set upstream_cert=false --set websocket=false --set server_replay_files=C:\\\Users\\\task_1567899972\\\testing\\\mozproxy\\\google-search.mp --scripts C:\\\Users\\\task_1567899972\\\build\\\venv\\\lib\\\site-packages\\\mozproxy\\\backends\\\mitm\\\scripts\\\alternate-server-replay-4.0.4.py
[task 2019-09-08T00:27:06.614Z] 00:27:06     INFO -  mozproxy Aborting: Mitmproxy process did not startup
[task 2019-09-08T00:27:06.614Z] 00:27:06     INFO -  mozproxy Stopping mitmproxy playback, killing process 1736
[task 2019-09-08T00:27:06.631Z] 00:27:06     INFO -  mozproxy Mitmproxy exited with error code 572
[task 2019-09-08T00:27:06.631Z] 00:27:06     INFO -  raptor-control-server Info: shutting down control server
[task 2019-09-08T00:27:06.801Z] 00:27:06     INFO -  raptor-main Info: finished
[task 2019-09-08T00:27:06.806Z] 00:27:06    ERROR -  Traceback (most recent call last):
[task 2019-09-08T00:27:06.806Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\tests\raptor\raptor\raptor.py", line 1394, in <module>
[task 2019-09-08T00:27:06.806Z] 00:27:06     INFO -      main()
[task 2019-09-08T00:27:06.806Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\tests\raptor\raptor\raptor.py", line 1362, in main
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\tests\raptor\raptor\raptor.py", line 201, in run_tests
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -      self.run_test_teardown(test)
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\tests\raptor\raptor\raptor.py", line 782, in run_test_teardown
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -      if self.runner.is_running():
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\venv\lib\site-packages\mozrunner\base\runner.py", line 176, in is_running
[task 2019-09-08T00:27:06.807Z] 00:27:06     INFO -      return self.returncode is None
[task 2019-09-08T00:27:06.808Z] 00:27:06     INFO -    File "C:\Users\task_1567899972\build\venv\lib\site-packages\mozrunner\base\runner.py", line 92, in returncode
[task 2019-09-08T00:27:06.808Z] 00:27:06     INFO -      raise RunnerNotStartedError("returncode accessed before runner started")
[task 2019-09-08T00:27:06.808Z] 00:27:06     INFO -  mozrunner.errors.RunnerNotStartedError: returncode accessed before runner started
[task 2019-09-08T00:27:06.936Z] 00:27:06    ERROR - Return code: 1
Flags: needinfo?(marian.raiciof)
Flags: needinfo?(alexandru.ionescu)
Assignee: nobody → alexandru.ionescu
Flags: needinfo?(alexandru.ionescu)

The issue seems to be related to the LOG variable that is used in mitm.py file:
https://searchfox.org/mozilla-central/source/testing/mozbase/mozproxy/mozproxy/backends/mitm/mitm.py#19-23
That LOG imported from mozproxy.utils will display INFO messages even when LOG.error() is used.

Proposed solution: import RaptorLogger class and use that as the logging class:
https://searchfox.org/mozilla-central/source/testing/raptor/logger/logger.py#12
https://searchfox.org/mozilla-central/source/testing/raptor/raptor/raptor.py#67

I will create a patch.

Flags: needinfo?(marian.raiciof)
Pushed by mraiciof@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6f5711305396
Intermittent mozrunner.errors.RunnerNotStartedError r=perftest-reviewers,sparky
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Assignee: alexandru.ionescu → marian.raiciof

Doesn't seem to be fixed: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=testfailed%2Cbusted%2Cexception&searchStr=windows%2C10%2Cx64%2C2017%2Cref%2Chw%2Copt&revision=9a16c53ed5c313681b657961a6ae7c6ecf1dfc49&selectedJob=270326991

Log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=270326991&repo=mozilla-central&lineNumber=657

[task 2019-10-08T18:31:50.753Z] 18:31:50 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using env path: C:\Users\task_1570555129\build\application\firefox;C:\Users\task_1570555129\build\venv\Scripts;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0;C:\WINDOWS\System32\OpenSSH;C:\Program Files\Puppet Labs\Puppet\bin;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program Files\Mercurial;C:\Program 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 Files (x86)\Windows Kits\10\Windows Performance Toolkit;C:\Program Files\Git\cmd;C:\Users\task_1570555129\AppData\Local\Microsoft\WindowsApps
[task 2019-10-08T18:31:50.753Z] 18:31:50 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using command: C:\Users\task_1570555129\testing\mozproxy\mitmdump-4.0.4\mitmdump -v --set upstream_cert=false --set websocket=false --set server_replay_files=C:\\Users\\task_1570555129\\testing\\mozproxy\\amazon.mp --scripts C:\\Users\\task_1570555129\\build\\venv\\lib\\site-packages\\mozproxy\\backends\\mitm\\scripts\\alternate-server-replay-4.0.4.py
[task 2019-10-08T18:32:22.132Z] 18:32:22 ERROR - raptor-mitmproxy Error: Aborting: Mitmproxy process did not startup
[task 2019-10-08T18:32:22.132Z] 18:32:22 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 4148
[task 2019-10-08T18:32:22.162Z] 18:32:22 ERROR - raptor-mitmproxy Error: Mitmproxy exited with error code 572
[task 2019-10-08T18:32:22.162Z] 18:32:22 INFO - raptor-control-server Info: shutting down control server
[task 2019-10-08T18:32:22.621Z] 18:32:22 INFO - raptor-main Info: finished
[task 2019-10-08T18:32:22.623Z] 18:32:22 ERROR - Traceback (most recent call last):
[task 2019-10-08T18:32:22.623Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\tests\raptor\raptor\raptor.py", line 1521, in <module>
[task 2019-10-08T18:32:22.623Z] 18:32:22 INFO - main()
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\tests\raptor\raptor\raptor.py", line 1489, in main
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\tests\raptor\raptor\raptor.py", line 212, in run_tests
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - self.run_test_teardown(test)
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\tests\raptor\raptor\raptor.py", line 903, in run_test_teardown
[task 2019-10-08T18:32:22.624Z] 18:32:22 INFO - if self.runner.is_running():
[task 2019-10-08T18:32:22.625Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\venv\lib\site-packages\mozrunner\base\runner.py", line 171, in is_running
[task 2019-10-08T18:32:22.625Z] 18:32:22 INFO - return self.returncode is None
[task 2019-10-08T18:32:22.625Z] 18:32:22 INFO - File "C:\Users\task_1570555129\build\venv\lib\site-packages\mozrunner\base\runner.py", line 87, in returncode
[task 2019-10-08T18:32:22.625Z] 18:32:22 INFO - raise RunnerNotStartedError("returncode accessed before runner started")
[task 2019-10-08T18:32:22.625Z] 18:32:22 INFO - mozrunner.errors.RunnerNotStartedError: returncode accessed before runner started
[task 2019-10-08T18:32:23.040Z] 18:32:23 ERROR - Return code: 1
[task 2019-10-08T18:32:23.040Z] 18:32:23 WARNING - setting return code to 1
[task 2019-10-08T18:32:23.040Z] 18:32:23 INFO - Copying Raptor results to upload dir:
[task 2019-10-08T18:32:23.040Z] 18:32:23 INFO - C:\Users\task_1570555129\build\blobber_upload_dir\perfherder-data.json
[task 2019-10-08T18:32:23.041Z] 18:32:23 INFO - Copying raptor results from C:\Users\task_1570555129\build\raptor.json to C:\Users\task_1570555129\build\blobber_upload_dir\perfherder-data.json
[task 2019-10-08T18:32:23.041Z] 18:32:23 CRITICAL - Error copying results C:\Users\task_1570555129\build\raptor.json to upload dir C:\Users\task_1570555129\build\blobber_upload_dir\perfherder-data.json

Flags: needinfo?(marian.raiciof)

Robert,
Could you please redirect this to someone who can look into it?

Flags: needinfo?(rwood)

I think we should mark this as a duplicate for
https://bugzilla.mozilla.org/show_bug.cgi?id=1587387

Assignee: marian.raiciof → nobody
Flags: needinfo?(marian.raiciof)
See Also: → 1587387
Flags: needinfo?(rwood)
Resolution: FIXED → DUPLICATE
Duplicate of bug: 1587387
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---

There are 37 failures associated to this bug in the last 7 days. These are occurring on windows10-64-ref-hw-2017 opt builds.

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

See Also: → 1611781
See Also: 1611781

Should be resolved by:
Bug 1611110

Status: REOPENED → RESOLVED
Closed: 1 year ago9 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.