Skip to content

Smoke me/fix caller issues #18568

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
wants to merge 3 commits into from
Closed

Smoke me/fix caller issues #18568

wants to merge 3 commits into from

Conversation

demerphq
Copy link
Collaborator

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.

@demerphq demerphq requested a review from iabyn February 13, 2021 09:08
@demerphq
Copy link
Collaborator Author

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.

@demerphq
Copy link
Collaborator Author

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.

@demerphq
Copy link
Collaborator Author

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.

@hvds
Copy link
Contributor

hvds commented Mar 3, 2022

@demerphq is this PR closable? It looks like the collective unreversion has since been applied by f6387cf.

@jkeenan
Copy link
Contributor

jkeenan commented Sep 16, 2022

@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.

@jkeenan jkeenan added the Closable? We might be able to close this ticket, but we need to check with the reporter label Sep 16, 2022
@KES777
Copy link
Contributor

KES777 commented Sep 17, 2022

If it is required, I could check how it works on recent perl's.

@demerphq
Copy link
Collaborator Author

demerphq commented Sep 17, 2022 via email

@jkeenan
Copy link
Contributor

jkeenan commented Sep 17, 2022

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).

@KES777
Copy link
Contributor

KES777 commented Dec 6, 2022

@jkeenan Done. See here

perl-5.36.0 and perl-5.37.6 works as expected, but 5.34.1 does not.

@demerphq
Copy link
Collaborator Author

demerphq commented Dec 6, 2022

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

@demerphq demerphq closed this Dec 6, 2022
@demerphq demerphq deleted the smoke-me/fix_caller_issues branch December 6, 2022 15:00
@demerphq demerphq removed Closable? We might be able to close this ticket, but we need to check with the reporter hasConflicts labels Dec 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@iabyn iabyn Awaiting requested review from iabyn

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
4 participants
@demerphq @hvds @jkeenan @KES777