NAME

DBIx::LogAny - Perl extension for DBI to selectively log DBI methods, SQL, parameters, result-sets, transactions etc with Log::Any.

SYNOPSIS

# Simple log to a file - you'll need IO::File for this
use DBIx::LogAny;
use Log::Any::Adapter ('File', '/path/to/file.log');
my $dbh = DBIx::LogAny->connect('dbi:ODBC:mydsn', $user, $pass);
$dbh->DBI_METHOD(args);

# Make DBIx::LogAny like DBIx::Log4perl i.e. use Log::LogAny
# by default sets the category to DBIx::LogAny. You can override the
# category with the dbix_la_category attribute.
use Log::Any::Adapter ('Log4perl');
use Log::Log4perl;
use DBIx::LogAny;
Log::Log4perl->init("/etc/mylog.conf");
my $dbh = DBIx::LogAny->connect('dbi:ODBC:mydsn', $user, $pass);
$dbh->DBI_METHOD(args);

# use your own log handle passed to DBIx::LogAny
use Log::Any::Adapter('File', '/path/to/file.log');
use Log::Any;
use DBIx::LogAny;
my $log2 = Log::Any->get_logger();
my $dbh = DBIx::LogAny->connect('dbi:ODBC:mydsn', $user, $pass,
                                {dbix_la_logger => $log2});
$dbh->DBI_METHOD(args);

DESCRIPTION

DBIx::LogAny is a wrapper over DBI which adds logging of your DBI activity via Log::Any. It is based on the much older DBIx::Log4perl.

DBIx::LogAny is almost identical to DBIx::Log4perl except:

o it checks if Log::LogAny is loaded before setting wrapper_register.

o Log::Any does not support closures passed to log methods so they are removed and an "if $log->is_xxx" added.

I'll try and keep DBIx::Log4perl and DBIx::LogAny in synch for a while but I may eventually drop DBIx::Log4perl.

METHODS

DBIx::LogAny adds the following methods over DBI.

dbix_la_getattr

$h->dbxi_l4p_getattr('dbix_la_logmask');

Returns the value for a DBIx::LogAny attribute (see "ATTRIBUTES").

dbix_la_setattr

$h->dbix_la_setattr('dbix_la_logmask', 1);

Set the value of the specified DBIx::LogAny attribute (see "ATTRIBUTES").

dbix_la_logdie

$h->dbix_la_logdie($message);

Calls the internal _error_handler method with the message $message then dies with Carp::confess.

The internal error handler is inserted into DBI's HandleError if "DBIX_LA_LOG_ERRCAPTURE" is enabled. It attempts to log as much information about the SQL you were executing, parameters etc.

As an example, you might be checking a $dbh->do which attempts to update a row really does update a row and want to die with all possible information about the problem if the update fails. Failing to update a row would not ordinarily cause DBI's error handler to be called.

$affected = $dbh->do(q/update table set column = 1 where column = 2/);
$dbh->dbix_logdie("Update failed") if ($affected != 1);

GLOBAL VARIABLES

DBIx::LogAny::LogMask

This variable controls the amount of logging logged to Log::Any. There are a number of constants defined which may be ORed together to obtain the logging level you require:

CONSTANTS

The following constants may be imported via the :masks group

use DBIx::LogAny qw(:masks);

DBIX_LA_LOG_DEFAULT

DBIX_LA_LOG_ALL

Log everything, all possible masks ORed together which also includes delaying the logging of bind_param (see "DBIX_LA_LOG_DELAYBINDPARAM").

DBIX_LA_LOG_INPUT

Log at LogAny debug level input SQL to do, prepare, select* methods and any value returned from last_insert_id. In addition, if the SQL is an insert/update/delete statement the rows affected will be logged.

NOTE: Many databases return 0 rows affected for DDL statements like create, drop etc.

DBIX_LA_LOG_OUTPUT

Log at LogAny debug level the result-sets generated by select* or fetch* methods. Be careful, this could produce a lot of output if you produce large result-sets.

DBIX_LA_LOG_CONNECT

Log at LogAny debug level any call to the connect and disconnect methods and their arguments.

On connect the DBI version, DBIx::LogAny version, the driver name and version will be logged at LogAny info level.

DBIX_LA_LOG_TXN

Log at LogAny debug level all calls to begin_work, commit and rollback.

DBIX_LA_LOG_ERRORS

Log at LogAny error level any method which fails which is not caught by RaiseError. Currently this is only the execute_array method.

DBIX_LA_LOG_WARNINGS

Log at LogAny warning level any calls to do which return no affected rows on an insert, update or delete opertion.

