Logging to a database

Usually log messages are sent to a logfile or another host. In certain cases though, it pays off to put your log messages into a database.

We have a webapp which receives a large number of requests. The requests are dispatched to various drivers. For each request we'll store the following data in the request table: the user which made the request, the driver to which it as been dispatched and the status of the request result. In addition to this we'll provide the driver with a logger object, which can be use to store messages in another table (message). Each message is associated to it's corresponding request via a foreign key.

The Database

Let's use an SQLite database and set up the two tables:

CREATE TABLE request (
    id INTEGER PRIMARY KEY,
    user TEXT NOT NULL,
    driver TEXT NOT NULL,
    status TEXT NOT NULL
);

CREATE TABLE message (
    request_id INTEGER NOT NULL,
    level TEXT NOT NULL,
    msg_text TEXT NOT NULL,
    msg_timestamp TEXT NOT NULL DEFAULT CURRENT_TIMESTAMP,
    CONSTRAINT fk_request_id FOREIGN KEY (request_id) REFERENCES request(id) ON DELETE CASCADE
);

Yes, foreign key constraints aren't enforced in SQLite, but you can enforce them with triggers.

Our webapp already does log to files with the quite wonderful Log::Log4perl module. We want to keep using this module for the database logging.

Here's what we're gonna do: when a request has arrived and has been validated, we'll create a request record and use its id for all the messages logged during that request's handling. The only problem is letting the driver know the request id as easy as possible.

As it turns out, Log::Log4perl has just the right tools for our task. They're called: Log::Log4perl::Appender::DBI and Log::Log4perl::MDC. The first one maps a log call to an SQL query, which will insert the message into the message table. The second one is called Mapped Diagnostic Context and it provides us with a hash to store data in. This hash can be accessed directly from the appender, so the driver doesn't even need to know the request id and can log as easy to the database as it would log to a file.

The Setup

Before we get to the proper Log::Log4perl configuration, let's see how we'll setup the request and request id:

package WebApp;

use Log::Log4perl;
Log::Log4perl::init('log4perl.conf');

sub handle_request {
    ...
    $db->insert('request',{
        user => $user,
        driver => $driver,
        status => $status,
    });
    my $request_id = $db->last_insert_id;
    Log::Log4perl::MDC->put('req_id', $request_id);
    ...
}

That's all there is to it. We're using DBIx::Simple here. I've already talked about it, but here are some new features. The insert method is quite straightforward. It takes a table name and a hash and inserts the hash values into the table using the corresponding hash keys as column names. The last_insert_id method is mapped to the DBI method with same name and it returns the id of the last inserted row, namely our request id. Finally, we store the request id in the MDC hash for the appender to use.

The Configuration

Now we must configure Log::Log4perl to store the messages in the database, more precisely in message table, with the proper request id. To do so we edit the log4perl.conf configuration file:

# request logger
log4perl.logger.request=DEBUG, request_log

# request appender
log4perl.appender.request_log=Log::Log4perl::Appender::DBI
log4perl.appender.request_log.datasource=DBI:SQLite:dbname=log.db
log4perl.appender.request_log.sql=INSERT INTO message (request_id, level, msg_text) VALUES( ?, ? , ?);
log4perl.appender.request_log.params.1=%X{req_id}
log4perl.appender.request_log.params.2=%p
log4perl.appender.request_log.usePreparedStmt=1

