I was trying to write some unit tests for a module that makes use of code attributes via Attribute::Handlers. Because of the way that the attributes might interact with child functions I wanted to run through a set of three nested subs with each combination of with and without attributes (so eight tests total). I wrote it with three loops using string eval to redefine the functions each iteration.
The original code made use of the function name, derived via *{$symbol}{NAME} and what I noticed was that sometimes the function name did not match up with the sub that had the attribute defined on it. It is predictable (not really -- see example at the bottom) and repeatable, but I don't understand why it's happening. I don't even really understand what is happening. The pattern, as I can see it, is that when a given function changes from with-attribute to without-attribute, the function following the one that lost the attribute has it's symbol name switch to the function that lost the attribute.
For example, if I have three functions, foo, bar, and baz, where all three have the attribute in one iteration, and the middle one loses the attribute in the next iteration, the symbol names get reported as foo and bar even though the attributes are on foo and baz.
NOTE: that's not really the pattern -- see the example at the bottom.
Here's the stripped down code with some added debug statements:
#!/usr/bin/env perl
use strict;
use warnings;
use 5.036;
use Attribute::Handlers;
sub TestAttr : ATTR(CODE)
{
foreach my $arg (@_) { $arg //= ""; print "<$arg> "; }; print "\n";
my ($package, $symbol, $referent, $attr, $data, $phase, $filename, $linenum) = @_;
my $function_name = *{$symbol}{NAME};
say("FN: $function_name / $referent / $symbol / @$data");
return;
}
my($sub_def_str) = <<EOS;
no warnings qw(redefine);
sub foo :FooAttr { }
sub bar :BarAttr { }
sub baz :BazAttr { }
EOS
foreach my $foo (":TestAttr(xFOO)", "") {
foreach my $bar (":TestAttr(xBAR)", "") {
foreach my $baz (":TestAttr(xBAZ)", "") {
my($newdef) = "$sub_def_str";
$newdef =~ s{ :FooAttr}{ $foo}g;
$newdef =~ s{ :BarAttr}{ $bar}g;
$newdef =~ s{ :BazAttr}{ $baz}g;
say("---------");
say("<$newdef>");
eval "$newdef";
die $@ if $@;
}
}
}
The first two iterations run fine:
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c00e6e0)> <TestAttr> <ARRAY(0x7f835c026888)> <CHECK> <(eval 5)> <3>
FN: foo / CODE(0x7f835c00e6e0) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c00e668)> <TestAttr> <ARRAY(0x7f835c00e698)> <CHECK> <(eval 5)> <4>
FN: bar / CODE(0x7f835c00e668) / GLOB(0x7f835d808db8) / xBAR
<main> <GLOB(0x7f835c815718)> <CODE(0x7f835d808d70)> <TestAttr> <ARRAY(0x7f835c82e798)> <CHECK> <(eval 5)> <5>
FN: baz / CODE(0x7f835d808d70) / GLOB(0x7f835c815718) / xBAZ
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c839348)> <TestAttr> <ARRAY(0x7f835c810980)> <CHECK> <(eval 9)> <3>
FN: foo / CODE(0x7f835c839348) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835d808dd0)> <TestAttr> <ARRAY(0x7f835c810908)> <CHECK> <(eval 9)> <4>
FN: bar / CODE(0x7f835d808dd0) / GLOB(0x7f835d808db8) / xBAR
but the third one shows the issue:
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c810800)> <TestAttr> <ARRAY(0x7f835c025df0)> <CHECK> <(eval 12)> <3>
FN: foo / CODE(0x7f835c810800) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c810920)> <TestAttr> <ARRAY(0x7f835c810938)> <CHECK> <(eval 12)> <5>
FN: bar / CODE(0x7f835c810920) / GLOB(0x7f835d808db8) / xBAZ
The attribute is on baz as shown by the data (xBAZ) and the line number (5), but the symbol name is reported as bar. The same thing would have probably happened in the second iteration had there been a fourth sub. Here's the whole output (all 8 iterations):
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c00e6e0)> <TestAttr> <ARRAY(0x7f835c026888)> <CHECK> <(eval 5)> <3>
FN: foo / CODE(0x7f835c00e6e0) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c00e668)> <TestAttr> <ARRAY(0x7f835c00e698)> <CHECK> <(eval 5)> <4>
FN: bar / CODE(0x7f835c00e668) / GLOB(0x7f835d808db8) / xBAR
<main> <GLOB(0x7f835c815718)> <CODE(0x7f835d808d70)> <TestAttr> <ARRAY(0x7f835c82e798)> <CHECK> <(eval 5)> <5>
FN: baz / CODE(0x7f835d808d70) / GLOB(0x7f835c815718) / xBAZ
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c839348)> <TestAttr> <ARRAY(0x7f835c810980)> <CHECK> <(eval 9)> <3>
FN: foo / CODE(0x7f835c839348) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835d808dd0)> <TestAttr> <ARRAY(0x7f835c810908)> <CHECK> <(eval 9)> <4>
FN: bar / CODE(0x7f835d808dd0) / GLOB(0x7f835d808db8) / xBAR
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c810800)> <TestAttr> <ARRAY(0x7f835c025df0)> <CHECK> <(eval 12)> <3>
FN: foo / CODE(0x7f835c810800) / GLOB(0x7f835c00e5d8) / xFOO
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c810920)> <TestAttr> <ARRAY(0x7f835c810938)> <CHECK> <(eval 12)> <5>
FN: bar / CODE(0x7f835c810920) / GLOB(0x7f835d808db8) / xBAZ
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar { }
sub baz { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c00dcf0)> <TestAttr> <ARRAY(0x7f835d808a88)> <CHECK> <(eval 15)> <3>
FN: foo / CODE(0x7f835c00dcf0) / GLOB(0x7f835c00e5d8) / xFOO
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835c00e5d8)> <CODE(0x7f835c815ef8)> <TestAttr> <ARRAY(0x7f835c8109c8)> <CHECK> <(eval 17)> <4>
FN: foo / CODE(0x7f835c815ef8) / GLOB(0x7f835c00e5d8) / xBAR
<main> <GLOB(0x7f835c815718)> <CODE(0x7f835d808f50)> <TestAttr> <ARRAY(0x7f835c0260d8)> <CHECK> <(eval 17)> <5>
FN: baz / CODE(0x7f835d808f50) / GLOB(0x7f835c815718) / xBAZ
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c815ef8)> <TestAttr> <ARRAY(0x7f835c810620)> <CHECK> <(eval 20)> <4>
FN: bar / CODE(0x7f835c815ef8) / GLOB(0x7f835d808db8) / xBAR
---------
< no warnings qw(redefine);
sub foo { }
sub bar { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f835d808db8)> <CODE(0x7f835c00e6c8)> <TestAttr> <ARRAY(0x7f835d808a88)> <CHECK> <(eval 22)> <5>
FN: bar / CODE(0x7f835c00e6c8) / GLOB(0x7f835d808db8) / xBAZ
---------
< no warnings qw(redefine);
sub foo { }
sub bar { }
sub baz { }
>
On a whim I switched the middle iteration from ON/OFF to OFF/ON, and the pattern stayed the same except in the final iteration. So my loops change to this:
foreach my $foo (":TestAttr(xFOO)", "") {
foreach my $bar ("", ":TestAttr(xBAR)") {
foreach my $baz (":TestAttr(xBAZ)", "") {
and the final two iterations look like this:
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f8750819b70)> <CODE(0x7f8750812378)> <TestAttr> <ARRAY(0x7f8750818c30)> <CHECK> <(eval 20)> <4>
FN: bar / CODE(0x7f8750812378) / GLOB(0x7f8750819b70) / xBAR
<main> <GLOB(0x7f8750819bd0)> <CODE(0x7f8752018948)> <TestAttr> <ARRAY(0x7f8750855580)> <CHECK> <(eval 20)> <5>
FN: baz / CODE(0x7f8752018948) / GLOB(0x7f8750819bd0) / xBAZ
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f8750828090)> <TestAttr> <ARRAY(0x7f875086ab20)> <CHECK> <(eval 23)> <4>
FN: foo / CODE(0x7f8750828090) / GLOB(0x7f8750012fd8) / xBAR
The foo sub didn't lose its attribute yet the bar function name is showing up as foo, so now I'm truly lost.
The full output with the switched middle iteration is:
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f87500130e0)> <TestAttr> <ARRAY(0x7f8750812378)> <CHECK> <(eval 5)> <3>
FN: foo / CODE(0x7f87500130e0) / GLOB(0x7f8750012fd8) / xFOO
<main> <GLOB(0x7f8750819bd0)> <CODE(0x7f8750819d50)> <TestAttr> <ARRAY(0x7f875086ab08)> <CHECK> <(eval 5)> <5>
FN: baz / CODE(0x7f8750819d50) / GLOB(0x7f8750819bd0) / xBAZ
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar { }
sub baz { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f87500130c8)> <TestAttr> <ARRAY(0x7f875086abc8)> <CHECK> <(eval 8)> <3>
FN: foo / CODE(0x7f87500130c8) / GLOB(0x7f8750012fd8) / xFOO
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f87508188e8)> <TestAttr> <ARRAY(0x7f875086ab38)> <CHECK> <(eval 10)> <3>
FN: foo / CODE(0x7f87508188e8) / GLOB(0x7f8750012fd8) / xFOO
<main> <GLOB(0x7f8750819b70)> <CODE(0x7f8750013098)> <TestAttr> <ARRAY(0x7f8750013248)> <CHECK> <(eval 10)> <4>
FN: bar / CODE(0x7f8750013098) / GLOB(0x7f8750819b70) / xBAR
<main> <GLOB(0x7f8750819bd0)> <CODE(0x7f8750828930)> <TestAttr> <ARRAY(0x7f875086ac28)> <CHECK> <(eval 10)> <5>
FN: baz / CODE(0x7f8750828930) / GLOB(0x7f8750819bd0) / xBAZ
---------
< no warnings qw(redefine);
sub foo :TestAttr(xFOO) { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f8750819c90)> <TestAttr> <ARRAY(0x7f875086b108)> <CHECK> <(eval 14)> <3>
FN: foo / CODE(0x7f8750819c90) / GLOB(0x7f8750012fd8) / xFOO
<main> <GLOB(0x7f8750819b70)> <CODE(0x7f87500126c0)> <TestAttr> <ARRAY(0x7f8752009b98)> <CHECK> <(eval 14)> <4>
FN: bar / CODE(0x7f87500126c0) / GLOB(0x7f8750819b70) / xBAR
---------
< no warnings qw(redefine);
sub foo { }
sub bar { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f8750819b70)> <CODE(0x7f8750819c90)> <TestAttr> <ARRAY(0x7f875086ac28)> <CHECK> <(eval 17)> <5>
FN: bar / CODE(0x7f8750819c90) / GLOB(0x7f8750819b70) / xBAZ
---------
< no warnings qw(redefine);
sub foo { }
sub bar { }
sub baz { }
>
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz :TestAttr(xBAZ) { }
>
<main> <GLOB(0x7f8750819b70)> <CODE(0x7f8750812378)> <TestAttr> <ARRAY(0x7f8750818c30)> <CHECK> <(eval 20)> <4>
FN: bar / CODE(0x7f8750812378) / GLOB(0x7f8750819b70) / xBAR
<main> <GLOB(0x7f8750819bd0)> <CODE(0x7f8752018948)> <TestAttr> <ARRAY(0x7f8750855580)> <CHECK> <(eval 20)> <5>
FN: baz / CODE(0x7f8752018948) / GLOB(0x7f8750819bd0) / xBAZ
---------
< no warnings qw(redefine);
sub foo { }
sub bar :TestAttr(xBAR) { }
sub baz { }
>
<main> <GLOB(0x7f8750012fd8)> <CODE(0x7f8750828090)> <TestAttr> <ARRAY(0x7f875086ab20)> <CHECK> <(eval 23)> <4>
FN: foo / CODE(0x7f8750828090) / GLOB(0x7f8750012fd8) / xBAR
Can anyone explain what is happening?
Attribute::Handlers uses a cache for symbol lookups in A::H::findsym(). There seems to be a problem with redefinitions of subs not invalidating the cache. If I comment out line 12 in Attribute::Handlers:
# return $symcache{$pkg,$ref} if $symcache{$pkg,$ref};
everything works as expected.