DBIX_LA_LOG_ERRCAPTURE

Install a DBI error handler which logs at LogAny fatal level as much information as it can about any trapped error. This includes some or all of the following depending on what is available:

Handle type being used
Number of statements under the current connection
Name of database
Username for connection to database
Any SQL being executed at the time
The error message text
Any parameters in ParamValues
Any parameters in ParamArrays
A stack trace of the error

If you install your own error handler in the connect call it will be replaced when connect is called in DBI but run from DBIx::LogAny's error handler.

DBIx::LogAny always returns 0 from the error handler if it is the only handler which causes the error to be passed on. If you have defined your own error handler then whatever your handler returns is passed on.

DBIX_LA_LOG_DBDSPECIFIC

This logging depends on the DBD you are using:

DBD::Oracle

Use DBD::Oracle's methods for obtaining the buffer containing dbms_output.put_line output. Whenever $dbh->execute is called DBIx::LogAny will use $dbh->func('dbms_output_get') to obtain an array of lines written to the buffer with put_line. These will be written to the log (prefixed with "dbms") at level DEBUG for the execute method.

NOTE: If "DBIX_LA_LOG_DBDSPECIFIC" is enabled, DBIx::LogAny calls $dbh->func(dbms_output_enable) after the connect method has succeeded. This will use DBD::Oracle's default buffer size. If you want to change the buffer size see DBD::Oracle and change it after the connect method has returned.

As useful as this may seem you are warned against using it as when the dbms_output buffer is full it will generate an Oracle exception which is probably not what you want. This can happen if the procedure you call calls dbms_output.put_line too often and fills the buffer before returning to DBI.

DBIX_LA_LOG_DELAYBINDPARAM

If set (and it is not the default) this prevents the logging of bind_param method calls and instead the bound parameters and parameter types (if available) are logged with the execute method instead. Example output for:

my $st = $ph->prepare(q/insert into mje2 values(?,?)/);
$st->bind_param(1, 1);
$st->bind_param(2, "fred");
$st->execute;

will output something like:

DEBUG - prepare(0.1): 'insert into mje values(?,?)'
DEBUG - $execute(0.1) = [{':p1' => 1,':p2' => 'fred'},undef];
DEBUG - affected(0.1): 1

instead of the more usual:

DEBUG - prepare(0.1): 'insert into mje values(?,?)'
DEBUG - $bind_param(0.1) = [1,1];
DEBUG - $bind_param(0.1) = [2,'fred'];
DEBUG - execute(0.1)
DEBUG - affected(0.1): 1

where the parameter names and values are displayed in the {} after execute and the parameter types are the next argument. Few DBDs support the ParamTypes attribute in DBI and hence mostly these are displayed as undef as in the above case which was using DBD::Oracle. Most (if not all) DBDs support ParamValues but you might want to check that before setting this flag.

DBIX_LA_LOG_SQL

If set this logs the SQL passed to the do, prepare and select* methods. This just separates SQL logging from what "DBIX_LA_LOG_INPUT" does and is generally most useful when combined with DBIX_LA_LOG_DELAYBINDPARAM.

DBIX_LA_LOG_STORE

Log calls to DBI's STORE method.

ATTRIBUTES

When you call connect you may add DBIx::LogAny attributes to those which you are passing to DBI. You may also get and set attributes after connect using dbix_la_getattr() and dbix_la_setattr(). DBIx::LogAny supports the following attributes:

dbix_l4a_category

This is the string to pass on to Log::Any as the category. e.g.

$logger = Log::Any->get_logger(category => 'xxx::yyy');

By default, if you do not specify this attribute DBIx::LogAny is set as the category.

dbix_l4a_logger

If you have already initialised and created your own Log::Any handle you can pass it in as dbix_l4a_logger and DBIx::LogAny will use it instead of getting its own logger.

dbix_la_logmask

A mask of the flags defined under "CONSTANTS".

dbix_la_ignore_err_regexp

A regular expression which will be matched against $DBI::err in the error handler and execute and if it matches no diagnostics will be output; the handler will just return (maybe causing the next handler in the chain to be called if there is one).

An example of where this can be useful is if you are raising application errors in your procedures (e.g., RAISE_APPLICATION_ERROR in Oracle) where the error indicates something that is expected. Say you validate a web session by looking for the session ID via a procedure and raise an error when the session is not found. You probably don't want all the information DBIx::LogAny normally outputs to the error log about this error in which case you set the regular expression to match your error number and it will no longer appear in the log.

FORMAT OF LOG

Example output

For a connect the log will contain something like:

