Logging and being proactive

October 5th, 2008 by Patrick Boucher - Viewed 9276 times -




You write tools for artists under a deadline (yours and theirs). You live in a production oriented world. Unit testing, beta testing and anticipating can only go so far, and that is only if you have time to properly test. You have to accept that eventually, your code will break. How it breaks and how you react to such a break becomes as important as your capacity to create the tool in the first place.

You’ve probably seen the following idiom used many times on this website and in other places that do XSI scripting in Python:

1
2
3
from win32com.client import constants as c
xsi = Application
log = xsi.LogMessage

It is a shortcut that allows you to use log as if it was the native LogMessage call:

1
log('This is an info message.', c.siInfo)

Here is a way to extend this by using the standard logging module in a way that can help you be more proactive. I suggest you get familiar with the logging module from the standard Python docs, it’s bound to eventually be helpful.

Logging in XSI

Here is a construct I’ve started using lately that I am starting to enjoy, its advantages are:

  • Concise and self documenting
  • It has a trap to catch any unexpected error and log it
  • Logs both to the script editor and to file
  • Easily extensible to other logging mechanisms (email, event viewer)
  • You can pass non string messages and it will convert to string for you (Yay!)
  • Easily useable in scripts and other modules
1
2
3
4
5
6
7
8
9
10
11
12
13
from hookolo.xsi import *
 
def main():
	log.comment('comment')
	log.debug('debug')
	log.info('info')
	log.warning('warning')
	log.error('error')
	log.fatal('fatal')
	log.critical('critical')
	raise Exception('Totally unexpected exception!')
 
run('demoScript', main)

The code above would produce the following output in XSI’s script editor.

# comment
# VERBOSE : debug
# INFO : info
# WARNING : warning
# ERROR : error
# ERROR : fatal
# FATAL : critical
# ERROR : Trap reached in demoScript
# Traceback (most recent call last):
#   File "C:\hookolo\libs\hookolo\xsi\__init__.py", line 18, in run
#     func(*args, **kwargs)
#   File "<script Block >", line 11, in main
# Exception: Totally unexpected exception!
# ERROR : Traceback (most recent call last):
#   File "<script Block >", line 13, in <module>
#     run('demoScript', main)
#   File "C:\hookolo\libs\hookolo\xsi\__init__.py", line 21, in run
#     raise StopScriptError('Check the logs!')
# StopScriptError: Check the logs!
#  - [line 13]

The calls to log.comment, log.debug, log.info, log.warning, log.error and log.critical are all self explanatory as they are all equivalent to LogMessage calls with the appropriate severity argument. The call log.fatal is an addition of my own who’s severity is equivalent or just a tiny bit lower than critical. Fatal errors will not pop a dialog box.

In the setup I have here, both fatal and critical, will be logged to a file in the users’ XSI_HOME directory that looks like follows.

2008-10-04 23:46:13,720 - hookolo.xsi - FATAL - fatal
2008-10-04 23:46:13,720 - hookolo.xsi - CRITICAL - critical
2008-10-04 23:46:13,720 - hookolo.xsi - FATAL - Trap reached in demoScript
Traceback (most recent call last):
  File "C:\hookolo\libs\hookolo\xsi\__init__.py", line 18, in run
    func(*args, **kwargs)
  File "<script Block >", line 11, in main
Exception: Totally unexpected exception!

By having a file like this, I don’t have to wade through XSI’s scripting log as I have a file that only includes important script errors. I also don’t have to worry about a user coming to me and saying: “Your script exploded.” Followed by the inevitable: “No, I don’t remember the error and I don’t have it in my scripting window anymore.” Now I can just open up this file from their XSI_HOME directory and look for myself.

The usage of a main() function and a run() function allows to build a trap for any unexpected errors that might occur and allow for logging. By putting the runner in a library we can benefit from it with very little hassle in even the tiniest of scripts.

Pushing the envelope

A system such as this one could even easily be extended to allow for sending of fatal and critical errors via email. You would know that a script failed even before the artist had walked the corridor to your office to tell you about the failure. This extension wouldn’t even be that hard as the logging module includes an SMTPHandler for just this purpose.

Support code

Here is the library that makes this all possible.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
import logging
import os
import sys
import types
 
from win32com.client import constants as c
from win32com.client import Dispatch
 
__all__ = ['xsi', 'log', 'c', 'run', 'XSIError']
 
COMPANY_NAME = 'Hookolo'
COMPANY_PREFIX = 'hookolo'
 
xsi = Dispatch('XSI.Application').Application
 
def run(scriptName, func, *args, **kwargs):
	try:
		func(*args, **kwargs)
	except:
		log.log(45, 'Trap reached in %s' % scriptName, exc_info=1)
		raise StopScriptError('Check the logs!')
 
class XSILogger(logging.Logger):
	def fatal(self, msg, *args, **kwargs):
		self.log(45, msg, *args, **kwargs)
 
	def comment(self, msg, *args, **kwargs):
		self.log(5, msg, *args, **kwargs)
 
class XSIHandler(logging.Handler):
	def emit(self, record):
		if record.levelno == logging.CRITICAL:
			xsiLvl = c.siFatal
		elif record.levelno in [logging.ERROR, 45]:
			xsiLvl = c.siError
		elif record.levelno == logging.WARNING:
			xsiLvl = c.siWarning
		elif record.levelno == logging.INFO:
			xsiLvl = c.siInfo
		elif record.levelno == logging.DEBUG:
			xsiLvl = c.siVerbose
		else:
			xsiLvl = c.siComment
 
		if isinstance(record.msg, types.StringTypes):
			msg = self.format(record)
		else:
			record.msg = str(record.msg)
			msg = self.format(record)
 
		xsi.LogMessage(msg, xsiLvl)
 
def getLogger(name=None):
	if name is None:
		return logging.getLogger(COMPANY_PREFIX + '.xsi')
	else:
		return logging.getLogger(COMPANY_PREFIX + '.xsi.' + name)
 
if not hasattr(sys, 'XSI_LOGGING_CONFIGURED'):
	logging.setLoggerClass(XSILogger)
	logging.addLevelName(45, 'FATAL')
	logging.addLevelName(5, 'COMMENT')
	log = logging.getLogger()
	xsiHandler = XSIHandler()
	xsiHandler.setLevel(0)
	fileHandler = logging.FileHandler(os.path.join(os.environ['XSI_USERHOME'], 'xsiScriptLog.txt'))
	fileHandler.setFormatter(logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s"))
	fileHandler.setLevel(45)
	log.addHandler(xsiHandler)
	log.addHandler(fileHandler)
	log.setLevel(0)
	sys.XSI_LOGGING_CONFIGURED = True
 
log = getLogger()
 
class XSIError(Exception):
	pass
 
class StopScriptError(XSIError):
	pass

One Response to “Logging and being proactive”

  1. Steven Caron says:

    thanks for the post patrick

    i get interrupted countless times a day with support related questions. i can usually debug it quickly and educate the user, fix, or improve the error handling regardless of who wrote the tool in the studio. but! there are times when i can’t fix a tool because i never hear about it. the user then never uses the tool again because they dont trust it. they may never let us know its not working. i am going to look into a email notification system for our tools so that we can get reports of failing tools regardless of how proactive our animators are. need to be sure i add an email filter for the countless number of emails i am going to get from failing tools in the studio.

    i can see another area where sending notifications is useful… statistics gathering and profiling of tools. once those tools have been tuned and made bug free you can disable the unnecessary logging.