Exceptions not caught by debugger in indirectly-loaded scripts


I am trying to use PTVS for Blender addon development. This is how debugging works:
  1. I create a a project for my addon.
  2. I create a second project which loads Blender as a Python module, enables my addon, and calls it.
  3. I debug the second project. My addon is executed and breakpoints are hit (albeit in a duplicated document window - possibly another symptom of this bug).
So far so good. The problem is that exceptions raised in my addon don't make it to VS. Instead I see them in the output and then get Blender's "press any key to exit" message. Exceptions in the startup project do appear in VS.

Win7 x64, PTVS 2.0 Integrated Shell and Python 3.3.3 x64. I can send you the Blender build and my Python code if needed.


Artfunkel wrote Dec 21, 2013 at 5:12 PM

Some good news: exceptions are caught if I'm stepping through the code in pause mode. It's only when the code is running that they are missed.

Artfunkel wrote Dec 31, 2013 at 11:43 AM

This bug causes tests to report success when the indirectly-loaded script(s) actually threw an exception.

pminaev wrote Jan 2 at 7:54 PM

Are those exceptions caught & handled by the caller? The default is to report exceptions that are unhandled (i.e. for which no except handler was found after walking the stack and looking at source code for the frames, if available) - but this can be changed in the Debug -> Exceptions dialog.

Artfunkel wrote Jan 3 at 12:23 PM

I've enabled breaking when any Python exception is thrown and the exception window does now appear. Progress!

However, I am definitely not handling these exceptions myself: once one is thrown (with break-on-throw disabled) I can continue hitting Step Over and watch it bubble up the call stack until the process terminates.

This is the output when an exception is thrown but not caught in the debugger:
Error: Traceback (most recent call last):
  File "C:\Users\Tom\AppData\Roaming\Blender Foundation\Blender\2.69\scripts\addons\io_scene_valvesource\export_smd.py", line 132, in execute
  File "C:\Python33\2.69\scripts\modules\bpy\ops.py", line 188, in __call__
    ret = op_call(self.idname_py(), None, kw)
RuntimeError: Operator bpy.ops.mesh.spin.poll() failed, context is incorrect

location: C:\Python33\2.69\scripts\modules\bpy\ops.py:188

The thread 'MainThread' (0xcfc) has exited with code 0 (0x0).
The program '[2044] pythonw.exe' has exited with code 0 (0x0).
This is how Blender raises the above exception:
PyErr_Format(PyExc_RuntimeError, "Operator bpy.ops.%.200s.poll() %.200s", opname, msg ? msg : "failed, context is incorrect");
This is the StdErr output of a test which succeeds despite throwing an exception:
Result StandardError:   
ERROR: test_Export_Armature_Curve (tests.bpy_266a)
Traceback (most recent call last):
  File "F:\Users\Tom\Documents\Mods\blender-smd\src\tests.py", line 60, in test_Export_Armature_Curve
  File "F:\Users\Tom\Documents\Mods\blender-smd\src\tests.py", line 39, in runExportTest
  File "F:\Users\Tom\Documents\Mods\blender-smd\src\tests.py", line 33, in ex
    result = bpy.ops.export_scene.smd(export_scene=do_scene)
  File "C:\Python33\2.66\scripts\modules\bpy\ops.py", line 188, in __call__
    ret = op_call(self.idname_py(), None, kw)
RuntimeError: Error: Traceback (most recent call last):
  File "C:\Users\Tom\AppData\Roaming\Blender Foundation\Blender\2.66\scripts\addons\io_scene_valvesource\export_smd.py", line 192, in execute
    self.exportId(context, id)
  File "C:\Users\Tom\AppData\Roaming\Blender Foundation\Blender\2.66\scripts\addons\io_scene_valvesource\export_smd.py", line 234, in exportId
ZeroDivisionError: division by zero
location: C:\Python33\2.66\scripts\modules\bpy\ops.py:188
Ran 1 test in 0.904s
FAILED (errors=1)
Traceback (most recent call last):
  File "C:\Users\Tom\AppData\Roaming\Blender Foundation\Blender\2.66\scripts\addons\io_scene_valvesource\export_smd.py", line 192, in execute
    self.exportId(context, id)
  File "C:\Users\Tom\AppData\Roaming\Blender Foundation\Blender\2.66\scripts\addons\io_scene_valvesource\export_smd.py", line 234, in exportId
ZeroDivisionError: division by zero
location: C:\Python33\2.66\scripts\modules\bpy\ops.py:188
location: C:\Python33\2.66\scripts\modules\bpy\ops.py:188

Artfunkel wrote Jan 3 at 12:30 PM

I've isolated a (or the?) cause of the bug. Consider this code:
The debugger doesn't break when the exception is thrown. finally doesn't count as handling it! :)

Zooba wrote Jan 3 at 4:32 PM

Good catch - that's exactly what we're getting wrong. Looking at PythonProcess.cs (about line 550) it seems we assume that no handlers means everything is handled.

