Caller inside BEGIN block return wrong info #15109

p5pRT · 2015-12-30T12:30:57Z

Migrated from rt.perl.org#127083 (status was 'open')

Searchable as RT127083$

p5pRT · 2015-12-30T12:30:59Z

From @KES777

Created by @KES777

$cat t.pl
#!/usr/bin/env perl

BEGIN {
local $" = ' - ';
my $level = 0;
while( my @frame = caller( $level++ ) ) {
print "@frame[0..3]\n";
}
print "\n";
}

use Mod2;

$cat Mod2.pm
package Mod2;
#2
#3
#4
BEGIN {
local $" = ' - ';
my $level = 0;
while( my @frame = caller( $level++ ) ) {
print "@frame[0..3]\n";
}
print "\n";
}

use Mod1;

1;

$cat Mod1.pm
package Mod1;
#2
#3
#4
#5
#6
BEGIN {
local $" = ' - ';
my $level = 0;
while( my @frame = caller( $level++ ) ) {
print "@frame[0..3]\n";
}
print "\n";
}

1;

The output is:
main - ./t.pl - 10 - main::BEGIN
main - ./t.pl - 10 - (eval)

main - Mod2.pm - 12 - Mod2::BEGIN
main - Mod2.pm - 12 - (eval)
main - ./t.pl - 12 - (eval)
main - Mod2.pm - 12 - main::BEGIN
main - Mod2.pm - 12 - (eval)

main - Mod1.pm - 14 - Mod1::BEGIN
main - Mod1.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - (eval)
main - Mod1.pm - 14 - Mod2::BEGIN
main - Mod1.pm - 14 - (eval)
main - ./t.pl - 12 - (eval)
main - Mod1.pm - 14 - main::BEGIN
main - Mod1.pm - 14 - (eval)

It is not expected that the information about last frames is changed.
I think that the call to 'caller' from Mod1 should look like:
main - Mod1.pm - 14 - Mod1::BEGIN
main - Mod1.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - (eval)
main - Mod2.pm - 12 - Mod2::BEGIN
main - Mod2.pm - 12 - (eval)
main - ./t.pl - 12 - (eval)
main - ./t.pl - 10 - main::BEGIN
main - ./t.pl - 10 - (eval)

Perl Info


Flags:
    category=core
    severity=low

Site configuration information for perl 5.22.0:

Configured by kes at Tue Sep 29 16:12:55 EEST 2015.

Summary of my perl5 (revision 5 version 22 subversion 0) configuration:
   
  Platform:
    osname=linux, osvers=3.13.0-37-generic, archname=x86_64-linux
    uname='linux keswork 3.13.0-37-generic #64-ubuntu smp mon sep 22 21:28:38 utc 2014 x86_64 x86_64 x86_64 gnulinux '
    config_args='-des -Dprefix=/home/kes/perl'
    hint=recommended, useposix=true, d_sigaction=define
    useithreads=undef, usemultiplicity=undef
    use64bitint=define, use64bitall=define, uselongdouble=undef
    usemymalloc=n, bincompat5005=undef
  Compiler:
    cc='cc', ccflags ='-fwrapv -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
    optimize='-O2',
    cppflags='-fwrapv -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include'
    ccversion='', gccversion='4.8.4', gccosandvers=''
    intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678, doublekind=3
    d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16, longdblkind=3
    ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8
    alignbytes=8, prototype=define
  Linker and Libraries:
    ld='cc', ldflags =' -fstack-protector -L/usr/local/lib'
    libpth=/usr/local/lib /usr/lib/gcc/x86_64-linux-gnu/4.8/include-fixed /usr/include/x86_64-linux-gnu /usr/lib /lib/x86_64-linux-gnu /lib/../lib /usr/lib/x86_64-linux-gnu /usr/lib/../lib /lib
    libs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
    perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
    libc=libc-2.19.so, so=so, useshrplib=false, libperl=libperl.a
    gnulibc_version='2.19'
  Dynamic Linking:
    dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E'
    cccdlflags='-fPIC', lddlflags='-shared -O2 -L/usr/local/lib -fstack-protector'



@INC for perl 5.22.0:
    /home/kes/work/projects/perl_libs/lib
    /home/kes/perl5/lib/perl5/x86_64-linux
    /home/kes/perl5/lib/perl5
    /home/kes/perl/lib/site_perl/5.22.0/x86_64-linux
    /home/kes/perl/lib/site_perl/5.22.0
    /home/kes/perl/lib/5.22.0/x86_64-linux
    /home/kes/perl/lib/5.22.0
    .


