Tuesday, May 5, 2009

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!

1 comment:

  1. Nice!

    Do you use a SQLite DB in a production environment for logging like this?

    An issue I have with Log4perl in conjunction with Catalyst and mod_perl is that every app logs in the same logfile...

    ReplyDelete