Download ODBC Drivers for Oracle, SQL Server, Salesforce, MongoDB, Access, Derby, InterBase & DB2.

Debugging Perl DBI

Introduction
Good DBI programming practice
What you get in DBI to help you
DBIx::Log4perl

Introduction

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

Good DBI programming practice

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. For example, DBDs return a true value for an INSERT operation that inserts zero rows. However, if you know the INSERT should insert a row, you test the returned value is true and not 0E0 (which is true but zero). Refer to the RaiseError and Test inserts and updates worked sections.

`RaiseError`

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

Without RaiseError, the following code prints out the error (because PrintError is on by default) but the program doesn't die:

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

The program prints an error saying your SQL is invalid but does not die. This makes it difficult to track down where the error occurred or worse, compounds 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 executed.

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

With RaiseError on, 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 automatically dies on the first do that fails.

Test inserts and updates worked

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

For example, suppose you have the table:

table : test
column : a integer

and the table contains one row where a is 1.

$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.

It's better to:

$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:

$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 value may be -1 if the DBD driver doesn't know how many rows were affected. In practice, we don't know of a DBD module which cannot tell you this.

Protect calls you expect could legitimately fail with `eval`

Once RaiseError is turned on, you no longer need to test every operation worked (unless you're inserting or updating). However, if you expect an operation may legitimately fail, wrap it in an eval. For example:

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

For example, 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're going to do a number of updates or inserts that are logically grouped together such that they should all work or none of them work, use transactions.

Say you have 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's difficult to debug since the warn and the die occurs on a different line to the one that actually failed, so the location of the problem is specified with the die text.

Consider adding comments to your SQL

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

Comments start with a double dash --. Use comments to embed debugging information in your SQL. For example:

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

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

What you get in DBI to help you

DBI 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. The higher the TraceLevel value. the greater the logging 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. For example, setting:

DBI_TRACE=1=dbitrace.log
export DBI_TRACE

before running your program, sets the trace level to 1 and writes trace information to dbitrace.log. If you don't specify a file, the trace information is written to standard output (stdout), which is what happens if you set the trace level on a handle with:

$handle->{TraceLevel} = $n;

Increase the trace level to output SQL executed, parameters bound, and internal trace information from the DBD driver you are using. The problem with tracing is that the output is rather verbose and won't mean a lot to anyone other than the author of DBI or the DBD driver you're using.

Download ODBC Drivers for Oracle, SQL Server, Salesforce, MongoDB, Access, Derby, InterBase & DB2.

DBIx::Log4perl

Advantages of using DBIx::Log4perl

DBIx::Log4perl is a subclass of DBI that logs DBI operations in terms of DBI methods called. The log output therefore relates to what the application is doing instead of what DBI or the DBD driver is doing.

The advantages of using DBIx::Log4perl are:

You can build tracing into your application such that trace output is only displayed or executed if tracing is turned on or a particular trace level is set.
You only get trace output for the DBI methods called and no internal DBI or DBD tracing.
It captures errors automatically, reporting all the possible information about where the error occurred, what SQL was being executed, the values of any bound parameters, and so on.
You can turn logging on or off or change the logging level without changing your code.
Different log levels allow you to separate warnings, errors, and fatals into different files and appenders.
The ability to send errors, warnings, fatals, and so on to different places. For example, warnings to a file, errors, and fatals to a specified email address.

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:

Install Log::Log4perl.
Install DBI and your DBD driver, we assume you've already done this and have Perl scripts using DBI already running.
Edit your Perl script and add:
```
use Log::Log4perl;
use DBIx::Log4perl;
```
Create your Log4perl configuration file. (There's an example that comes with DBIx::Log4perl called example.conf.) Add a line to your Perl script before connecting to your database similar to:
```
Log::Log4perl->init("/etc/mylog.conf");
```
where /etc/mylog.conf is created from example.conf.

Change your call to DBI's connect method to:

$dbh = DBIx::Log4perl->connect('DBI:odbc:mydsn', $user, $pass,
                                 {attribute => value});

where the DBI->connect becomes:

DBIx::Log4perl->connect

and the other arguments and attributes stay the same.

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

Download ODBC Drivers for Oracle, SQL Server, Salesforce, MongoDB, Access, Derby, InterBase & DB2.

Example DBIx::Log4perl output

Assuming you've used the example.conf Log4perl configuration file, logging information is written to /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;

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 an insert that affected 1 row (which means the insert worked) and finally the disconnect. The DBI version, DBIx::Log4perl version, and driver name and version are also 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 set in your Perl DBI code.

Assuming you've 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 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:

The error reported by the DBD driver and the method called (do in this case).
The last handle used and the SQL for the last statement executed.
The connection the error occurred in.
The handle type the error occurred on, db, or stmt (db in this case).
Other SQL that may error under this connection. For example, if you were executing multiple statements on a single connection.
The Kids and ActiveKids value for this db (refer to the DBI documentation) and the error message text in DBI::errstr.
Any SQL parameters passed to DBI. (Refer to the DBI documentation for the parameter values.)
A trace of where the problem occurred.
In this case, the final problem was in db.pm, but as this is DBIx::Log4perl's do method, the real issue was in the stack element below this, which was errors.pl line 12.

Adding additional error logging to your Perl script

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

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

All the Log4perl methods are available using the logger handle retrieved above (debug, warn, error, and so on).

As a convenience, there's also the dbix_l4p_logdie method, which works like die but logs the message to Log4perl and avoids having to retrieve the logger handle first. For example:

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

Log4perl configuration file

Log4perl uses a configuration file to define what gets logged and where to. 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

This logs everything at level ERROR 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:

There are many different appenders: email them, insert them into a database, and so on.
Filter messages so that different classes of messages go to different files or percolate up through the hierarchy.
The format of the log message is highly configurable.

Changing the default logging level in DBIx::Log4perl

The default logging level 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.

You can change what's logged using these mechanisms:

The global variable DBIx::Log4perl::LogMask.
$h->dbix_l4p_setattr('DBIx_l4p_logmask', $value) where $h is the handle on which you want to change the log mask and $value is the masks ORed together.

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

Refer to the DBIx::Log4perl global variables section 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 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 produces:

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're only getting the SQL and the parameters.

Download ODBC Drivers for Oracle, SQL Server, Salesforce, MongoDB, Access, Derby, InterBase & DB2.

Debugging Perl DBI

Contents

Introduction

Good DBI programming practice

Check the returns from DBI calls

`RaiseError`

Test inserts and updates worked

Protect calls you expect could legitimately fail with `eval`

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

Consider adding comments to your SQL

What you get in DBI to help you

DBIx::Log4perl

Advantages of using DBIx::Log4perl

Where to get DBIx::Log4perl

DBIx::Log4perl dependencies

DBIx::Log4perl documentation

DBIx::Log4perl quick start

Example DBIx::Log4perl output

Catching errors with DBIx::Log4perl

Adding additional error logging to your Perl script

Log4perl configuration file

Changing the default logging level in DBIx::Log4perl

Logging only SQL and parameters

About Easysoft

Products

Services

Licensing

Support

Search

Popular Resources

Legal

Debugging Perl DBI

Contents

Introduction

Good DBI programming practice

Check the returns from DBI calls

RaiseError

Test inserts and updates worked

Protect calls you expect could legitimately fail with eval

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

Consider adding comments to your SQL

What you get in DBI to help you

DBIx::Log4perl

Advantages of using DBIx::Log4perl

Where to get DBIx::Log4perl

DBIx::Log4perl dependencies

DBIx::Log4perl documentation

DBIx::Log4perl quick start

Example DBIx::Log4perl output

Catching errors with DBIx::Log4perl

Adding additional error logging to your Perl script

Log4perl configuration file

Changing the default logging level in DBIx::Log4perl

Logging only SQL and parameters

About Easysoft

Products

Services

Licensing

Support

Search

Popular Resources

Legal

`RaiseError`

Protect calls you expect could legitimately fail with `eval`

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