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

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

This is related to the thread "Intermittent problems when using signal
to reread log configuration", but it focuses more on where I think the
problem is (i.e. my code).  I'm hoping someone will be able to tell me
where I'm going wrong!

I'm having some trouble with a subclass of the DBI appender I have
written.  I call it "DBI_Buffer" (attached).  It is basically a wrapper
around the DBI appender to handle buffering when the database is down.

It  does a ping for every log message (inefficient, I know!).  If the
ping fails, it attempts to reconnect (up to X configured number of
times).  If it fails to reconnect, it stores log messages in an array.
It then periodically checks to see if the database has come back up.
When the connection is restored, it flushes the buffered messages to the
database.

(BTW, if someone knows a better way to prevent blocking when attempting
to log while the database is down, I'd love to hear it!)

I'm also using init_and_watch to reread my Log4perl config when the
process receives SIGHUP.

If I use the included DBI appender, when I send a SIGHUP to any perl
process using that appender, it closes the existing connections and
makes new ones.

But when I am using my DBI_Buffer appender, it doesn't close the
existing database connections.  It does however make new ones, and
logging continues to work.  However, since the connections to the DB
stick around basically forever -- eventually I run out of connections!
Unfortunately the error I get is not usually "Too many connections"; it
is instead:
	Can't call method "log" on an undefined value at
/opt/ActivePerl-5.8/lib/site_perl/5.8.7/Log/Log4perl/Appender.pm line 189.

I'm puzzled why I get this misleading error, but, well at least I know
it is because I have run out of mysql connections.

It seems to perhaps be related to the post_init() check I do (which I
borrowed from Log::Log4perl::Appender::Synchronized).  If the user wants
to log database errors to a local logfile, they define an
"errorappender" in the DBI_Buffer config.

What's telling is that if I remove the "errorappender" definition from
the config (thus removing the need to call post_init), I don't have a
problem with stupidly persistent DB connections.

I think this is a clue:  Synchronized has this line of code:
	push @{$options{l4p_depends_on}}, $self->{appender};

But I do not.

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

(minimal test program and config attached as well)

To reproduce, you need a mysql server and associated tables.  Edit the
attached config to match.

Then run init_and_watch.pl in the background.  Use a mysql client to
look at the current connections.  For mysql 4.1 and 5.x, this works:
	show processlist;

Send a SIGHUP to the running perl process, and check the mysql
processlist again.  There will be a new one.

---------
Side question (somewhat related): both DBI and DBI_Buffer seem to make
connections to databases aren't really necessary.  In other words, if
all of these conditions are true:
	1) "Database1" and "Database2" are both defined in the config file as
DBI appenders
	2)  Two categories are defined that use both Database appenders, e.g.:
	log4perl.category.DB1 = INFO, Database1
	log4perl.category.DB2 = INFO, Database2

	3)  Run a program that only uses the "DB1" category, e.g:
	my $logger = get_logger("DB1");

Then it it makes connections to both databases, even though only DB1 is
used.  Is this expected behavior?    I know this behavior isn't causing
my problem, because if I SIGHUP a program using the DBI appender, the
connections are remade instead of hanging around needlessly as when I
use DBI_Buffer.  I'm just curious.

-- 
Rob