Debugging Perl DBI

Contents

Introduction

You’ve read our other Perl tutorials, installed Perl DBI and a DBD and have started writing your application but it is not working properly. What can you do? This tutorial ignores syntax errors in your Perl (which you can easily track down with perl -cw) and concentrates on locating those tough to find SQL, incorrect use of the DBI interface, transaction and logic errors.

Good DBI programming practise

Check the returns from DBI calls

Test the return from DBI method calls return a success value.

DBI->connect("dbi:ODBC:mydsn", "xxx", "yyy") or die "$DBI::errstr";

Normally this is a true and non-zero value, but in some cases it is a true but zero value e.g. DBDs will return a true value for an insert operation that inserts zero rows, but if you know the insert should insert a row, you test the returned value is true and not "0E0" (which is true but zero). See the next section, "RaiseError" and "Test inserts worked".

RaiseError

The handle attribute RaiseError is, by default, turned off. When the RaiseError attribute is turned on for a handle, it causes die to be called (or your HandleError routine) when an error occurs using DBI. If you turn RaiseError on in the DBI connect method, it will be inherited by all other handles created off that connection handle.

Without RaiseError, the following code (by default) will print the error (because PrintError is on by default) but not cause your program to die:

use DBI;
$dbh = DBI->connect("dbi:ODBC:mydsn","xxx", "yyy");
$sth = $dbh->prepare("invalid sql");
$sth->execute;
print "Got here without dying\n";

which when run, by default, prints an error saying your SQL is invalid but does not die, so your program continues making it difficult to track down where the error occurred or worse, compounding the problem, by continuing on to do other processing.

In comparison, changing the DBI connect method to:

$dbh = DBI->connect("dbi:ODBC:mydsn","xxx", "yyy", {RaiseError=>1});

causes your program to die when the invalid SQL is seen.

Normally, if you turn RaiseError on you will turn PrintError off but you don’t need to; the main purpose for turning it on is to kill your program at the point of failure, so you can diagnose the problem without doing any more damage.

With RaiseError enabled, you no longer need to test every return status so:

$dbh = DBI->connect("dbi:ODBC:mydsn", "xxx", "yyy") or
    die "$DBI::errstr";
$dbh->do("some sql") or die "DBI::errstr";
$dbh->do("some sql") or die "DBI::errstr";
$dbh->do("some sql") or die "DBI::errstr";
$dbh->do("some sql") or die "DBI::errstr";
$dbh->do("some sql") or die "DBI::errstr";

becomes:

$dbh = DBI->connect("dbi:ODBC:mydsn", "xxx", "yyy",
                    {RaiseError => 1}) or die "$DBI::errstr";
$dbh->do("some sql");
$dbh->do("some sql");
$dbh->do("some sql");
$dbh->do("some sql");
$dbh->do("some sql");

instead and DBI will automatically die on the first "do" which fails.

Test inserts/updates worked

If you execute an insert or update statement, check the operation inserted or affected some rows. By default, most DBDs will return true for a successful insert/update even if no rows were inserted or updated (a do method call is successful so long as the SQL runs).

e.g.

Suppose you have the table:

table : test
 column : a integer

and the table contains one row where "a" is 1. A:

$dbh->do(q/update test set a = 2 where a = 999/) or die "$dbh->{errstr)";

will generally return success and not die, but the real value will be ’0E0’, which means the do ran successfully but no rows were updated.

Better to do:

$affected = $dbh->do(q/update test set a = 2 where a = 1/);
die "$dbh->errstr" if (!affected); # trap errors
die "No rows updated" if ($affected eq '0E0'); # trap no insert/update

or turn RaiseError on and simple do:

$affected = $dbh->do(q/update test set a = 2 where a = 1/);
die "No rows updated" if ($affected eq '0E0');

Warning The DBI documentation suggests the rows affected may be -1 if the DBD does not know how many rows were affected. In practise, we do not know of a DBD which cannot tell you this.

Protect calls you expect could legitimately fail with evals

Once RaiseError is turned on (see RaiseError), you no longer need to test every operation worked (see exception in "Test inserts/updates worked"). However, if you expect an operation may legitimately fail, wrap it in an eval. e.g.

eval {
  $dbh->do(qq/insert into table (x,y) values ($a, $b)/);
};
warn "failed to insert $a,$b into table - $dbh->errstr" if ($@);

