1351353 - Intermittent error: Unable to find vcvarsall.bat

Status: RESOLVED WORKSFORME

(Testing :: Marionette Client and Harness, defect)

Description

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

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

02:38:02     INFO - Running command: ['C:\\slave\\test\\build\\venv\\Scripts\\pip', 'install', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'psutil>=3.1.1'] in C:\slave\test\build
02:38:02     INFO - Copy/paste: C:\slave\test\build\venv\Scripts\pip install --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub psutil>=3.1.1
02:38:02     INFO - Using env: {'ALLUSERSPROFILE': 'C:\\ProgramData',
02:38:02     INFO -  'APPDATA': 'C:\\Users\\cltbld\\AppData\\Roaming',
02:38:02     INFO -  'COMMONPROGRAMFILES': 'C:\\Program Files\\Common Files',
02:38:02     INFO -  'COMPUTERNAME': 'T-W732-IX-127',
02:38:02     INFO -  'COMSPEC': 'C:\\windows\\system32\\cmd.exe',
02:38:02     INFO -  'DCLOCATION': 'SCL3',
02:38:02     INFO -  'DEVENVDIR': 'D:\\msvs8\\Common7\\IDE',
02:38:02     INFO -  'DNSSUFFIX': 'wintest.releng.scl3.mozilla.com',
02:38:02     INFO -  'FP_NO_HOST_CHECK': 'NO',
02:38:02     INFO -  'FRAMEWORKDIR': 'C:\\WINDOWS\\Microsoft.NET\\Framework',
02:38:02     INFO -  'FRAMEWORKSDKDIR': 'D:\\msvs8\\SDK\\v2.0',
02:38:02     INFO -  'FRAMEWORKVERSION': 'v2.0.50727',
02:38:02     INFO -  'HOMEDRIVE': 'C:',
02:38:02     INFO -  'HOMEPATH': '\\Users\\cltbld',
02:38:02     INFO -  'KTS_HOME': 'C:\\Program Files\\KTS',
02:38:02     INFO -  'KTS_VERSION': '1.19c',
02:38:02     INFO -  'LIBPATH': 'C:\\WINDOWS\\Microsoft.NET\\Framework\\v2.0.50727;D:\\msvs8\\VC\\ATLMFC\\LIB',
02:38:02     INFO -  'LOCALAPPDATA': 'C:\\Users\\cltbld\\AppData\\Local',
02:38:02     INFO -  'LOGONSERVER': '\\\\T-W732-IX-127',
02:38:02     INFO -  'MONDIR': 'C:\\Monitor_config\\',
02:38:02     INFO -  'MOZBUILDDIR': 'C:\\mozilla-build\\',
02:38:02     INFO -  'MOZILLABUILD': 'D:\\mozilla-build',
02:38:02     INFO -  'MOZILLABUILDDRIVE': 'C:',
02:38:02     INFO -  'MOZILLABUILDPATH': '\\mozilla-build\\',
02:38:02     INFO -  'MOZ_AIRBAG': '1',
02:38:02     INFO -  'MOZ_CRASHREPORTER_NO_REPORT': '1',
02:38:02     INFO -  'MOZ_HIDE_RESULTS_TABLE': '1',
02:38:02     INFO -  'MOZ_MSVCVERSION': '8',
02:38:02     INFO -  'MOZ_NO_REMOTE': '1',
02:38:02     INFO -  'MOZ_TOOLS': 'D:\\mozilla-build\\moztools',
02:38:02     INFO -  'MSVCDIR': 'D:\\msvs8\\VC',
02:38:02     INFO -  'NO_EM_RESTART': '1',
02:38:02     INFO -  'NO_FAIL_ON_TEST_ERRORS': '1',
02:38:02     INFO -  'NUMBER_OF_PROCESSORS': '8',
02:38:02     INFO -  'OS': 'Windows_NT',
02:38:02     INFO -  'OURDRIVE': 'C:',
02:38:02     INFO -  'PATH': 'C:\\Program Files\\NVIDIA Corporation\\PhysX\\Common;C:\\windows\\system32;C:\\windows;C:\\windows\\System32\\Wbem;C:\\windows\\System32\\WindowsPowerShell\\v1.0\\;C:\\mozilla-build\\python27;C:\\mozilla-build\\python27\\Scripts;C:\\mozilla-build\\msys\\bin;C:\\mozilla-build\\vim\\vim72;C:\\mozilla-build\\wget;C:\\mozilla-build\\info-zip;C:\\CoreUtils\\bin;C:\\mozilla-build\\buildbotve\\scripts;C:\\mozilla-build\\hg;c:\\Program Files\\Microsoft Windows Performance Toolkit\\;c:\\mozilla-build\\hg\\',
02:38:02     INFO -  'PATHEXT': '.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC',
02:38:02     INFO -  'PROCESSOR_ARCHITECTURE': 'x86',
02:38:02     INFO -  'PROCESSOR_IDENTIFIER': 'x86 Family 6 Model 30 Stepping 5, GenuineIntel',
02:38:02     INFO -  'PROCESSOR_LEVEL': '6',
02:38:02     INFO -  'PROCESSOR_REVISION': '1e05',
02:38:02     INFO -  'PROGRAMDATA': 'C:\\ProgramData',
02:38:02     INFO -  'PROGRAMFILES': 'C:\\Program Files',
02:38:02     INFO -  'PROMPT': '$P$G',
02:38:02     INFO -  'PROPERTIES_FILE': 'C:\\slave\\test/buildprops.json',
02:38:02     INFO -  'PSMODULEPATH': 'C:\\windows\\system32\\WindowsPowerShell\\v1.0\\Modules\\',
02:38:02     INFO -  'PUBLIC': 'C:\\Users\\Public',
02:38:02     INFO -  'PWD': 'C:\\slave\\test',
02:38:02     INFO -  'RUNLOGFILE': 'C:\\slave\\\\runslave.log',
02:38:02     INFO -  'SLAVEDIR': 'C:\\slave\\',
02:38:02     INFO -  'SYSTEMDRIVE': 'C:',
02:38:02     INFO -  'SYSTEMROOT': 'C:\\windows',
02:38:02     INFO -  'TEMP': 'C:\\Users\\cltbld\\AppData\\Local\\Temp',
02:38:02     INFO -  'TEST1': 'testie',
02:38:02     INFO -  'TMP': 'C:\\Users\\cltbld\\AppData\\Local\\Temp',
02:38:02     INFO -  'USERDOMAIN': 'T-W732-IX-127',
02:38:02     INFO -  'USERNAME': 'cltbld',
02:38:02     INFO -  'USERPROFILE': 'C:\\Users\\cltbld',
02:38:02     INFO -  'VCINSTALLDIR': 'D:\\msvs8\\VC',
02:38:02     INFO -  'VCVARS': 'D:\\msvs8\\VC\\bin\\vcvars32.bat',
02:38:02     INFO -  'VSINSTALLDIR': 'D:\\msvs8',
02:38:02     INFO -  'WINDIR': 'C:\\windows',
02:38:02     INFO -  'WINDOWS_TRACING_FLAGS': '3',
02:38:02     INFO -  'WINDOWS_TRACING_LOGFILE': 'C:\\BVTBin\\Tests\\installpackage\\csilogfile.log',
02:38:02     INFO -  'XPCOM_DEBUG_BREAK': 'warn'}
02:38:03     INFO -  Ignoring indexes: http://pypi.python.org/simple/
02:38:03     INFO -  Downloading/unpacking psutil>=3.1.1
02:38:03     INFO -    Running setup.py egg_info for package psutil
02:38:03     INFO -      warning: no previously-included files matching '*' found under directory 'docs\_build'
02:38:03     INFO -      warning: manifest_maker: MANIFEST.in, line 18: 'recursive-include' expects <dir> <pattern1> <pattern2> ...
02:38:03     INFO -  Installing collected packages: psutil
02:38:03     INFO -    Running setup.py install for psutil
02:38:03     INFO -      building 'psutil._psutil_windows' extension
02:38:03     INFO -      error: Unable to find vcvarsall.bat
02:38:03     INFO -      Complete output from command C:\slave\test\build\venv\Scripts\python.exe -c "import setuptools;__file__='C:\\slave\\test\\build\\venv\\build\\psutil\\setup.py';execfile(__file__)" install --single-version-externally-managed --record c:\users\cltbld\appdata\local\temp\pip-zcoace-record\install-record.txt --install-headers C:\slave\test\build\venv\include\site\python2.7:
02:38:03     INFO -      running install

