How to debug Maya crashes? about cmdx HOT 9 OPEN

I just discovered a method of debugging in Maya that I hope everyone already knows and that I wish I had known about years ago.

trace

Whenever Maya crashes as a result of calling Python, such as maya.cmds or maya.api.OpenMaya, what you're left with is the Output Window and garbage like this.

Stack trace:
  OGSMayaBridge.dll!OGSSubSceneItem::update
  OGSMayaBridge.dll!OGSMayaSubSceneManager::UpdateAllSubScenes
  OGSMayaBridge.dll!Ttask::syncExecuteChildren
  OGSMayaBridge.dll!Ttask::syncExecuteChildren
  OGSMayaBridge.dll!OGSApplicationBridge::UpdateScene
  OGSMayaBridge.dll!OGSMayaRenderer::updateScene
  OGSMayaBridge.dll!OGSMayaBaseRenderer::performSceneRender
  OGSMayaBridge.dll!OGSMayaStrokePainter::isViewInfoLegal
  OGSMayaBridge.dll!OGSMayaStrokePainter::isViewInfoLegal
  DataModel.dll!TidleRefreshCmd::refreshOGSRender
  DataModel.dll!TidleRefreshCmd::refresh
  DataModel.dll!TidleRefreshCmd::doIt
  ExtensionLayer.dll!TeventHandler::doIdles
  ExtensionLayer.dll!TeventHandler::suspendIdleEvents
  Qt5Core.dll!QObject::event
  Qt5Widgets.dll!QApplicationPrivate::notify_helper
  Qt5Widgets.dll!QApplication::notify

Which most often is not very helpful at all.

What if you could instead get output like this?

...
304642 |  --- modulename: cmdx, funcname: commit
304643 | cmdx.py(6950):     if not ENABLE_UNDO:
304644 | cmdx.py(6953):     if not hasattr(cmds, unique_command):
304645 | cmdx.py(6961):     try:
304646 | cmdx.py(6962):         assert shared.redoId is None
304647 | cmdx.py(6963):         assert shared.undoId is None
304648 | cmdx.py(6969):     shared.undoId = "%x" % id(undo)
304649 | cmdx.py(6970):     shared.redoId = "%x" % id(redo)
304650 | cmdx.py(6971):     shared.undos[shared.undoId] = undo
304651 | cmdx.py(6972):     shared.redos[shared.redoId] = redo
304652 | cmdx.py(6975):     getattr(cmds, unique_command)()
304653 |  --- modulename: __init__, funcname: cmdx_0_5_1_command
304654 | <string>(2): cmdx.py(4964):         self._doLockAttrs()
304655 |  --- modulename: cmdx, funcname: _doLockAttrs
304656 | cmdx.py(4905):         while self._lockAttrs:
304657 | cmdx.py(4965):         self._doKeyableAttrs()
304658 |  --- modulename: cmdx, funcname: _doKeyableAttrs
304659 | cmdx.py(4913):         while self._keyableAttrs:
304661 | cmdx.py(4966):         self._doNiceNames()
304662 |  --- modulename: cmdx, funcname: _doNiceNames
304663 | cmdx.py(4921):         while self._niceNames:
304664 | cmdx.py(4753):             cmds.undoInfo(chunkName="%x" % id(self), closeChunk=True)
<Crash>

And for the love of all that is holy, you can!

import sys
import trace

def trace_this(func, fname):
    oldout = sys.stdout
    olderr = sys.stderr

    try:
        with open(fname, "w") as f:
            sys.stdout = f
            sys.stderr = f
            tracer = trace.Trace(count=False, trace=True)
            tracer.runfunc(func)

    finally:
        sys.stdout = oldout
        sys.stderr = olderr

def crashing_function():
    from maya.api import OpenMaya as om
    fn = om.MFnDagNode()
    node = fn.create("transform")
    om.MGlobal.deleteNode(node)

    # Do not run this. Yes, it actually crashes Maya
    plug = fn.findPlug("translateX", True)

trace_this(crashing_function, r"c:\crashing_function.txt")

And that's it! Now Python will print every line it executes to disk, right up until it crashes. Which means you can tell the exact line responsible for the crash. Almost. Most of the time the final line is half-written, other times it's a few lines too old. Maya is crashing after all, and Python seems to be amongst the first to go.

But! The above example trace is 300,000 lines long, and the crashing function I was debugging was only about 1/4 of the way done before crashing. Up until discovering trace, I had been guessing what might go wrong, commenting things out, printing things - even though as we've learned, once Maya goes you aren't getting any of your printed messages.

The Function

For completeness, I'll point out a few things about the tracing function above that are important.

1. sys.stdout is Maya's output file handle, it's more or less how you communicate with the Script Editor and what print() redirects to. So you'll want to take care not to overwrite it and forget to restore it.
2. sys.stderr is not necessary for the tracer, it only outputs using print(), but by including it we're also capturing error messages. Or so I think, I didn't actually get any at the time of using this.
3. Trace has a outfile argument, but it isn't what you think. It's only to store previous "count" values, presumably for profiling. It doesn't actually output the trace to a file like we do "manually" here.

from cmdx.

Not noobish at all, debugging Maya is impossible. Simply put. They do not provide debug symbols and crashes reveal little to no information about why it happened. Best one can do is trial-and-error your way to a suitable workaround.

To speed up iteration time, I use mayapy along these lines.

from maya import standalone
standaline.initialize()

import my_module
my_module.test()

Booting up mayapy is somewhat quicker than booting up the UI, and crashes have been consistent between the two so far.

Once you've got a reproducible case with cmdx, I would recommend reproducing it with plain maya.api.OpenMaya, such that it can also be posted on the Autodesk forums for more help.

from cmdx.

OK so I made some progress on that crash:

• in Plug.deleteAttr(), we do _fn.removeAttribute(), but we don't delete our own cached MPlug
• next time we access the attribute, cmdx returns the cached MPlug... which we can survive until we read() it -> crash
  • I wasn't able to trace exactly where in read() the crash occurs, as hooking up a debugger at that point causes Maya to rage-quit, no crash reporter or anything... bad manners, Maya!
  • I'd like to add an assert in findPlug() to check that the cached plug we return is still valid... problem is, I don't know how! I'm looking for an isValid or isAlive property (MPlug.isNull returns false at that point).
• so we're missing a del _state["plugs"][attr], basically
  • for Compounds, we also need to delete the children, recursively (I assume _fn.removeAttribute() is already recursive?)
  • (not sure if/how array items are cached and whether they should be purged as well)
  • not sure if this is also an issue for non-Compounds, but IMO the current test in deleteAttr() is incomplete: it's adding an attribute, deleting it, then using hasAttr() to check its non-existence; problem is, hasAttr() uses the _fn directly, it doesn't go through the cache system. If I'm right, then doing eg value = node["myAttr"].read() after the delete would crash.
  • I have a fix here (for compounds), and possibly a PR at some point... though I expect you'll want tests 😄 !
• while I was in there, I also noticed that findPlug() uses the non-full-path name as a key, so eg "myNestedAttr" where IMO it should key "myCompound.myNestedAttr", otherwise we'd get a clash if I have "someOtherCompound.myNestedAttr" (which I'm not sure is allowed? have to check)
  • are Maya attributes case-sensitive? if not, maybe we should lower-case the key and accesses
  • also it'd be nice to support full-path access, eg node["myCompound.myNestedAttr"] (currently only node["myNestedAttr"] is supported; not sure the internal findPlug() supports full-name access).

from cmdx.

Great summary. I don't use compound attributes, nor delete attributes, myself so it's quite possible there are low-hanging fruit to be harvested in this issue forest.

To confirm it's related to plug reuse, you could try cmdx.clear(). It'll wipe all reuse, for both nodes and plugs (plugs are stored within nodes).

from cmdx.

Not noobish at all, debugging Maya is impossible. Simply put.

Ugh, well that's disappointing.
Is there at least a way to access the script editor log after a crash? The crash log doesn't contain it.

Booting up mayapy is somewhat quicker than booting up the UI, and crashes have been consistent between the two so far.

Good tip! I'll try that next time.

To confirm it's related to plug reuse, you could try cmdx.clear().

Yup I did try it, that solves it. I'm now looking for a more surgical approach, as well as asserting for future safety.

from cmdx.

Is there at least a way to access the script editor log after a crash? The crash log doesn't contain it.

Not that I'm aware of. :S If you're lucky, the Output Window (on Windows) remains open long enough for you to spot what's going on, it contains at least some useful information. Especially for C++ development where this debugging problem is also rampant.

That said, you can redirect the script editor to a file via Python's logging module. Maya uses this logging handler for Script Editor output, maya.utils.MayaGuiLogHandler. You should be able to either append another handler, or override and overwrite this handler to save to disk. That way, at least you've got that file to inspect after a crash. Adding/modifying handlers is standard Python stuff, so you should be able to turn to StackOverflow or the like for help. It's possible there is something else in that maya.utils package to help with this, but I've honestly never gone this route and always chosen to live with it haha.

Yup I did try it, that solves it.

Ok. Then that's definitely a cmdx bug. Come to think of it, I have had issues deleting attributes. My "solution" has been to use cmds.deleteAttr for those cases; it's so rare I hadn't even thought of investigating what the cause might be. So if you do manage to find a fix, that would be amazing.

from cmdx.

That said, you can redirect the script editor to a file via Python's logging module. Maya uses this logging handler for Script Editor output, maya.utils.MayaGuiLogHandler.

Awesome! I can probably also use that to pipe back to my IDE (VsCode) and get line hyperlinks in the console... someday!

Regarding the delete issue, I do have a working fix, seems stable so far.
Could be a life-changer for me honestly because for months now, every time I did something a bit brutal (ie regenerate a node/attribute hierarchy from some proprietary data), it was super brittle but felt random so I could never pinpoint it. Only recently did I start a feature that made it 100% reproducible.

I'm giving up on trying to detect dead plugs in findPlug() though; sometimes a symptom is that mplug.partialName() returns an empty string; sometimes it appears valid but actually returns the name of plug n+1 or n-1 (I suppose om.findPlug returns an offset in the node's plug array or sth); most of the time though, just calling .name() (or anything other that .isNull really) is enough to crash.
So yeah, the only way to detect crashyness... is to crash. Good times.

from cmdx.

I'm giving up on trying to detect dead plugs in findPlug() though

I know how you feel. I've been dealing with arbitrary crashes and proxy attributes in Maya (2019, specifically) lately. Maya is not forgiving when it comes to crashes.

It would be a totally reasonable temporary solution to clear any plug cache whenever an attribute is deleted though. I've done that a few times only to realise and spot a solution shortly thereafter. Deletion generally isn't run-time sensitive, and even if it was stability is more important than performance.

from cmdx.

Sure clearing is reasonable perf-wise. I like being more precise though, only to make sure I've understood the issue precisely, gives me more confidence. If it still crashes after that, then it means there's more to the issue.

from cmdx.