Open Bug 1798766 Opened 3 years ago Updated 3 years ago

when running process-switch and welcome tests on upgraded python, the tests fail to run

Categories

(Testing :: Performance, defect, P3)

Product:
Testing
Component:
Performance
Version:
Default
Type:
defect

Tracking

(Not tracked)

People

(Reporter: jmaher, Unassigned)

Details

on try we appear to run all the talos/browsertime tests just fine except for ps and welcome. There are no in-tree changes, we are working on the image. The changes to the image of concern are upgrading python from 3.6.5 -> 3.9.5.

For some reason these two tests fail, here is a clip from a ps log:

[task 2022-10-31T19:00:34.637Z] 19:00:34     INFO -  raptor-browsertime Info: Running tests using Firefox - 25 iteration(s)
[task 2022-10-31T19:00:34.640Z] 19:00:34     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-10-31T19:00:38.009Z] 19:00:38     INFO -  raptor-browsertime Info: Starting a process switch test
[task 2022-10-31T19:00:38.010Z] 19:00:38     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-10-31T19:00:39.010Z] 19:00:39     INFO -  raptor-browsertime Info: Navigating to about:blank
[task 2022-10-31T19:00:39.010Z] 19:00:39     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2022-10-31T19:00:44.043Z] 19:00:44     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-10-31T19:00:45.043Z] 19:00:45     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-10-31T19:00:45.043Z] 19:00:45     INFO -  raptor-browsertime Info: Navigating to url https://mozilla.seanfeng.dev/files/red.html iteration 1
[task 2022-10-31T19:00:53.075Z] 19:00:53     INFO -  raptor-browsertime Info: Testing url https://mozilla.pettay.fi/moztests/blue.html iteration 1
[task 2022-10-31T19:00:53.076Z] 19:00:53     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-10-31T19:00:58.940Z] 19:00:58     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-10-31T19:00:58.976Z] 19:00:58    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-10-31T19:00:59.033Z] 19:00:59 CRITICAL -  raptor-browsertime Critical: Could not find window recording directory in C:\Users\task_1667241843\build\blobber_upload_dir\browsertime-results\process-switch
[task 2022-10-31T19:00:59.033Z] 19:00:59     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-10-31T19:00:59.033Z] 19:00:59     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-10-31T19:00:59.034Z] 19:00:59     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 4728
[task 2022-10-31T19:00:59.034Z] 19:00:59     INFO -  raptor-mitmproxy Info: Sending CTRL_BREAK_EVENT to mitmproxy
[task 2022-10-31T19:01:01.033Z] 19:01:01     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2022-10-31T19:01:01.034Z] 19:01:01     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-10-31T19:01:01.034Z] 19:01:01     INFO -  raptor-mitmproxy Info: writing: C:\Users\task_1667241843\build\application\firefox\distribution\policies.json
[task 2022-10-31T19:01:01.035Z] 19:01:01     INFO -  raptor-perftest Info: Removing temporary directory: C:\Users\task_1667241843\AppData\Local\Temp\tmpd7grpgn9
[task 2022-10-31T19:01:01.064Z] 19:01:01    ERROR -  Traceback (most recent call last):
[task 2022-10-31T19:01:01.064Z] 19:01:01     INFO -    File "C:\Users\task_1667241843\build\tests\raptor\raptor\raptor.py", line 206, in <module>
[task 2022-10-31T19:01:01.064Z] 19:01:01     INFO -      main()
[task 2022-10-31T19:01:01.065Z] 19:01:01     INFO -    File "C:\Users\task_1667241843\build\tests\raptor\raptor\raptor.py", line 152, in main
[task 2022-10-31T19:01:01.065Z] 19:01:01     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-10-31T19:01:01.066Z] 19:01:01     INFO -    File "C:\Users\task_1667241843\build\tests\raptor\raptor\perftest.py", line 467, in run_tests
[task 2022-10-31T19:01:01.066Z] 19:01:01     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-10-31T19:01:01.067Z] 19:01:01     INFO -    File "C:\Users\task_1667241843\build\tests\raptor\raptor\browsertime\base.py", line 801, in run_test
[task 2022-10-31T19:01:01.067Z] 19:01:01     INFO -      raise Exception(self.browsertime_failure)
[task 2022-10-31T19:01:01.067Z] 19:01:01     INFO -  Exception: Could not find window recording directory in C:\Users\task_1667241843\build\blobber_upload_dir\browsertime-results\process-switch
[task 2022-10-31T19:01:01.124Z] 19:01:01    ERROR - Return code: 1

