Skip to content
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.

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

Caller inside BEGIN block return wrong info #15109

Closed
p5pRT opened this issue Dec 30, 2015 · 11 comments
Closed

Caller inside BEGIN block return wrong info #15109

p5pRT opened this issue Dec 30, 2015 · 11 comments

Comments

@p5pRT
Copy link

p5pRT commented Dec 30, 2015

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

Searchable as RT127083$

@p5pRT
Copy link
Author

p5pRT commented Dec 30, 2015

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
Copy link
Author

p5pRT commented Jan 6, 2016

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
Copy link
Author

p5pRT commented Jan 6, 2016

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

iabyn added a commit that referenced this issue Dec 13, 2019
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
Copy link
Member

atoomic commented Dec 20, 2019

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

@iabyn
Copy link
Contributor

iabyn commented Dec 25, 2019

Yes, this commit fixed the issue.

@iabyn iabyn closed this as completed Dec 25, 2019
@haarg
Copy link
Contributor

haarg commented Jan 2, 2020

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
Copy link
Contributor

iabyn commented Jan 3, 2020 via email

@haarg
Copy link
Contributor

haarg commented Jan 3, 2020

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.

steve-m-hay pushed a commit that referenced this issue Feb 12, 2020
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)
iabyn added a commit that referenced this issue Mar 12, 2020
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().
iabyn added a commit that referenced this issue Mar 18, 2020
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
Copy link
Collaborator

demerphq commented Jan 13, 2022 via email

@rjbs rjbs reopened this Jan 16, 2022
demerphq added a commit that referenced this issue Feb 14, 2022
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 <davem@iabyn.com>
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.
demerphq added a commit that referenced this issue Feb 17, 2022
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 <davem@iabyn.com>
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.
demerphq added a commit that referenced this issue Feb 17, 2022
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 <davem@iabyn.com>
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.
leonerd pushed a commit that referenced this issue Feb 19, 2022
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 <davem@iabyn.com>
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
Copy link
Contributor

KES777 commented Dec 6, 2022

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
Copy link
Collaborator

demerphq commented Dec 6, 2022

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants