::useful-ifying error messages::

May 4th, 2011 by hamish download the zooToolBox

Printing out warning and error messages from script is the easiest way to communicate things to a user. Maya has generally trained users reasonably well to look for warnings and errors in the script editor. This isn’t really ideal mind you – but thats a topic for another time.

Anyway, as useful as warnings and errors are, if you’re writing modular, re-usable code then writing stuff to the script editor isn’t always as helpful as it should be. Sometimes its hard to know exactly where a message is coming from. Sure, you can grep your code base, but sometimes even this isn’t that easy to do if the message itself is constructed.

In the olden days of MEL I would often try to put the function name at the beginning of the message in the hope of making it easier to track down the reference at a later date – but this wasn’t terribly ideal either. It required me to remember to do it, plus it was just one more reference to update when refactoring.

Python however gives you the tools to solve this problem in a nifty way. You can write a print handler that will figure out where in the code the print/warning/error statement happened and put all that in the message.

For example, I can write code like this:

printWarningStr( "WOW!" )

And the following message gets spewed to the console:

# Warning: WOW!: from line 14 in the function main in the script D:\someScript.py #

As you can see, in the message is encoded the warning prefix (it also turns the script line pink as per usual warning messages in maya) as well as the name of the function it came from, and the location of the script. You could also put the line number in there as well, but I figured I’d omit that for the sake of brevity.

Python is such an awesome language – so deliciously introspective.

So does this get done?

Well, I have two places that I setup this code. The first is in a generic, maya agnostic module so that I can use it in non-maya tools. It looks like this:

def generateTraceableStrFactory( prefix, printFunc=None ):
	'''
	returns 2 functions - the first will generate a traceable message string, while
	the second will print the generated message string.  The second is really a
	convenience function, but is called enough to be worth it

	you can also specify your own print function - if no print function is specified
	then the print builtin is used
	'''
	def generateTraceableStr( *args, **kw ):
		frameInfos = inspect.getouterframes( inspect.currentframe() )

		_nFrame = kw.get( '_nFrame', 1 )

		#frameInfos[0] contains the current frame and associated calling data, while frameInfos[1] is the frame that called this one - which is the frame we want to print data about
		callingFrame, callingScript, callingLine, callingName, _a, _b = frameInfos[_nFrame]
		lineStr = 'from line %s in the function %s in the script %s' % (callingLine, callingName, callingScript)

		return '%s%s: %s' % (prefix, ' '.join( map( str, args ) ), lineStr)

	def printTraceableStr( *args ):
		msg = generateTraceableStr( _nFrame=2, *args )
		if printFunc is None:
			print( msg )
		else:
			printFunc( msg )

	return generateTraceableStr, printTraceableStr

generateInfoStr, printInfoStr = generateTraceableStrFactory( '*** INFO ***: ' )
generateWarningStr, printWarningStr = generateTraceableStrFactory( '*** WARNING ***: ' )
generateErrorStr, printErrorStr = generateTraceableStrFactory( '*** ERROR ***: ' )

As you can see, this is a factory function that returns a function that will generate the message, and one that will actually print the message. You almost always want to use the print one, but if you ever need to generate an info/warning/error message using the same code, the generate function is available.

So the factory function allows you specify a print handler. It defaults to python’s built in print function (or statement if you’re pre 3.0), but this makes it easy to generate maya specific print functions using MGlobal.displayWarning and MGlobal.displayError. In another module I have the following code:

from maya.OpenMaya import MGlobal

generateInfoStr, printInfoStr = generateTraceableStrFactory( '*** INFO ***', MGlobal.displayInfo )
generateWarningStr, printWarningStr = generateTraceableStrFactory( '', MGlobal.displayWarning )
generateErrorStr, printErrorStr = generateTraceableStrFactory( '', MGlobal.displayError )

So in maya tools I simply use the above functions instead of print and voila – I get useful information in the console spew.

Anyway – not a super useful chunk of code, but I thought others might find such a technique useful. Its ~15 lines of code that occasionally saves me a grep of the codebase. Plus its good practice to have logging hooks like this in place.

Share

This post is public domain

This entry was posted on Wednesday, May 4th, 2011 at 19:37 and is filed under main. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.

  • karlerlandsen

    Out of curiosity, have you tried using Python’s “logging” module at all? I guess you’ve rolled your own? :)

    Logging’s a subject that’s a bit near to my heart, since we’ve had three cracks at Python logging at Framestore, and it’s only on the third attempt that it feels like we (finally!) got it right. And certainly using Python logging’s not easy! It’s more of a loose series of base-classes than a comprehensive solution; you still have to make your own wrapper module that initialises it differently for Maya/Houdini/Nuke/etc, replaces sys.excepthook so that uncaught exceptions are sent to the appropriate log.critical(), hooks into the Maya API so that you receive standard Maya print()s and so on… And in the process of making your own logging handlers, you notice that the API of these base classes isn’t great – you occasionally have to mess with private members of the parent class to get what you need.

    But once you get a configuration that works for you, it’s awesome. Every Python module logs to its own namespace, so can be filtered, handled differently, etc. All of our logging messages are automatically added to an in-memory sqlite database, and we’ve got custom PyQt widgets for displaying logging information from these databases, which is a cross between the Maya script editor and this:

    http://plumberjack.blogspot.com/2011/02/desktop-log-viewer-released.html

    Since most Python modules use logging in some form (nose, sqlalchemy, etc), it automatically integrates well with them too. We’ve also set it up so that whenever an uncaught exception happens, this sqlite DB log is dumped to disk and an email is sent to the owner of the module that failed to catch the exception with information like sys.path, currently opened scene, and a link to this DB dump. It’s completely changed our approach to handling error reports… It’s just a shame it took us three tries to get the damn thing right! :)

    Karl

  • Anonymous

    Heya Karl!

    y’know I haven’t actually messed with the logging module.  Honestly I don’t use logging that much.  I’ve not encountered enough cases where it would have been useful.  Not to say that I don’t think logging is useful – just that given the complexity of the tools we use around here, I don’t think it adds enough value.

    but what you describe does sound super cool – and way more in depth than anything I’ve done.  I have been meaning to look into the logging module more.

    thanks for sharing!