I assume there is something specific to these two tests.

:sparky, could you help find the problem or someone who could help out?

Flags: needinfo?(gmierz2)

It's unclear to me what's going on here. At the moment, I think it has something to do with this code because in both the passing, and failing case the browsertime commands are identical: https://searchfox.org/mozilla-central/source/testing/raptor/raptor/results.py#340-345

These are custom tests (in contrast to pageload) but there isn't much different with them aside from this line: https://searchfox.org/mozilla-central/source/testing/raptor/raptor/browsertime/base.py#244

I'm seeing an error in one of the tasks that suggests the result dir isn't being created for some reason so it's really something going on with path creation/existence in either Raptor or Browsertime:

[task 2022-10-31T23:46:17.128Z] 23:46:17     INFO -  raptor-browsertime Info: browsertime cmd: C:/Users/task_1667259416/fetches/node/node.exe C:/Users/task_1667259416/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath C:/Users/task_1667259416/fetches/geckodriver.exe C:\Users\task_1667259416\build\tests\raptor\raptor\browsertime\..\..\browsertime\process_switch.js --firefox.noDefaultPrefs --browsertime.page_cycle_delay 1000 --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --timeouts.pageLoad 60000 --timeouts.script 120000 --browsertime.page_cycles 2 --pageCompleteWaitTime 1000 --browsertime.url https://mozilla.seanfeng.dev/files/red.html,https://mozilla.pettay.fi/moztests/blue.html --browsertime.post_startup_delay 1000 --iterations 25 --videoParams.androidVideoWaitTime 20000 --browsertime.chimera true --browsertime.test_bytecode_cache false --firefox.perfStats false --pageCompleteCheckInactivity true --browsertime.commands  --viewPort 1280x1024 --browser firefox --firefox.binaryPath C:\Users\task_1667259416\build\application\firefox\firefox.exe --resultDir C:\Users\task_1667259416\build\blobber_upload_dir\browsertime-results\process-switch --firefox.profileTemplate C:\Users\task_1667259416\AppData\Local\Temp\tmpfjws3qzu\profile --video true --visualMetrics true --visualMetricsContentful true --visualMetricsPerceptual true --visualMetricsPortable true --videoParams.keepOriginalVideo true --firefox.windowRecorder true --browsertime.testName process-switch --browsertime.liveSite False --browsertime.loginRequired False
[task 2022-10-31T23:46:17.128Z] 23:46:17     INFO -  raptor-browsertime Info: browsertime_ffmpeg: C:/Users/task_1667259416/fetches/ffmpeg-4.4.1-full_build/bin/ffmpeg.exe
[task 2022-10-31T23:46:17.131Z] 23:46:17     INFO -  raptor-browsertime Info: PATH: b'C:\\Users\\task_1667259416\\fetches\\ffmpeg-4.4.1-full_build\\bin;C:\\Users\\task_1667259416\\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\\Mellanox\\MLNX_VPI\\IB\\Tools;C:\\Program Files\\Mellanox\\MLNX_CIMProvider\\lib\\mft;C:\\Program Files\\Git\\cmd;C:\\Program Files (x86)\\GNU\\GnuPG\\pub;C:\\Program Files (x86)\\Windows Kits\\10\\Windows Performance Toolkit\\;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:\\Users\\task_1667259416\\AppData\\Local\\Microsoft\\WindowsApps'
[task 2022-10-31T23:46:17.762Z] 23:46:17     INFO -  raptor-browsertime Info: Running tests using Firefox - 25 iteration(s)
[task 2022-10-31T23:46:17.765Z] 23:46:17     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-10-31T23:46:21.105Z] 23:46:21     INFO -  raptor-browsertime Info: Starting a process switch test
[task 2022-10-31T23:46:21.105Z] 23:46:21     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-10-31T23:46:22.105Z] 23:46:22     INFO -  raptor-browsertime Info: Navigating to about:blank
[task 2022-10-31T23:46:22.105Z] 23:46:22     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2022-10-31T23:46:27.134Z] 23:46:27     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-10-31T23:46:28.136Z] 23:46:28     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-10-31T23:46:28.136Z] 23:46:28     INFO -  raptor-browsertime Info: Navigating to url https://mozilla.seanfeng.dev/files/red.html iteration 1
[task 2022-10-31T23:46:36.166Z] 23:46:36     INFO -  raptor-browsertime Info: Testing url https://mozilla.pettay.fi/moztests/blue.html iteration 1
[task 2022-10-31T23:46:36.167Z] 23:46:36     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-10-31T23:46:42.030Z] 23:46:42     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-10-31T23:46:42.056Z] 23:46:42    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-10-31T23:46:42.116Z] 23:46:42    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-10-31T23:46:42.116Z] 23:46:42     INFO -  raptor-browsertime Info:     at findRecordingStartTime (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\video\screenRecording\firefox\firefoxWindowRecorder.js:63:23)
[task 2022-10-31T23:46:42.117Z] 23:46:42     INFO -  raptor-browsertime Info:     at FirefoxWindowRecorder.stop (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\video\screenRecording\firefox\firefoxWindowRecorder.js:196:31)
[task 2022-10-31T23:46:42.117Z] 23:46:42     INFO -  raptor-browsertime Info:     at async Measure._stopVideo (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\core\engine\command\measure.js:101:7)
[task 2022-10-31T23:46:42.118Z] 23:46:42     INFO -  raptor-browsertime Info:     at async Measure.stop (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\core\engine\command\measure.js:287:5)
[task 2022-10-31T23:46:42.118Z] 23:46:42     INFO -  raptor-browsertime Info:     at async module.exports (C:\Users\task_1667259416\build\tests\raptor\browsertime\process_switch.js:39:5)
[task 2022-10-31T23:46:42.118Z] 23:46:42     INFO -  raptor-browsertime Info:     at async C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\core\engine\run.js:7:9
[task 2022-10-31T23:46:42.119Z] 23:46:42     INFO -  raptor-browsertime Info:     at async Iteration.run (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\core\engine\iteration.js:223:9)
[task 2022-10-31T23:46:42.119Z] 23:46:42     INFO -  raptor-browsertime Info:     at async Engine.runByScript (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\lib\core\engine\index.js:266:20)
[task 2022-10-31T23:46:42.120Z] 23:46:42     INFO -  raptor-browsertime Info:     at async run (C:\Users\task_1667259416\fetches\browsertime\node_modules\browsertime\bin\browsertime.js:74:22)
[task 2022-10-31T23:46:42.120Z] 23:46:42    ERROR -  raptor-browsertime Critical: TypeError: Cannot read properties of undefined (reading 'substr')