... aaand we're done. What we've done is create a new logger (named request) and told it to use the request_log appender. This appender talks to the database we've configured (in the datasource field) and executes a prepared statement (it's faster!) with the given SQL query. Note that the query itself uses placeholders to avoid any SQL injection issues. The query parameters are first filled out from the config: the first one (mapped to request_id) is taken from the MDC hash we set up earlier. The second one is the log level (debug, info, warn, error, ...). The rest of ther parameters (well, there's only one left, msg_text) will be taken from the log call and yes, it's the log message itself.

The Payoff

Every driver can get a database logger object and log information into the database:

package MyDriver;

use Log::Log4perl;
my $logger = Log::Log4perl::get_logger('request');
...
$logger->warn('Invalid frobnitz detected');

What's more, SQLite will kindly record a timestamp for the log message too (in the msg_timestamp. The messages will be linked to their request and you can select and aggregate them them by level, time, user, driver or status.

The Bonus

The log message table structure can be extended easily. Just add these two lines to the Log::Log4perl config:

log4perl.appender.request_log.layout=Log::Log4perl::Layout::NoopLayout
log4perl.appender.request_log.warp_message=0

They will keep Log::Log4perl from concatenating the arguments of a log. Now you to use more parameters in the log call and map them to other fields in the table. For example we'd like the driver to provide an error code along with the log message. Just add the error_code column to the message table and change the SQL query config line to:

log4perl.appender.request_log.sql=INSERT INTO message (request_id, level, msg_text, error_code) VALUES( ?, ?, ?, ?);

Now the driver can provide the code as the second parameter:

$logger->warn('Frobnitz is invalid', 'INVALID_FROBNITZ');

Even if the driver provides no second parameter the error_code column will be NULL.

The Pitch

That's amazing! You've seen it with your own eyes, folks, yes, Log::Log4perl can log it all!! Even to a database.... with more than one field... and a many-to-one relationship!!! It's true! It logs like no other! Buy Install now!

Quick'n'Dirty SQL

I'm a convinced DBIx::Class user, but from time to time I find myself in need of a quick'n'dirty alternative. Something that let's me meddle with a database without the need of setting up result set classes or using loaders, but at the same time something more powerful and expressive than pure DBI.

Therefore, I present to you DBIx::Simple . It's half-way between the thought-out, "enterprisey" DBIx::Class and the raw, "bare-metal" DBI.

Let's see what you can do with it! It tend to use it in conjunction with SQL::Abstract, since I'm familiar with it via the search method of DBIx::Class.

First things first: setting up a DBIx::Simple object is trivial if you already have a connected DBIx::Class schema:

$my_dbs = DBIx::Simple->connect( $my_schema->storage->dbh );

Even if you don't have a schema, you can use the same semantics as with DBIC (namely an array):

$my_dbs = DBIx::Simple->connect( $dsn, $user, $pass, \%options );

Quick'n'Dirty Hashes

Let's say we have a database which describes articles (i.e. there's table articles which has an article_id and a name column) and we want to turn that into a hash with the id as key and the name as value:

%articles = $my_dbs->select('articles')->map;

Note: assumes the table has just these two columns and article_id is the first column.

OK, but what if we want to mark some articles in the database as unavailable and have the hash return only the available articles? Just add an available column and there you go:

$available_articles = $my_dbs->select('articles', [qw/article_id name/], { available => 1 })->map;

Note: now we specify the two columns which make up the hash, along with the select condition so order and additional columns are not relevant anymore.

You might have noticed that the first code snippet creates a hash, while the second one creates a hash reference. DBIx::Simple will detect the context and return the appropriate value.

Quick'n'Dirty Arrays

You can also just pull out a list of all articles names, instead of a hash:

@article_list = $my_dbs->select('articles', ['name'])->flat;

Oh, just a list of unavailable articles, but you want the ids instead of the names? OK:

$unavailable_articles = $my_dbs->select('articles', ['article_id'], { available => 0 })->flat;

Note: as with map, DBIx::Simple will allow you to create either arrays or array references depending on context.

Quick'n'Dirty Complex Data Structures

Now let's consider something more complex. Let's get all the data pertaining to articles in a big array. Each record will be a hash with column names as keys and record values as values:

@all_articles = $my_dbs->select('articles')->hashes;

That's all there is to it. Of course you can get an array of arrays (with the arrays method, of course). For arrays of arrays it's best to specify a column list so as not to rely on the implicit column order provided by the database:

@articles_as_arrays = $my_dbs->select('articles', [qw/article_id name available supplier/])->arrays;

But let's go to something even more wonderful, like a hash of hashes. The first level hash will have the article_id as key and the second level hashes will have column names as hashes (just like in the previous examples):

$article_hash = $my_dbs->select('articles')->map_hashes('article_id');

As you can see, any way you want to slice and dice your database data, DBIx::Simple will lend a helpful hand.

Quick'n'Dirty Updates

Quickly make all articles from the ACME supplier as unavailable, because he's temporarily unable to deliver? No problem:

$my_dbs->update('articles', { available => 0 }, { supplier => 'ACME'} );

The first hash represents column to set and the second columns on which to filter.

Quick'n'Dirty Cleanup

And finally, as a bonus, a method to quickly empty all tables in a MySQL database (hopefully, it's the test database and not the production one):

@table_list = $my_dbs->query('SHOW TABLES')->flat;
$my_dbs->delete($table) foreach my $table (@table_list);

That's it! But there are plenty more examples and informations available on CPAN.