Comment 1

[Sebastian Pacurar [:spacurar]]

I did some investigation and noticed that the successful jobs also have the following error in the logs: error: Unable to find vcvarsall.bat
Example here: https://treeherder.mozilla.org/logviewer.html#?job_id=86821713&repo=autoland&lineNumber=515
When you see “unable to find vcvarsall.bat”, it means you’re installing a package that has an extension module, but only the source code. “vcvarsall.bat” is part of the compiler in Visual Studio that is necessary to compile the module.
But this is not the case why the job failed.

The real problem why the job fails is that Marionette is not handling SIGTERM signal interrupts correctly: 
https://bugzilla.mozilla.org/show_bug.cgi?id=1201871#c0
Also see https://bugzilla.mozilla.org/show_bug.cgi?id=1336953#c0

02:41:19    ERROR -  {"thread": "MainThread", "level": "ERROR", "pid": 3896, "source": "Marionette test runner", "time": 1490694079607, "action": "log", "message": "Failure during harness execution", "stack": "Traceback (most recent call last):\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_harness\\runtests.py\", line 92, in cli\n    failed = harness_instance.run()\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_harness\\runtests.py\", line 72, in run\n    runner.run_tests(tests)\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\base.py\", line 818, in run_tests\n    self.marionette = self.driverclass(**self._build_kwargs())\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 606, in __init__\n    self.raise_for_port(timeout=startup_timeout)\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 28, in _\n    m._handle_socket_failure()\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 23, in _\n    return func(*args, **kwargs)\n\n  File \"C:\\slave\\test\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 692, in raise_for_port\n    self.host, self.port))\n\nIOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on localhost:2828!)\n"}

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Sebastian, I believe you meant to dupe this bug against a different one than bug 1201871. Both have nothing in common.