I believe this is meant to handle error cases (where parsing has failed for some reason - we don't want to crash the debugger, obviously) but it's also getting the try/finally case wrong.

What we want to do is assume that nothing is handled if statement.Finally != null but that everything is handled otherwise.

Artfunkel wrote Jan 3 at 6:05 PM

Great! The exceptions are dropped even when I haven't wrapped them in try/finally in my script, but perhaps Blender is doing a try/finally internally?

Zooba wrote Jan 3 at 6:59 PM

That's entirely likely. It should be easy enough to set a breakpoint near where the exception is being thrown and walking up the call stack yourself to check. (In fact, it would be great if you could do that to confirm. Otherwise we may have another issue here.)

Artfunkel wrote Jan 3 at 8:10 PM

Unfortunately Blender compiles to a binary module, so I can't see what it's doing in terms of internal Python calls. I've attached a C debugger but nothing leaps out as a try/finally block from that perspective.

Zooba wrote Jan 3 at 10:53 PM

Hmm... maybe I haven't fixed the problem then. If we can't see Python source code then we assume that the exception is unhandled, which means we'll break (or keep looking for a handler). There's no way we can find an exception in a binary module, but since the exception is user-unhandled in this case we should be breaking.

I'll set up Blender on one of my machines and check it out.

Artfunkel wrote Jan 17 at 5:44 PM

Hi Zooba, any chance of an update? Nobody has pushed any code since the 3rd of December. It would be great to have the try/finally fix if nothing else.

Zooba wrote Jan 17 at 6:14 PM

I've had a brief look at how Blender's libraries affect us, but as you said, they're entirely in native code and can't be causing this (unless they're doing something tricky like lying about their filenames...)

We've had an internal 'blockage' that's prevented up from pushing code for a bit. Rest assured, it will be coming soon and there'll be a dev build to go with it. We'll also release an official alpha in the next few weeks, though the dev build will be first.

Artfunkel wrote Jan 19 at 11:35 AM

Good to hear. I've just made a discovery: exceptions thrown by a function hooking one of Blender's event handlers (e.g. bpy.app.handlers.scene_update_post) are caught normally by the debugger.

Artfunkel wrote Jan 20 at 2:19 PM

I don't know what's changed, but in fact all exceptions thrown outside try/finally blocks now appear in the debugger as expected. The only thing I can think of is that I recently changed my VS2013 Express debug settings; perhaps they are leaking over into VS2013 Shell?

Tests are unchanged: they report success on failure and when being debugged won't break when an exceptions is thrown.

Zooba wrote Jan 20 at 6:57 PM

It's possible, though those settings are supposed to be completely isolated. Just My Code is the most likely option to have an effect, but even that shouldn't matter too much.

At this point I'm running with the theory that Blender has a try/finally somewhere, so once we can get that fix to you it should all be fine.

Artfunkel wrote Feb 5 at 11:35 AM

I've upgraded to the new dev build (2.1.20128.00) and exceptions are now properly caught by the debugger. Thanks!

Tests which raise exceptions still report success, however.

Zooba wrote Feb 5 at 6:26 PM

Good to hear!

Unfortunately, we may not be able to do anything for now about the tests. We rely on unittest to return a non-zero exit code if the test fails, which apparently is not happening with something in your stack.

If you set the option to break on all exceptions (Debug->Exceptions menu) and debug the test, does it break on the exception?

Artfunkel wrote Feb 6 at 1:41 PM

With break on throw enabled, VS does indeed break (if I'm debugging the test).

The return code doesn't seem to be the whole story. I've edited the end of visualstudio_py_testlauncher.py to look like this:
result = runner.run(test)
The test reports success until I comment out result = runner.run(test), after which it reports failure.

Zooba wrote Feb 6 at 3:52 PM

runner.run probably does its own sys.exit. Try this and see what we report:
    result = runner.run(test)
except SystemExit:

Artfunkel wrote Feb 6 at 4:52 PM

Tried that already I'm afraid, there's no change in behaviour.

I always get a "FAILED" message printed out, so it's not a case of unittest throwing any exceptions.

Zooba wrote Feb 6 at 5:44 PM

I was thinking it more likely that someone is calling sys.exit(0), which will make it look to VS as if all the tests have passed. Handling SystemExit should block that and force the exit code to be non-zero, which should be displayed as a failure (note that except Exception: pass won't handle SystemExit, but except: pass will, so if you tried the first then it's worth giving this one a try).

The "FAILED" message is coming from the test runner, but we don't look at that on the VS side. It's all about the exit code.

Artfunkel wrote Feb 7 at 10:59 AM

I now have this in the file:
    result = runner.run(test)
print("Hello world!")
I see "Hello world!" in the output, yet the test still succeeds.

Artfunkel wrote Feb 7 at 4:48 PM

>>> import sys
>>> sys.exit(-1)

Blender quit
Blender is issuing its own exit code after visualstudio_py_testlauncher's, overwriting the script's failure code with its own success code. Odd behaviour for a Python module, but then it is a C application behind the scenes! I'll report this as a bug on their end.

This code avoids the problem:
result = runner.run(test)
os._exit(not result.wasSuccessful()) # immediate termination, no chance for other exit codes to intervene

Zooba wrote Feb 7 at 7:43 PM

Ah, that makes sense.

Thanks for figuring that out and reporting it to them. I'll go ahead and resolve this issue.