Log warnings for unexpected ImportError of submodules instead of hiding

[justinfx]

We recently had an issue importing PySide2 that required a bit of debugging to ultimately figure out the cause. The failure to the user looked like ImportError: No module named QtCore or 'module' object has no attribute QtGui, depending on which version of Qt.py one is running.

The circumstances of the error are as follows: User observes command working fine locally with PySide2 within Nuke, and sends it to the render farm. Command fails on the render farm, running outside of Nuke, looking as if PySide2 is not available in the environment. As it turns out, the cause of the failure is that Nuke's libraries were being picked up first in the LD_LIBRARY_PATH on the farm and conflicting with the external PySide2 causing an ImportError:

ImportError: /path/to/PySide2/QtCore.so: symbol _ZN23QOperatingSystemVersion13MacOSCatalinaE version Qt_5 not defined in file libQt5Core.so.5 with link time reference 

But this error is being masked by the _setup() failing on the first attempt and hiding the exception, then trying again with a second import approach. If we could see this error it would have made it a lot more obvious that it was seeing PySide2 but conflicting with the Qt libraries.

This patch logs unexpected ImportErrors of just the submodules, as a warning. So this means PySide2 would first succeed as being imported and available, but then some kind of problem happens with its submodules.

Qt.py [warning]: ImportError: /path/to/PySide2/QtCore.so: symbol _ZN23QOperatingSystemVersion13MacOSCatalinaE version Qt_5 not defined in file libQt5Core.so.5 with link time reference
...
Traceback ...
AttributeError: 'module' object has no attribute 'QtCore' 

Open to feedback on different ways to capture or present this.

[mottosso]

Seems reasonable, hard to say whether there's a better way without having experienced the issue. Not sure how I feel about moving the error handling away from the exception catching though, couldn't we just handle it then and there, without an additional module-scope function? If more cases in need of such a function pops up maybe we could add it back in.

[justinfx]

I can move the function to be defined within the scope of _setup() if you would rather not have it defined at the module scope. I just thought to put it near the other logging functions and centralize the logic for checking the exception. Either way its good to log the unexpected exceptions instead of hiding them since it made debugging harder for us.

[mottosso]

I can see what you mean. It should definitely not hide the exceptions like it was, and there are more places where that happens which I can see makes debugging harder than it needs to.

I'm happy to follow your judgement on this PR, let me know when you're happy and I'll make a release.

[justinfx]

Thanks for the feedback on this. I have moved the warning function into the scope of _setup as requested.

Also, if you want to see a reproduction of what the problem looks like, I have put together this Dockerfile:

FROM bildcode/pyside2:py3.7

RUN pip install Qt.py; \
    rm -f /usr/local/lib/python3.7/site-packages/PySide2/Qt/lib/libQt5Core.so.5; \
    mkdir -p /opt/python

ENV PYTHONPATH "/opt/python:${PYTHONPATH}"

RUN printf '\
#!/bin/bash \n\
echo "\n== from PySide2 import QtCore ==" \n\
python -c "from PySide2 import QtCore" \n\
echo "\n== from Qt import PySide2 ==" \n\
python -c "from Qt import PySide2" \
' > cmd.sh && chmod +x cmd.sh

CMD ./cmd.sh

It simulates a problem that could occur when PySide2 does exist but something is wrong in the submodules such as a linking error.

# with current release of Qt.py
docker run -it --rm <image>
# with local checkout mounted into pythonpath
docker run -it --rm -v $(pwd):/opt/python <image>

[mottosso]

Thanks Justin, and sorry for the delay, holiday times (but back now!). This looks fine to me, merge-ahoy!