Skip Menu |

Subject: file:line caller info is changed unexpectedly
To: perlbug <perlbug [...] perl.org>
Date: Mon, 26 Jun 2017 23:22:32 +0300
From: KES <kes-kes [...] yandex.ru>
Download (untitled) / with headers
text/plain 9.5k
Reply-To: kes-kes@yandex.ru To: perlbug@perl.org Message-Id: <5.24.1_10074_1498507436@kes-X751SA> From: kes-kes@yandex.ru Cc: kes-kes@yandex.ru Subject: file:line caller info is changed unexpectedly This is a bug report for perl from kes-kes@yandex.ru, generated with the help of perlbug 1.40 running under perl 5.24.1. ----------------------------------------------------------------- [Please describe your issue here] 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 [Please do not change anything below this line] ----------------------------------------------------------------- --- 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
To: perl5-porters [...] perl.org
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
From: Zefram <zefram [...] fysh.org>
Date: Tue, 27 Jun 2017 07:32:10 +0100
KES wrote: Show quoted text
>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
Date: Tue, 27 Jun 2017 08:50:32 +0100
From: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
To: perl5-porters [...] perl.org
On Mon, Jun 26, 2017 at 01:22:47PM -0700, KES wrote: Show quoted text
> 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
To: "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
Date: Tue, 27 Jun 2017 12:16:55 +0300
From: KES <kes-kes [...] yandex.ru>
Download (untitled) / with headers
text/plain 1.9k
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
Download Test.pm
text/x-perl 17b

Message body is not shown because sender requested not to inline it.

Download output
application/octet-stream 523b

Message body not shown because it is not plain text.

Download DB.pm
text/x-perl 297b

Message body is not shown because sender requested not to inline it.

Download example.pl
text/x-perl 228b

Message body is not shown because sender requested not to inline it.

From: Dave Mitchell <davem [...] iabyn.com>
Date: Thu, 29 Jun 2017 09:55:51 +0100
CC: "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
To: KES <kes-kes [...] yandex.ru>
Download (untitled) / with headers
text/plain 1.3k
On Tue, Jun 27, 2017 at 12:16:55PM +0300, KES wrote: Show quoted text
> 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.
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
To: Dave Mitchell <davem [...] iabyn.com>
From: demerphq <demerphq [...] gmail.com>
Date: Thu, 29 Jun 2017 11:13:00 +0200
CC: KES <kes-kes [...] yandex.ru>, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Download (untitled) / with headers
text/plain 1.8k
On 29 June 2017 at 10:55, Dave Mitchell <davem@iabyn.com> wrote: Show quoted text
> 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.
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? Show quoted text
> 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/"
To: demerphq <demerphq [...] gmail.com>
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
CC: KES <kes-kes [...] yandex.ru>, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
From: Dave Mitchell <davem [...] iabyn.com>
Date: Thu, 29 Jun 2017 10:57:40 +0100
Download (untitled) / with headers
text/plain 842b
On Thu, Jun 29, 2017 at 11:13:00AM +0200, demerphq wrote: Show quoted text
> > 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"
From: KES <kes-kes [...] yandex.ru>
Date: Fri, 30 Jun 2017 00:09:11 +0300
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
To: "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Download (untitled) / with headers
text/plain 459b
Show quoted text
>The question is, does it need fixing?
yes, it does Show quoted text
>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
From: Sawyer X <xsawyerx [...] gmail.com>
Date: Sun, 2 Jul 2017 20:33:07 -0400
To: Zefram <zefram [...] fysh.org>, perl5-porters [...] perl.org
Subject: Re: [perl #131660] file:line caller info is changed unexpectedly
On 06/27/2017 02:32 AM, Zefram wrote: Show quoted text
> 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.


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

For issues related to this RT instance (aka "perlbug"), please contact perlbug-admin at perl.org