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

file:line caller info is changed unexpectedly #16047

Open
p5pRT opened this issue Jun 26, 2017 · 14 comments
Open

file:line caller info is changed unexpectedly #16047

p5pRT opened this issue Jun 26, 2017 · 14 comments

Comments

@p5pRT
Copy link

p5pRT commented Jun 26, 2017

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

Searchable as RT131660$

@p5pRT
Copy link
Author

p5pRT commented Jun 26, 2017

From @KES777

Created by @KES777

In next dump of stack frames you can notice that​:

1. lib/Devel/DB.pm​:74
2. /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm​:133

Appears at many stack frames and before -e​:0 frame
That is impossible that code which is used from -e​:0 appears early.

I suppose that some reference is placed into frame info (or reference to some global variable)
So when this global variable is changed later in a code the info for first frame is changed too.

$ perl -Ilib -d​:DB -e 0
[
  [
  [
  ],
  DB,
  lib/Devel/DB.pm,
  72,
  DB​::frames,
  1,
  1,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  lib/Devel/DB.pm,
  74,
  DB​::BEGIN,
  1,
  undef,
  undef,
  undef,
  256,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  lib/Devel/DB.pm,
  74,
  (eval),
  0,
  undef,
  undef,
  undef,
  256,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  -e,
  0,
  (eval),
  0,
  ,
  Devel/DB.pm,
  1,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  lib/Devel/DB.pm,
  74,
  main​::BEGIN,
  1,
  undef,
  undef,
  undef,
  256,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  lib/Devel/DB.pm,
  74,
  (eval),
  0,
  undef,
  undef,
  undef,
  256,
  undef,
  undef,
  ],
][
  [
  [
  ],
  DB,
  lib/Devel/DB.pm,
  78,
  DB​::frames,
  1,
  1,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  Scope​::Cleanup,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  DB​::DB,
  ,
  1,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  Scope​::Cleanup​::BEGIN,
  1,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  (eval),
  0,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  DB,
  lib/Devel/DB.pm,
  83,
  (eval),
  0,
  ,
  Scope/Cleanup.pm,
  1,
  256,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  DB​::BEGIN,
  1,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  (eval),
  0,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  -e,
  0,
  (eval),
  0,
  ,
  Devel/DB.pm,
  1,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  main​::BEGIN,
  1,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
  [
  [
  ],
  main,
  /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm,
  133,
  (eval),
  0,
  undef,
  undef,
  undef,
  0,
  undef,
  undef,
  ],
Undefined subroutine &Scope​::Cleanup​::establish_cleanup called at lib/Devel/DB.pm line 80.
BEGIN failed--compilation aborted at /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm line 133.
Compilation failed in require at lib/Devel/DB.pm line 83.
BEGIN failed--compilation aborted at lib/Devel/DB.pm line 83.
Compilation failed in require.
BEGIN failed--compilation aborted.

The code to reproduce this case​:

cat lib/Devel/DB.pm
package DB;

# use Sub​::Identify qw/ sub_name /;
use B qw/ svref_2object /;
sub sub_name {
  my $r = shift;
  return $r unless ref $r;
  return $r unless my $cv = svref_2object( $r );
  return $r unless $cv->isa( 'B​::CV' )
  and my $gv = $cv->GV
  ;
  my $name = '';
  if ( my $st = $gv->STASH ) {
  $name = $st->NAME . '​::';
  }
  my $n = $gv->NAME;
  if ( $n ) {
  $name .= $n;
  if ( $n eq '__ANON__' ) {
  $name .= ' defined at ' . $gv->FILE . '​:' . $gv->LINE;
  }
  }
  return $name;
}

sub frames {
  my( $count ) = @​_;
  $count //= -1; # infinite

  my $frames = [];
  my $lvl = 0;
  while( $count-- && (my @​frame = caller( $lvl++ )) ) {
  push @​$frames, [ [ @​DB​::args ], @​frame ];
  }

  return $frames;
}

sub dumper {
  my( $data, $level ) = @​_;
  $level //= 0;

  my $result;
  my $type = ref $data;
  if( $type eq 'HASH' ) {
  $result = '{';
  $result .= join '', map{
  "\n" .' 'x($level+1) ."$_ => ".dumper( $data->{$_}, $level +1 ) .','
  } sort keys %$data;
  $result .= "\n" .' 'x($level) ."}";
  }
  elsif( $type eq 'ARRAY' ) {
  $result = '[';
  $result .= join '', map{
  "\n" .' 'x($level+1) .dumper( $_, $level +1 ) .','
  } @​$data;
  $result .= "\n" .' 'x($level) ."]";
  }
  elsif( $type eq 'CODE' ) {
  $result = '&' .DB​::sub_name( $data );
  }
  else {
  $result = defined $data ? $data : 'undef';
  }

  return $result;
}

sub fn { 1 }

BEGIN{
  print dumper( frames() );
  $DB​::trace = 1;
}

sub DB {
  print dumper( frames() );

  Scope​::Cleanup​::establish_cleanup( \&fn );
}

use Scope​::Cleanup();

1;

The problem posibly relates to​:
https://rt.perl.org/Public/Bug/Display.html?id=127083
https://rt.perl.org/Public/Bug/Display.html?id=129239

Perl Info

Flags:
    category=core
    severity=medium

Site configuration information for perl 5.24.1:

Configured by kes at Sun Apr 30 22:40:30 EEST 2017.

Summary of my perl5 (revision 5 version 24 subversion 1) configuration:
   
  Platform:
    osname=linux, osvers=4.4.0-53-generic, archname=x86_64-linux
    uname='linux kes-x751sa 4.4.0-53-generic #74-ubuntu smp fri dec 2 15:59:10 utc 2016 x86_64 x86_64 x86_64 gnulinux '
    config_args='-de -Dprefix=/home/kes/perl5/perlbrew/perls/perl-5.24.1 -Aeval:scriptdir=/home/kes/perl5/perlbrew/perls/perl-5.24.1/bin'
    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-strong -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
    optimize='-O2',
    cppflags='-fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
    ccversion='', gccversion='5.4.0 20160609', 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-strong -L/usr/local/lib'
    libpth=/usr/local/lib /usr/lib/gcc/x86_64-linux-gnu/5/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.23.so, so=so, useshrplib=false, libperl=libperl.a
    gnulibc_version='2.23'
  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-strong'

Locally applied patches:
    Devel::PatchPerl 1.38


@INC for perl 5.24.1:
    /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux
    /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1
    /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/5.24.1/x86_64-linux
    /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/5.24.1


Environment for perl 5.24.1:
    HOME=/home/kes
    LANG=en_US.UTF-8
    LANGUAGE=en
    LC_ADDRESS=uk_UA.UTF-8
    LC_IDENTIFICATION=uk_UA.UTF-8
    LC_MEASUREMENT=uk_UA.UTF-8
    LC_MESSAGES=en_US.UTF-8
    LC_MONETARY=uk_UA.UTF-8
    LC_NAME=uk_UA.UTF-8
    LC_NUMERIC=uk_UA.UTF-8
    LC_PAPER=uk_UA.UTF-8
    LC_TELEPHONE=uk_UA.UTF-8
    LD_LIBRARY_PATH (unset)
    LOGDIR (unset)
    PATH=/home/kes/perl5/perlbrew/bin:/home/kes/perl5/perlbrew/perls/perl-5.24.1/bin:/home/kes/bin:/home/kes/bin:/home/kes/bin:/home/kes/.local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games
    PERLBREW=command perlbrew
    PERLBREW_BASHRC_VERSION=0.78
    PERLBREW_HOME=/home/kes/.perlbrew
    PERLBREW_MANPATH=/home/kes/perl5/perlbrew/perls/perl-5.24.1/man
    PERLBREW_PATH=/home/kes/perl5/perlbrew/bin:/home/kes/perl5/perlbrew/perls/perl-5.24.1/bin
    PERLBREW_PERL=perl-5.24.1
    PERLBREW_ROOT=/home/kes/perl5/perlbrew
    PERLBREW_VERSION=0.78
    PERL_BADLANG (unset)
    SHELL=/bin/bash

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From zefram@fysh.org

KES wrote​:

Appears at many stack frames and before -e​:0 frame
That is impossible that code which is used from -e​:0 appears early.

Debugger hooks, which you're using, get called implicitly from many
places. It's not surprising for your debugger code, and things that it
calls, to appear repeatedly in the stack trace. Nor is it surprising
for it to appear very early​: -e​:0 isn't a real location, and the real
location in Scope/Cleanup.pm that is pointed at is a "use" statement
invoked during loading of Scope​::Cleanup.

Please stop reporting bugs around the debugger mechanisms until you
understand what you're doing.

Btw, you're using Scope​::Cleanup incorrectly. You need to load the
S​:C module before you can compile a call to S​:C​:establish_cleanup(),
because it's not callable as an ordinary subroutine​: its operation
depends on compile-time magic. You're actually doing even worse​:
by virtue of debugger hooks, you're *calling* S​:C​:establish_cleanup()
before the module is loaded, which wouldn't work even for an ordinary
module-supplied subroutine.

-zefram

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

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

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @iabyn

On Mon, Jun 26, 2017 at 01​:22​:47PM -0700, KES wrote​:

In next dump of stack frames you can notice that​:

1. lib/Devel/DB.pm​:74
2. /home/kes/perl5/perlbrew/perls/perl-5.24.1/lib/site_perl/5.24.1/x86_64-linux/Scope/Cleanup.pm​:133

Appears at many stack frames and before -e​:0 frame
That is impossible that code which is used from -e​:0 appears early.

I suppose that some reference is placed into frame info (or reference to some global variable)
So when this global variable is changed later in a code the info for first frame is changed too.

Sorry, but life is too short. Can you do any or all of of the following​:

provide an example which doesn't rely on external modules to reproduce
(i.e. Scope​::Cleanup);

provide a clear explanation of what the output you show represents;

explain in more detail which part of the output is not as you expect,
and what you instead expect?

--
The crew of the Enterprise encounter an alien life form which is
surprisingly neither humanoid nor made from pure energy.
  -- Things That Never Happen in "Star Trek" #22

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @KES777

Hi. I fixed Devel​::DB by replacing Scope​::Cleanup by Test​::

In both places when I do stacktrace​:
1. Devel​::DB​:17
2. Devel​::DB​:23

I am called from -e​:0 so first three frames should be same.
But they are differ​:

main -e 0 (eval)
main lib/Devel/DB.pm 19 main​::BEGIN
main lib/Devel/DB.pm 19 (eval)

VS

main -e 0 (eval)
main lib/Test.pm 0 main​::BEGIN
main lib/Test.pm 0 (eval)

Look at attached example.pl
$ perl example.pl
main example.pl 15 main​::frames
main example.pl 16 main​::BEGIN
main example.pl 16 (eval)

Because -d will add 'use DB​::Devel;' as zero line I expect '-e​:0' file​:line for first two frames for both cases;

2. Also you may notice that first, second, fourth, fifth frames have have file​:line.
main lib/Devel/DB.pm 19 DB​::BEGIN
main lib/Devel/DB.pm 19 (eval)
main lib/Devel/DB.pm 19 main​::BEGIN
main lib/Devel/DB.pm 19 (eval)

main lib/Test.pm 0 DB​::BEGIN
main lib/Test.pm 0 (eval)
main lib/Test.pm 0 main​::BEGIN
main lib/Test.pm 0 (eval)

I suppose the reference is placed onto the stack, but copy should be done

What I expect to see​:
ACTUAL #EXPECTED
$ perl -Ilib -d​:DB -e 0
DB lib/Devel/DB.pm 17 DB​::frames
main lib/Devel/DB.pm 19 DB​::BEGIN
main lib/Devel/DB.pm 19 (eval)
main -e 0 (eval)
main lib/Devel/DB.pm 19 main​::BEGIN # main -e 0 main​::BEGIN
main lib/Devel/DB.pm 19 (eval) # main -e 0 (eval)

DB lib/Devel/DB.pm 23 DB​::frames
Test lib/Test.pm 2 DB​::DB
DB lib/Devel/DB.pm 26 (eval)
main lib/Test.pm 0 DB​::BEGIN # main lib/Devel/DB.pm 26 DB​::BEGIN
main lib/Test.pm 0 (eval) # main lib/Devel/DB.pm 26 (eval)
main -e 0 (eval)
main lib/Test.pm 0 main​::BEGIN # main -e 0 main​::BEGIN
main lib/Test.pm 0 (eval) # main -e 0 (eval)

DB lib/Devel/DB.pm 23 DB​::frames
main -e 1 DB​::DB

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @KES777

Test.pm

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @KES777

output

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @KES777

DB.pm

@p5pRT
Copy link
Author

p5pRT commented Jun 27, 2017

From @KES777

example.pl

@p5pRT
Copy link
Author

p5pRT commented Jun 29, 2017

From @iabyn

On Tue, Jun 27, 2017 at 12​:16​:55PM +0300, KES wrote​:

I am called from -e​:0 so first three frames should be same.
But they are differ​:

main -e 0 (eval)
main lib/Devel/DB.pm 19 main​::BEGIN
main lib/Devel/DB.pm 19 (eval)

VS

main -e 0 (eval)
main lib/Test.pm 0 main​::BEGIN
main lib/Test.pm 0 (eval)

This has nothing in particular to do with DB - a similar result can be
seen without it​:

$ cat /tmp/P.pm

  package P;

  use Carp;

  sub foo {
  $x;
  Carp​::cluck();
  $x;
  }

  BEGIN {
  $x;
  foo();
  $x;
  }
  1;

$ ./perl -Ilib -I/tmp -MP -e0
at /tmp/P.pm line 8.
  P​::foo() called at /tmp/P.pm line 14
  P​::BEGIN() called at /tmp/P.pm line 16
  eval {...} called at /tmp/P.pm line 16
  require P.pm called at -e line 0
  main​::BEGIN() called at /tmp/P.pm line 16
  eval {...} called at /tmp/P.pm line 16

The issue is that when the caller is not runtime code but the parser
(as is the case with BEGIN blocks), then the caller cop is set as
&PL_compiling. This fake COP is shared, so all stack dump lines where the
caller is not runtime will see the same file/lineno etc.

I think this would non-trivial to fix.

The question is, does it need fixing? Is this actually an important issue
for you?

--
Lear​: Dost thou call me fool, boy?
Fool​: All thy other titles thou hast given away; that thou wast born with.

@p5pRT
Copy link
Author

p5pRT commented Jun 29, 2017

From @demerphq

On 29 June 2017 at 10​:55, Dave Mitchell <davem@​iabyn.com> wrote​:

On Tue, Jun 27, 2017 at 12​:16​:55PM +0300, KES wrote​:

I am called from -e​:0 so first three frames should be same.
But they are differ​:

main -e 0 (eval)
main lib/Devel/DB.pm 19 main​::BEGIN
main lib/Devel/DB.pm 19 (eval)

VS

main -e 0 (eval)
main lib/Test.pm 0 main​::BEGIN
main lib/Test.pm 0 (eval)

This has nothing in particular to do with DB - a similar result can be
seen without it​:

$ cat /tmp/P.pm

package P;

use Carp;

sub foo \{
    $x;
    Carp&#8203;::cluck\(\);
    $x;
\}

BEGIN \{
    $x;
    foo\(\);
    $x;
\}
1;

$ ./perl -Ilib -I/tmp -MP -e0
at /tmp/P.pm line 8.
P​::foo() called at /tmp/P.pm line 14
P​::BEGIN() called at /tmp/P.pm line 16
eval {...} called at /tmp/P.pm line 16
require P.pm called at -e line 0
main​::BEGIN() called at /tmp/P.pm line 16
eval {...} called at /tmp/P.pm line 16

The issue is that when the caller is not runtime code but the parser
(as is the case with BEGIN blocks), then the caller cop is set as
&PL_compiling. This fake COP is shared, so all stack dump lines where the
caller is not runtime will see the same file/lineno etc.

I think this would non-trivial to fix.

Could it be worked around by making the file/lineno from these cases
show something like "called at parser.c line 0" instead, so they can
be differentiated?

The question is, does it need fixing? Is this actually an important issue
for you?

I have to admit I have been confused by these in the past, I know what
is going on, so I ignored it, but it can be a distraction when
deciphering backtraces.

Yves

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

@p5pRT
Copy link
Author

p5pRT commented Jun 29, 2017

From @iabyn

On Thu, Jun 29, 2017 at 11​:13​:00AM +0200, demerphq wrote​:

The issue is that when the caller is not runtime code but the parser
(as is the case with BEGIN blocks), then the caller cop is set as
&PL_compiling. This fake COP is shared, so all stack dump lines where the
caller is not runtime will see the same file/lineno etc.

I think this would non-trivial to fix.

Could it be worked around by making the file/lineno from these cases
show something like "called at parser.c line 0" instead, so they can
be differentiated?

In a simple implementation that would zap the correct entries which make
use of &PL_compiling as well as the incorrect ones. Its not obvious to me
how you would distinguish between correct and incorrect entries.

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

@p5pRT
Copy link
Author

p5pRT commented Jun 29, 2017

From @KES777

The question is, does it need fixing?
yes, it does

Is this actually an important issue for you?
In most cases it is not, but when I need to debug module loading order it is significant.

Example​:
$ perl test.pl
main - Test3.pm - 10
main - Test3.pm - 10
Test2 - Test2.pm - 2
main - Test3.pm - 10
main - Test3.pm - 10
Test1 - Test1.pm - 2
main - Test3.pm - 10
main - Test3.pm - 10
main - test.pl - 1
main - Test3.pm - 10
main - Test3.pm - 10

This confuse

@p5pRT
Copy link
Author

p5pRT commented Jul 3, 2017

From @xsawyerx

On 06/27/2017 02​:32 AM, Zefram wrote​:

KES wrote​:

Appears at many stack frames and before -e​:0 frame
That is impossible that code which is used from -e​:0 appears early.
Debugger hooks, which you're using, get called implicitly from many
places. It's not surprising for your debugger code, and things that it
calls, to appear repeatedly in the stack trace. Nor is it surprising
for it to appear very early​: -e​:0 isn't a real location, and the real
location in Scope/Cleanup.pm that is pointed at is a "use" statement
invoked during loading of Scope​::Cleanup.

Please stop reporting bugs around the debugger mechanisms until you
understand what you're doing.

Zefram, I understand your frustration with this situation, but this
remark can be easily perceived as negative and hurtful. "What you are
doing" (at the lack of specifics) is vague and sounds condescending,
whether that was the intent or not. From our interaction, I assume no
offense was meant, but it's important to clarify the way we interact and
what effect it can have on both parties.

Thank you,
Sawyer.

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

2 participants