log4perl-devel

[log4perl-devel] Intermittent problems when using signal to reread log configuration

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

I have been using Log4perl for quite some time in a large project of mine.   There are about 20 perl programs, all of which should always be running.  I'm using init_and_watch to allow users to update the configuration file; i.e:

    # Init Log4perl
    Log::Log4perl->init_and_watch("../ANSlog.conf",'HUP');
    $logger = get_logger("category")

After updating the config file, I use a script to send SIGHUP to all the currently running processes (simple "kill -HUP <PID>").

Most of the time (I'd guess ~80%), this works fine.  When it doesn't work, I get the following error on STDERR (even though I've wrapped STDERR with a "Trapper" as described in the FAQ):

	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.

And the perl program dies.

I'm using ActivePerl 5.8.7 due to an restriction from a third-party Perl module; I can't update perl itself or use another perl distribution.

I'm using Log4perl 1.20.  The system is CentOS 4.2.

My log4perl configuration is rather large, but it is below.  I tried removing the Database appender from the configuration (i.e. leaving only the File appender "Logfile"), but it still happens without it.


#-----------------------------------------------------------------------
##
## Root logger threshold and appenders
##
log4perl.rootLogger = DEBUG

##
## Categories for each ANS module
##
log4perl.category.ANS           = INFO, Logfile
log4perl.category.ANS.asistlog  = INFO, Database
log4perl.category.ANS.email     = INFO, Database
log4perl.category.ANS.event     = INFO, Database
log4perl.category.ANS.event.main = INFO
log4perl.category.ANS.event.readconfig = INFO
log4perl.category.ANS.event.forkchildren = INFO
log4perl.category.ANS.event.refork = INFO
log4perl.category.ANS.event.housekeeping = INFO
log4perl.category.ANS.event.connopen = INFO
log4perl.category.ANS.event.connclose = INFO
log4perl.category.ANS.event.connquery = WARN
log4perl.category.ANS.event.repeat = INFO
log4perl.category.ANS.event.GetFieldValue = INFO
log4perl.category.ANS.heartbeat = INFO, Database
log4perl.category.ANS.htmlizer  = INFO, Database
# This category is special -- no inheritance from ANS category,
# so messages only go to the alert database
log4perl.category.htmlizer.sql  = INFO, AlertDatabase
log4perl.category.asistlog.sql  = INFO, ASISTDatabase, DMZDatabase
#
log4perl.category.ANS.component = INFO, Database
log4perl.category.ANS.satwatch                  = INFO, Database
log4perl.category.ANS.satwatch.parse            = INFO
# ****** NOTE!  DEBUG output for Catalog iS HUUUUUGE ********
log4perl.category.ANS.satwatch.catalog          = INFO
log4perl.category.ANS.satwatch.filter           = INFO
log4perl.category.ANS.satwatch.typehandler      = INFO
log4perl.category.ANS.satwatch.grouphandler     = INFO
log4perl.category.ANS.satwatch.registerhandler  = INFO
log4perl.category.ANS.satwatch.filterhandler    = INFO
log4perl.category.ANS.satwatch.eventhandler     = INFO
log4perl.category.ANS.satwatch.regexphandler    = INFO
log4perl.category.ANS.satwatch.occurshandler    = INFO
log4perl.category.ANS.satwatch.intervalhandler  = INFO
log4perl.category.ANS.satwatch.ignore           = INFO
log4perl.category.ANS.satwatch.watch            = INFO
log4perl.category.ANS.satwatch.clear            = INFO
log4perl.category.ANS.satwatch.flush            = INFO
log4perl.category.ANS.satwatch.flushnow         = INFO
log4perl.category.ANS.satwatch.cleaner          = INFO
log4perl.category.ANS.satwatch.cleanup          = INFO
log4perl.category.ANS.source    = INFO, Database
log4perl.category.ANS.target    = INFO, SyncDatabase
log4perl.category.ANS.trapper   = INFO, Database

##
## Logfile appender
##
log4perl.appender.Logfile       = Log::Log4perl::Appender::File
log4perl.appender.Logfile.filename = \
        sub { if ($ENV{'ANSROOT'}) { \
                return "$ENV{'ANSROOT'}/ANSlog.txt" \
        } else { \
                die "ENV{ANSROOT} not defined!" \
        } }
log4perl.appender.Logfile.mode  = append
log4perl.appender.Logfile.recreate = 1
log4perl.appender.Logfile.recreate_check_signal = USR1
#log4perl.appender.Logfile.recreate_check_interval = 5
log4perl.appender.Logfile.layout= Log::Log4perl::Layout::PatternLayout
log4perl.appender.Logfile.layout.ConversionPattern = \
         %d{yyyy-DDD/HH:mm:ss} %-5p %F{2} %P %m%n

##
## Screen Appender
##
log4perl.appender.Screen         = Log::Log4perl::Appender::Screen
log4perl.appender.Screen.stderr  = 0
log4perl.appender.Screen.layout=Log::Log4perl::Layout::PatternLayout
log4perl.appender.Screen.layout.ConversionPattern = \
        %d{yyyy-DDD/HH:mm:ss} %-5p %F{2} %P %m%n

##
## Database Appender
##
# NOTE: DBI_Buffer uses all options from Log::Log4perl::Appender::DBI
log4perl.appender.Database              = Log::Log4perl::Appender::DBI
log4perl.appender.Database.usePreparedStmt = 1
log4perl.appender.Database.layout       = Log::Log4perl::Layout::NoopLayout
log4perl.appender.Database.datasource   = DBI:mysql:database=ansdb:host=localhost;mysql_auto_reconnect=1
log4perl.appender.Database.username     = foo
log4perl.appender.Database.password     = bar
log4perl.appender.Database.logbuffer    = 4000
log4perl.appender.Database.errorappender= Logfile
log4perl.appender.Database.errorstodatabase= 1
log4perl.appender.Database.sql          = \
        insert into anslog              \
        (date, loglevel, filename, hostname, PID, message) \
        values (?,?,?,?,?,?)
log4perl.appender.Database.params.1   = %d{yyyy-DDD/HH:mm:ss}
log4perl.appender.Database.params.2   = %p
log4perl.appender.Database.params.3   = %F{2}
log4perl.appender.Database.params.4   = %H
log4perl.appender.Database.params.5   = %P
log4perl.appender.Database.params.6   = %m

##
## Alert Database Appender
##
# NOTE: DBI_Buffer uses all options from Log::Log4perl::Appender::DBI
log4perl.appender.AlertDatabase                 = DBI_Buffer
log4perl.appender.AlertDatabase.layout          = Log::Log4perl::Layout::NoopLayout
log4perl.appender.AlertDatabase.warp_message    = 0
log4perl.appender.AlertDatabase.datasource      = DBI:mysql:database=ansdb:host=localhost;mysql_auto_reconnect=1
log4perl.appender.AlertDatabase.username        = foo
log4perl.appender.AlertDatabase.password        = bar
log4perl.appender.AlertDatabase.logbuffer       = 4000
log4perl.appender.AlertDatabase.errorappender   = Logfile
log4perl.appender.AlertDatabase.errorstodatabase= 0
log4perl.appender.AlertDatabase.sql     = \
        insert into alerts              \
        (date, loglevel, filename, hostname, PID, \
                timestamp, emailgroup, message) \
        values (?,?,?,?,?,?,?,?)
log4perl.appender.AlertDatabase.params.1   = %d{yyyy-DDD/HH:mm:ss}
log4perl.appender.AlertDatabase.params.2   = %p
log4perl.appender.AlertDatabase.params.3   = %F{2}
log4perl.appender.AlertDatabase.params.4   = %H
log4perl.appender.AlertDatabase.params.5   = %P
                                      #6 is timestamp from log call
                                      #7 is emailgroup from log call
                                      #8 is message from log call

##
## Define a filter routine to remove SDO Commands
## from the event log
##
log4perl.filter.CommandFilter   = sub { \
        !/CMH-I:CMD/ \
        };

##
## ASIST Database Appender
##
# NOTE: DBI_Buffer uses all options from Log::Log4perl::Appender::DBI
log4perl.appender.ASISTDatabase                 = DBI_Buffer
log4perl.appender.ASISTDatabase.Filter          = CommandFilter
log4perl.appender.ASISTDatabase.layout          = Log::Log4perl::Layout::NoopLayout
log4perl.appender.ASISTDatabase.warp_message    = 0
log4perl.appender.ASISTDatabase.datasource      = DBI:mysql:database=asistdb:host=localhost;mysql_auto_reconnect=1
log4perl.appender.ASISTDatabase.username        = foo
log4perl.appender.ASISTDatabase.password        = bar
log4perl.appender.ASISTDatabase.logbuffer       = 4000
log4perl.appender.ASISTDatabase.errorappender   = Logfile
log4perl.appender.ASISTDatabase.errorstodatabase = 0
log4perl.appender.ASISTDatabase.sql     = \
        insert into events              \
        (date, loglevel, filename, hostname, PID, \
                asisthost, timestamp, class, message) \
        values (?,?,?,?,?,?,?,?,?)
log4perl.appender.ASISTDatabase.params.1   = %d{yyyy-DDD/HH:mm:ss}
log4perl.appender.ASISTDatabase.params.2   = %p
log4perl.appender.ASISTDatabase.params.3   = %F{2}
log4perl.appender.ASISTDatabase.params.4   = %H
log4perl.appender.ASISTDatabase.params.5   = %P
                                      #6 is asisthost from log call
                                      #7 is timestamp from log call
                                      #8 is class from log call
                                      #9 is message from log call
##
##
## DMZ Database Appender
##
# NOTE: DBI_Buffer uses all options from Log::Log4perl::Appender::DBI
log4perl.appender.DMZDatabase                   = DBI_Buffer
log4perl.appender.DMZDatabase.Filter            = CommandFilter
log4perl.appender.DMZDatabase.layout            = Log::Log4perl::Layout::NoopLayout
log4perl.appender.DMZDatabase.warp_message      = 0
log4perl.appender.DMZDatabase.datasource        = DBI:mysql:database=asistdb:host=remotesys;mysql_auto_reconnect=1
log4perl.appender.DMZDatabase.username          = foo
log4perl.appender.DMZDatabase.password          = bar
log4perl.appender.DMZDatabase.logbuffer         = 4000
log4perl.appender.DMZDatabase.errorappender     = Logfile
log4perl.appender.DMZDatabase.errorstodatabase  = 0
log4perl.appender.DMZDatabase.sql       = \
        insert into events              \
        (date, loglevel, filename, hostname, PID, \
                asisthost, timestamp, class, message) \
        values (?,?,?,?,?,?,?,?,?)
log4perl.appender.DMZDatabase.params.1   = %d{yyyy-DDD/HH:mm:ss}
log4perl.appender.DMZDatabase.params.2   = %p
log4perl.appender.DMZDatabase.params.3   = %F{2}
log4perl.appender.DMZDatabase.params.4   = %H
log4perl.appender.DMZDatabase.params.5   = %P
                                      #6 is asisthost from log call
                                      #7 is timestamp from log call
                                      #8 is class from log call
                                      #9 is message from log call

##
## DB Syncronizer
##
# Technically, only the forked children for event.pl and target.pl
# need to be Sync'd, but we are syncing all of the modules
# If performance becomes an issue, try syncing only event.pl and target.pl
log4perl.appender.SyncDatabase            = Log::Log4perl::Appender::Synchronized
log4perl.appender.SyncDatabase.appender   = Database
# Random semaphore key; otherwise they clobber each other
log4perl.appender.SyncDatabase.key        = sub { int(rand(10000)); }


-- 
Thanks,
Rob

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

On Wed, 18 Feb 2009, Robert Jacobson wrote:

> Most of the time (I'd guess ~80%), this works fine.  When it doesn't
> work, I get the following error on STDERR (even though I've wrapped
> STDERR with a "Trapper" as described in the FAQ):
>
>       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.

Hmm, that's peculiar. I wonder what kind of config change would cause
this. Are you removing an appender by any chance?

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

Mike Schilli m-at-perlmeister.com |log4perl_sourceforge| wrote:
> Hmm, that's peculiar. I wonder what kind of config change would cause
> this. Are you removing an appender by any chance?

Nope, usually I'm only changing the log level.

But I can reproduce the error without changing anything in the config, too.

It does seem to only have a problem when the system is heavily loaded.
Perhaps this is a race condition that is more likely when resources are
heavily used?  (just a guess, I really don't know)

-- 
Rob

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

On Fri, 20 Feb 2009, Robert Jacobson wrote:
>> I wonder what kind of config change would cause
>> this. Are you removing an appender by any chance?
>
> Nope, usually I'm only changing the log level.
>
> But I can reproduce the error without changing anything in the config, too.

Interesting ... is there a way you could send a narrowed-down test
program to let me reproduce this? I'd be interested to find out what's
causing this. Also, is this only happening on Windows with ActiveState
Perl or have you seen it happen on other OS and perl distros as well?

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

Mike Schilli m-at-perlmeister.com |log4perl_sourceforge| wrote:
> On Fri, 20 Feb 2009, Robert Jacobson wrote:
>>> I wonder what kind of config change would cause
>>> this. Are you removing an appender by any chance?
>>
>> Nope, usually I'm only changing the log level.
>>
>> But I can reproduce the error without changing anything in the config, 
>> too.
> 
> Interesting ... is there a way you could send a narrowed-down test
> program to let me reproduce this? 

I can try, but it'll have to wait until I'm at work again.

> I'd be interested to find out what's
> causing this. Also, is this only happening on Windows with ActiveState
> Perl or have you seen it happen on other OS and perl distros as well?

I am using ActiveState perl on CentOS 4.2 and RHEL4; they both exhibit 
the problem.  I haven't tried Windows; does SIGHUP even exist there? 
(nvm, doesn't matter :)  )


--
Rob

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

On Sat, 21 Feb 2009, Robert Jacobson wrote:

> I am using ActiveState perl on CentOS 4.2 and RHEL4; they both exhibit
> the problem.  I haven't tried Windows; does SIGHUP even exist there?
> (nvm, doesn't matter :)  )

Never mind, I was assuming you were using Windows because I've never
used ActiveState Perl on Unix! :)

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

Ah, apparently I *had* left some appenders using DBI_Buffer (DBI
appender subclass) in my config.   I retested a bunch of things today
and I could not reproduce the error unless I had my DBI_Buffer appender
in the config.

Further investigation showed that the mysql server was reaching its
maximum number of allowed connections (currently set at 250).

Apparently my appender is not closing its dbh filehandles.  I'm going to
start a separate thread, since the problem is something totally
different (in my code, probably).

I apologize for my inadequate testing :(

-- 
Rob

Re: [log4perl-devel] Intermittent problems when using signal to reread log configuration

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

On Mon, 23 Feb 2009, Robert Jacobson wrote:

> Apparently my appender is not closing its dbh filehandles.  I'm going
> to start a separate thread, since the problem is something totally
> different (in my code, probably). I apologize for my inadequate
> testing :(

No problem at all, glad we've found an explanation :)

-- Mike

Mike Schilli
m...@pe...