:jmaher, could you make a try run for those two in verbose mode (add -vv in the try run command) and provide the link?

We could also try a browsertime upgrade to see if that helps. You can do an upgrade with ./mach browsertime --update-upstream-url https://github.com/sitespeedio/browsertime/tarball/92170f21ffb87795cf1b290f44d70353f181c744 and then commit the changed files.

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

I tried adding -vv to the command here, but it looks like I did it in the wrong spot.

Flags: needinfo?(jmaher)

Ah I'm sorry! That was for browsertime..you can add --verbose and it'll give us basically the same thing

Flags: needinfo?(jmaher)

Thanks :jmaher, unfortunately the verbose logs don't reveal anything and the browser is failing to start there for some reason too.

That said, I don't think the issue is coming from browsertime because you've only updated the python version. It could come from the visual-metrics script but we don't even make it there in the failures. At this stage, I'm suspecting that it has something to do with the use of os for paths on windows in raptor.

:jmaher, would you have a patch I could apply to reproduce this issue and run some tests?

Flags: needinfo?(jmaher)

good point, I think in some python updates on windows builders we have had a lot of issues with upper/lower case of paths, and '/', '\' as well.

you can run tests on the pool with new python like this:
./mach try fuzzy --worker-override="t-win10-64-1803-hw=releng-hardware/gecko-t-win10-64-dev"

then select the test you want. possibly you could do:
./mach try fuzzy --worker-override="t-win10-64-1803-hw=releng-hardware/gecko-t-win10-64-dev" -q 'test-windows10 firefox-welcome'

all the other talos and browsertime/pageload tests work.

Flags: needinfo?(jmaher)
Severity: -- → S3
Priority: -- → P3
You need to log in before you can comment on or make changes to this bug.