DEBUG - connect(0): DBI:mysql:mjetest, bet
INFO - DBI: 1.50, DBIx::LogAny: 0.02, Driver: mysql(3.0002_4)

For

$sth = $dbh->prepare('insert into mytest values (?,?)');
$sth->execute(1, 'one');

you will get:

DEBUG - prepare(0.1): 'insert into mytest values (?,?)'
DEBUG - $execute(0.1) (insert into mytest values (?,?)) = [1,'one'];

In this latter case the SQL is repeated for convenience but this only occurs if execute is called with parameters. If execute is called without any arguments the SQL is not repeated in the execute. Also note the output will include bind_param calls if you bound parameters seperately but how this is logged depends on "DBIX_LA_LOG_DELAYBINDPARAM".

The numbers in the () after a method name indicate which connection or statement handle the operation was performed on. The first connection your application makes will be connection 0 (see "connect(0)" above). Each statement method will show the connection number followed by a '.' and the statement number (e.g., "prepare(0.1)" above is the second statement handle on the first connection).

NOTE: Some DBI methods are combinations of various methods e.g. selectrow_* methods. For some of these methods DBI does not actually call all the lower methods because the driver implements selectrow_* methods in C. For these cases, DBIx::LogAny will only be able to log the selectrow_* method, the SQL, any parameters and any returned result-set and you will not necessarily see a prepare, execute and fetch in the log. e.g.,

$dbh->selectrow_array('select b from mytest where a = ?',undef,1);

results in:

DEBUG - $selectrow_array = ['select b from mytest where a = ?',undef,1];

with no evidence prepare/execute/fetch was called.

If DBIX_LA_LOG_ERRCAPTURE is set all possible information about an error is written to the log by the error handler. In addition a few method calls will attempt to write a separate log entry containing information which may not be available in the error handler e.g.

$sth = $dbh->prepare(q/insert into mytest values (?,?)/);
$sth->bind_param_array(1, [51,1,52,53]);
$sth->bind_param_array(2, ['fiftyone', 'one', 'fiftythree', 'fiftytwo']);
$inserted = $sth->execute_array( { ArrayTupleStatus => \@tuple_status } );

when the mytest table has a primary key on the first column and a row with 1 already exists will result in:

ERROR - $Error = [1062,'Duplicate entry \'1\' for key 1','S1000'];
ERROR -          for 1,fiftytwo

because the @tuple_status is not available in the error handler. In this output 1062 is the native database error number, the second argument is the error text, the third argument the state and the additional lines attempt to highlight the parameters which caused the problem.

Example captured error

