log4perl-devel

Re: [log4perl-devel] subclassed DBI (DBI_Buffer) does not release dbh filehandles on reinit

[Robert J. <yad...@sn...>]

Robert Jacobson wrote:

> If I add equivalent code to my existing conditional for the definition
> of errorappender, i.e.:
> 
>     if ($self->{errorappender}) {
>         # Pass back the appender to be synchronized as a dependency
>         # to the configuration file parser
>         push @{$p{l4p_depends_on}}, $self->{errorappender};
>         push @{$p{l4p_post_config_subs}}, sub { $self->post_init() };
>     }
> 
> Then I get this error from Log::Log4perl::Appender::DBI:
> 
> Log4perl: DBI appender failed to reconnect to database after 1 attempt
> at init_and_watch.pl line 10

I added some debug to DBI.pm and found that when I add the "depends_on"
code, the sub in DBI query_execute gets called with extra arguments.  I
turned on the warn to print out the DBI::errstr and found that it isn't
really a connection error, it's a failure to execute the DBI statement:

Exe: failed: called with 7 bind variables when 6 are needed at
.../Log/Log4perl/Appender/DBI.pm line 159.

(line number different because of my local edits to DBI.pm)

Adding a "Dumper" for qmarks:

$VAR1 = '2009-055/17:35:41';
$VAR2 = 'INFO';
$VAR3 = 'component.pl';
$VAR4 = 'ansdev2';
$VAR5 = '25227';
$VAR6 = 'ARRAY(0x813274c)';
$VAR7 = 'Starting ....';

Those are mostly the expected values from the Layout I specified (time,
log level, script name, hostname, PID, ?????, message).

Where the heck did that "ARRAY" string come from?  I checked using
ref(); it really is a string of characters and not an actual array ref.

-- 
Rob

Re: [log4perl-devel] subclassed DBI (DBI_Buffer) does not release dbh filehandles on reinit

[Mike S. <m...@pe...>]

On Tue, 24 Feb 2009, Robert Jacobson wrote:

> Those are mostly the expected values from the Layout I specified
> (time, log level, script name, hostname, PID, ?????, message).

That's peculiar ... what does your layout look like?

It's hard to diagnose the problem without code that reproduces it, can
you post a stripped-down version of your appender?

-- Mike

Mike Schilli
m...@pe...

> Robert Jacobson wrote:
>
>> If I add equivalent code to my existing conditional for the definition
>> of errorappender, i.e.:
>>
>>     if ($self->{errorappender}) {
>>         # Pass back the appender to be synchronized as a dependency
>>         # to the configuration file parser
>>         push @{$p{l4p_depends_on}}, $self->{errorappender};
>>         push @{$p{l4p_post_config_subs}}, sub { $self->post_init() };
>>     }
>>
>> Then I get this error from Log::Log4perl::Appender::DBI:
>>
>> Log4perl: DBI appender failed to reconnect to database after 1 attempt
>> at init_and_watch.pl line 10
>
> I added some debug to DBI.pm and found that when I add the "depends_on"
> code, the sub in DBI query_execute gets called with extra arguments.  I
> turned on the warn to print out the DBI::errstr and found that it isn't
> really a connection error, it's a failure to execute the DBI statement:
>
> Exe: failed: called with 7 bind variables when 6 are needed at
> .../Log/Log4perl/Appender/DBI.pm line 159.
>
> (line number different because of my local edits to DBI.pm)
>
> Adding a "Dumper" for qmarks:
>
> $VAR1 = '2009-055/17:35:41';
> $VAR2 = 'INFO';
> $VAR3 = 'component.pl';
> $VAR4 = 'ansdev2';
> $VAR5 = '25227';
> $VAR6 = 'ARRAY(0x813274c)';
> $VAR7 = 'Starting ....';
>

Re: [log4perl-devel] subclassed DBI (DBI_Buffer) does not release dbh filehandles on reinit

[Robert J. <yad...@sn...>]

Mike Schilli m-at-perlmeister.com |log4perl_sourceforge| wrote:
> On Tue, 24 Feb 2009, Robert Jacobson wrote:
> 
>> Those are mostly the expected values from the Layout I specified
>> (time, log level, script name, hostname, PID, ?????, message).
> 
> That's peculiar ... what does your layout look like?
> 
> It's hard to diagnose the problem without code that reproduces it, can
> you post a stripped-down version of your appender?


I attached the appender code (full version), a configuration file, and a
test program in the first post I made.   I could understand how you'd
want a stripped-down version of the appender :)

I wasn't sure what would happen if I stripped it down -- but it turns
out that even with only two subs defined (new and post_init), the
appender exhibits the problem of persistent DB connections.

The stripped-down version of DBI_Buffer is attached, along with the test
program and config.  (again, modify the database config to match your
database).

For the error "called 7 bind variables when 6 are needed...", I added a
little debug to DBI.pm (while still using my subclassed appender).  With
the "l4_depends_on" code in the stripped-down DBI_Buffer.pm i.e.:

    if ($self->{errorappender}) {
        # Pass back the appender to be synchronized as a dependency
        # to the configuration file parser
        push @{$p{l4p_depends_on}}, $self->{errorappender};
        push @{$p{l4p_post_config_subs}}, sub { $self->post_init() };
    }


Then $p in DBI::calculate_bind_values shows the message as an array, e.g.:

calculate_bind_values Dump p:
$VAR1 = {
          'log4p_level' => 'INFO',
          'log4p_category' => 'ANS.component',
          'level' => 1,
          'name' => 'Database',
          'message' => [
                         'Starting ....'
                       ]
        };

I thought the message array ref would get compressed to a scalar string
value, but that doesn't seem to be the case.

I tried messing with the warp_message values of the Logfile and Database
appenders, but I still end up with 7 bind values no matter what
warp_message setting I use.

-- 
Rob