e.g. if column x was a defined as an integer and the insert could legitimately have $a set to a value that does not convert to an integer, this code would issue a warning instead of dying.

Use transactions, protect them with eval and commit or roll them back after the eval

If you are going to perform a number of updates or inserts that are logically grouped together such that they should all work or none of them work then use transactions.

Say you had two tables:

employee
    employee_id int auto_increment primary key
    name char(128)

  salary
    employee_id int primary key
    salary numeric(10,2)
    foreign key (employee_id) references employee(employee_id)

when we add a new employee, we insert a row into the employee table and then we insert a row for their salary into the salary table. If we fail to insert the employee record, we don’t want to attempt to insert a record into the salary table.

We do this with:

$dbh = DBI->connect("dbi:ODBC:mydsn","xxx", "yyy", {RaiseError=>1})
  or die "Failed to connect - $DBI::errstr";
eval {
     $dbh->begin_work;
     my $affected;
     $affected = $dbh->do(
        qq/insert into employee (name) values ($new_employee_name)/);
     die "no insert on new employee $new_employee_name"
       if ($affected != 1);
     # see DBI docs on last_insert_id
     my $lid = $dbh->last_insert_id(undef, undef, "employee", undef);
     $affected = $dbh->do(qq/insert into salary (employee_id, salary)
       values ($lid, $salary)/);
     die "Failed to insert salary $salary for $new_employee_name"
       if ($affected != 1);
};
if ($@) {
  $dbh->rollback;
  warn "Rollback - " .
    "Failed to create employee $new_employee_name with salary $salary" .
    $dbh->errstr;
} else {
  $dbh->commit;
}

Although this works as expected, it is difficult to debug since the warning or die occurs on a different line to the one that actually failed, so the location of the problem is down to the text in the die.

Consider adding comments to SQL

Most (if not all) SQL92 databases support adding comments to the SQL you execute. This can be an invaluable debugging aid, especially with DBIx::Log4perl, which shows the SQL you were executing when an error occurred.

The comment introduction is usually a double dash "--". You can embed debugging information into the SQL by appending the comment introduction and then your comment e.g.

insert into username (col1) values(?) -- insert_user, create user

If this fails, your debugging log will automatically help identify where this happened or what you were doing.

What you get in DBI out of the box to help you

DBI supports a tracing mechanism that allows you to trace DBI method calls and further internals depending on the trace level you set. Typically, you set the TraceLevel integer attribute on a handle to the value you require, with higher values logging greater detail. You can also set the DBI_TRACE environment handle before you run your Perl program to set the DBI trace level and optionally the name of a file to write the trace information to:

DBI_TRACE=1=dbitrace.log
export DBI_TRACE

before running, your program sets the trace level to 1 and writes the trace information to the file dbitrace.log. If you do not specify a file, the trace appears on stdout, which is what happens if you set the trace level on a handle with:

$handle->{TraceLevel} = $n;

With increasing trace levels, you can see the SQL executed and the parameters bound, plus, with even higher trace levels, internal tracing from the DBD you are using. The problem with even the lower trace levels is that the output is rather verbose and won’t mean a lot to anyone other than the author of DBI or the DBD you are using.

DBIx::Log4perl

Advantages of using DBIx::Log4perl

DBIx::Log4perl is a subclass of DBI that will log DBI operations in terms of DBI methods called, so the log output relates to what the application is doing instead of what the DBI or DBD is doing.

The advantages of using DBIx::Log4perl are:

Where to get DBIx::Log4perl

You can get DBIx::Log4perl from http://search.cpan.org/~mjevans/DBIx-Log4perl/.

DBIx::Log4perl dependencies

DBIx::Log4perl is dependent (currently) on DBI 1.50, (although 1.51 is preferred) and Log::Log4perl (version 1.04). You may also want to install Log::Dispatch for some of the additional appenders.

DBIx::Log4perl documentation

You can find the latest DBIx::Log4perl documentation on CPAN at:

http://search.cpan.org/~mjevans/DBIx-Log4perl/lib/DBIx/Log4perl.pm

DBIx::Log4perl quick start

The simplest way to get started with DBIx::Log4perl is to:

Now when you run your Perl script, the DBIx::Log4perl logging will appear in the file you designated in /etc/mylog.conf.

Example DBIx::Log4perl output

Assuming you’ve used the example.conf Log4perl configuration file, the logging will appear in /tmp/dbix.log. Unlike DBI tracing, this (by default) only contains logging for the DBI methods you call and the arguments you pass to these methods:

