search

PixarAnimationStudios / OpenUSD

Universal Scene Description
http://www.openusd.org
Other
5.45k stars 1.13k forks source link

Problem with Tf python dll loading using reversed() #3024

Closed seando-adsk closed 1 month ago

seando-adsk commented 1 month ago

Description of Issue

In PR #2595 , the DLL loading order was changed by using reversed() on PATH. In MayaUsd when I try to update to USD v24.03 we have a few of the pxr plugin unit tests failing. I think the root cause is the python module usdMaya fails to load. Some of the failing tests do from pxr import UsdMaya. @pmolodo Do you have any ideas what could be wrong now.

Steps to Reproduce

  1. Build MayaUsd using USD v24.03.
  2. Run the unit tests. An example of failing test is testUsdMayaGetVariantSetSelections.

The entire list of failing tests is below. All of these tests are part of the pxr plugin in MayaUsd repo.

testUsdExportAssemblyEdits
testUsdExportPointInstancer
testUsdMayaGetVariantSetSelections
testUsdMayaModelKindProcessor
testUsdMayaReferenceAssemblyEdits
testUsdReferenceAssemblyChangeRepresentations
testPxrUsdAlembicChaser
sunyab commented 1 month ago

@seando-adsk Do you have any output from those failing tests? If they're run via ctest, ctest -V produces verbose output.

pmolodo commented 1 month ago

Yeah, the exact error when it fails to import usdMaya would be handy. And the exact PATH at that time, if possible. It's interesting that only these tests fail - I'm assuming nearly all the python tests import usdMaya. Do these tests modify the PATH? Or rely on a dll on the path that others don't?

jesschimein commented 1 month ago

Filed as internal issue #USD-9501

seando-adsk commented 1 month ago

Here is the full output from the test failure. Note: there is a super long line that has the full set of env vars passed to the test. In there you can see the path. testUsdMayaGetVariantSetSelections is one that does and is failing now. If I changed the Tf/__init__,py back to not reversed the test passes.

There are not that many places that import this usdMaya:

$ git grep 'from pxr import UsdMaya'
plugin/pxr/doc/README.md:from pxr import UsdMaya
plugin/pxr/maya/lib/pxrUsdMayaGL/testenv/testBatchRendererIsolateSelection.py:from pxr import UsdMaya
plugin/pxr/maya/lib/pxrUsdMayaGL/testenv/testRefAssemblyDrawRepresentations.py:from pxr import UsdMaya
plugin/pxr/maya/lib/usdMaya/AEpxrUsdReferenceAssemblyTemplate.py:from pxr import UsdMaya
plugin/pxr/maya/lib/usdMaya/testenv/testUsdMayaGetVariantSetSelections.py:from pxr import UsdMaya
plugin/pxr/maya/lib/usdMaya/testenv/testUsdMayaReferenceAssemblyEdits.py:from pxr import UsdMaya
test/lib/mayaUsd/fileio/testSchemaApiAdaptor.py:    from pxr import UsdMaya
test/lib/usd/translators/testUsdExportSchemaApi.py:    from pxr import UsdMaya

T:\ecg-maya-usd\usd_v24.03\build\RelWithDebInfo>ctest -VV -R testUsdMayaGetVariantSetSelections
UpdateCTestConfiguration  from :T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/DartConfiguration.tcl
UpdateCTestConfiguration  from :T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/DartConfiguration.tcl
Test project T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 276
    Start 276: testUsdMayaGetVariantSetSelections

