Monthly Archives: September 2007

The python logging module is much better than print statements

Posted on by

A while back, I swore off using adding print statements to my code while debugging. I forced myself to use the python debugger to see values inside my code. I’m really glad I did it. Now I’m comfortable with all those cute single-letter commands that remind me of gdb. The pdb module and the command-line pdb.py script are both good friends now.

However, every once in a while, I find myself lapsing back into cramming a bunch of print statements into my code because they’re just so easy. Sometimes I don’t want to walk through my code using breakpoints. I just need to know a simple value when the script runs.

The bad thing is when I write in a bunch of print statements, then debug the problem, then comment out or remove all those print statements, then run into a slightly different bug later., and find myself adding in all those print statements again.

So I’m forcing myself to use logging in every script I do, no matter how trivial it is, so I can get comfortable with the python standard library logging module. So far, I’m really happy with it.

I’ll start with a script that uses print statements and revise it a few times and show off how logging is a better solution. Here is the original script, where I use print statements to watch what happens:

# This is a.py

def g():
1 / 0

def f():
print "inside f!"
try:
g()
except Exception, ex:
print "Something awful happened!"
print "Finishing f!"

if __name__ == "__main__": f()

Running the script yields this output:

$ python a.py
inside f!
Something awful happened!
Finishing f!

It turns out that rewriting that script to use logging instead just ain’t that hard:

# This is b.py.

import logging

# Log everything, and send it to stderr.
logging.basicConfig(level=logging.DEBUG)

def g():
1/0

def f():
logging.debug("Inside f!")
try:
g()
except Exception, ex:
logging.exception("Something awful happened!")
logging.debug("Finishing f!")

if __name__ == "__main__":
f()

And here is the output:

$ python b.py
DEBUG 2007-09-18 23:30:19,912 debug 1327 Inside f!
ERROR 2007-09-18 23:30:19,913 error 1294 Something awful happened!
Traceback (most recent call last):
File "b.py", line 22, in f
g()
File "b.py", line 14, in g
1/0
ZeroDivisionError: integer division or modulo by zero
DEBUG 2007-09-18 23:30:19,915 debug 1327 Finishing f!

Note how we got that pretty view of the traceback when we used the exception method. Doing that with prints wouldn’t be very much fun.

So, at the cost of a few extra lines, we got something pretty close to print statements, which also gives us better views of tracebacks.

But that’s really just the tip of the iceberg. This is the same script written again, but I’m defining a custom logger object, and I’m using a more detailed format:

# This is c.py
import logging

# Make a global logging object.
x = logging.getLogger("logfun")
x.setLevel(logging.DEBUG)
h = logging.StreamHandler()
f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s")
h.setFormatter(f)
x.addHandler(h)

def g():

1/0

def f():

logfun = logging.getLogger("logfun")

logfun.debug("Inside f!")

try:

g()

except Exception, ex:

logfun.exception("Something awful happened!")

logfun.debug("Finishing f!")

if __name__ == "__main__":
f()

And the output:
$ python c.py
DEBUG 2007-09-18 23:32:27,157 f 23 Inside f!
ERROR 2007-09-18 23:32:27,158 exception 1021 Something awful happened!
Traceback (most recent call last):
File "c.py", line 27, in f
g()
File "c.py", line 17, in g
1/0
ZeroDivisionError: integer division or modulo by zero
DEBUG 2007-09-18 23:32:27,159 f 33 Finishing f!

Now I will change how the script handles the different types of log messages. Debug messages will go to a text file, and error messages will be emailed to me so that I am forced to pay attention to them.

# This is d.py
import logging, logging.handlers

# Make a global logging object.
x = logging.getLogger("logfun")
x.setLevel(logging.DEBUG)

# This handler writes everything to a file.
h1 = logging.FileHandler("/var/log/myapp.log")
f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s")
h1.setFormatter(f)
h1.setLevel(logging.DEBUG)
x.addHandler(h1)

# This handler emails me anything that is an error or worse.
h2 = logging.handlers.SMTPHandler('localhost', '[email protected]', ['[email protected]'], 'ERROR log')
h2.setLevel(logging.ERROR)
h2.setFormatter(f)
x.addHandler(h2)

def g():

1/0

def f():

logfun = logging.getLogger("logfun")

logfun.debug("Inside f!")

try:

g()

except Exception, ex:

logfun.exception("Something awful happened!")

logfun.debug("Finishing f!")

if __name__ == "__main__":
f()

Lots of really great handlers exist in the logging.handlers module. You can log by sending HTTP gets or posts, you can send UDP packets, you can write to a local file, etc.

Finally, I’d like to point out that Mike Pirnat has some excellent slides (in PDF format) on logging using the standard python library here.

Habits killed my cell phone

Posted on by

Every day, I pour a mug of coffee, drop my son off at day care, then drive across town to work. I have about a half-hour commute, which is plenty of time to finish that coffee.

Then on the way home, every day, I put my laptop bag in the back seat, plug my cell phone into the car charger, and put the cell phone into the empty coffee mug in the arm rest.

So, yesterday, I took the day off. I still dropped my son off at day care. Then I did not do a drive across town. I met a friend on the east side.

Then at the end of the day when I left to pick up my son, I went through the same routine. Then, when I got home, I retrieved the cell phone from the mug and that is when I realized that my cell phone had spent the last twenty minutes bathing in eight-hour-old coffee.

May it rest in peace.

A few neat night spots in Cleveland Heights and remarks on UFC 76

Posted on by