use Log::Log4perl qw(get_logger :levels);
Log::Log4perl->init_and_watch("example.conf");
my $dbh = DBIx::Log4perl->connect('dbi:Oracle:XE', 'user', 'password') or
    die "$DBD::errstr";
$dbh->do("insert into mytable values(?, ?)", undef, 1, 'string');
$dbh->disconnect;

by default produces:

DEBUG - connect: dbi:Oracle:XE, bet
INFO - DBI: 1.51, DBIx::Log4perl: 0.06, Driver: Oracle(1.17)
DEBUG - $do = ['insert into mytable values(?, ?)',undef,1,'string'];
DEBUG - affected: 1
DEBUG - disconnect

which shows us the connect, followed by the insert that affected 1 row (i.e. the insert worked) and finally the disconnect. In addition, the DBI version, DBIx::Log4perl version and driver name and version are recorded.

This is also a lot more succinct than the 39 lines you get from a level 1 DBI trace.

Catching errors with DBIx::Log4perl

By default, DBIx::Log4perl replaces any DBI error handler you have with its own error handler. The error handler first logs all possible information about the SQL that was executing when the error occurred, the parameters involved, the statement handle and a stack dump of where the error occurred. Once DBIx::Log4perl’s error handler is executed, it continues to call any error handler you have specifically set in your Perl DBI code.

Assuming you’d just run the following script:

use Log::Log4perl qw(get_logger :levels);
Log::Log4perl->init_and_watch("example.conf");
my $dbh = DBIx::Log4perl->connect('dbi:Oracle:XE', 'user', 'password') or
    die "$DBD::errstr";