276: Test command: T:\Artifactory\Windows\rundev-master\202403232042\runtime\814d529\runTime\bin\mayapy.exe "T:/ecg-maya-usd/ecg-maya-usd/maya-usd/plugin/pxr/cmake/macros/testWrapper.py" "--verbose" "--testenv-dir=T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/tests/ctest/testUsdMayaGetVariantSetSelections" "--env-var=MAYA_PLUG_IN_PATH=T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/maya/plugin" "--env-var=MAYA_SCRIPT_PATH=T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/maya/lib/usd/usdMaya/resources" "--env-var=MAYA_DISABLE_CIP=1" "--env-var=MAYA_DISABLE_CER=1" "--env-var=MAYA_NO_MORE_ASSERT=1" "--env-var=MAYA_NO_STANDALONE_ATEXIT=1" "--env-var=MAYA_APP_DIR=<PXR_TEST_DIR>/maya_profile" "--env-var=PYTHONPATH=T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/lib/python;T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/lib/python;T:/Artifactory/Windows/USD/7fbcb41/lib/python" "--env-var=PXR_PLUGINPATH_NAME=T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/maya/plugin;T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/lib/usd" "--pre-path=T:/Artifactory/Windows/cmake/3.20.3/afe857a/bin;C:/Program Files/Microsoft Visual Studio/2022/Professional/VC/Tools/MSVC/14.37.32822/bin/HostX64/x64;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/VC/VCPackages;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/CommonExtensions/Microsoft/TestWindow;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/CommonExtensions/Microsoft/TeamFoundation/Team Explorer;C:/Program Files/Microsoft Visual Studio/2022/Professional/MSBuild/Current/bin/Roslyn;C:/Program Files/Microsoft Visual Studio/2022/Professional/Team Tools/Performance Tools/x64;C:/Program Files/Microsoft Visual Studio/2022/Professional/Team Tools/Performance Tools;C:/Program Files (x86)/Microsoft Visual Studio/Shared/Common/VSPerfCollectionTools/vs2019//x64;C:/Program Files (x86)/Microsoft Visual Studio/Shared/Common/VSPerfCollectionTools/vs2019/;C:/Program Files (x86)/Microsoft SDKs/Windows/v10.0A/bin/NETFX 4.8 Tools/x64/;C:/Program Files (x86)/HTML Help Workshop;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/CommonExtensions/Microsoft/FSharp/Tools;C:/Program Files (x86)/Windows Kits/10/bin/10.0.22621.0//x64;C:/Program Files (x86)/Windows Kits/10/bin//x64;C:/Program Files/Microsoft Visual Studio/2022/Professional//MSBuild/Current/Bin/amd64;C:/Windows/Microsoft.NET/Framework64/v4.0.30319;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/Tools/;T:/Artifactory/Windows/cmake/3.26.0/80c217d/bin;T:/Artifactory/Windows/ninja/1.11.1/9b2eeca;T:/maya/builds/main/build/RelWithDebInfo/runTime/bin;C:/WINDOWS/system32;C:/WINDOWS;C:/WINDOWS/System32/Wbem;C:/WINDOWS/System32/WindowsPowerShell/v1.0/;C:/WINDOWS/System32/OpenSSH/;C:/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL;C:/Program Files/Intel/Intel(R) Management Engine Components/DAL;C:/Program Files/Microsoft SQL Server/150/Tools/Binn/;C:/Program Files/Microsoft SQL Server/Client SDK/ODBC/170/Tools/Binn/;C:/Program Files/dotnet/;C:/Users/donnels/AppData/Local/Programs/Python/Python311/Scripts/;C:/Users/donnels/AppData/Local/Programs/Python/Python311/;C:/Users/donnels/AppData/Local/Programs/Python/Launcher/;C:/Users/donnels/AppData/Local/Microsoft/WindowsApps;C:/Users/donnels/AppData/Local/Programs/oh-my-posh/bin;;C:/Program Files/Git/cmd;C:/Program Files/Git/usr/bin;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/CommonExtensions/Microsoft/CMake/CMake/bin;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/CommonExtensions/Microsoft/CMake/Ninja;C:/Program Files/Microsoft Visual Studio/2022/Professional/Common7/IDE/VC/Linux/bin/ConnectionManagerExe;T:/Artifactory/Windows/USD/7fbcb41/bin;T:/Artifactory/Windows/USD/7fbcb41/lib;T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/maya/lib;T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/lib" "T:/Artifactory/Windows/rundev-master/202403232042/runtime/814d529/runTime/bin/mayapy.exe T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/tests/testUsdMayaGetVariantSetSelections"
276: Working Directory: T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/plugin/pxr/maya/lib/usdMaya
276: Environment variables:
276:  TMP=T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/test/Temporary/testUsdMayaGetVariantSetSelections
276:  TEMP=T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/test/Temporary/testUsdMayaGetVariantSetSelections
276: Test timeout computed to be: 10000000
276: Traceback (most recent call last):
276:   File "T:\ecg-maya-usd\usd_v24.03\install\RelWithDebInfo\MayaUSD\plugin\pxr\tests\testUsdMayaGetVariantSetSelections", line 18, in <module>
276:     from pxr import UsdMaya
276:   File "c:\projects\ecg-maya-usd\usd_v24.03\install\relwithdebinfo\mayausd\plugin\pxr\lib\python\pxr\UsdMaya\__init__.py", line 18, in <module>
276:     Tf.PreparePythonModule('_usdMaya')
276:   File "c:\projects\artifactory\windows\usd\7fbcb41\lib\python\pxr\Tf\__init__.py", line 103, in PreparePythonModule
276:     module = importlib.import_module(
276:              ^^^^^^^^^^^^^^^^^^^^^^^^
276:   File "T:\Artifactory\Windows\rundev-master\202403232042\runtime\814d529\runTime\Python\Lib\importlib\__init__.py", line 126, in import_module
276:     return _bootstrap._gcd_import(name[level:], package, level)
276:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
276: ImportError: DLL load failed while importing _usdMaya: The operating system cannot run %1.
276: Error: return code 1 doesn't match expected 0 (EXPECTED_RETURN_CODE).chdir: T:\ecg-maya-usd\usd_v24.03\build\RelWithDebInfo\test\Temporary\testUsdMayaGetVariantSetSelections\tmpq941qro6
276: copying testenv dir: T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/tests/ctest/testUsdMayaGetVariantSetSelections
276: cmd: ['T:/Artifactory/Windows/rundev-master/202403232042/runtime/814d529/runTime/bin/mayapy.exe', 'T:/ecg-maya-usd/usd_v24.03/install/RelWithDebInfo/MayaUSD/plugin/pxr/tests/testUsdMayaGetVariantSetSelections']
1/1 Test #276: testUsdMayaGetVariantSetSelections ...***Failed    1.68 sec

0% tests passed, 1 tests failed out of 1

Total Test time (real) =   3.10 sec

The following tests FAILED:
        276 - testUsdMayaGetVariantSetSelections (Failed)
Errors while running CTest
Output from these tests are in: T:/ecg-maya-usd/usd_v24.03/build/RelWithDebInfo/Testing/Temporary/LastTest.log
Use "--rerun-failed --output-on-failure" to re-run the failed cases verbosely.
pmolodo commented 1 month ago

Hmm - can you turn on more dll debugging info with glags, and let us know what it prints then?

gflags /i mayapy.exe +sls

Also - I'd be curious to know what would happen if you changed the --pre-path into a --post-path. (And - do you know how that --pre-path got added to the test command - I looked pxr_register_test(testUsdMayaGetVariantSetSelections) call, and it didn't have any PRE_PATH specified. Is that automatically getting added somehow, or is that only on a specific branch?)

