CodeSOD: Reopening the Log

The list of things never to write yourself contains some obvious stars: don't write your own date handling, your own encryption, your own authentication/authorization. It's not that no one should write these things, it's that these domains all are very complicated, require a great deal of specialized knowledge, and while easy to get almost correct, they're nearly impossible to get actually correct. If you embark on these tasks, it's because you want to create a product that solves these problems, hopefully not because you've got a terminal case of NIH syndrome.

While it's not as big a star on the list, another domain you probably shouldn't try and solve yourself is logging. Today's anonymous submission isn't the worst home-grown logging I can imagine, but it's got enough bad choices in it to merit some analysis.

#!/usr/bin/python## A Logger to append text to a file# No support for multiple processes sharing the same file (one to one for now)# Add locking support later if we need it.#import datetime, traceback,osclass Logger: "Simple logger to append text to a file" def __init__(self, logFileName): assert os.path.isabs(logFileName), "Path must be absolute path" assert os.path.exists(os.path.dirname(logFileName)), "Directory: " + os.path.dirname(logFileName) + " doesn't exist" self.LogFileName = logFileName def log(self, msg): try: fh = open(self.LogFileName, "a+") try: now = datetime.datetime.now() fh.write( now.strftime("%Y-%m-%d %H:%M:%S") + " " + msg + "\n") finally: fh.close() except: print "Error: can\'t open file or write data" print traceback.format_exc()

Right off the bat, I'm concerned about the shebang. It's not wrong, but when a file contains clear library code, I'm suspicious about the intent of running it as a script. It might be because it supports some unit testing, but... let's be realistic. Nobody wrote tests for this.

This particular code came from our submitter's senior devs, and it shows, because they add some asserts for defensive programming in the constructor. The requirement that the input is an absolute path is mostly a choice, but in my mind, a sane logging library should be able to handle relative paths, and while this code predates PathLib, even in older editions of Python, resolving paths wasn't a huge task. Still, that's not a WTF, and it's explicitly a "simple logger", so we shouldn't pick on it for missing features.

Let's pick on it for bad choices, instead.

For every message we want to log, we open the file, write the message, and then close the file. I know that, if we're using Python, we've already given up on high performance code, but every logging message has the overhead of opening a file. "No support for multiple processes" indeed.

Even better, however, is the exception handling behavior. If we try to open the file and fail, we print out an error message. But, if we succeed in opening the file but fail to write to it- the logging message is lost and no error is reported. Here's hoping this never runs when the disk fills up.

Remember how I, without evidence, said "nobody wrote tests for this"? This code also provides the evidence: the fact that the act of logging opens the file, fetches the current time, formats the message, writes the message, and closes the file all in one function makes it pretty much impossible to actually unit test this. Maybe, maybe they've written some kind of functional test that logs a bunch of messages and then checks the result. But it's far more likely that the developer just ran the program, visually confirmed the output, and said, "It's good."

Now, if you'll excuse me, I have to get back to implementing logging myself- using a set of well-tested and well-understood libraries.

[Advertisement] Keep the plebs out of prod. Restrict NuGet feed privileges with ProGet. Learn more.