By default, DBIx::LogAny replaces any DBI error handler you have with its own error handler which 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::LogAny's error handler is executed it continues to call any error handler you have specifically set in you 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::LogAny->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 then DBIx::LogAny 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::LogAny::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/LogAny/db.pm line 32
      DBIx::LogAny::db::do('DBIx::LogAny::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:

o the error reported by the DBD and the method called (do in this case).

o the last handle used and the SQL for the last statement executed

o the connection the error occurred in

o the handle type the error occurred on, db or stmt (db in this case)

o Other possible SQL that may be in error under this db connection e.g. if you were executing multiple statements on a single db connection

o the Kids and ActiveKids value for this db - (see DBI docs)

o the error message text in DBI::errstr

o any sql parameters passed to DBI (see DBI for ParamValues)

o a trace of where the problem occurred In this case the final problem was in db.pm but as this is DBIx::LogAny's do method, the real issue was in the stack element below this which was errors.pl line 12.

Use of Data::Dumper

DBIx::LogAny makes extensive use of Data::Dumper to output arguments passed to DBI methods. In some cases it combines the method called with the data it is logging e.g.

DEBUG - $execute = [2,'two'];

This means the execute method was called with placeholder arguments of 2 and 'two'. The '$' prefixing execute is because Data::Dumper was called like this:

Data::Dumper->dump( [ \@execute_args ], [ 'execute'] )

so Data::Dumper believes it is dumping $execute. DBIx::LogAny uses this method extensively to log the method and arguments - just ignore the leading '$' in the log.

NOTES

During the development of this module I came across of large number of issues in DBI and various DBDs. I've tried to list them here but in some cases I cannot give the version the problem was fixed in because it was not released at the time of writing.

DBI and $h->{Username}

If you get an error like:

Can't get DBI::dr=HASH(0x83cbbc4)->{Username}: unrecognised attribute name

in the error handler it is because it was missing from DBI's XS code.

This is fixed in DBI 1.51.

DBI and $h->{ParamArrays}

This is the same issue as above for $h->{Username}.

DBD::ODBC and ParamValues

In DBD::ODBC 1.13 you cannot obtain ParamValues after an execute has failed. I believe this is because DBD::ODBC insists on describing a result-set before returning ParamValues and that is not necessary for ParamValues.

Fixed in 1.14.

DBD::mysql and ParamArrays

DBD::mysql 3.002_4 does not support ParamArrays.

I had to add the following to dbdimp.c to make it work:

case 'P':
  if (strEQ(key, "PRECISION"))
    retsv= ST_FETCH_AV(AV_ATTRIB_PRECISION);
  /* + insert the following block */
  if (strEQ(key, "ParamValues")) {
      HV *pvhv = newHV();
      if (DBIc_NUM_PARAMS(imp_sth)) {
          unsigned int n;
          SV *sv;
          char key[100];
          I32 keylen;
          for (n = 0; n < DBIc_NUM_PARAMS(imp_sth); n++) {
              keylen = sprintf(key, "%d", n);
              hv_store(pvhv, key, keylen, newSVsv(imp_sth->params[n].value), 0);
          }
      }
      retsv = newRV_noinc((SV*)pvhv);
  }
  /* - end of inserted block */
  break;

I believe this code is now added in DBD::mysql 3.0003_1.

Contributing

There are six main ways you may help with the development and maintenance of this module:

Submitting patches

Please get the latest version from CPAN and submit any patches against that.

Reporting installs

Install CPAN::Reporter and report you installations. This is easy to do - see "CPAN Testers Reporting".

Report bugs

If you find what you believe is a bug then enter it into the http://rt.cpan.org/Dist/Display.html?Name=DBIx::LogAny system. Where possible include code which reproduces the problem including any schema required and the versions of software you are using.

If you are unsure whether you have found a bug report it anyway.

pod comments and corrections

If you find inaccuracies in the DBIx::LogAny pod or have a comment which you think should be added then go to http://annocpan.org and submit them there. I get an email for every comment added and will review each one and apply any changes to the documentation.

Review DBIx::LogAny

Add your review of DBIx::LogAny on http://cpanratings.perl.org.

submit test cases

The test suite for DBIx::LogAny is pitifully small. Any test cases would be gratefully received. In particular, it would be really nice to add support for Test::Database.

CPAN Testers Reporting

Please, please, please (is that enough), consider installing CPAN::Reporter so that when you install perl modules a report of the installation success or failure can be sent to cpan testers. In this way module authors 1) get feedback on the fact that a module is being installed 2) get to know if there are any installation problems. Also other people like you may look at the test reports to see how successful they are before choosing the version of a module to install.

CPAN::Reporter is easy to install and configure like this:

perl -MCPAN -e shell
cpan> install CPAN::Reporter
cpan> reload cpan
cpan> o conf init test_report

Simply answer the questions to configure CPAN::Reporter.

You can find the CPAN testers wiki at http://wiki.cpantesters.org/ and the installation guide for CPAN::Reporter at http://wiki.cpantesters.org/wiki/CPANInstall.

TO_DO

better testing

REQUIREMENTS

You will need at least Log::Any 0.14 and DBI 1.50.

DBI-1.51 contains the changes listed under "NOTES".

Versions of Log::Log4perl before 1.04 work but unfortunately you will get code references in some of the log output where DBIx::LogAny does:

$log->logwarn(sub {Data::Dumper->Dump(something)})

The same applies to logdie. See the Log4perl mailing list for details.

AUTHOR

M. J. Evans, <mjevans@cpan.org>

COPYRIGHT AND LICENSE

This library is free software; you can redistribute it and/or modify it under the same terms as Perl itself, either Perl version 5.8.7 or, at your option, any later version of Perl 5 you may have available.

To install DBIx::LogAny, copy and paste the appropriate command in to your terminal.

cpanm

cpanm DBIx::LogAny

CPAN shell

perl -MCPAN -e shell
install DBIx::LogAny

For more information on module installation, please visit the detailed CPAN module installation guide.

	Global
`s`	Focus search bar
`?`	Bring up this help dialog

	GitHub
`g` `p`	Go to pull requests
`g` `i`	go to github issues (only if github is preferred repository)

	POD
`g` `a`	Go to author
`g` `c`	Go to changes
`g` `i`	Go to issues
`g` `d`	Go to dist
`g` `r`	Go to repository/SCM
`g` `s`	Go to source
`g` `b`	Go to file browse

	Search terms
module: (e.g. module:Plugin)
distribution: (e.g. distribution:Dancer auth)
author: (e.g. author:SONGMU Redis)
version: (e.g. version:1.00)