DBIx::LogAny - Perl extension for DBI to selectively log DBI methods, SQL, parameters, result-sets, transactions etc with Log::Any.
# 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);
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
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.
DBIx::LogAny adds the following methods over DBI.
$h->dbxi_l4p_getattr('dbix_la_logmask');
Returns the value for a DBIx::LogAny attribute (see "ATTRIBUTES").
$h->dbix_la_setattr('dbix_la_logmask', 1);
Set the value of the specified DBIx::LogAny attribute (see "ATTRIBUTES").
$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);
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:
The following constants may be imported via the :masks group
:masks
use DBIx::LogAny qw(:masks);
By default LogMask is set to DBIX_LA_LOG_DEFAULT which is currently DBIX_LA_LOG_TXN | DBIC_L4P_LOG_CONNECT | DBIX_LA_LOG_INPUT | DBIX_LA_LOG_ERRCAPTURE | DBIX_LA_LOG_ERRORS | DBIX_LA_LOG_DBDSPECIFIC.
Log everything, all possible masks ORed together which also includes delaying the logging of bind_param (see "DBIX_LA_LOG_DELAYBINDPARAM").
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.
do
prepare
last_insert_id
NOTE: Many databases return 0 rows affected for DDL statements like create, drop etc.
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.
Log at LogAny debug level any call to the connect and disconnect methods and their arguments.
connect
disconnect
On connect the DBI version, DBIx::LogAny version, the driver name and version will be logged at LogAny info level.
Log at LogAny debug level all calls to begin_work, commit and rollback.
begin_work
commit
rollback
Log at LogAny error level any method which fails which is not caught by RaiseError. Currently this is only the execute_array method.
Log at LogAny warning level any calls to do which return no affected rows on an insert, update or delete opertion.
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.
This logging depends on the DBD you are using:
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.
dbms_output.put_line output
$dbh->execute
$dbh->func('dbms_output_get')
put_line
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.
$dbh->func(dbms_output_enable)
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.
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.
undef
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.
Log calls to DBI's STORE method.
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_la_getattr()
dbix_la_setattr()
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.
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".
execute
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.
DBIX_LA_LOG_ERRCAPTURE
$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.
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
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.
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.
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.
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.
This is the same issue as above for $h->{Username}.
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 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.
There are six main ways you may help with the development and maintenance of this module:
Please get the latest version from CPAN and submit any patches against that.
Install CPAN::Reporter and report you installations. This is easy to do - see "CPAN Testers Reporting".
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.
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.
Add your review of DBIx::LogAny on http://cpanratings.perl.org.
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.
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.
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.
DBI
Log::Any
Log::Any::Adapter
Log::Log4perl
DBIx::Log4perl
Log::Any::For::DBI
M. J. Evans, <mjevans@cpan.org>
Copyright (C) 2012-2017 by M. J. Evans
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.