Debugging Your Code

Seeing The Output

Now we're ready to see our logging code in action. I put the code in wiz/rhialto/python/scratch.py, so I can cast the spell like this:

cast wyvern/wiz/rhialto/python/scratch.py on rhialto

Normally when I cast the spell, this is the output I get:

You cast scratch on rhialto
You scratch yourself.
You scratch yourself.
You suddenly belch.
You scratch yourself.
You scratch your ear.
You rub your nose.
...

It continues like this, every 20 seconds, until I dispel the spell with dispel 1 (or dispel scratch).

I can turn logging on with the debug command. To do this, I type debug in my client, with the log level to use, and the class to debug. For example, I typed:

debug fine scratch.py

and it told me:

You will start seeing log messages at level FINE for scratch.py

I then cast the spell to see the log output, and this is what I saw:

--scratch.py.start(): setting timer
--scratch.py.start(): making dispellable
--scratch.py.start(): looking for target
You cast scratch on rhialto
--scratch.py.timerExpired(): entering
You scratch your ear.
--scratch.py.timerExpired(): entering
You rub your nose.
dispel 1
--scratch.py.dispel(): calling superclass
--scratch.py.dispel(): killing timer
You suddenly feel more sophisticated.
You dispel your scratch spell.

As you can see, we're getting lots more output now. We're seeing all the messages at level FINE and higher. For some situations, this might be enough to tell you if there's a problem in your code. For example, you might be wondering if the timer's getting called at all, and this would tell whether it is or not.

I can get even more output by turning on FINER mode debugging:

debug finer scratch.py

You will start seeing log messages at level FINER for scratch.py

cast wyvern/wiz/rhialto/python/scratch.py on rhialto

--scratch.py.getArt(): ENTRY
--scratch.py.start(): looking for target
--scratch.py.start(): setting timer
--scratch.py.start(): making dispellable
You cast scratch on rhialto
--scratch.py.timerExpired(): entering
--scratch.py.timerExpired(): rolled 68
--scratch.py.timerExpired(): gender his
--scratch.py.timerExpired(): name: rhialto
You suddenly belch.

And of course, if I want to see everything, I can turn on FINEST debugging, and get more output than I ever wished for.

Note: I spent at least an hour debugging this example, because my finer() messages weren't printing. It turns out that when Jython executes this line:

it causes the method to exit immediately without (apparently) throwing any exceptions to any logs. It doesn't know how to convert the int roll into a string with the + operator, so you have to do it yourself:

So make sure all your logging messages use correct Jython syntax, or you'll wind up having to debug your debugging code!

The next lessons cover some important things you should know about logging before you start using it in your code.