$dbh->do("insert into mytable values(?, ?)", undef, 1,
         'string too long for column - will be truncated which
          is an error');
$dbh->disconnect;

but the string argument to the insert is too big for the column, DBIx::Log4perl would provide error output similar to the following:

FATAL -   ============================================================
  DBD::Oracle::db do failed: ORA-12899: value too large for column
   "BET"."MYTABLE"."B" (actual: 64, maximum: 10) (DBD ERROR: error
   possibly near <*> indicator at char 32 in
   'insert into martin values(:p1, :<*>p2)')
   [for Statement "insert into martin values(?, ?)"]
  lasth Statement (DBIx::Log4perl::db=HASH(0x974cf64)):
    insert into martin values(?, ?)
  DB: XE, Username: user
  handle type: db
  SQL: Possible SQL: /insert into mytable values(?, ?)/
  db Kids=0, ActiveKids=0
  DB errstr: ORA-12899: value too large for column "BET"."MYTABLE"."B"
   (actual: 64, maximum: 10) (DBD ERROR: error possibly near <*>
   indicator at char 32 in 'insert into mytable values(:p1, :<*>p2)')
  ParamValues captured in HandleSetErr:
    1,'string too long for column - will be truncated which is an error',
  0 sub statements:
  DBI error trap at /usr/lib/perl5/site_perl/5.8.8/DBIx/Log4perl/db.pm
   line 32
        DBIx::Log4perl::db::do('DBIx::Log4perl::db=HASH(0x97455d8)',
        'insert into mytable values(?, ?)', 'undef', 1, 'string too long
        for column - will be truncated which is an error')
        called at errors.pl
         line 12

What this shows is:

Adding additional error logging to your Perl script

If you want to add additional logging to the same Log4perl target as DBIx::Log4perl is using, you need to use the dbix_l4p_getattr method to retrieve the logger handle and then use that logger handle like this:

$logger = $dbh->dbix_l4p_getattr('DBIx_l4p_logger');
$logger->debug('stuff I want logged');

All the methods Log4perl has are available using the $logger handle retrieved above i.e. debug, warn, error etc.

As a convenience, there is also the dbix_l4p_logdie method, which works like die but logs the message to Log4perl and avoids you having to retrieve the logger handle first e.g.

$dbh->dbix_l4p_logdie("serious error");

Log4perl configuration file

Log4perl uses a configuration file to define what gets logged and where to (see the documentation at http://log4perl.sourceforge.net/). The example.conf that comes with DBIx::Log4perl looks like this:

# Example Log4perl config file
# All categories inherit FATAL from root
log4perl.logger = FATAL, LOGFILE

# LOGFILE appender used by root (here)
# log anything at level ERROR and above to /tmp/root.log
log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
log4perl.appender.LOGFILE.filename=/tmp/root.log
log4perl.appender.LOGFILE.mode=append
log4perl.appender.LOGFILE.Threshold = ERROR
log4perl.appender.LOGFILE.layout=PatternLayout
log4perl.appender.LOGFILE.layout.ConversionPattern=[%r] %F %L %c - %m%n

# Define DBIx::Log4perl to output DEBUG and above msgs to
# /tmp/dbix.log using the simple layout
log4perl.logger.DBIx.Log4perl=DEBUG, A1
log4perl.appender.A1=Log::Log4perl::Appender::File
log4perl.appender.A1.filename=/tmp/dbix.log
log4perl.appender.A1.mode=append
log4perl.appender.A1.layout=Log::Log4perl::Layout::SimpleLayout

which logs everything at level DEBUG and above to /tmp/root.log and everything at DEBUG and above to dbix.log.

You can do some seriously clever things with Log4perl (much of which is beyond the scope of this document) like:

Changing the default logging in DBIx::Log4perl

The default logging in DBIx::Log4perl is:

DBIX_L4P_LOG_DEFAULT, which is DBIX_L4P_LOG_TXN, DBIC_L4P_LOG_CONNECT, DBIX_L4P_LOG_INPUT and DBIX_L4P_LOG_ERRCAPTURE ORed together.

You can change what is logged using these mechanisms:

Specifically, the DBIX_L4P_LOG_OUTPUT and DBIX_L4P_LOG_WARNINGS masks are not enabled by default. Warning DBIX_L4P_LOG_OUTPUT can generate a lot of output as it logs all result-sets.

See DBIx::Log4perl global variables in the pod for more details.

Logging only SQL and parameters

There are two ways to log SQL and parameters and the method to use depends on the version of DBIx::Log4perl you have. Up to version 0.25, you can get your SQL and parameters logged (but with a few additional logs like calls to STORE) by using using DBIX_L4P_LOG_SQL and DBIX_L4P_LOG_DELAYBINDPARAM in your connect call. For example:

use Log::Log4perl;
use DBIx::Log4perl qw(:masks);

Log::Log4perl->init("/tmp/log4");

my $h = DBIx::Log4perl->connect(
    "dbi:ODBC:mydsn","user","password",
    {dbix_l4p_logmask => DBIX_L4P_LOG_INPUT|DBIX_L4P_LOG_DELAYBINDPARAM});

$h->do(q/drop table test/);
$h->do(q/create table test (a int)/);
my $s = $h->prepare(q/insert into test values(?)/);
$s->execute(1);
$s->execute(2);

my $r = $h->selectall_arrayref(q/select * from test where a = ?/, undef, 1);

This will produce:

DEBUG - $STORE(0) = ['dbi_connect_closure',sub { "DUMMY" }];
DEBUG - do(0): 'drop table test'
DEBUG - $STORE(0) = ['Statement','drop table test'];
DEBUG - affected(0): -1
DEBUG - do(0): 'create table test (a int)'
DEBUG - $STORE(0) = ['Statement','create table test (a int)'];
DEBUG - affected(0): -1
DEBUG - prepare(0.0): 'insert into test values(?)'
DEBUG - execute(0.0) (insert into test values(?)): 1
DEBUG - execute(0.0) (insert into test values(?)): 2
DEBUG - $selectall_arrayref(0) = ['select * from test where a = ?',undef,1];

This log output is pretty good, but does contain extra logging beyond just the SQL and parameters.

From version 0.26, the better option is to use DBIX_L4P_LOG_SQL and DBIX_L4P_LOG_DELAYBINDPARAM by using a connect like this:

my $h = DBIx::Log4perl->connect(
    "dbi:ODBC:test","user","password",
    {dbix_l4p_logmask => DBIX_L4P_LOG_SQL|DBIX_L4P_LOG_DELAYBINDPARAM});

Now, our example outputs:

DEBUG - do(0): 'drop table test'
DEBUG - do(0): 'create table test (a int)'
DEBUG - prepare(0.0): 'insert into test values(?)'
DEBUG - execute(0.0) (insert into test values(?)): 1
DEBUG - execute(0.0) (insert into test values(?)): 2
DEBUG - $selectall_arrayref(0) = ['select * from test where a = ?',undef,1];

This is much better as we are only getting the SQL and the parameters.

Appendix A: Resources

Article Feedback

* Did this content help you?
* Please select one option based on your first choice:

(* Required Fields)