log4perl-devel

[log4perl-devel] eradicate / NFS

[Foudil <fou...@fr...>]

Hi all,

In order to log to a tmp directory (that we want to remove later), we create an appender in a script that we add to our project's loggers:

Log::Log4perl->init_and_watch($path_conf."/log.conf", 'HUP'); # HUP needed for logrotate
my $logger = get_logger($FindBin::Script);
my $logger_all = Log::Log4perl->get_logger("OurProject");
# Local appender to log in tmp directory.
my $local_appender;
my $local_appender_name = 'LogTmp';

...

    # Create appender to log error in tmp directory.
    $local_appender = Log::Log4perl::Appender->new(
        "Log::Log4perl::Appender::File",
        name      => $local_appender_name,
        filename  => "$spool_tmp/error.log",
        mode      => 'write',
        syswrite  => 1,
        utf8      => 1,
       );
    my $layout = Log::Log4perl::Layout::PatternLayout->new("%d %P %p> %F{1}:%L %M - %m%n");
    $local_appender->layout($layout);
    $local_appender->threshold($CFG{'l4p_appender_logtmp_threshold'});
    $logger->add_appender($local_appender);
    $logger_all->add_appender($local_appender); # add appender to project modules' logger

...

    $logger->remove_appender($local_appender_name);
    $logger_all->remove_appender($local_appender_name);
    rmtree($spool_tmp, {error => \my $err});
    if (@$err) {
        file_path_error($err);
        exit;
    }
    $logger->info("removed $spool_tmp");

But rmtree() (File::Path) is complaining that $spool_tmp is not empty. $spool_tmp is on an NFS mount.

So we solved the pb with:

    #$logger->remove_appender($local_appender_name);
    #$logger_all->remove_appender($local_appender_name);
    # "will first remove the appender from every logger in the system and then
    # will delete all references Log4perl holds to it." (Log::Log4perl)
    Log::Log4perl->eradicate_appender($local_appender_name);
    # ...but the appender is still alive and keeps filehandles open. So we need
    #  to close them explicitly. Especially under NFS, where deleted but still
    #  opened files are kept by the kernel as '.nfsxxx' (see "NFS silly
    #  rename")
    $local_appender->file_close(); # (undocumented, look into the code)
    rmtree($spool_tmp, {error => \my $err});
    if (@$err) {
        file_path_error($err);
        exit;
    }
    $logger->info("removed $spool_tmp");

My guess may be wrong, and I'd be interested to know if there is a better solution.

Best
Foudil

Re: [log4perl-devel] eradicate / NFS

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

On Tue, 6 Jul 2010, Foudil wrote:

> In order to log to a tmp directory (that we want to remove later), we
> create an appender in a script that we add to our project's loggers:
> Log::Log4perl->init_and_watch($path_conf."/log.conf", 'HUP');

Hi Foudil,

sorry for the long wait. I've noticed that you're using init_and_watch()
along with user-defined appenders. Just a heads-up that this can lead to
unpredictable situations: Whenever Log4perl/init_and_watch() notices
that it needs to reload the configuration file (because it has changed),
you'll lose the temporary appender, because the Log4perl configuration
will be overwritten.

Even if you don't need the appender permanently, it makes sense to have
it in the configuration, if only for reasons of clarity.

>    Log::Log4perl->eradicate_appender($local_appender_name);
>    # ...but the appender is still alive and keeps filehandles open. So we need
>    #  to close them explicitly.

The eradicate_appender() method should take are of the issue in this
situation. Only exception: if still have references to the appender 
anywhere in your application code, the appender destructor won't run and
you need to run file_close() manually.

Hope that helps!

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] eradicate / NFS

[<fou...@bi...>]