If none of the above gives any hints - we might need to know what the COMPLETE path is - the command only lists the entries in --pre-path, but not the values that are "already there". Do you think you could add a print of os.environ["PATH"] in testUsdMayaGetVariantSetSelections.py, immediately before the from pxr import UsdMaya?

seando-adsk commented 1 month ago

Thanks for the info Paul. Yes the pre-path is being automatically added here.

If you notice in the --pre-path flag you'll see all my current path (including the Visual Studio paths). This is because at line 355 since it adds "$ENV{PATH}".

I tried changing the --pre-path into a --post-path which I thought might work, but the tests still fail (same reason). I think because all my PATH is being added into --pre-path.

I think the proper thing to do might be to use PXR_USD_WINDOWS_DLL_PATH instead. This way we can add just the paths needed to load the libs. I'm going to give this a try. This is just for the Pixar plugin tests. So I'm not worried about the actual MayaUsd or Pixar plugins as they work fine.

Thanks, Sean

pmolodo commented 1 month ago

Using PXR_USD_WINDOWS_DLL_PATH directly should work - it would avoid any question of how PATH is handled for dll search order, and would mean you wouldn't need to figure out the exact ordering conflict that's happening.

However - if you do want to figure out that exact conflict- I think the fact that you do --pre-path "$ENV{PATH}${MAYA_TEST_PATHS}" is interesting - and probably speaks to the reason why the reversed() change was made in the first place.

