`post_rotate` is inconsistent and its usefulness is neutered

[ikegami]

This report brings up two issues with a common solution. Suggested solution at the bottom.

post_rotate is called an inconsistent number of times

• If the highest numbered file before rotate is < max-1, post_rotate is called for files that weren't rotated.
• If the highest numbered file before rotate is ≥ max-1, post_rotate is only called for files that were rotated.

Test program and output:

#!/usr/bin/env perl
# problem1.pl

use strict;
use warnings;
use feature qw( say );

use Log::Dispatch::FileRotate qw( );

my $rotate_size = 1_000;

my $file = $0 =~ s/(?:\.pl)?\z/.log/r;

my $log = Log::Dispatch->new(
    outputs => [
        [
            'FileRotate' => (
                min_level => 'debug',
                mode      => '>>',
                newline   => 1,
                filename  => $file,
                size      => $rotate_size,
                max       => 3,
                post_rotate => sub {
                    my ($filename, $index, $fileRotate) = @_;
                    say sprintf "[%s]", $filename;
                },
            ),
        ],
    ],
);

$log->info("x" x $rotate_size);
$log->info("x");
say "--";
$log->info("x" x $rotate_size);
$log->info("x");
say "--";
$log->info("x" x $rotate_size);
$log->info("x");

$ rm problem1.log* 2>/dev/null; perl problem1.pl
[problem1.log.1]     <-- Didn't exist
[problem1.log]       <-- Existed
--
[problem1.log.2]     <-- Didn't exist
[problem1.log.1]     <-- Existed
[problem1.log]       <-- Existed
--
[problem1.log.2]     <-- Existed
[problem1.log.1]     <-- Existed
[problem1.log]       <-- Existed

---

post_rotate 's usefulness is neutered

The callback is provided the original name of the rotated file, but it would be nice if it was also provided the new name of the file.

Currently, the documentation claims the first parameter is "the path of the rotated file", which unclear. That could mean

• The current path of the rotated file.
• The former path of the rotated file.

The first parameter is the former path of the rotated file. This is not the interpretation I find the most likely, and it's the least useful of the two options. In fact, the former bit of information (the new name of the rotated file) is not provided at all. It would be useful to have this.

Test program and output:

#!/usr/bin/env perl
# problem2.pl

use strict;
use warnings;
use feature qw( say );

use Log::Dispatch::FileRotate qw( );

my $rotate_size = 1_000;

my $file = $0 =~ s/(?:\.pl)?\z/.log/r;

my $log = Log::Dispatch->new(
    outputs => [
        [
            'FileRotate' => (
                min_level => 'debug',
                mode      => '>>',
                newline   => 1,
                filename  => $file,
                size      => $rotate_size,
                max       => 1,
                post_rotate => sub {
                    my ($filename, $index, $fileRotate) = @_;
                    say sprintf "[%s][%s]", $filename, $fileRotate->filename();
                },
            ),
        ],
    ],
);

$log->info("x" x $rotate_size);
$log->info("x");

$ rm problem2.log* 2>/dev/null; perl problem2.pl
[problem2.log][problem2.log]     <-- Neither of these are the name of the rotated file as it now exists.

---

Suggested Solution

In order to preserver backwards compatibility, I propose the following solution:

1. Remove the following code from rotate:

   if (ref $self->{post_rotate} eq 'CODE') {
       $self->debug('Calling user post-rotate callback');
       $self->_for_each_file($self->{post_rotate});
   }

2. Add the following code to _move_file:

   if (ref $self->{post_rotate} eq 'CODE') {
       $self->{post_rotate}->($filename, $idx, $fileRotate, $newfile);
   }

In any case, the documentation for the $filename parameter needs fixing.

[ikegami]

This ticket was filed in response to the following question on SO: https://stackoverflow.com/q/64111885/589924

[ikegami]

Workaround:

sub post_rotate {
   my (undef, $index, $fileRotate) = @_;

   # Current path to the rotated file.
   my $current_qfn = $fileRotate->filename() . "." . ($index+1);

   # Handle the situation where this callback is called too many times.
   return if !-e $current_qfn;

   ...
}

[XSven]

I have applied your test programs to the most recent version 1.38 of Log::Dispatch::FileRotate and I cannot confirm all your findings.

• problem1.pl: $filename (the first parameter passed to the post_rotate callback) all the time exists as a physical file.
• problem2.pl: max => 1 means that there should be no rotated file: $filename == $fileRotate->filename == problem2.log is ok but problem2.log.1 should not exist although it does. In general there exists always one more file with the index max that should not exist.

[ikegami]

Deleted a comment. It's not quite right.

[ikegami]

I have applied your test programs to the most recent version 1.38 of Log::Dispatch::FileRotate and I cannot confirm all your findings.

The programs still output exactly the same result. The problems still exist.

---

• problem1.pl: $filename (the first parameter passed to the post_rotate callback) all the time exists as a physical file.

The problem isn't that the file doesn't exist when post_rotate was called. The problem is that post_rotate is sometimes called more times than the number of rotations.

With max => 3,

• When only one file is rotated (because only one file existed pre-rotate), it calls post_rotate twice .
• When only two files are rotated (because only two files existed pre-rotate), it calls post_rotate thrice.
• When three files are rotated, it calls post_rotate thrice (as expected).

This is harmful, and in direct contradiction of the documentation ("Will be called one time for every rotated file")

---

• problem2.pl: max => 1 means that there should be no rotated file:

That's not relevant. The same lack of information exists regardless of the value of max.

For example, make these changes to problem2.pl:

max => 2

$log->info("x" x $rotate_size);
$log->info("x");
say "--";
$log->info("x" x $rotate_size);
$log->info("x");

The output is now:

...
--
[problem2.log.1][problem2.log]
[problem2.log][problem2.log]

• problem2.log.1 was renamed problem2.log.2. But the callback isn't provided problem2.log.2. We need to calculate that ourselves. We shouldn't have to do so.
• problem2.log was renamed problem2.log.1. But the callback isn't provided problem2.log.1. We need to calculate that ourselves. We shouldn't have to do so.

It would be nice if we didn't have to calculate the new name ourselves.

---

Sorry I wasn't clearer.