Le 10/07/2010 08:02, Mike Schilli a écrit :
> On Tue, 6 Jul 2010, Foudil wrote:
> 
>> In order to log to a tmp directory (that we want to remove later), we
>> create an appender in a script that we add to our project's loggers:
>> Log::Log4perl->init_and_watch($path_conf."/log.conf", 'HUP');
> 
> Hi Foudil,
> 
> sorry for the long wait. I've noticed that you're using init_and_watch()
> along with user-defined appenders. Just a heads-up that this can lead to
> unpredictable situations: Whenever Log4perl/init_and_watch() notices
> that it needs to reload the configuration file (because it has changed),
> you'll lose the temporary appender, because the Log4perl configuration
> will be overwritten.
> 
> Even if you don't need the appender permanently, it makes sense to have
> it in the configuration, if only for reasons of clarity.

Hi Mike,

[also sorry for the delay]

Thank you for the hint. I'm not sure how to put the configuration for the temporary appender in the general configuration file: because the temporary file appender needs to get created during the execution in a temporary directory (that gets created itself during execution). Whereas if the configuration for the temporary file appender is in the general configuration file, then the temporary log file seems to get created in the beginning... leading to an error because of the missing temporary directory...

>>    Log::Log4perl->eradicate_appender($local_appender_name);
>>    # ...but the appender is still alive and keeps filehandles open. So we need
>>    #  to close them explicitly.
> 
> The eradicate_appender() method should take are of the issue in this
> situation. Only exception: if still have references to the appender 
> anywhere in your application code, the appender destructor won't run and
> you need to run file_close() manually.

That's the expected behaviour, but the code snippets comes from a single script, so there should not be any other reference to the temporary appender. And what I could observe under NFS is that the appender *somehow* keeps the filehandle open. I just wanted to warn about this "somehow" (probably related to "NFS silly renames" ?), and maybe learn how to deal with it.

Best,
Foudil

Re: [log4perl-devel] eradicate / NFS

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

On Wed, 28 Jul 2010, fou...@bi... wrote:

> then the temporary log file seems to get
> created in the beginning... leading to an error because of the missing
> temporary directory...

The file appender lets you delay creation of the file until you write to
it, check the create_at_logtime option in

     http://search.cpan.org/~mschilli/Log-Log4perl-1.29/lib/Log/Log4perl/Appender/File.pm

> That's the expected behaviour, but the code snippets comes from a single script, so there should not be any other reference to the temporary appender.

Can you post a standalone script that reproduces the error?

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] eradicate / NFS

[<fou...@bi...>]

Le 31/07/2010 02:25, Mike Schilli a écrit :
> On Wed, 28 Jul 2010, fou...@bi... wrote:
> 
>> then the temporary log file seems to get
>> created in the beginning... leading to an error because of the missing
>> temporary directory...
> 
> The file appender lets you delay creation of the file until you write to
> it, check the create_at_logtime option in
> 
>      http://search.cpan.org/~mschilli/Log-Log4perl-1.29/lib/Log/Log4perl/Appender/File.pm

Hi Mike,
I was aware of that option, and I thought it was inappropriate in our context.
Now I have tested it and I can tell it's inappropriate:
we start logging prior to the temporary appender creation. So if we set create_at_logtime and put all the temp app config in the main log config, l4p tries to create the temp logfile before the creation of the temp dir meant to contain the temp logfile...

>> That's the expected behaviour, but the code snippets comes from a single script, so there should not be any other reference to the temporary appender.
> 
> Can you post a standalone script that reproduces the error?

It took some time, but here it is (attachment).

Re: [log4perl-devel] eradicate / NFS

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

On Mon, 16 Aug 2010, fou...@bi... wrote:

> we start logging prior to the temporary appender creation. So if we
> set create_at_logtime and put all the temp app config in the main log
> config, l4p tries to create the temp logfile before the creation of
> the temp dir meant to contain the temp logfile...

Somehow the use of a configuration file seems to defy the purpose of
this particular use case. The configuration is usually read at start-up
and determines the program's logging behavior.

What you could do to point Log4perl at a tempfile created sometime at
runtime, is obtain a reference to the file appender the configuration
uses (or add another file appender via perl code) and use the file
appender's file_switch( $newfile ) mode to point it to a newly created
file.

This might surprise your users, though, so be warned.

-- Mike

Mike Schilli
m...@pe...