perl5
perl5 copied to clipboard
Perl
Smoke me/fix caller issues
There are and have been multiple bug reports over the years related to caller() showing bogus data about require call frames.
For example issue #15109 and I believe #4125 and someewhere there is one I created as well. I am sure if we dig we will find more. The issue comes from using a single global variable to store the file and line data for the "fake" parts of the expansion of
use Foo;
into
BEGIN{ require Foo; }
Using one variable meant that certain exceptions were correct, but walking the callstack would end up pointers to the same data structure from multiple distinct frames in the stack, thus making every require in the call stack look as though there were "from" the same line and file, that of the most recent require. For the exact same code, depending on where in the call stack an exception is thrown mutliple frames will appear to change their origin.
This is not and cannot be correct. A given BEGIN block fires only once, it cannot appear in the callstack more than one, and it cannot be recursive.
Dave M then fixed the problem with various patches. These fixes then broke modules which had come to depend on the buggy implementation and the patches were reverted at the time. This PR reverts those reverts. The code which depends on the buggy stack data should be fixed so the rest of us have sane callstacks to debug our code with.
See Issue #17663 for details on the revert. I believe the statement contained in #15109 outlines the problem sufficiently. See also the test in the PR.
I wanted to add some demonstration of the bug this PR fixes. Consider the following program:
use strict;
use warnings;
use File::Temp qw(tempdir);
our @stack;
my $dir= tempdir(CLEANUP=>1);
my $max_depth= 5;
for my $depth (0 .. $max_depth) {
my $mod= "Mod$depth";
my $nextmod= $depth<$max_depth ? "Mod" . ($depth+1) : "";
open my $fh, ">", "$dir/$mod.pm";
print $fh "package $mod;\n";
print $fh "BEGIN { \$::stack[$depth]= Carp::longmess('depth $depth'); }\n";
print $fh "use $nextmod;\n" if $nextmod;
}
push @INC, $dir;
eval "use Mod0;";
$_=~s/\Q$dir\E/lib/g for @stack; # improve readability
print "stack at depth $_:\n$stack[$_]\n" for 0..$max_depth;
This produces the following output:
$ perl t_stack.pl
stack at depth 0:
depth 0 at lib/Mod0.pm line 2.
eval {...} called at lib/Mod0.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod0.pm line 2
eval {...} called at lib/Mod0.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 1:
depth 1 at lib/Mod1.pm line 2.
eval {...} called at lib/Mod1.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod1.pm line 2
eval {...} called at lib/Mod1.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod1.pm line 2
eval {...} called at lib/Mod1.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 2:
depth 2 at lib/Mod2.pm line 2.
eval {...} called at lib/Mod2.pm line 2
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod2.pm line 2
eval {...} called at lib/Mod2.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod2.pm line 2
eval {...} called at lib/Mod2.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod2.pm line 2
eval {...} called at lib/Mod2.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 3:
depth 3 at lib/Mod3.pm line 2.
eval {...} called at lib/Mod3.pm line 2
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod3.pm line 2
eval {...} called at lib/Mod3.pm line 2
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod3.pm line 2
eval {...} called at lib/Mod3.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod3.pm line 2
eval {...} called at lib/Mod3.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod3.pm line 2
eval {...} called at lib/Mod3.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 4:
depth 4 at lib/Mod4.pm line 2.
eval {...} called at lib/Mod4.pm line 2
require Mod4.pm called at lib/Mod3.pm line 3
Mod3::BEGIN() called at lib/Mod4.pm line 2
eval {...} called at lib/Mod4.pm line 2
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod4.pm line 2
eval {...} called at lib/Mod4.pm line 2
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod4.pm line 2
eval {...} called at lib/Mod4.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod4.pm line 2
eval {...} called at lib/Mod4.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod4.pm line 2
eval {...} called at lib/Mod4.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 5:
depth 5 at lib/Mod5.pm line 2.
eval {...} called at lib/Mod5.pm line 2
require Mod5.pm called at lib/Mod4.pm line 3
Mod4::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
require Mod4.pm called at lib/Mod3.pm line 3
Mod3::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
require Mod0.pm called at (eval 9) line 1
main::BEGIN() called at lib/Mod5.pm line 2
eval {...} called at lib/Mod5.pm line 2
eval 'use Mod0;' called at t_stack.pl line 17
So somehow we end up with a set of stack traces from the same code path, taken at different depths, and each one is different, and the data they show is clearly wrong. lib/Mod5.pm could not be source the second deepest call frame. There is a clear inconsistency, the frame before shows that a "use Mod0;" call was executed, yet the next frame think it was called from lib/Mod5.pm line 2, which is obviously wrong, and very misleading to someone not familiar with this bug.
Now, some may argue exactly what is correct here. I have seen some discussion about what type of lie to tell about these frames, since they do not strictly speaking come from code directly and I do not stake our a position here beyond that I think what this patch does is a reasonable thing.
However, what I am really concerned with and pretty insistent on is that the current behavior is not correct. A stack trace is supposed to show the path through the code. It cannot be that taking the Kth step on the path changes the record of what previous steps were. Sure, there is useful information interspersed with this junk data, but IMO we would better not showing anything than showing what we do, and IMO Dave M's patch is an even better solution. That does not mean that there is not an alternative better solution, but I think there cannot be any debate that the current behavior is buggy and confusing.
Compare the above mess with what the patch produces:
stack at depth 0:
depth 0 at lib/Mod0.pm line 2.
eval {...} called at lib/Mod0.pm line 2
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 1:
depth 1 at lib/Mod1.pm line 2.
eval {...} called at lib/Mod1.pm line 2
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod0.pm line 3
eval {...} called at lib/Mod0.pm line 3
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 2:
depth 2 at lib/Mod2.pm line 2.
eval {...} called at lib/Mod2.pm line 2
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod1.pm line 3
eval {...} called at lib/Mod1.pm line 3
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod0.pm line 3
eval {...} called at lib/Mod0.pm line 3
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 3:
depth 3 at lib/Mod3.pm line 2.
eval {...} called at lib/Mod3.pm line 2
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod2.pm line 3
eval {...} called at lib/Mod2.pm line 3
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod1.pm line 3
eval {...} called at lib/Mod1.pm line 3
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod0.pm line 3
eval {...} called at lib/Mod0.pm line 3
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 4:
depth 4 at lib/Mod4.pm line 2.
eval {...} called at lib/Mod4.pm line 2
require Mod4.pm called at lib/Mod3.pm line 3
Mod3::BEGIN() called at lib/Mod3.pm line 3
eval {...} called at lib/Mod3.pm line 3
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod2.pm line 3
eval {...} called at lib/Mod2.pm line 3
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod1.pm line 3
eval {...} called at lib/Mod1.pm line 3
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod0.pm line 3
eval {...} called at lib/Mod0.pm line 3
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
stack at depth 5:
depth 5 at lib/Mod5.pm line 2.
eval {...} called at lib/Mod5.pm line 2
require Mod5.pm called at lib/Mod4.pm line 3
Mod4::BEGIN() called at lib/Mod4.pm line 3
eval {...} called at lib/Mod4.pm line 3
require Mod4.pm called at lib/Mod3.pm line 3
Mod3::BEGIN() called at lib/Mod3.pm line 3
eval {...} called at lib/Mod3.pm line 3
require Mod3.pm called at lib/Mod2.pm line 3
Mod2::BEGIN() called at lib/Mod2.pm line 3
eval {...} called at lib/Mod2.pm line 3
require Mod2.pm called at lib/Mod1.pm line 3
Mod1::BEGIN() called at lib/Mod1.pm line 3
eval {...} called at lib/Mod1.pm line 3
require Mod1.pm called at lib/Mod0.pm line 3
Mod0::BEGIN() called at lib/Mod0.pm line 3
eval {...} called at lib/Mod0.pm line 3
require Mod0.pm called at (eval 8) line 1
main::BEGIN() called at (eval 8) line 1
eval {...} called at (eval 8) line 1
eval 'use Mod0;' called at t_stack.pl line 17
We now have clarity and consistency. The bottom of the stack stays consistent as we go deeper into the dependency tree. This is more or less what I would expect to see and I expect anyone reading it would understand (with a bit of doc reading) what it was showing.
In case it isnt obvious consider the following modification of the test code:
$ cat t_stack.pl
use strict;
use warnings;
use File::Temp qw(tempdir);
use Test::More;
our @stack;
my $dir= tempdir(CLEANUP=>1);
my $max_depth= 5;
for my $depth (0 .. $max_depth) {
my $mod= "Mod$depth";
my $nextmod= $depth<$max_depth ? "Mod" . ($depth+1) : "";
open my $fh, ">", "$dir/$mod.pm";
print $fh "package $mod;\n";
print $fh "BEGIN { \$::stack[$depth]= Carp::longmess('depth $depth'); }\n";
print $fh "use $nextmod;\n" if $nextmod;
}
push @INC, $dir;
eval "use Mod0;";
$_=~s/\Q$dir\E/lib/g for @stack; # improve readability
if ($ENV{VERBOSE}) {
diag "stack at depth $_:\n$stack[$_]\n" for 0..$max_depth;
}
my @lines=map { [ reverse(split /\n/, $_) ] } @stack;
for my $depth (1..$max_depth) {
my $this_lines= $lines[$depth];
my $prev_lines= $lines[$depth-1];
for my $stack_height (0..$#$prev_lines-2) { # height as the lines are reversed, ignore top two
is($this_lines->[$stack_height],$prev_lines->[$stack_height],"check frame height $stack_height consistent at stack depth $depth");
}
}
done_testing();
With this PR applied:
$ ./perl -Ilib t_stack.pl
ok 1 - check frame height 0 consistent at stack depth 1
ok 2 - check frame height 1 consistent at stack depth 1
ok 3 - check frame height 2 consistent at stack depth 1
ok 4 - check frame height 3 consistent at stack depth 1
ok 5 - check frame height 0 consistent at stack depth 2
ok 6 - check frame height 1 consistent at stack depth 2
ok 7 - check frame height 2 consistent at stack depth 2
ok 8 - check frame height 3 consistent at stack depth 2
ok 9 - check frame height 4 consistent at stack depth 2
ok 10 - check frame height 5 consistent at stack depth 2
ok 11 - check frame height 6 consistent at stack depth 2
ok 12 - check frame height 0 consistent at stack depth 3
ok 13 - check frame height 1 consistent at stack depth 3
ok 14 - check frame height 2 consistent at stack depth 3
ok 15 - check frame height 3 consistent at stack depth 3
ok 16 - check frame height 4 consistent at stack depth 3
ok 17 - check frame height 5 consistent at stack depth 3
ok 18 - check frame height 6 consistent at stack depth 3
ok 19 - check frame height 7 consistent at stack depth 3
ok 20 - check frame height 8 consistent at stack depth 3
ok 21 - check frame height 9 consistent at stack depth 3
ok 22 - check frame height 0 consistent at stack depth 4
ok 23 - check frame height 1 consistent at stack depth 4
ok 24 - check frame height 2 consistent at stack depth 4
ok 25 - check frame height 3 consistent at stack depth 4
ok 26 - check frame height 4 consistent at stack depth 4
ok 27 - check frame height 5 consistent at stack depth 4
ok 28 - check frame height 6 consistent at stack depth 4
ok 29 - check frame height 7 consistent at stack depth 4
ok 30 - check frame height 8 consistent at stack depth 4
ok 31 - check frame height 9 consistent at stack depth 4
ok 32 - check frame height 10 consistent at stack depth 4
ok 33 - check frame height 11 consistent at stack depth 4
ok 34 - check frame height 12 consistent at stack depth 4
ok 35 - check frame height 0 consistent at stack depth 5
ok 36 - check frame height 1 consistent at stack depth 5
ok 37 - check frame height 2 consistent at stack depth 5
ok 38 - check frame height 3 consistent at stack depth 5
ok 39 - check frame height 4 consistent at stack depth 5
ok 40 - check frame height 5 consistent at stack depth 5
ok 41 - check frame height 6 consistent at stack depth 5
ok 42 - check frame height 7 consistent at stack depth 5
ok 43 - check frame height 8 consistent at stack depth 5
ok 44 - check frame height 9 consistent at stack depth 5
ok 45 - check frame height 10 consistent at stack depth 5
ok 46 - check frame height 11 consistent at stack depth 5
ok 47 - check frame height 12 consistent at stack depth 5
ok 48 - check frame height 13 consistent at stack depth 5
ok 49 - check frame height 14 consistent at stack depth 5
ok 50 - check frame height 15 consistent at stack depth 5
1..50
Without this PR:
$ perl t_stack.pl
ok 1 - check frame height 0 consistent at stack depth 1
not ok 2 - check frame height 1 consistent at stack depth 1
# Failed test 'check frame height 1 consistent at stack depth 1'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod1.pm line 2'
# expected: ' eval {...} called at lib/Mod0.pm line 2'
not ok 3 - check frame height 2 consistent at stack depth 1
# Failed test 'check frame height 2 consistent at stack depth 1'
# at t_stack.pl line 28.
# got: ' main::BEGIN() called at lib/Mod1.pm line 2'
# expected: ' main::BEGIN() called at lib/Mod0.pm line 2'
ok 4 - check frame height 3 consistent at stack depth 1
ok 5 - check frame height 0 consistent at stack depth 2
not ok 6 - check frame height 1 consistent at stack depth 2
# Failed test 'check frame height 1 consistent at stack depth 2'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod2.pm line 2'
# expected: ' eval {...} called at lib/Mod1.pm line 2'
not ok 7 - check frame height 2 consistent at stack depth 2
# Failed test 'check frame height 2 consistent at stack depth 2'
# at t_stack.pl line 28.
# got: ' main::BEGIN() called at lib/Mod2.pm line 2'
# expected: ' main::BEGIN() called at lib/Mod1.pm line 2'
ok 8 - check frame height 3 consistent at stack depth 2
not ok 9 - check frame height 4 consistent at stack depth 2
# Failed test 'check frame height 4 consistent at stack depth 2'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod2.pm line 2'
# expected: ' eval {...} called at lib/Mod1.pm line 2'
not ok 10 - check frame height 5 consistent at stack depth 2
# Failed test 'check frame height 5 consistent at stack depth 2'
# at t_stack.pl line 28.
# got: ' Mod0::BEGIN() called at lib/Mod2.pm line 2'
# expected: ' Mod0::BEGIN() called at lib/Mod1.pm line 2'
ok 11 - check frame height 6 consistent at stack depth 2
ok 12 - check frame height 0 consistent at stack depth 3
not ok 13 - check frame height 1 consistent at stack depth 3
# Failed test 'check frame height 1 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod3.pm line 2'
# expected: ' eval {...} called at lib/Mod2.pm line 2'
not ok 14 - check frame height 2 consistent at stack depth 3
# Failed test 'check frame height 2 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' main::BEGIN() called at lib/Mod3.pm line 2'
# expected: ' main::BEGIN() called at lib/Mod2.pm line 2'
ok 15 - check frame height 3 consistent at stack depth 3
not ok 16 - check frame height 4 consistent at stack depth 3
# Failed test 'check frame height 4 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod3.pm line 2'
# expected: ' eval {...} called at lib/Mod2.pm line 2'
not ok 17 - check frame height 5 consistent at stack depth 3
# Failed test 'check frame height 5 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' Mod0::BEGIN() called at lib/Mod3.pm line 2'
# expected: ' Mod0::BEGIN() called at lib/Mod2.pm line 2'
ok 18 - check frame height 6 consistent at stack depth 3
not ok 19 - check frame height 7 consistent at stack depth 3
# Failed test 'check frame height 7 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod3.pm line 2'
# expected: ' eval {...} called at lib/Mod2.pm line 2'
not ok 20 - check frame height 8 consistent at stack depth 3
# Failed test 'check frame height 8 consistent at stack depth 3'
# at t_stack.pl line 28.
# got: ' Mod1::BEGIN() called at lib/Mod3.pm line 2'
# expected: ' Mod1::BEGIN() called at lib/Mod2.pm line 2'
ok 21 - check frame height 9 consistent at stack depth 3
ok 22 - check frame height 0 consistent at stack depth 4
not ok 23 - check frame height 1 consistent at stack depth 4
# Failed test 'check frame height 1 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod4.pm line 2'
# expected: ' eval {...} called at lib/Mod3.pm line 2'
not ok 24 - check frame height 2 consistent at stack depth 4
# Failed test 'check frame height 2 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' main::BEGIN() called at lib/Mod4.pm line 2'
# expected: ' main::BEGIN() called at lib/Mod3.pm line 2'
ok 25 - check frame height 3 consistent at stack depth 4
not ok 26 - check frame height 4 consistent at stack depth 4
# Failed test 'check frame height 4 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod4.pm line 2'
# expected: ' eval {...} called at lib/Mod3.pm line 2'
not ok 27 - check frame height 5 consistent at stack depth 4
# Failed test 'check frame height 5 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' Mod0::BEGIN() called at lib/Mod4.pm line 2'
# expected: ' Mod0::BEGIN() called at lib/Mod3.pm line 2'
ok 28 - check frame height 6 consistent at stack depth 4
not ok 29 - check frame height 7 consistent at stack depth 4
# Failed test 'check frame height 7 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod4.pm line 2'
# expected: ' eval {...} called at lib/Mod3.pm line 2'
not ok 30 - check frame height 8 consistent at stack depth 4
# Failed test 'check frame height 8 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' Mod1::BEGIN() called at lib/Mod4.pm line 2'
# expected: ' Mod1::BEGIN() called at lib/Mod3.pm line 2'
ok 31 - check frame height 9 consistent at stack depth 4
not ok 32 - check frame height 10 consistent at stack depth 4
# Failed test 'check frame height 10 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod4.pm line 2'
# expected: ' eval {...} called at lib/Mod3.pm line 2'
not ok 33 - check frame height 11 consistent at stack depth 4
# Failed test 'check frame height 11 consistent at stack depth 4'
# at t_stack.pl line 28.
# got: ' Mod2::BEGIN() called at lib/Mod4.pm line 2'
# expected: ' Mod2::BEGIN() called at lib/Mod3.pm line 2'
ok 34 - check frame height 12 consistent at stack depth 4
ok 35 - check frame height 0 consistent at stack depth 5
not ok 36 - check frame height 1 consistent at stack depth 5
# Failed test 'check frame height 1 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod5.pm line 2'
# expected: ' eval {...} called at lib/Mod4.pm line 2'
not ok 37 - check frame height 2 consistent at stack depth 5
# Failed test 'check frame height 2 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' main::BEGIN() called at lib/Mod5.pm line 2'
# expected: ' main::BEGIN() called at lib/Mod4.pm line 2'
ok 38 - check frame height 3 consistent at stack depth 5
not ok 39 - check frame height 4 consistent at stack depth 5
# Failed test 'check frame height 4 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod5.pm line 2'
# expected: ' eval {...} called at lib/Mod4.pm line 2'
not ok 40 - check frame height 5 consistent at stack depth 5
# Failed test 'check frame height 5 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' Mod0::BEGIN() called at lib/Mod5.pm line 2'
# expected: ' Mod0::BEGIN() called at lib/Mod4.pm line 2'
ok 41 - check frame height 6 consistent at stack depth 5
not ok 42 - check frame height 7 consistent at stack depth 5
# Failed test 'check frame height 7 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod5.pm line 2'
# expected: ' eval {...} called at lib/Mod4.pm line 2'
not ok 43 - check frame height 8 consistent at stack depth 5
# Failed test 'check frame height 8 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' Mod1::BEGIN() called at lib/Mod5.pm line 2'
# expected: ' Mod1::BEGIN() called at lib/Mod4.pm line 2'
ok 44 - check frame height 9 consistent at stack depth 5
not ok 45 - check frame height 10 consistent at stack depth 5
# Failed test 'check frame height 10 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod5.pm line 2'
# expected: ' eval {...} called at lib/Mod4.pm line 2'
not ok 46 - check frame height 11 consistent at stack depth 5
# Failed test 'check frame height 11 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' Mod2::BEGIN() called at lib/Mod5.pm line 2'
# expected: ' Mod2::BEGIN() called at lib/Mod4.pm line 2'
ok 47 - check frame height 12 consistent at stack depth 5
not ok 48 - check frame height 13 consistent at stack depth 5
# Failed test 'check frame height 13 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' eval {...} called at lib/Mod5.pm line 2'
# expected: ' eval {...} called at lib/Mod4.pm line 2'
not ok 49 - check frame height 14 consistent at stack depth 5
# Failed test 'check frame height 14 consistent at stack depth 5'
# at t_stack.pl line 28.
# got: ' Mod3::BEGIN() called at lib/Mod5.pm line 2'
# expected: ' Mod3::BEGIN() called at lib/Mod4.pm line 2'
ok 50 - check frame height 15 consistent at stack depth 5
1..50
# Looks like you failed 30 tests of 50.
I think it incumbent on anyone objecting to this PR to either provide an alternative solution, or provide a compelling reason why this test isn't reasonable. Surely we all accept that the stack should stay consistent as we go deeper as we look at it at different levels? It seems to me to be absurd to argue otherwise.
Furthermore on this I checked into the failure in DBIx::Class. It would seem that t/53lean_startup.t uses a set of heuristics (which aren't entirely clear to me) to notice what plug ins are being loaded. The old behavior of caller() meant that those heuristics started noticing that Class::C3::Componentised is loading a module, MRO::Compat, which it has been loading all along. The solution is pretty simple:
commit df052966ad4c29f4eb745fd8129a2a80e66c4387 (HEAD -> master)
Author: Yves Orton <[email protected]>
Date: Sat Feb 13 13:12:22 2021 +0100
Ignore MRO::Compat
In newer perls various bugs related to use statements and how
caller reports them have been fixed. This means that our heuristics
now notice a dependency of Class::C3::Componentised that it has
been loading for some time, MRO::Compat, but which due to the bugs
in caller() and the heuristics in t/53lean_startup.t was not registered
as a valid plug in.
diff --git a/t/53lean_startup.t b/t/53lean_startup.t
index 9a4ef85..6b7216f 100644
--- a/t/53lean_startup.t
+++ b/t/53lean_startup.t
@@ -136,6 +136,7 @@ BEGIN {
Class::Accessor::Grouped
Class::C3::Componentised
+ MRO::Compat
SQL::Abstract::Util
));
After applying this patch the test pass. It seems to me that the reality is the test code is making faulty assumptions in the first place since it seems it failed to notice this before, even though it was indeed being loaded. The stack frame counter variable $up changes from 3 to 13 in the old to new code because in the old code it thinks the BEGIN block is called from main, but it not, the BEGIN is executed in package Class::C3::Componentized, so with a fixed caller() the heuristic no longer gets confused and notices what it should have noticed in the first place. I dont really understand the strategy employed in this test file. If i was testing this I wouldn't do any of this crazy stack walking. I would just track what was required() and then later check to see that it doesn't contain anything I don't expect, without any heuristics about the stack. The stack contains unreliable data and the code doesn't detect when that data is not reliable nor do anything about it. It is a very error prone strategy. GIGO.
@demerphq is this PR closable? It looks like the collective unreversion has since been applied by f6387cff9c.
@demerphq is this PR closable? It looks like the collective unreversion has since been applied by f6387cf.
@demerphq, as @hvds asked: Is this p.r. closable? If it should remain open, can you resolve merge conflicts so @iabyn can review?
Thank you very much.
Sorr
On Fri, 16 Sept 2022, 23:40 James E Keenan, @.***> wrote:
@demerphq https://github.com/demerphq is this PR closable? It looks like the collective unreversion has since been applied by f6387cf https://github.com/Perl/perl5/commit/f6387cff9cb31db4cf18c8641917ea4639ac2b65 .
@demerphq https://github.com/demerphq, as @hvds https://github.com/hvds asked: Is this p.r. closable? If it should remain open, can you resolve merge conflicts so @iabyn https://github.com/iabyn can
Sorry i won't be able to review this properly until Thursday. If anyone wants to do their own check please do. I thought this was all merged already tho...
Yves
If it is required, I could check how it works on recent perl's.
That would be appreciated, as it would permit us, once blead is modified, to consider a backport to the maintenance branch of 5.36 (and maybe 5.34).
I am closing this ticket. The fix was finally applied in the 5.35.x and released in 5.36. Thanks for the report confirming this @KES777