Effectively you end up with is this as your final PATH:

{OLD_PATHS}{MAYA_TEST_PATHS}{OLD_PATHS}

Because the old behavior was:

...by sandwiching MAYA_TEST_PATHS between OLD_PATHS, you always search OLD_PATHS first, regardless of which direction you're going from - so for both dlls and executables.

The new behavior is more consistent, and matches conventions/expectations:

Because it's now always left to right :arrow_right: with the change, in theory you wouldn't need to do the sandwiching - ie, you could just do:

--post-path "${PXR_INSTALL_PREFIX}/maya/lib;${CMAKE_INSTALL_PREFIX}/lib"

...to ensure that OLD_PATHS came before MAYA_TEST_PATHS

Of course - that wouldn't fix the problem you're having now - which is that one of either reversed(MAYA_TEST_PATHS) or reversed(OLD_PATHS) doesn't work for dll loading.

The easiest way to to check whether the ordering conflict is in the OLD_PATH or the extra MAYA_TEST_PATHS would be to just switch the order of the MAYA_TEST_PATHS - ie, change line 355 to:

set(_testPrePath "$ENV{PATH};${CMAKE_INSTALL_PREFIX}/lib;${PXR_INSTALL_PREFIX}/maya/lib")

....and make no other changes. If the problem goes away, great - if not, then the problem is in the pre-existing OLD_PATHS...

pmolodo commented 1 month ago

If the problem is with the OLD_PATHS - looking at what's in there... it jumps out that the final two items seem to be custom USD ones:

T:/Artifactory/Windows/USD/7fbcb41/bin
T:/Artifactory/Windows/USD/7fbcb41/lib

With the old way things worked, those would have had the highest priority... now they're the lowest. If, wherever these paths are getting set up, you made sure that you prepended them (instead of appending them) in flipped order:

set PATH=T:/Artifactory/Windows/USD/7fbcb41/lib;T:/Artifactory/Windows/USD/7fbcb41/bin;%PATH%

...my guess is that would fix your issue. If not, the next most likely culprit seems to be T:/maya/builds/main/build/RelWithDebInfo/runTime/bin - I'd try moving that to either the front or back.

seando-adsk commented 1 month ago

Thanks for all the info Paul. I did try a bunch of different things. In one scenario I got the tests working when I ran them individually (using ctest -R), but when I ran them as part of the full build they were still failing. I didn't figure out why.

I also started removing paths from CTestTestfile.cmake to see if I could nail down where the conflict was. At first I removed all the VS2022 paths just to start with less and to my surprise the tests worked. So one-by-one I removed VS2022 paths until I found this one C:/Program Files (x86)/Microsoft Visual Studio/Shared/Common/VSPerfCollectionTools/vs2019//x64. Removing just this one path made the test work. I really don't understand how this VS2022 path conflicted with loading a python module in maya-usd.

At that point I decided that it was just safer to go with setting PXR_USD_WINDOWS_DLL_PATH. If you are curious my fix (in maya-usd repo) is https://github.com/Autodesk/maya-usd/pull/3689

Thanks for all your help, Sean

seando-adsk commented 1 month ago

So I guess we can just close this issue?

jesschimein commented 1 month ago

Thank you! I'll go ahead and close this one out!