Acme MUD

Logging July 26, 2014

So I made I a project plan this week. Well not so much a project plan as a bunch of issues that are marked as either release 0.1 or 0.2. But I have a list, so that’s something. Working my way from top to bottom in order of unsexiness, the next task after documentation generator is logging. Writing it was kind of a grind (as was most of the doc generator), but without a solution in place pretty much every piece of code is going to have to be amended later when it eventually does come along. Logging is in everything. I suspect there are still a number of bugs to be found since I didn’t really test everything, but whatever, that ubiquity just means we’ll find em faster.

So here it is for your consideration. It’s basically a simplified port of log4j but it does have a couple MUD-specific bells and whistles to show off.

intro to log4j

So when I say log4j, I’m really talking about any number of logging libraries that use the same basic schematic. There are a number of them – the ones I’ve bumped into are a wrapper API slf4j, and Python’s logging library to name a couple. If you’re new to Java and are working out in the world, one of the first things yr gonna have to do is learn how log4j works. From what I can tell, pretty much everyone uses something like it (even those embedded folks I bet). With that kind of adoption rate, I felt like it wasn’t even worth the effort to consider some alternative solution. The interface is hopefully pretty intuitive even if you’ve never used one of those other loggers before. The typical usage is something like this: <pre>object logger = LoggerFactory->get_logger(THISO); logger->warn("it's a trick, get an %s", "axe"); </pre>

First there ya got your LoggerFactory call. LoggerFactory creates and configures Logger instances which will be described in depth later. Once you got your logger, you just call one of several different logging methods with your message. The arguments to the warn() function above are interpreted as if you were calling printf(). One of the things I hate HATE about log4j is this: <pre>if (logger.isDebugEnabled()) logger.debug(some + complicated + ass + message) </pre>

If ever there were an excuse for AOP, it’s logging. slf4j mitigates this somewhat by providing these {} tokens you can use to do string replacement, but I like the sprintf() syntax better. Granted you still have your is_foo_enabled() functions on the logger object for situations where there’s a bunch of other voodoo that has to happen to build the message; but for simple string addition, no enabled check needed.

The event in this example is just a warning, but there are like 6 log levels to choose from. Then you write this config file that specifies what exactly gets written, when, and where. That “THISO” argument up there is the “category”, and configuration options are grouped by hierarchical category tree. This last part is important; it’s one of the reasons I adopted the design that I did, but I need to explain the structure of the configuration files before I can get into that.

etc/logger.properties

The properties file is where things start to go off the rail a bit. A typical file looks like this:

logger.output=f:log/eternal-city.log
logger.format=%d %p %l - %m
logger.level=ERROR
logger.library.output=f:log/eternal-city.log,c:thisp
logger.library.level=DEBUG

</code> Every line is of the format <pre>logger.<category>.prop=value</pre>, where category needs to match the category we passed to the get_logger() call above, and the prop is one of “output”, “format”, and “level”.

In the example above, the first line does not specify a category, which means it applies to every category descended from and including the root category. The root category in this case is private.eternal, because the properties file is in the /private/eternal/etc folder. All paths and categories you specify in the config will be relative to this directory (minus the /etc part). The property that is being configured is the output property, which determines where the log message is written. This is comma-delimited list of target specifiers, where a target is specified as target type and a target spec, separated by a colon. If the target type is ‘c’, the target spec is interpreted as an object spec, and logger will tell_object() the message to the targets. If the target type is ‘f’, the target spec is interpreted as a filename (relative to the root) to which the message will be written.

The next line is the format string, which specifies exactly what information is written to the log (beyond just the message that was provided to the warn() call above. There’s a lot going on here, so I’ll save this for next section.

The third line sets the minimum level a log message needs to be in order to be logged. So the the first three lines altogether instruct the logger to: log every message of ERROR level or higher, logged from inside the /private/eternal directory and its descendants, to /private/eternal/log/eternal-city.log.

So one of the things I like about this model is that it massages your directory hierarchy to be complementary to your workflow. Take for instance the fourth and fifth lines above. Let’s say that some code in the Eternal City library errored and the message was found in eternal-city.log, but did not provide enough information to remedy the problem. So someone has gone in and modified the logger.properties file to turn on logging for the all the DEBUG messages in the library. They also added a console output spec for thisp, because they plan on through the area and looking for the problem. This is all possible because the source code that makes up Eternal City has been thematically grouped by location, and the library has its own category.

the format string

The format string is kind of neat. I borrowed the same design I used for the prompt on EotL:

1. split up the string with our format specifier (the percent sign in this case)
2. iterate over the different parts and build a sprintf format string as well as a list of sprintf arguments. each argument is expressed as an uncompiled lambda closure.
3. once you have all the pieces, build your final lambda closure out of the with an sprintf call and send that closure to the logger. all the logger has to do when it goes to log something is run the closure with the needed runtime args.

We can (and do) even share these formatter closures between loggers that are configured to use the same format string. That’s something I should have done with the prompt but never did. As far as the format string itself goes, I just copied all the log4j patterns that applied for now. The environment we’re in actually allows for a whole bunch of other things we might want to log (THISP, info about the command being executed, stacktraces), but I’m not gonna try to anticipate every need right now. Here are the patterns we do support:

• %c{x} - the category of the logger, (or optionally the last x components of the category)
• %C{x} - the program name of the caller, (or optionally the last x components of the name)
• %d{x} - the current time, as expressed by strftime using x as the format string
• %l - the location string. formatted like Java’s %l right now but should be tweaked.
• %L - the line number
• %m - the message being logged
• %n - a newline
• %p - the priority of the logging event
• %r - milliseconds in the current second
• %% - the percent sign

inherited properties

So one of the things my logger does that I’m not sure if log4j does anything similar, is walk up the directory tree looking for properties files looking for matching configuration directives. In fact, any file called etc/logger.properties is considered for logger configuration if it’s in the path of the object doing the logging. Conflicting config properties favor the property being defined in the file lower down in the directory tree. In the example above, the library could have also defined its own file /private/eternal/library/etc/logger.properties to override those set for all of Eternal City.

logger reuse and cleanup

So one thing the LoggerFactory does is, once it’s cloned and configured a new logger, it stores that logger away for later use. So if there are multiple calls to get_logger() from the same object, it doesn’t need to build a new logger every time. In fact, one of the things that may be worth doing in the future, is writing some equality test for loggers so we can share them between similarly configured clients.

Clean-up in the individual Logger instances is turned off, but every reset, stale loggers are destroyed by the LoggerFactory based on their last ref time and current ref count. Any logger not being referred to by anything but the logger factory is eligible for clean up. At this time, LoggerFactory is set to noclone, but it’s conceivable that we may want to allow for multiple factory instances which have different cleanup schedules (e.g. one for long-lived loggers, one for short-lived loggers).

And there ya have it. The API docs are up in the documentation section. Oh and here’s some sample output from my local instance:

2014-07-26 17:15:52,908725 WARN  private/home/devo/tmp/cc->cc(private/home/devo/tmp/cc.c:2) - this is a test

There’s still a buncha TODOs I left myself that say “log a warning” that I gotta deal with, but it’s not as bad as it could have been had I waited. I think next up after that is more utility stuff, like a pager. I’d really like to do something more iteresting like say and tell, but not sure I want to dive into communication just yet. Also before the weekend’s over I need to take a first pass at the About page.