Beefy Boxes and Bandwidth Generously Provided by pair Networks
Pathologically Eclectic Rubbish Lister
 
PerlMonks  

caller() returns wrong line on multi-line function call

by jh (Beadle)
on Sep 13, 2017 at 18:24 UTC ( [id://1199342]=perlquestion: print w/replies, xml ) Need Help??

jh has asked for the wisdom of the Perl Monks concerning the following question:

Using 5.18, I have found that in a multi-line function call, where one of the arguments contains a dereference operation, that caller() returns the line where the dereference occurs, not the line where the function call actually happens. On a multi-line function call with no dereference operation, caller() seems to work:

Here is a minimal example that demonstrates this behavior:

#!/usr/bin/perl -w use strict; sub print_calling_line { my $actual_line = $_[0]; my $caller_line = (caller)[2]; printf "Called from line %2d; caller() reports line %2d\n", $actual_line, $caller_line; } print_calling_line( __LINE__, { A => 1, B => 2, C => 3 } ); print_calling_line( __LINE__, %{{ A => 1, B => 2, C => 3 }} );

This outputs

Called from line 11; caller() reports line 11 Called from line 15; caller() reports line 16

I am guessing this is related to CORE::GLOBAL::caller reports strange lines around coderef definitions, though it's not the same exactly.

Indexing into a reference does not seem to be a problem, just a dereference of the whole data structure (including getting a slice). Here is a more elaborate example that demonstrates this behavior:

#!/usr/bin/perl -w use strict; my %HASH = ( A => 1, B => 2, C => 3, D => 4, E => 5 ); my $HASHREF = \%HASH; my @ARRAY = ( 1 .. 5 ); my $ARRAYREF = \@ARRAY; my $SCALAR = "strings_are_scalar"; my $SCALARREF = \$SCALAR; sub CODE { rand } my $CODEREF = \&CODE; sub print_calling_line { my $actual_line = shift; my $caller_line = (caller)[2]; my $different = $actual_line != $caller_line ? "***" : ""; printf "%3s Called from line %2d; caller() reports line %2d [args: @ +_]\n", $different, $actual_line, $caller_line; } print "\n"; print_calling_line( __LINE__, %HASH ); print_calling_line( __LINE__, $HASHREF ); print_calling_line( __LINE__, %{$HASHREF} ); print_calling_line( __LINE__, $HASH{A} ); print_calling_line( __LINE__, $HASHREF->{A} ); print_calling_line( __LINE__, @HASH{qw(B C D)} ); print_calling_line( __LINE__, @{$HASHREF}{qw(B C D)} ); print "\n"; print_calling_line( __LINE__, %HASH ); print_calling_line( __LINE__, $HASHREF ); print_calling_line( __LINE__, %{$HASHREF} ); print_calling_line( __LINE__, $HASH{A} ); print_calling_line( __LINE__, $HASHREF->{A} ); print_calling_line( __LINE__, @HASH{qw(A)} ); print_calling_line( __LINE__, @{$HASHREF}{qw(A)} ); print "\n"; print_calling_line( __LINE__, @ARRAY ); print_calling_line( __LINE__, $ARRAYREF ); print_calling_line( __LINE__, @{$ARRAYREF} ); print_calling_line( __LINE__, $ARRAY[0] ); print_calling_line( __LINE__, $ARRAYREF->[0] ); print_calling_line( __LINE__, @ARRAY[2 .. 4] ); print_calling_line( __LINE__, @{$ARRAYREF}[2 .. 4] ); print "\n"; print_calling_line( __LINE__, @ARRAY ); print_calling_line( __LINE__, $ARRAYREF ); print_calling_line( __LINE__, @{$ARRAYREF} ); print_calling_line( __LINE__, $ARRAY[0] ); print_calling_line( __LINE__, $ARRAYREF->[0] ); print_calling_line( __LINE__, @ARRAY[2 .. 4] ); print_calling_line( __LINE__, @{$ARRAYREF}[2 .. 4] ); print "\n"; print_calling_line( __LINE__, $SCALAR ); print_calling_line( __LINE__, $SCALARREF ); print_calling_line( __LINE__, ${$SCALARREF} ); print "\n"; print_calling_line( __LINE__, $SCALAR ); print_calling_line( __LINE__, $SCALARREF ); print_calling_line( __LINE__, ${$SCALARREF} ); print "\n"; print_calling_line( __LINE__, &CODE ); print_calling_line( __LINE__, $CODEREF ); print_calling_line( __LINE__, &{$CODEREF} ); print "\n"; print_calling_line( __LINE__, &CODE ); print_calling_line( __LINE__, $CODEREF ); print_calling_line( __LINE__, &{$CODEREF} ); print "\n"; print_calling_line( __LINE__, ${$SCALARREF} ); print_calling_line( __LINE__, ${$SCALARREF} ); print_calling_line( __LINE__, "space_1", ${$SCALARREF} ); print_calling_line( __LINE__, "space_1", "space_2", ${$SCALARREF} ); print_calling_line( __LINE__, "space_1", "space_2", ${$SCALARREF}, "space_3", "space_4", ); print "\n";

outputs:

Called from line 22; caller() reports line 22 [args: A 1 D 4 C 3 E + 5 B 2] Called from line 23; caller() reports line 23 [args: HASH(0x974070 +)] Called from line 24; caller() reports line 24 [args: A 1 D 4 C 3 E + 5 B 2] Called from line 25; caller() reports line 25 [args: 1] Called from line 26; caller() reports line 26 [args: 1] Called from line 27; caller() reports line 27 [args: 2 3 4] Called from line 28; caller() reports line 28 [args: 2 3 4] Called from line 31; caller() reports line 31 [args: A 1 D 4 C 3 E + 5 B 2] Called from line 34; caller() reports line 34 [args: HASH(0x974070 +)] *** Called from line 37; caller() reports line 38 [args: A 1 D 4 C 3 E + 5 B 2] Called from line 40; caller() reports line 40 [args: 1] Called from line 43; caller() reports line 43 [args: 1] Called from line 46; caller() reports line 46 [args: 1] *** Called from line 49; caller() reports line 50 [args: 1] Called from line 54; caller() reports line 54 [args: 1 2 3 4 5] Called from line 55; caller() reports line 55 [args: ARRAY(0x99973 +0)] Called from line 56; caller() reports line 56 [args: 1 2 3 4 5] Called from line 57; caller() reports line 57 [args: 1] Called from line 58; caller() reports line 58 [args: 1] Called from line 59; caller() reports line 59 [args: 3 4 5] Called from line 60; caller() reports line 60 [args: 3 4 5] Called from line 63; caller() reports line 63 [args: 1 2 3 4 5] Called from line 66; caller() reports line 66 [args: ARRAY(0x99973 +0)] *** Called from line 69; caller() reports line 70 [args: 1 2 3 4 5] Called from line 72; caller() reports line 72 [args: 1] Called from line 75; caller() reports line 75 [args: 1] Called from line 78; caller() reports line 78 [args: 3 4 5] *** Called from line 81; caller() reports line 82 [args: 3 4 5] Called from line 86; caller() reports line 86 [args: strings_are_s +calar] Called from line 87; caller() reports line 87 [args: SCALAR(0x9999 +e0)] Called from line 88; caller() reports line 88 [args: strings_are_s +calar] Called from line 91; caller() reports line 91 [args: strings_are_s +calar] Called from line 94; caller() reports line 94 [args: SCALAR(0x9999 +e0)] *** Called from line 97; caller() reports line 98 [args: strings_are_s +calar] Called from line 102; caller() reports line 102 [args: 0.728356104 +883463] Called from line 103; caller() reports line 103 [args: CODE(0x999a +50)] Called from line 104; caller() reports line 104 [args: 0.996905960 +000248] Called from line 107; caller() reports line 107 [args: 0.690901509 +291631] Called from line 110; caller() reports line 110 [args: CODE(0x999a +50)] *** Called from line 113; caller() reports line 114 [args: 0.898765947 +759735] Called from line 118; caller() reports line 118 [args: strings_are +_scalar] *** Called from line 119; caller() reports line 120 [args: strings_are +_scalar] *** Called from line 122; caller() reports line 124 [args: space_1 str +ings_are_scalar] *** Called from line 126; caller() reports line 129 [args: space_1 spa +ce_2 strings_are_scalar] *** Called from line 131; caller() reports line 134 [args: space_1 spa +ce_2 strings_are_scalar space_3 space_4]

Replies are listed 'Best First'.
Re: caller() returns wrong line on multi-line function call
by ikegami (Patriarch) on Sep 14, 2017 at 00:05 UTC

    At the start of each statement is a nextstate op which sets the current line number. Remember that %{{ A => 1, B => 2, C => 3 }} use the %BLOCK syntax and BLOCK contains a sequence of statements.

      > Remember that %{{ A => 1, B => 2, C => 3 }} use the %BLOCK syntax and BLOCK contains a sequence of statements.

      I had problems to see why dereferencing should be implemented with a block syntax, but indeed one is free to include any statement inside %{...} as long as it can't be confused with a variable

      for instance

      DB<2> print %{ ( do{ {A=>1} } ) } A1

      Actually the problem is not restricted to dereferencing. other block syntax is having the same impact of messing up "nextstate".

      Like this

      print_calling_line( __LINE__, do { A => 1, B => 2, C => 3 } );

      will report the line of the do statement.

      Cheers Rolf
      (addicted to the Perl Programming Language and ☆☆☆☆ :)
      Je suis Charlie!

      update

      actually the line of the last block will be reported

      print_calling_line( __LINE__, do { A => 1, B => 2, C => 3 }, do { A => 1, B => 2, C => 3 }, do { A => 1, B => 2, C => 3 } ); ... Called from line 27; caller() reports line 30

      looks like the line number is stored inside a localized variable in C and overwritten while parsing following blocks.

        It looks like some block statements report the line the block begins—dereferences, as in my OP, as well as calls to do and eval (block style only!)—but others, notably inline creation of an anonymous subroutine with sub { }, report the line after the block (???). I haven't messed around with the decompiler, but I assume this has to do with where the nextstate elements get placed.

        Example:

Re: caller() returns wrong line on multi-line function call
by GrandFather (Saint) on Sep 13, 2017 at 22:23 UTC

    Which is "the line where the function call actually happens"? Is it the line containing the function name, or the line containing the closing ), or the line half way between, or some other line? You could make up pretty good stories for almost any of those lines, but I can't see any being The One True Line.

    In the most common context where it's likely to be interesting - debugging the code, any of the lines should be sufficient so long as indentation doesn't disguise the fact that the call spans multiple lines. Have you a context where one of the lines is more important for some reason? If so, tell us about that and maybe we can help solve the problem of determining the one true line from the dross for you.

    Premature optimization is the root of all job security
      Any attempt to use life introspection for refactoring of function names would be sabotaged by this bug, since the op-tree is flawed.

      :-[

      Cheers Rolf
      (addicted to the Perl Programming Language and ☆☆☆☆ :)
      Je suis Charlie!

      I would argue that the One True Line—for debugging and other purposes—is the line that contains the function name. That said, if caller() reported some other line (e.g. the line with the open paren or close paren) consistently, then it would be OK, I guess, but the inconsistency seems like a Problem.

        No need to argue, the one true line is by definition where a statement starts.

        This is for sure a bug and it's not caller's fault.

        Probably also affecting other statements not only function calls.

        Cheers Rolf
        (addicted to the Perl Programming Language and ☆☆☆☆ :)
        Je suis Charlie!

      I was writing a script to generate a Perl module full of regexes, and I wanted to include in the output any comments in the script adjacent to each function call to generate a regex in the output... I ended up going a different way because I decided that solution was too Clever.

        I wanted to include in the output any comments in the script adjacent to each function call to generate a regex in the output

        Seems a reasonable thing to me.

        My approach would be to change the script so those comments are string literal instead of actual comments. Then the text is readily available to your generator script to include in the generated module.

      I would say the "true line" is either the line with the function name or the line with the closing ) (or the last argument, in the case of a function call without parenthesis).

      The reason I say this is because the arguments to a function call may be any expression that can be used on the right-hand side of an assignment, including another function call.

        The information in nextstate is used by the debugger to display the current line while stepping thru

        • hence it has to be the start of the statement,
        • hence the line with the sub statement in our case
        • not the "function name", since it could be in another line

        Sorry, I don't think there is any room left to argue.

        edit
        The debugger can't work properly with this bug, and actually fails.

        If you type v you'll see something like

        DB<1> n main::tst(caller_subline.pl:24): do { A +=> 1, B => main::tst(caller_subline.pl:25): ); DB<1> v 21 22 23 print_calling_line( __LINE__, 24==> do { A => 1, B => 2, C => 3 } 25 ); 26 27 print_calling_line( __LINE__, 28: do { A => 1, B => 2, C => 3 }, 29: do { A => 1, B => 2, C => 3 , 30: do { A => 1, B => 2, C => 3 } DB<1> n Called from line 23; caller() reports line 24 main::tst(caller_subline.pl:29): do { A +=> 1, B =>

        Cheers Rolf
        (addicted to the Perl Programming Language and ☆☆☆☆ :)
        Je suis Charlie!

Re: caller() returns wrong line on multi-line function call (op-code nextstate)
by LanX (Saint) on Sep 14, 2017 at 13:01 UTC
    Good catch!!!

    The problem already happens during compilation, the "wrong" line numbers are stored into the op-tree (see "nextstate")

    I ran your code through B::Deparse and B::Concise to be sure

    -*- mode: compilation; default-directory: "d:/Users/RolfLangsdorf/pm/" + -*- Compilation started at Thu Sep 14 16:09:01 C:/Perl_64/bin\perl.exe pm/caller_subline.pl Perl v5.016003 Called from line 18; caller() reports line 18 Called from line 23; caller() reports line 24 === B::Deparse -l: { use strict; #line 18 "pm/caller_subline.pl" print_calling_line('18', {'A', 1, 'B', 2, 'C', 3}); #line 24 "pm/caller_subline.pl" print_calling_line('23', do { 'A', 1, 'B', 2, 'C', 3 }); } === B::Concise: main::tst: r <1> leavesub[1 ref] K/REFC,1 ->(end) - <@> lineseq KP ->r 1 <;> nextstate(main -5 caller_subline.pl:18) v:*,&,x*,x&,x$,$ +->2 d <1> entersub[t3] vKS/TARG,2 ->e - <1> ex-list K ->d 2 <0> pushmark s ->3 3 <$> const[PV "18"] sM ->4 b <@> anonhash sKM*/1 ->c 4 <0> pushmark s ->5 5 <$> const[PV "A"] s/BARE ->6 6 <$> const[IV 1] s ->7 7 <$> const[PV "B"] s/BARE ->8 8 <$> const[IV 2] s ->9 9 <$> const[PV "C"] s/BARE ->a a <$> const[IV 3] s ->b - <1> ex-rv2cv sK/2 ->- c <#> gv[*print_calling_line] s ->d e <;> nextstate(main -4 caller_subline.pl:24) v:*,&,x*,x&,x$,$ +->f q <1> entersub[t6] KS/TARG,2 ->r - <1> ex-list K ->q f <0> pushmark s ->g g <$> const[PV "23"] sM ->h - <1> null lKM*/1 ->p - <@> scope lK ->- - <0> ex-nextstate v ->h o <@> list lK ->p h <0> pushmark s ->i i <$> const[PV "A"] s/BARE ->j j <$> const[IV 1] s ->k k <$> const[PV "B"] s/BARE ->l l <$> const[IV 2] s ->m m <$> const[PV "C"] s/BARE ->n n <$> const[IV 3] s ->o - <1> ex-rv2cv sK/2 ->- p <#> gv[*print_calling_line] s ->q Compilation finished at Thu Sep 14 16:09:01

    Cheers Rolf
    (addicted to the Perl Programming Language and ☆☆☆☆ :)
    Je suis Charlie!

    update

    added code, rearranged output

Re: caller() returns wrong line on multi-line function call
by Anonymous Monk on Sep 13, 2017 at 19:36 UTC
    this is a problem for you or just a curiosity? this function call occupies three lines:
    foo( __LINE__, __LINE__, __LINE__);

      It is 90% a curiosity, but I have debugging routines that occasionally report the wrong calling line because of this bug.

      Passing __LINE__ to the test function was just illustrative.

Log In?
Username:
Password:

What's my password?
Create A New User
Domain Nodelet?
Node Status?
node history
Node Type: perlquestion [id://1199342]
Approved by beech
Front-paged by LanX
help
Chatterbox?
and the web crawler heard nothing...

How do I use this?Last hourOther CB clients
Other Users?
Others sharing their wisdom with the Monastery: (4)
As of 2024-03-28 22:41 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found