log4perl-devel

[log4perl-devel] suggested patch for Log::Log4perl::Appender::DBI

[Mark B. <ma...@ex...>]

Hi,

In the Appender::DBI man page, we see the following sentence,
"If there are more '?' placeholders than there are values in
your message, it will use undef for the rest." However, I was
unable to observe this behaviour with my configuration.

I used the following tiny patch to Appender::DBI.pm to get
the described behaviour and it may be of general interest.
It does rely on the DBI statement handle attribute NUM_OF_PARAMS
which is driver dependent, however I can't currently see any other
way of achieving this.

--- ./original/Log/Log4perl/Appender/DBI.pm   2007-03-15  
07:53:47.000000000 +0000
+++ ./patched/Log/Log4perl/Appender/DBI.pm       2007-12-13  
15:00:48.000000000 +0000
@@ -134,6 +134,13 @@

      for my $attempt (0..$self->{reconnect_attempts}) {
          #warn "Exe: @qmarks"; # TODO
+
+        # if we're short of bind variables, fill in the remainder  
with undef
+        if( $sth->{NUM_OF_PARAMS}-1 > $#qmarks ){
+                # use the old "assign past the end of array to  
extend it" thing.
+                undef $qmarks[$sth->{NUM_OF_PARAMS}-1];
+        }
+
          if(! $sth->execute(@qmarks)) {
                  # Exe failed
                  # warn "Log4perl: DBI->execute failed $DBI::errstr,  
\n".


- Mark

Re: [log4perl-devel] suggested patch for Log::Log4perl::Appender::DBI

[Kevin M. G. <cp...@go...>]

Mark Blackman wrote:
> In the Appender::DBI man page, we see the following sentence,
> "If there are more '?' placeholders than there are values in
> your message, it will use undef for the rest." However, I was
> unable to observe this behaviour with my configuration.

Odd, it looks like it's working to me. What was the behavior you *did*
obverve?  Can you send a test case to demonstrate the problem?

Here's the part of the existing code that handles the case, it looks ok
to me:

               #here handle cases where we ran out of message bits
               #before we ran out of bind_value_layouts, just keep going
            }elsif (ref $p->{message} eq 'ARRAY'){
                $msg = undef;
                $p->{message} = undef;

I just added test cases to the unit test to demonstrate the behavior and
it looks ok.  Could you download this guy and see if it runs for you?
(You'll need to 'mkdir -p t/tmp/')

http://log4perl.cvs.sourceforge.net/*checkout*/log4perl/Log-Log4perl/t/034DBI.t?revision=1.15&content-type=text%2Fplain

Re: [log4perl-devel] suggested patch for Log::Log4perl::Appender::DBI

[Mark B. <ma...@ex...>]

On 13 Dec 2007, at 17:52, Kevin M. Goess wrote:

> Mark Blackman wrote:
>> In the Appender::DBI man page, we see the following sentence,
>> "If there are more '?' placeholders than there are values in
>> your message, it will use undef for the rest." However, I was
>> unable to observe this behaviour with my configuration.
>
> Odd, it looks like it's working to me. What was the behavior you *did*
> obverve?  Can you send a test case to demonstrate the problem?

Well, I think the existing implementation isn't sufficiently general
to handle my requirement. I didn't examine the existing code
in excruciating detail, but  I believe the code path you mention is
only executed if you have at least one bind param defined in your
config. i.e

if ($self->{bind_value_layouts}) {

Secondly, as far as I could tell the implementation below
also seems to assume that the largest numbered bind param
will correspond to the last placeholder.

i.e. I couldn't spot in the code where the number of
placeholders expected in the prepared statemente was counted
or evaluated, only the largest numbered bind param.

On reflection, I could probably have achieved my requirement
to call the logger with between 1 and 4 arguments, but using
an artificially inserted bind param in the config file for
a fifth placeholder and the code path below would have taken
care of the undefs for me.

I've attached the details of my config, call and DBI_TRACE
output below if you're that keen to look at it.



>
> Here's the part of the existing code that handles the case, it  
> looks ok
> to me:
>
>                #here handle cases where we ran out of message bits
>                #before we ran out of bind_value_layouts, just keep  
> going
>             }elsif (ref $p->{message} eq 'ARRAY'){
>                 $msg = undef;
>                 $p->{message} = undef;
>
> I just added test cases to the unit test to demonstrate the  
> behavior and
> it looks ok.  Could you download this guy and see if it runs for you?
> (You'll need to 'mkdir -p t/tmp/')
>
> http://log4perl.cvs.sourceforge.net/*checkout*/log4perl/Log- 
> Log4perl/t/034DBI.t?revision=1.15&content-type=text%2Fplain
>

Your test runs fine for me, although I suspect it's because
the DBD::CSV driver doesn't mind getting too few arguments
for a prepared statement ->execute and the DBD::Pg driver does object
to too few arguments. That's pure speculation at this point
though. I made a brief attempt to convert the test to use DBD::Pg
but hit too many issues to carry on.

Perhaps I've missed some important point, and if so please educate me.

- Mark


log4perl config:
=========================================

log4perl.category.events = DEBUG, fx-dbi
log4perl.addivity.events = 0
log4perl.appender.fx-dbi=Log::Log4perl::Appender::DBI
log4perl.appender.fx-dbi.datasource  = dbi:Pg:dbname=fx;host=127.0.0.1
log4perl.appender.fx-dbi.username    = postgres81
log4perl.appender.fx-dbi.sql = \
        INSERT INTO event_log \
           (event, user_id,payment_id,order_id) \
           VALUES (?,?,?,?)
log4perl.appender.fx-dbi.layout    = Log::Log4perl::Layout::NoopLayout
log4perl.appender.fx-dbi.warp_message = 0
log4perl.appender.fx-dbi.usePreparedStmt = 1

my log4perl caller (snippet):
=============================================
use Log::Log4perl qw(get_logger);
my $events=get_logger('events');
$events->info('hello chuck');

DBI_TRACE=1 output:
=============================================
    <- prepare('INSERT INTO event_log (event,  
user_id,payment_id,order_id) VALUES (?,?,?,?)')= DBI::st=HASH 
(0x1a93bac) at DBI.pm line 88
     !! ERROR: -1 'called with 1 bind variables when 4 are  
needed' (err#0)
     <- execute('hello chuck')= undef at DBI.pm line 137
        ERROR: -1 'called with 1 bind variables when 4 are  
needed' (err#0)
     <- ping= 1 at DBI.pm line 147
     <- prepare('INSERT INTO event_log (event,  
user_id,payment_id,order_id) VALUES (?,?,?,?)')= DBI::st=HASH 
(0x1a93da4) at DBI.pm line 88
     <- DESTROY(DBI::st=HASH(1a93b94))= undef at DBI.pm line 168
     !! ERROR: -1 'called with 1 bind variables when 4 are  
needed' (err#0)
     <- execute('hello chuck')= undef at DBI.pm line 137
Log4perl: DBI appender failed to reconnect to database after 1  
attempt at /Volumes/cs/MBlackman/ffx/fx-live/FX/script/../lib/FX.pm  
line 85
Compilation failed in require at FX/script/fx_server.pl line 52.