Environment for perl 5.22.0:
    HOME=/home/kes
    LANG=ru_UA.UTF-8
    LANGUAGE=en
    LC_MESSAGES=en_US.UTF-8
    LD_LIBRARY_PATH (unset)
    LOGDIR (unset)
    PATH=/home/kes/perl/bin:/home/kes/perl/bin:/home/kes/perl5/bin:/home/kes/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games
    PERL5DB=BEGIN { require "Devel/KillPrint.pm" }
    PERL5LIB=/home/kes/work/projects/perl_libs/lib:/home/kes/perl5/lib/perl5
    PERLDB_OPTS=RemotePort=keswork:9001
    PERL_BADLANG (unset)
    PERL_MB_OPT=--install_base "/home/kes/perl5"
    PERL_MM_OPT=INSTALL_BASE=/home/kes/perl5
    SHELL=/bin/bash

p5pRT · 2016-01-06T16:30:35Z

From @iabyn

On Wed, Dec 30, 2015 at 04:31:01AM -0800, KES wrote:

It is not expected that the information about last frames is changed.
I think that the call to 'caller' from Mod1 should look like:

Here's a slightly simplified example that only requires a single module:

Mod.pm:

package Mod;
BEGIN {
print "MOD BEGIN: ", ::top_call(), "\n";
}
print "MOD: ", ::top_call(), "\n";

/tmp/t:

#return file and line of top-most level call site
sub top_call {
my $i = 0;
my $where;
while(my @c = caller($i++)) {
$where = "$c[1]:$c[2]";
}
$where;
}

BEGIN {
print "MAIN BEGIN: ", ::top_call(), "\n";
require Mod;
}

sub f { print "f(): ", ::top_call(), "\n"; }
f();

This code prints the outermost call-site at various places. It outputs:

MAIN BEGIN: /tmp/t:16
MOD BEGIN: /tmp/Mod.pm:4
MOD: /tmp/Mod.pm:0
f(): /tmp/t:19

I'd expect the middle two to be

MOD BEGIN: /tmp/t:16
MOD: /tmp/t:16

instead, since they're both called from the BEGIN in /tmp/t.

Still present in blead.

--
O Unicef Clearasil!
Gibberish and Drivel!
-- "Bored of the Rings"

p5pRT · 2016-01-06T16:30:35Z

The RT System itself - Status changed from 'new' to 'open'

GH #15109 The output of caller() (e.g. as produced by carp::Confess) produces multiple identical outputs when within a nested use/require. This is because at the time of calling the 'BEGIN { require ... }', PL_curcop is set to &PL_compiling, which is a fixed buffer within the interpreter, whose individual file and line fields are saved and restored when doing a new require/eval. This means that within the innermost require, PL_compiling has file:lineno of the innermost source file, and multiple saved PL_curcop values in the context stack frames all point to the same &PL_copmpiling. So all levels of the stack trace appear to come from the innermost file. This commit fixes this (after a fashion) by, at the start of calling a BEGIN, making PL_curcop point to a temporary copy of PL_compiling instead. This is all a bit of a hack.

atoomic · 2019-12-20T21:04:55Z

@iabyn was this fixed by f2f32cd and so we can close this case?

iabyn · 2019-12-25T18:02:27Z

Yes, this commit fixed the issue.

haarg · 2020-01-02T17:06:53Z

This change broke my module Devel::CompileLevel. The module works by modifying ${^WARNING_BITS}, then trying to detect those changes using the warnings bitmask returned by caller. Although this is a bit weird, it does seem like a reasonable thing to expect to work. The module doesn't have any users that I know of though.

iabyn · 2020-01-03T10:53:32Z