Comment 4

[Sebastian Pacurar [:spacurar]]

The bug title might be a bit confusing since it refers to "vcvarsall.bat". There is an error thrown because of that, but the tests fail because of a different error regarding Marionette connection. Since Firefox is not closed correctly from SIGTERM, it generates the error I attached as snippet in https://bugzilla.mozilla.org/show_bug.cgi?id=1351353#c1 about Marionette not being able to connect to port 2828: (Reason: Timed out waiting for connection on localhost:2828!)

To be more detailed: as you mentioned in https://bugzilla.mozilla.org/show_bug.cgi?id=1201871#c0 there is a conflict with port 2828 because Python does not close Firefox properly, and because of this Firefox hangs on that port, while there will be a connection timed out error from Marionette. Closing it with SIGINT might indeed fix the problem since it is KeyboardInterruption, but SIGTERM does not work properly and causes this error to be intermittent. 

Am I missing something here?

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so first it looks like to be a log from the external-media-tests job. Moving to the appropriate component.

Then how is this related to SIGTERM? What in the logs gave you the impression? I cannot find anything about that. But what I see is that the initial connection to Marionette fails. It might be that Firefox didn't start up correctly due to some unknown reasons. Sadly the gecko.log as attached to the job is empty, so there is no clear way to figure that out.

Comment 6

[Sebastian Pacurar [:spacurar]]

I can't find an error like this anymore, to check gecko.log.
I will unassign myself from the bug, to let someone more experienced in this area take care of it.

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 2

Platform breakdown:
* windows8-64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1351353&startday=2017-06-26&endday=2017-07-02&tree=all

Comment 8

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

This doesn't look to be external media test specific. Indeed, the external media tests have been removed from tree and this still appears to be happening. The vcvars part looks like psutil is failing to install into the venv. Looks like this is happening as part of marionette setup, but I'm not too familiar with what exactly takes place there. Going to move this to Marionette based on the above.

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows8-64: 1

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

Comment 10

[David Burns :automatedtester]

not seen a while so closing

Comment 11

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.