New release (0.18) of DBIx::Log4perl

Yesterday I released DBIx::Log4perl 0.18 This principally add supports for DBI's clone method and fixes fetchrow_array ignoring calling context. It also adds a few speedups spotted using Devel::NYTProf, adds logging of connection attributes and fixes a few more minor issues. I've no idea how many people are using DBIx::Log4perl. I get the odd bug reported and the occasional email asking for an enhancement. None of this really matters (although it is nice to know someone is getting something worth while from it) as I only wrote it to help my team with our current project and it is still proving invaluable in debugging our DBI based applications. DBI tracing can be useful but it a) contains way too much under the hood detail for the average person b) is hard to configure to get what you want c) cannot easily be turned off and on (especially whilst your application is running) d) does not contain timestamps or caller details e) needs an error handler defining to get the full detail of errors f) is inflexible in detail recorded. What we really needed was a log of the SQL we executed and the parameters, what SQL resulted in a database change, much greater detail when some SQL failed and where the SQL was issued. You can find an example (although not very comprehensive, a little out of date and not demonstrating the caller information Log::Log4perl can provide) here. A newer example is provided below: 2010/01/26 17:15:42 DEBUG> DB.pm:572 XXX::DB::connect - connect(2): dbi:Oracle:host=xxx;sid=devel, user, $attr = {FetchHashKeyName => 'NAME_lc',ora_module_name => 'xxx',dbix_l4p_logmask => 93,AutoCommit => 1,RaiseError => 1,ChopBlanks => 1,ora_ncharset => 'AL32UTF8',PrintError => 1,ora_charset => 'AL32UTF8',LongReadLen => 32768,Warn => 1,ShowErrorStatement => 0,dbix_l4p_ignore_err_regexp => qr/(?-xism:20[5-9]\d\d)/}; 2010/01/26 17:15:42 INFO> DB.pm:572 XXX::DB::connect - DBI: 1.611, DBIx::Log4perl: 0.18, Driver: Oracle(1.23) 2010/01/26 17:15:42 DEBUG> DBI.pm:725 DBI::connect - $STORE(2) = ['dbi_connect_closure',sub { "DUMMY" }]; 2010/01/26 17:15:42 DEBUG> DB.pm:2035 XXX::DB::_post_connect - $get_info(2) = [17,'Oracle']; 2010/01/26 17:15:42 DEBUG> DB.pm:2037 XXX::DB::_post_connect - $get_info(2) = [6,'DBD/Oracle.pm']; 2010/01/26 17:15:42 DEBUG> DB.pm:1905 XXX::DB::_do_special - do(2): 'alter session set nls_timestamp_format = 'yyyy-mm-dd hh24:mi:ss' -- _do_special' 2010/01/26 17:15:42 DEBUG> DB.pm:1906 XXX::DB::_do_special - do(2): 'alter session set nls_date_format = 'yyyy-mm-dd' -- _do_special' 2010/01/26 17:15:42 DEBUG> Oracle.pm:907 DBD::Oracle::db::ora_nls_parameters - selectall_arrayref(2): ' SELECT parameter, value FROM v$nls_parameters 2010/01/26 17:15:42 DEBUG> DB.pm:2042 XXX::DB::_post_connect - $STORE(2) = ['RowCacheSize',0]; 2010/01/26 17:15:42 DEBUG> DB.pm:665 XXX::DB::sessionID - $STORE(2) = ['RaiseError',undef]; 2010/01/26 17:15:42 DEBUG> DB.pm:665 XXX::DB::sessionID - $STORE(2) = ['RaiseError',1]; 2010/01/26 17:15:42 DEBUG> DB.pm:666 XXX::DB::sessionID - $STORE(2) = ['PrintError',undef]; 2010/01/26 17:15:42 DEBUG> DB.pm:666 XXX::DB::sessionID - $STORE(2) = ['PrintError',0]; 2010/01/26 17:15:42 DEBUG> DB.pm:669 XXX::DB::sessionID - selectrow_arrayref(2): 'select sid from v$session where audsid = SYS_CONTEXT('userenv', 'sessionid')' 2010/01/26 17:15:42 DEBUG> xxx.pl:11393 XXX::DB::sessionID - $STORE(2) = ['PrintError',1]; 2010/01/26 17:15:42 DEBUG> xxx.pl:11393 XXX::DB::sessionID - $STORE(2) = ['RaiseError',1]; 2010/01/26 17:15:42 DEBUG> DB.pm:1246 XXX::DB::prepareProc - prepare(0.4): 'begin pkg_xxx.p_runOrQueueJob(:1,:2,:3,:4,:5,:6,:7); end; -- run_now}' 2010/01/26 17:15:42 DEBUG> DB.pm:1246 XXX::DB::prepareProc - prepare(1.4): 'begin pkg_xxxuser.p_newXXX(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10); end; -- post_xxx}' 2010/01/26 17:15:42 DEBUG> DB.pm:908 XXX::DB::preparePkgFunc - prepare(0.5): 'begin ? := pkg_xxx.f_checkScheduledJobs(); end; -- xxx.pl}' 2010/01/26 17:15:42 DEBUG> DB.pm:974 XXX::DB::execPkgFunc - $bind_param_inout(0.5) = [1,\undef,513]; 2010/01/26 17:15:42 DEBUG> DB.pm:991 XXX::DB::execPkgFunc - execute(0.5) 2010/01/26 17:15:42 DEBUG> DB.pm:991 XXX::DB::execPkgFunc - affected(0.5): 1 2010/01/26 17:15:42 DEBUG> DB.pm:1246 XXX::DB::prepareProc - prepare(0.6): 'begin p_next_sequence(:1); end;' 2010/01/26 17:15:42 DEBUG> DB.pm:1437 XXX::DB::execProc - $bind_param_inout(0.6) = [1,\undef,513]; 2010/01/26 17:15:42 DEBUG> DB.pm:1452 XXX::DB::execProc - execute(0.6) 2010/01/26 17:15:42 DEBUG> DB.pm:1452 XXX::DB::execProc - affected(0.6): 1 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [1,'3902084']; 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [2,undef]; 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [3,undef]; 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [4,'xxx']; 2010/01/26 17:15:42 DEBUG> DB.pm:1421 XXX::DB::execProc - $bind_param(0.4) = [5,'{"priority":"3","jobid":"3902084","name":"xxxx","args":{"xxx_id":"16211"},"jobqed":"25/1/2010 15:51:28","jobinterr":"ORA-20564: xxxxxxx requested in wrong state 4\\nORA-06512: at \\"XXX.XXX\\", line 25\\nORA-06512: at \\"XXX.XXX\\", line 93\\nORA-06512: at \\"XXX.XXX\\", line 5245\\nORA-06512: at line 1 (DBD ERROR: OCIStmtExecute)","joblasterr":"Failed to xxxxx xxxx, xxxxx can only be xxxxx when in the xxxxx, yyyyyy or zzzzz states","comment":"test","type":"what!","jobflags":"1"}',{ora_type => 112}]; 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [6,undef]; 2010/01/26 17:15:42 DEBUG> DB.pm:1441 XXX::DB::execProc - $bind_param(0.4) = [7,1]; 2010/01/26 17:15:42 DEBUG> DB.pm:1452 XXX::DB::execProc - execute(0.4) 2010/01/26 17:15:42 DEBUG> DB.pm:1452 XXX::DB::execProc - affected(0.4): 1