On Thu, Jan 02, 2020 at 09:06:54AM -0800, Graham Knop wrote: This change broke my module [Devel::CompileLevel] (https://metacpan.org/pod/Devel::CompileLevel). The module works by modifying `${^WARNING_BITS}`, then trying to detect those changes using the warnings bitmask returned by `caller`. Although this is a bit weird, it does seem like a reasonable thing to expect to work. The module doesn't have any users that I know of though.

As far as I can see your module was exploiting a bug which my change fixed. The caller() function is documented to return the hints "that the caller was compiled with". Since the chain of BEGIN and/or import() subs that you are scanning back over have all been compiled, it's actually a bug if changing ${^WARNING_BITS} changes what caller() reports. In addition, caller()'s docs say that "the $hints and $bitmask values are subject to change between versions of Perl, and are not meant for external use". So all in all, I'm sanguine about this change.

…

-- "You may not work around any technical limitations in the software" -- Windows Vista license

haarg · 2020-01-03T12:03:00Z

The location it's detecting is not a BEGIN or import, but the level just beyond the closest BEGIN. That level hasn't finished compiling yet. The module isn't depending on $bitmask having any specific value, only that it matches ${^WARNING_BITS} as the docs claim it will. And the value isn't being reused for anything external. So I don't think that part of the caller docs are particularly relevant.

I'm not particularly attached to the module though.

GH #15109 The output of caller() (e.g. as produced by carp::Confess) produces multiple identical outputs when within a nested use/require. This is because at the time of calling the 'BEGIN { require ... }', PL_curcop is set to &PL_compiling, which is a fixed buffer within the interpreter, whose individual file and line fields are saved and restored when doing a new require/eval. This means that within the innermost require, PL_compiling has file:lineno of the innermost source file, and multiple saved PL_curcop values in the context stack frames all point to the same &PL_copmpiling. So all levels of the stack trace appear to come from the innermost file. This commit fixes this (after a fashion) by, at the start of calling a BEGIN, making PL_curcop point to a temporary copy of PL_compiling instead. This is all a bit of a hack. (cherry picked from commit f2f32cd)

GH #15109, #17567 My original fix for this issue, v5.31.6-141-gf2f32cd638 made a shallow copy of &PL_compiling. However, for non-default warning bits, this made two COPs share the malloced() cop_warnings, and bad things ensured. In particular this was flagged up in: GH #17567: "BBC: AYOUNG/OpenVZ-0.01.tar.gz" The fix in this commit is to do a deep copy of the COP using newSTATEOP().

GH #15109, #17567 [ this commit was originally applied as v5.31.9-121-gfb8188b84d, but was quickly reverted by v5.31.9-124-g6311900a66. I'm now -re-applying it, but with a 'SAVEFREEOP(PL_curcop)' added, which was missing from the original commit. ] My original fix for this issue, v5.31.6-141-gf2f32cd638 made a shallow copy of &PL_compiling. However, for non-default warning bits, this made two COPs share the malloced() cop_warnings, and bad things ensured. In particular this was flagged up in: GH #17567: "BBC: AYOUNG/OpenVZ-0.01.tar.gz" The fix in this commit is to do a deep copy of the COP using newSTATEOP().

demerphq · 2022-01-13T04:58:55Z

This ticket should be reopened as f2f32cd was reverted. Yves

…

On Fri, 20 Dec 2019 at 22:04, Nicolas R. ***@***.***> wrote: @iabyn <https://github.com/iabyn> was this fixed by f2f32cd <f2f32cd> and so we can close this case? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#15109?email_source=notifications&email_token=AAAZ5R5KLTYZJRK53SLQSYDQZUXPTA5CNFSM4J6CUVFKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHOFF5I#issuecomment-568087285>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAZ5RZYPO4KQKRC42XQS6TQZUXPTANCNFSM4J6CUVFA> .

-- perl -Mre=debug -e "/just|another|perl|hacker/"

This reapplies two reverted patches as a single squashed commit. Revert "Revert "avoid identical stack traces"" This reverts commit 79f75ea which itself reverted f2f32cd Revert "Revert "fixup to "avoid identical stack traces" - try 2"" This reverts commit 2abf7ef which itself reverted ad89278 Original Author: David Mitchell <[email protected]> Original Date: Fri Dec 13 13:48:25 2019 +0000 avoid identical stack traces GH #15109 The output of caller() (e.g. as produced by carp::Confess) produces multiple identical outputs when within a nested use/require. This is because at the time of calling the 'BEGIN { require ... }', PL_curcop is set to &PL_compiling, which is a fixed buffer within the interpreter, whose individual file and line fields are saved and restored when doing a new require/eval. This means that within the innermost require, PL_compiling has file:lineno of the innermost source file, and multiple saved PL_curcop values in the context stack frames all point to the same &PL_copmpiling. So all levels of the stack trace appear to come from the innermost file. This commit fixes this (after a fashion) by, at the start of calling a BEGIN, making PL_curcop point to a temporary copy of PL_compiling instead. This is all a bit of a hack.

KES777 · 2022-12-06T13:56:17Z

Perls are installed via perlbrew. 5.36.0 and 5.37.6 works as expected, but 5.34.1 does not.

Here is result of @iabyn test:
Perl 5.34.1

MAIN BEGIN: t.pl:14
MOD BEGIN: Mod.pm:4
MOD: Mod.pm:0
f(): t.pl:17

Perl 5.36.0

MAIN BEGIN: t.pl:14
MOD BEGIN: t.pl:14
MOD: t.pl:14
f(): t.pl:17

Perl 5.37.6

MAIN BEGIN: t.pl:14
MOD BEGIN: t.pl:14
MOD: t.pl:14
f(): t.pl:17

Here is output from my test:

Perl 5.34.1 (Not expected. Here is no info about Mod1 package. Also info about source file is broken)

main - k.pl - 10 - main::BEGIN
main - k.pl - 10 - (eval)

main - Mod2.pm - 12 - Mod2::BEGIN  << NOTICE: we are already inside package Mod2, but `main` is displayed
main - Mod2.pm - 12 - (eval)
main - k.pl - 12 - (eval)
main - Mod2.pm - 12 - main::BEGIN  << NOTICE: k.pl is changed by Mod2.pm
main - Mod2.pm - 12 - (eval)

main - Mod1.pm - 14 - Mod1::BEGIN
main - Mod1.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - (eval)
main - Mod1.pm - 14 - Mod2::BEGIN
main - Mod1.pm - 14 - (eval)
main - k.pl - 12 - (eval)
main - Mod1.pm - 14 - main::BEGIN
main - Mod1.pm - 14 - (eval)

Perl 5.36.0

main - k.pl - 10 - main::BEGIN
main - k.pl - 10 - (eval)

Mod2 - Mod2.pm - 12 - Mod2::BEGIN
Mod2 - Mod2.pm - 12 - (eval)
main - k.pl - 12 - (eval)
main - k.pl - 12 - main::BEGIN
main - k.pl - 12 - (eval)

Mod1 - Mod1.pm - 14 - Mod1::BEGIN
Mod1 - Mod1.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - Mod2::BEGIN
Mod2 - Mod2.pm - 14 - (eval)
main - k.pl - 12 - (eval)
main - k.pl - 12 - main::BEGIN
main - k.pl - 12 - (eval)

Perl 5.37.6

main - k.pl - 10 - main::BEGIN
main - k.pl - 10 - (eval)

Mod2 - Mod2.pm - 12 - Mod2::BEGIN
Mod2 - Mod2.pm - 12 - (eval)
main - k.pl - 12 - (eval)
main - k.pl - 12 - main::BEGIN
main - k.pl - 12 - (eval)

Mod1 - Mod1.pm - 14 - Mod1::BEGIN
Mod1 - Mod1.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - (eval)
Mod2 - Mod2.pm - 14 - Mod2::BEGIN
Mod2 - Mod2.pm - 14 - (eval)
main - k.pl - 12 - (eval)
main - k.pl - 12 - main::BEGIN
main - k.pl - 12 - (eval)

demerphq · 2022-12-06T14:57:57Z

Hi @KES777 this wasnt applied in 5.34.1 and it wasn't backported either.

I will close this ticket as the fix was finally remerged.

p5pRT added Severity Low distro-Linux type-core labels Oct 19, 2019

iabyn closed this as completed Dec 25, 2019

haarg mentioned this issue Feb 10, 2020

BBC: HAARG/Devel-CompileLevel-0.001002.tar.gz fails since 5.31.7 #17554

Closed

demerphq mentioned this issue Feb 12, 2021

Smoke me/fix caller issues #18568

Closed

rjbs reopened this Jan 16, 2022

demerphq closed this as completed Dec 6, 2022

mauke mentioned this issue Mar 22, 2023

BEGIN blocks have wrong caller package #15597

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Caller inside BEGIN block return wrong info #15109

Caller inside BEGIN block return wrong info #15109

p5pRT commented Dec 30, 2015

p5pRT commented Dec 30, 2015

p5pRT commented Jan 6, 2016

p5pRT commented Jan 6, 2016

atoomic commented Dec 20, 2019

iabyn commented Dec 25, 2019

haarg commented Jan 2, 2020

iabyn commented Jan 3, 2020 via email

haarg commented Jan 3, 2020

demerphq commented Jan 13, 2022 via email

KES777 commented Dec 6, 2022

demerphq commented Dec 6, 2022

Caller inside BEGIN block return wrong info #15109

Caller inside BEGIN block return wrong info #15109

Comments

p5pRT commented Dec 30, 2015

p5pRT commented Dec 30, 2015

From @KES777

Created by @KES777

p5pRT commented Jan 6, 2016

From @iabyn

p5pRT commented Jan 6, 2016

atoomic commented Dec 20, 2019

iabyn commented Dec 25, 2019

haarg commented Jan 2, 2020

iabyn commented Jan 3, 2020 via email

haarg commented Jan 3, 2020

demerphq commented Jan 13, 2022 via email

KES777 commented Dec 6, 2022

demerphq commented Dec 6, 2022