Watched UFC 76 last night with my friend at Jonny Malloy’s in Coventry. Malloy’s is a big old movie theatre with a bar in the back. It vaguely reminded me of the Alamo Drafthouse in Austin — but instead of playing hipster art-house movies and indie slasher flicks, they play UFC fights.

After that, we headed upstairs to City and East, which the last time I was there, was a place called The Loft that had way too many televisions. Now, City and East is a hookah bar. Sitting on couches and puffing on a hookah is a lot of fun. The place is not pretentious whatsoever. Apparently the Ohio smoking ban allows for hookah bars, which is just fine with me.

So, back to UFC 76.

There were several fights that ended with judge’s decisions. I don’t think a victory or a loss by a judge’s decision should be considered equivalent to a win or a loss by knockout or submission. And split decisions should probably be worth even less.

Anyhow, In the Sanchez – Fitch fight, Diego Sanchez immediately rushed Jon Fitch but couldn’t get him on the mat. Sanchez didn’t seem to have a plan B.

Forrest Griffin performed amazingly in his fight. Rua landed an elbow on Griffin’s forehead that opened a gash spurting blood like something from Kill Bill. In the end, Griffin won with a rear-naked choke and Rua looked exhausted.

The main event was brutal. Liddell really deserves the “iceman” moniker. He walks in the ring like he’s going out to mow the lawn. He doesn’t bounce from foot to foot and he looks like he’s bored when he stares at his opponent. He showed no acknowledgement no matter how many times Jardine landed those bruising kicks to Liddell’s leg and side.

Meanwhile, Keith Jardine must have an incredible chin. Liddell scored with his wild swooping left hook repeatedly and Jardine kept coming back for more, despite a face t that looked like a side of beef at the end of the first round.

Just like with the Sanchez – Fitch fight, if this had gone a few more rounds, anything could have happened. It was too early for a decision to be made. Maybe we should have a tie-breaker round in the event that the judges’ scorecards are not unanimous.

I’m sad about two consecutive losses for Diego Sanchez and Chuck Lidell. They both have distinctive styles and their fights are really fun to watch. The sport needs people that stick around and build up fan bases.

GTA Vice City is right-wing propaganda.

Posted on by

This is another post from when I had a job that was smart enough to let me write blogs all day. The original post, along with comments from the k5 community, can be seen here.

First, let me list the good things in this game:

  • All the radio stations are wonderful. I drove around aimlessly on the vespa scooter for nearly an hour just to see how much material they recorded for the KCHAT channel.
  • All the voice tracks are excellent.
  • The physics for car-driving were great fun. I especially liked getting a dump truck up to top speed and smashing into police cruisers.

However, I returned the game 3 days before the due date. Maybe the rest of you were entertained by the opportunity to beat cops and prostitutes, but the fun in that wore out pretty quick.

List of everything I didn’t like:

  • The character animation was awful. Most of the dialogue scenes reminded me of Jack from Tekken (may his blocky soul rest in peace).
  • At its core, the game consists of taking orders from bosses and running errands. That’s essentially my real life; how is this truly escapist?
  • The hand-to-hand fighting is clunky and uninteresting. I lost plenty of fights because I would punch and kick in the wrong direction. The designers should steal some ideas from recent games like Onimusha or Mark of Kri that have done hand-to-hand combat right. And give me a chance to do combos!
  • After a while, playing this game gets downright creepy. Do most ps2 owners really fantasize about this stuff?

I stopped playing at around the point where I was supposed to kill the Mob boss’s wife and make it look like an accident. You can call me whatever emasculating, effeminate names you want to, but I didn’t enjoy the fact that the game designers actually had the wife beg for help during that “mission”. Really bad taste. But not the good kind of bad taste, like what you get in early Jon Waters movies. I love that kind of bad taste. This was more like puerile misogynist bad taste from junior high study hall.

For those that are unaware, the gimmick with all the Grand Theft Auto games is that the player becomes a low-level criminal and interacts with other underworld denizens. In Vice City, players do stuff like kill mob bosses, blow up buildings, intimidate juries, etc.

When the first Grand Theft Auto 3 game hit stores, pundits argued that this first-person perspective glamorized crime. After playing for several hours myself, I don’t buy that argument.

Nobody that finishes this game will want to carjack a minivan and steal illegal microchips from a French courier.

Instead, if you’re willing to entertain the idea that the player is getting subconsciously programmed, Vice City is more likely to foster reactionary ideas about undeserving poor, the working class’s lack of morality, the futility of the welfare state, and the need for a brutally effective police force to keep the underclass in its place.

After spending the dozens and dozens of hours necessary to finish this game, the conclusion to be reached is that criminals deserve no mercy. You’re more likely to walk away from playing this game thinking like Pat Buchannan than wanting to be Tony Soprano.

There’s even weird pro-fascist themes: if you attack a cop, more cops come after you. If you kill those cops, police helicopters show up, followed by super-effective FBI agents. Contrast this with the consequences of using a meat cleaver on a prostitute and then taking her money. The message is that you can prey on the weak all you want, but you better not make a move against the establishment, or they will crush you.

Most of the characters that the player meets in the game are prostitutes, mafia members, crooked businessmen, drug dealers, thieves, etc; a panoply of suburban stereotypes about the inner city. These are the people that Tony Salvetti (the player’s identity) has to beat up or kill. The message here is that victims of violent crime are often criminals themselves. Or, if they’re not actually criminals, they’re still people of low character.

Instead of being thought-provoking, Grand Theft Auto Vice City pumps out an oversimplified, social-Darwinist, Reaganite view of the world. Perhaps that’s why the designers chose the 1980s setting.