Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

In general I think this will help. Not just because it helps the
debugger. Later (* * * * below) I'll elaborate on this.

But in short, either this patch doesn't solve this particular problem
or I hand-applied the patch incorrectly.

(A cut and paste to a file caused many rejections by "patch", so I did
the rest by hand. It's possible I missed something. Running the
regression test caused a failures in E01options.ztst with an eval and
$LINENO, and another in C05debug.ztst with debug-trap-bug, but I think
this is to be expected. )

When I run zsh with those patches on this program:
(
    x=$(print $LINENO); print $x
)

I still get 1. Is that what one gets with the patch applied?

Note that there are other problems encountered that not explained by
that patch. In particular, it doesn't explain the position zshdb2.sh:6
in the output that went:

./command/eval.sh:4 ./command/eval.sh:22 ./lib/processor.sh:67
./lib/processor.sh:16 ./zshdb2.sh:6 ./testing.sh:1 ./zshdb2.sh:34

The correct position there is ./zshdb2.sh:9 which does appear earlier.
Also it doesn't explain the missing funcfiletrace output which could
be explained if somehow if zsh didn't think there were any function
calls.

Finally there is a history bug, but for that's something probably
totally different and likely just a bug in the debugger code.

* * * *
Let me see if I understand the situation correctly: there is an
internal routine called parse_string() which can be called though eval
as well as backtick. For eval, one can argue its the right thing, but
for backtick seeing 1 as the value of $LINENO might be a bit odd.

zsh is not the only programming language where this issue comes up.
I've seen it in Python and Ruby. In both, when eval'ing a string, the
line number is reset to 1 and the filename is something bogus. In the
Python debugger, pydb, what I do is search for such eval functions in
the traceback and use the line number of the thing that called that
instead. I can't do that here because "eval" or "backtick" or
"parse_string" doesn't appear as a function call in funcstack or any
of the other arrays, It might be cool to put somewhere in funcstack or
funcfiletrace the ZSH_SUBSHELL value.

Ruby is a little nicer here (and that generally seems to be the case).
By default, the line number is reset, but if you want you can supply a
line number and file name as the optional final parameters.

However Ola Blini has observed that really the surrounding context
should be the default; he calls the workaround an "anti-pattern." See:
http://ola-bini.blogspot.com/search/label/eval

On Sun, Sep 28, 2008 at 5:16 PM, Peter Stephenson
<p.w.stephenson@ntlworld.com> wrote:
> On Sun, 28 Sep 2008 15:19:37 -0400
> "Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
>> There is what looks to me a bug in the recent funcfiletrace that I've
>> been trying to isolate.
>>
>> #!/usr/local/bin/zsh
>> # Test debugger handling of subshells
>> (
>>     x=$(print 5; print 6)
>> )
>> (/tmp/zshdb/testing.sh:1):
>> print 5                            # In a 2nd subshell, backtick
>> zshdb<((7))> where                 # ((..)) indicates this.
>>
>> What's wrong is that we aren't on line 1 of testing.sh.
>
> exec.c:parse_string() resets the line number for every invocation.
> That's fine for eval, where we've fixed this up explicitly, but doesn't
> work in the call from exec.c:getoutput() which is the case here.
> Obviously that's not consistent with the fact that it doesn't have its
> own file; we don't do the special eval handling of reconstructing the
> file location in this case.
>
> The reason (...) is different is it's parsed straight away when the
> shell reads it in; it's not stored as a string argument to be looked at
> again later.
>
> It's possible we can simply get away with not resetting the line number
> in any case without its own entry on the function stack.  That's about
> the simplest fix, but changes the meaning of line numbers in all string
> evaluations apart from eval, trap and functions, where we have the
> special handling.  I'm coming round to the view that this is nonetheless
> the best way of salvaging consistency of the debugging environment.
> Have a go at this and see if it looks sensible.
>
> Index: Src/builtin.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/builtin.c,v
> retrieving revision 1.209
> diff -u -r1.209 builtin.c
> --- Src/builtin.c       27 Sep 2008 19:57:33 -0000      1.209
> +++ Src/builtin.c       28 Sep 2008 21:11:21 -0000
> @@ -4781,7 +4781,7 @@
>     } else
>        fpushed = 0;
>
> -    prog = parse_string(zjoin(argv, ' ', 1));
> +    prog = parse_string(zjoin(argv, ' ', 1), 1);
>     if (prog) {
>        if (wc_code(*prog->prog) != WC_LIST) {
>            /* No code to execute */
> @@ -5781,7 +5781,7 @@
>     arg = *argv++;
>     if (!*arg)
>        prog = &dummy_eprog;
> -    else if (!(prog = parse_string(arg))) {
> +    else if (!(prog = parse_string(arg, 1))) {
>        zwarnnam(name, "couldn't parse trap command");
>        return 1;
>     }
> Index: Src/exec.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/exec.c,v
> retrieving revision 1.156
> diff -u -r1.156 exec.c
> --- Src/exec.c  26 Sep 2008 09:11:29 -0000      1.156
> +++ Src/exec.c  28 Sep 2008 21:11:22 -0000
> @@ -188,17 +188,21 @@
>
>  /**/
>  mod_export Eprog
> -parse_string(char *s)
> +parse_string(char *s, int reset_lineno)
>  {
>     Eprog p;
> -    zlong oldlineno = lineno;
> +    zlong oldlineno;
>
>     lexsave();
>     inpush(s, INP_LINENO, NULL);
>     strinbeg(0);
> -    lineno = 1;
> +    if (reset_lineno) {
> +       oldlineno = lineno;
> +       lineno = 1;
> +    }
>     p = parse_list();
> -    lineno = oldlineno;
> +    if (reset_lineno)
> +       lineno = oldlineno;
>     if (tok == LEXERR && !lastval)
>        lastval = 1;
>     strinend();
> @@ -954,7 +958,7 @@
>     Eprog prog;
>
>     pushheap();
> -    if ((prog = parse_string(s)))
> +    if ((prog = parse_string(s, 0)))
>        execode(prog, dont_change_job, exiting);
>     popheap();
>  }
> @@ -3445,7 +3449,7 @@
>     pid_t pid;
>     char *s;
>
> -    if (!(prog = parse_string(cmd)))
> +    if (!(prog = parse_string(cmd, 0)))
>        return NULL;
>
>     if ((s = simple_redir_name(prog, REDIR_READ))) {
> @@ -3566,7 +3570,7 @@
>        return NULL;
>     }
>     *str = '\0';
> -    if (str[1] || !(prog = parse_string(cmd + 2))) {
> +    if (str[1] || !(prog = parse_string(cmd + 2, 0))) {
>        zerr("parse error in process substitution");
>        return NULL;
>     }
> @@ -4453,7 +4457,7 @@
>                    d = metafy(d, rlen, META_REALLOC);
>
>                    scriptname = dupstring(s);
> -                   r = parse_string(d);
> +                   r = parse_string(d, 1);
>                    scriptname = oldscriptname;
>
>                    if (fname)
> Index: Src/glob.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/glob.c,v
> retrieving revision 1.65
> diff -u -r1.65 glob.c
> --- Src/glob.c  11 May 2008 19:55:21 -0000      1.65
> +++ Src/glob.c  28 Sep 2008 21:11:23 -0000
> @@ -3329,7 +3329,7 @@
>  {
>     Eprog prog;
>
> -    if ((prog = parse_string(str))) {
> +    if ((prog = parse_string(str, 0))) {
>        int ef = errflag, lv = lastval, ret;
>
>        unsetparam("reply");
> Index: Src/parse.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/parse.c,v
> retrieving revision 1.75
> diff -u -r1.75 parse.c
> --- Src/parse.c 24 Sep 2008 19:19:56 -0000      1.75
> +++ Src/parse.c 28 Sep 2008 21:11:24 -0000
> @@ -2831,7 +2831,7 @@
>        close(fd);
>        file = metafy(file, flen, META_REALLOC);
>
> -       if (!(prog = parse_string(file)) || errflag) {
> +       if (!(prog = parse_string(file, 1)) || errflag) {
>            errflag = 0;
>            close(dfd);
>            zfree(file, flen);
> Index: Src/Modules/parameter.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/Modules/parameter.c,v
> retrieving revision 1.49
> diff -u -r1.49 parameter.c
> --- Src/Modules/parameter.c     11 Sep 2008 17:14:39 -0000      1.49
> +++ Src/Modules/parameter.c     28 Sep 2008 21:11:24 -0000
> @@ -279,7 +279,7 @@
>
>     val = metafy(val, strlen(val), META_REALLOC);
>
> -    prog = parse_string(val);
> +    prog = parse_string(val, 1);
>
>     if (!prog || prog == &dummy_eprog) {
>        zwarn("invalid function definition", value);
> Index: Src/Modules/zpty.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/Modules/zpty.c,v
> retrieving revision 1.38
> diff -u -r1.38 zpty.c
> --- Src/Modules/zpty.c  15 May 2008 15:51:01 -0000      1.38
> +++ Src/Modules/zpty.c  28 Sep 2008 21:11:24 -0000
> @@ -299,7 +299,7 @@
>     if (!ineval)
>        scriptname = "(zpty)";
>
> -    prog = parse_string(zjoin(args, ' ', 1));
> +    prog = parse_string(zjoin(args, ' ', 1), 0);
>     if (!prog) {
>        errflag = 0;
>        scriptname = oscriptname;
> Index: Src/Modules/zutil.c
> ===================================================================
> RCS file: /cvsroot/zsh/zsh/Src/Modules/zutil.c,v
> retrieving revision 1.23
> diff -u -r1.23 zutil.c
> --- Src/Modules/zutil.c 6 Jul 2007 21:52:40 -0000       1.23
> +++ Src/Modules/zutil.c 28 Sep 2008 21:11:25 -0000
> @@ -251,7 +251,7 @@
>     if (eval) {
>        int ef = errflag;
>
> -       eprog = parse_string(zjoin(vals, ' ', 1));
> +       eprog = parse_string(zjoin(vals, ' ', 1), 0);
>        errflag = ef;
>
>        if (!eprog)
>
>
> --
> Peter Stephenson <p.w.stephenson@ntlworld.com>
> Web page now at http://homepage.ntlworld.com/p.w.stephenson/
>

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

On Sun, 28 Sep 2008 22:32:19 -0400
"Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
> In general I think this will help. Not just because it helps the
> debugger. Later (* * * * below) I'll elaborate on this.
> 
> But in short, either this patch doesn't solve this particular problem
> or I hand-applied the patch incorrectly.
>...
> When I run zsh with those patches on this program:
> (
>     x=$(print $LINENO); print $x
> )
> 
> I still get 1. Is that what one gets with the patch applied?

No, you should get the line number in the file as I do, and you shouldn't
get any additional test failures.  I don't think your version is working.

I've now committed it, but with one additional change:  parse_string()
still has the key additional reset_lineno logic, but it once again always
saves and restores the line number locally.  That wouldn't make a
difference in this particular case but sometimes with the previous version
(I haven't bothered tracking down the exact places) you might get the
global line number being incremented too much.  I don't think there's any
case where parsing the string should affect the line number from the
surrounding context.

> Let me see if I understand the situation correctly: there is an
> internal routine called parse_string() which can be called though eval
> as well as backtick. For eval, one can argue its the right thing, but
> for backtick seeing 1 as the value of $LINENO might be a bit odd.

Right.  However, I've now tried to arrange it so that the line number is
only reset in places where zsh provides (through the function stack) enough
supporting for finding out what's actually going on.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

[-- Attachment #1: Type: text/plain, Size: 3045 bytes --]

Thanks. This addresses one of the problem seen. There are still the
others -- output disappearing and weird line numbers shown further up
in the trace. But we will take these one at a time.

How do you feel about noting the subshell level in one of the
traceback stacks and allowing an optional parameter to set $LINENO in
those cases where it is reset to 1. (Is there a corresponding variable
for the filename?

I note that in
x="
$LINENO"

LINENO has the x's line number rather than the one it's on. No doubt
this is an artifact of xtrace wanting to show for tracing purposes x's
line. However probably more correct would be to keep that but have
$LINENO be the line that it itself is on.

However assuming this is what's desired,  attached is a test for the
recent lineno-in-subshell change as well as a test for the LINENO in
split assignment. Adjust that last test as desired.

I've put these in a separate file and my test would be to move some of
the other LINENO tests out of the overall variable test here, use
again adjust (or discard) as desired.

On Mon, Sep 29, 2008 at 4:52 AM, Peter Stephenson <pws@csr.com> wrote:
> On Sun, 28 Sep 2008 22:32:19 -0400
> "Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
>> In general I think this will help. Not just because it helps the
>> debugger. Later (* * * * below) I'll elaborate on this.
>>
>> But in short, either this patch doesn't solve this particular problem
>> or I hand-applied the patch incorrectly.
>>...
>> When I run zsh with those patches on this program:
>> (
>>     x=$(print $LINENO); print $x
>> )
>>
>> I still get 1. Is that what one gets with the patch applied?
>
> No, you should get the line number in the file as I do, and you shouldn't
> get any additional test failures.  I don't think your version is working.
>
> I've now committed it, but with one additional change:  parse_string()
> still has the key additional reset_lineno logic, but it once again always
> saves and restores the line number locally.  That wouldn't make a
> difference in this particular case but sometimes with the previous version
> (I haven't bothered tracking down the exact places) you might get the
> global line number being incremented too much.  I don't think there's any
> case where parsing the string should affect the line number from the
> surrounding context.
>
>> Let me see if I understand the situation correctly: there is an
>> internal routine called parse_string() which can be called though eval
>> as well as backtick. For eval, one can argue its the right thing, but
>> for backtick seeing 1 as the value of $LINENO might be a bit odd.
>
> Right.  However, I've now tried to arrange it so that the line number is
> only reset in places where zsh provides (through the function stack) enough
> supporting for finding out what's actually going on.
>
> --
> Peter Stephenson <pws@csr.com>                  Software Engineer
> CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
> Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070
>

[-- Attachment #2: V07lineno.ztst --]
[-- Type: application/octet-stream, Size: 354 bytes --]

# Tests of $LINENO variable
%prep

 mkdir lineno.tmp 
 cd lineno.tmp
 print 'a=1\nb="\n$LINENO"; print assignment lineno: $b\n(\n   c=$(print $LINENO); print backtick lineno: $c\n)' >lineno.sh

 
%test
  $ZTST_testdir/../Src/zsh ./lineno.sh
0:Checking split-line assignment LINENO and backtick subshell LINENO
>assignment lineno: 
>2
>backtick lineno: 5

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

"Rocky Bernstein" wrote:
> Thanks. This addresses one of the problem seen. There are still the
> others -- output disappearing and weird line numbers shown further up
> in the trace. But we will take these one at a time.

Please could you send a simple example of a remaining incorrect line
number.  I would expect it would be reproducible without the debugger.

> How do you feel about noting the subshell level in one of the
> traceback stacks and allowing an optional parameter to set $LINENO in
> those cases where it is reset to 1.

I'm not entirely sure what you're referring to, please could you give an
example of what behaviour you'd like.

> (Is there a corresponding variable for the filename?

LINENO itself doesn't necessarily relate to a file, but for now you can
use ${(%):-%x} and ${(%):-%I} for the filename and line number in the
shell code which is probably what you need.  I'll add variables for
these later if they turn out to be useful (probably ZSH_SOURCE_FILE and
ZSH_SOURCE_LINE).

> I note that in
> x="
> $LINENO"
> 
> LINENO has the x's line number rather than the one it's on. No doubt
> this is an artifact of xtrace wanting to show for tracing purposes x's
> line. However probably more correct would be to keep that but have
> $LINENO be the line that it itself is on.

I think we'd have to track the line number in subst.c:stringsubst().
That may or may not be simple, I'll have to try it.


-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

On Mon, Sep 29, 2008 at 7:25 AM, Peter Stephenson <pws@csr.com> wrote:
> "Rocky Bernstein" wrote:
>> Thanks. This addresses one of the problem seen. There are still the
>> others -- output disappearing and weird line numbers shown further up
>> in the trace. But we will take these one at a time.
>
> Please could you send a simple example of a remaining incorrect line
> number.  I would expect it would be reproducible without the debugger.

Sorry. Here's a trace from the reduced debugger. I've added comments as before.

./zshdb2.sh
./zshdb2.sh:39 ./zshdb2.sh:34   # Debug output in lib/frame.sh

# Above should be: ./lib/hook.sh:5 ./zshdb2.sh:34
# note: 34+5=39

(./zshdb2.sh:34):               # Comes from debugger via above save
. ./testing.sh
./zshdb2.sh:39 ./zshdb2.sh:34   # lib/frame.sh output again
zshdb<1> p ${funcfiletrace[@]}
./command/eval.sh:38 ./command/eval.sh:56 ./lib/processor.sh:100
./lib/processor.sh:49 ./zshdb2.sh:39 ./zshdb2.sh:34

# Above should be:  ./command/eval.sh:11 ./command/eval.sh:27
./lib/processor.sh:96 ./lib/processor.sh:44 ./lib/hook:13
./lib/hook.sh:6 ./zshdb2.sh:39 ./zshdb2.sh:34

Note that the difference in the two ./lib/processor.sh call lines is
52 in one case and 51 in another.

It gets even screwier after this, Just install that reduced debugger
and keep stepping and printing funcfiletrace. But again, perhaps it is
best to take things one step at a time.

>
>> How do you feel about noting the subshell level in one of the
>> traceback stacks and allowing an optional parameter to set $LINENO in
>> those cases where it is reset to 1.
>
> I'm not entirely sure what you're referring to, please could you give an
> example of what behaviour you'd like.

Ok. But I'm responding to your assertion that in some cases the line
number is reset to 1 in places where you can figure that out via
funcfiletrace. I see that eval doesn't seem to be such a case.

Suppose eval line numbers were reset but it is shown as a call in the
stack traces as it is in Python and Ruby. This code then

# This is line 5
eval "x=1;
y=$LINENO"

would set y to 2 since that's the second line in the eval. Since eval
is a POSIX "special" builtin, let's say there is an eval2 which allows
optional file and line number parameters

eval "x=1;
y=$LINENO" 10 foo.c

Then y would be set to 10. And *stack* routines where we can see
filename, it would be "foo.c"

>
>> (Is there a corresponding variable for the filename?
>
> LINENO itself doesn't necessarily relate to a file, but for now you can
> use ${(%):-%x} and ${(%):-%I} for the filename and line number in the
> shell code which is probably what you need.  I'll add variables for
> these later if they turn out to be useful (probably ZSH_SOURCE_FILE and
> ZSH_SOURCE_LINE).

Ok - Thanks. Will see how this works out. I'm not a fan of only having
% notation which looks like line noise and as you yourself had said in
the past %x is a bit non-intuitive.

>
>> I note that in
>> x="
>> $LINENO"
>>
>> LINENO has the x's line number rather than the one it's on. No doubt
>> this is an artifact of xtrace wanting to show for tracing purposes x's
>> line. However probably more correct would be to keep that but have
>> $LINENO be the line that it itself is on.
>
> I think we'd have to track the line number in subst.c:stringsubst().
> That may or may not be simple, I'll have to try it.

I think it will help. Thanks.

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

"Rocky Bernstein" wrote:
> ./zshdb2.sh
> ./zshdb2.sh:39 ./zshdb2.sh:34   # Debug output in lib/frame.sh
> 
> # Above should be: ./lib/hook.sh:5 ./zshdb2.sh:34
> # note: 34+5=39

Ah, I see, so this should be fairly obvious once I track back and see
what the code referred to is... I'll try and get round to this this
evening.

> Suppose eval line numbers were reset but it is shown as a call in the
> stack traces as it is in Python and Ruby. This code then
> 
> # This is line 5
> eval "x=1;
> y=$LINENO"
> 
> would set y to 2 since that's the second line in the eval. Since eval
> is a POSIX "special" builtin, let's say there is an eval2 which allows
> optional file and line number parameters
> 
> eval "x=1;
> y=$LINENO" 10 foo.c
> 
> Then y would be set to 10. And *stack* routines where we can see
> filename, it would be "foo.c"

There is already an EVALLINENO option to control the line number
behaviour in eval.  I wouldn't plan on making this even more complicated
without some clear evidence of need.  Use of (the
not-yet-properly-named) ZSH_FILE_LINE looks likely to be more useful.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

On Mon, 29 Sep 2008 15:25:28 +0100
Peter Stephenson <pws@csr.com> wrote:
> "Rocky Bernstein" wrote:
> > ./zshdb2.sh
> > ./zshdb2.sh:39 ./zshdb2.sh:34   # Debug output in lib/frame.sh
> > 
> > # Above should be: ./lib/hook.sh:5 ./zshdb2.sh:34
> > # note: 34+5=39
> 
> Ah, I see, so this should be fairly obvious once I track back and see
> what the code referred to is... I'll try and get round to this this
> evening.

Wasn't so easy, since there was quite a lot of irrelevant stuff to
strip.  It turns out the problem is handling of functions inside traps.
These inherit the behaviour of the parent (eval-style, i.e. not
TRAP...() { ... } ) trap that the line number isn't updated, it's kept
as that in the line that caused the trap.  This causes oddities like
this, so I think it wants turning off so that the functions called from
the trap act normally.  This seems to accord with the principle of least
surprise, too.  That seems to fix the problem, but I'm sure I'll be
hearing if it doesn't.  I suspect sources inside eval-style traps behave
similarly and ought to be fixed, which could be done with sourcelevel,
but sufficient unto the day etc.  (The tests could also be done by
pushing a special FS_TRAP type onto funcstack, but that has obvious
visible consequences.  funcstack is a relative latecomer and could have
been used for also sorts of things we now do other ways.)

Responses avoiding "it should have been done completely differently from
the start", "it would be nice to have an option to do it completely
differently" and "other languages do this much better" preferred.

Index: Src/exec.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/exec.c,v
retrieving revision 1.157
diff -u -r1.157 exec.c
--- Src/exec.c	29 Sep 2008 08:46:32 -0000	1.157
+++ Src/exec.c	29 Sep 2008 21:33:16 -0000
@@ -992,7 +992,7 @@
 	return (lastval = 1);
 
     /* In evaluated traps, don't modify the line number. */
-    if ((!intrap || trapisfunc) && !ineval && code)
+    if (!IN_EVAL_TRAP() && !ineval && code)
 	lineno = code - 1;
 
     code = wc_code(*state->pc++);
@@ -1053,7 +1053,7 @@
 	ltype = WC_LIST_TYPE(code);
 	csp = cmdsp;
 
-	if ((!intrap || trapisfunc) && !ineval) {
+	if (!IN_EVAL_TRAP() && !ineval) {
 	    /*
 	     * Ensure we have a valid line number for debugging,
 	     * unless we are in an evaluated trap in which case
@@ -1543,7 +1543,7 @@
 	return;
 
     /* In evaluated traps, don't modify the line number. */
-    if ((!intrap || trapisfunc) && !ineval && WC_PIPE_LINENO(pcode))
+    if (!IN_EVAL_TRAP() && !ineval && WC_PIPE_LINENO(pcode))
 	lineno = WC_PIPE_LINENO(pcode) - 1;
 
     if (pline_level == 1) {
@@ -4628,6 +4628,7 @@
     es->trap_return = trap_return;
     es->trap_state = trap_state;
     es->trapisfunc = trapisfunc;
+    es->traplocallevel = traplocallevel;
     es->noerrs = noerrs;
     es->subsh_close = subsh_close;
     es->underscore = ztrdup(underscore);
@@ -4657,6 +4658,7 @@
     trap_return = exstack->trap_return;
     trap_state = exstack->trap_state;
     trapisfunc = exstack->trapisfunc;
+    traplocallevel = exstack->traplocallevel;
     noerrs = exstack->noerrs;
     subsh_close = exstack->subsh_close;
     setunderscore(exstack->underscore);
Index: Src/prompt.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/prompt.c,v
retrieving revision 1.55
diff -u -r1.55 prompt.c
--- Src/prompt.c	25 Sep 2008 11:26:03 -0000	1.55
+++ Src/prompt.c	29 Sep 2008 21:33:18 -0000
@@ -727,7 +727,7 @@
 		break;
 	    case 'I':
 		if (funcstack && funcstack->tp != FS_SOURCE &&
-		    (!intrap || trapisfunc)) {
+		    !IN_EVAL_TRAP()) {
 		    /*
 		     * We're in a function or an eval with
 		     * EVALLINENO.  Calculate the line number in
@@ -751,7 +751,7 @@
 		break;
 	    case 'x':
 		if (funcstack && funcstack->tp != FS_SOURCE &&
-		    (!intrap || trapisfunc))
+		    !IN_EVAL_TRAP())
 		    promptpath(funcstack->filename ? funcstack->filename : "",
 			       arg, 0);
 		else
Index: Src/signals.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/signals.c,v
retrieving revision 1.52
diff -u -r1.52 signals.c
--- Src/signals.c	26 Sep 2008 09:11:30 -0000	1.52
+++ Src/signals.c	29 Sep 2008 21:33:19 -0000
@@ -1077,6 +1077,13 @@
 int trapisfunc;
 
 /*
+ * If the current trap is not a function, at what function depth
+ * did the trap get called?
+ */
+/**/
+int traplocallevel;
+
+/*
  * sig is the signal number.
  * *sigtr is the value to be taken as the field in sigtrapped (since
  *   that may have changed by this point if we are exiting).
@@ -1132,6 +1139,7 @@
     /* execsave will save the old trap_return and trap_state */
     execsave();
     breaks = retflag = 0;
+    traplocallevel = locallevel;
     runhookdef(BEFORETRAPHOOK, NULL);
     if (*sigtr & ZSIG_FUNC) {
 	int osc = sfcontext;
Index: Src/zsh.h
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/zsh.h,v
retrieving revision 1.147
diff -u -r1.147 zsh.h
--- Src/zsh.h	29 Sep 2008 15:18:55 -0000	1.147
+++ Src/zsh.h	29 Sep 2008 21:33:20 -0000
@@ -924,6 +924,7 @@
     int trap_return;
     int trap_state;
     int trapisfunc;
+    int traplocallevel;
     int noerrs;
     int subsh_close;
     char *underscore;
@@ -2261,6 +2262,9 @@
     TRAP_STATE_FORCE_RETURN
 };
 
+#define IN_EVAL_TRAP() \
+    (intrap && !trapisfunc && traplocallevel == locallevel)
+
 /***********/
 /* Sorting */
 /***********/


-- 
Peter Stephenson <p.w.stephenson@ntlworld.com>
Web page now at http://homepage.ntlworld.com/p.w.stephenson/

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

On Mon, Sep 29, 2008 at 5:42 PM, Peter Stephenson
<p.w.stephenson@ntlworld.com> wrote:
> On Mon, 29 Sep 2008 15:25:28 +0100
> Peter Stephenson <pws@csr.com> wrote:
>> "Rocky Bernstein" wrote:
>> > ./zshdb2.sh
>> > ./zshdb2.sh:39 ./zshdb2.sh:34   # Debug output in lib/frame.sh
>> >
>> > # Above should be: ./lib/hook.sh:5 ./zshdb2.sh:34
>> > # note: 34+5=39
>>
>> Ah, I see, so this should be fairly obvious once I track back and see
>> what the code referred to is... I'll try and get round to this this
>> evening.
>
> Wasn't so easy, since there was quite a lot of irrelevant stuff to
> strip.

If you started with zshdb-0.01bug, if it is of any consolation, I'd
been stripping stuff out all weekend, well as trying to create simple
test cases. If you started with the git source well, yes, that's quite
large.

>  It turns out the problem is handling of functions inside traps.
> These inherit the behaviour of the parent (eval-style, i.e. not
> TRAP...() { ... } ) trap that the line number isn't updated, it's kept
> as that in the line that caused the trap.  This causes oddities like
> this, so I think it wants turning off so that the functions called from
> the trap act normally.  This seems to accord with the principle of least
> surprise, too.

Works much better. Thanks! (Really, I had been living with messed up
line numbers in debugger code for a while. You get them in xtrace
output as well. )

> That seems to fix the problem, but I'm sure I'll be
> hearing if it doesn't.

You are correct. It's really the next set of problems that I was more
concerned about since this is something users of a debugger see rather
than me or folks who happen to use trap DEBUG. Since you asked for
specific line numbers, posted them. And I think in order to get to the
next part I guess we have to remove this problem first since it is
what is the most glaring part.

So if you have zshdb-0.01bug around keep stepping:

$ ./zshdb2.sh

./zshdb2.sh:7 ./zshdb2.sh:34  # Much better. Thanks!
(./zshdb2.sh:34):
. ./testing.sh
./zshdb2.sh:9 ./zshdb2.sh:34  # Also correct!
zshdb<1> p ${funcfiletrace[@]}

./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./zshdb2.sh:34
# Above is still good! Now watch what happens next
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<2> s

./zshdb2.sh:7 ./testing.sh:3 ./zshdb2.sh:34 # Correct
(./testing.sh:3):
( x=$(print 5; print 6) )
./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34 # Correct
zshdb<3> p ${funcfiletrace[@]}

./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
# Were did that double set of lines come from?
# Try again..
zshdb<4> s

./zshdb2.sh:7 ./testing.sh:4 ./zshdb2.sh:34 # Correct
(./testing.sh:4):
x=$(print 5; print 6)
./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34 # Correct
zshdb<(5)> p ${funcfiletrace[@]}

./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34
./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34
./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34
# Now 3 copies
./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34
zshdb<(6)> ...

And the printing of funcfiletrace masks another problem which I think
is more serious. It's possible this has nothing to do with
funcfiletrace but might be related to the repeating lines above. What
is happing is that instead of duplicate lines, output disappears. The
missing output occurs before "zshdb<((4))>" below.

#
$ ./zshdb2.sh
./zshdb2.sh:7 ./zshdb2.sh:34
(./zshdb2.sh:34):
. ./testing.sh
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<1> s

./zshdb2.sh:7 ./testing.sh:3 ./zshdb2.sh:34
(./testing.sh:3):
( x=$(print 5; print 6) )
./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
zshdb<2> s

./zshdb2.sh:7 ./testing.sh:4 ./zshdb2.sh:34
(./testing.sh:4):
x=$(print 5; print 6)
./zshdb2.sh:9 ./testing.sh:4 ./zshdb2.sh:34
zshdb<(3)> s

zshdb<((4))> s

zshdb<((5))>

> I suspect sources inside eval-style traps behave
> similarly and ought to be fixed, which could be done with sourcelevel,
> but sufficient unto the day etc.  (The tests could also be done by
> pushing a special FS_TRAP type onto funcstack, but that has obvious
> visible consequences.  funcstack is a relative latecomer and could have
> been used for also sorts of things we now do other ways.)
>
> Responses avoiding "it should have been done completely differently from
> the start", "it would be nice to have an option to do it completely
> differently" and "other languages do this much better" preferred.

I'm not complaining! Beggar's can't be choosers.

Personally, I think it interesting and useful to know about how other
languages which have encountered the same or similar problems have
solved them. But if this is irksome, I'll not mention in the future.

Thanks for the speedy fixes on these issues.

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

On Mon, 29 Sep 2008 20:18:52 -0400
"Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
> zshdb<3> p ${funcfiletrace[@]}
> 
> ./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
> ./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
> ./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
> ./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
> ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
> # Were did that double set of lines come from?

Hmmm... I'm not convinced this has got anything directly to do with the
shell rather than the debugger.  Here's what I get when I simply ask for
the PID repeated times:

---------------
./zshdb2.sh:7 ./zshdb2.sh:34
===============
(./zshdb2.sh:34):
. ./testing.sh
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<1> p $$
711
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<2> p $$
711
711
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<3> p $$
711
711
711
./zshdb2.sh:9 ./zshdb2.sh:34
zshdb<4> 

It looks like something is odd with whatever is holding the command to be
executed.  You know better than me how that works.

-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

My mistake. You are correct. This bug was introduced in paring down
the program and removing an initial truncate output (leaving the
subsequent append outputs). And I now see the answer to why output was
disappearing in the subshell which was my initial concern.

Thanks for all the help!

Any thoughts on marking subshell level inside one of the stack traces
or having return inside trap DEBUG with a negative number cause an
immediate return?

Thanks again.



On Tue, Sep 30, 2008 at 12:53 PM, Peter Stephenson <pws@csr.com> wrote:
> On Mon, 29 Sep 2008 20:18:52 -0400
> "Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
>> zshdb<3> p ${funcfiletrace[@]}
>>
>> ./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
>> ./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
>> ./command/eval.sh:11 ./command/eval.sh:27 ./lib/processor.sh:96
>> ./lib/processor.sh:44 ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
>> ./zshdb2.sh:9 ./testing.sh:3 ./zshdb2.sh:34
>> # Were did that double set of lines come from?
>
> Hmmm... I'm not convinced this has got anything directly to do with the
> shell rather than the debugger.  Here's what I get when I simply ask for
> the PID repeated times:
>
> ---------------
> ./zshdb2.sh:7 ./zshdb2.sh:34
> ===============
> (./zshdb2.sh:34):
> . ./testing.sh
> ./zshdb2.sh:9 ./zshdb2.sh:34
> zshdb<1> p $$
> 711
> ./zshdb2.sh:9 ./zshdb2.sh:34
> zshdb<2> p $$
> 711
> 711
> ./zshdb2.sh:9 ./zshdb2.sh:34
> zshdb<3> p $$
> 711
> 711
> 711
> ./zshdb2.sh:9 ./zshdb2.sh:34
> zshdb<4>
>
> It looks like something is odd with whatever is holding the command to be
> executed.  You know better than me how that works.

Sorry you are correct. This bug was introduced in paring down the
program. Line 6 of lib/eval.sh should be:

  print "$@" > $_Dbg_evalfile

rather than

print "$@" >> $_Dbg_evalfile

However after this is fixed we have the disappearing output when in
that 2nd set of subshells which is the problem that motivated all of
this. What you want to print or eval is written to _Dbg_evalfile along
with some other commands to try to simulate the environment you were
in before entering the debugger. Then that file is sourced via:

   if [[ -t $_Dbg_fdi  ]] ; then
       _Dbg_set_dol_q $_Dbg_debugged_exit_code
       . $_Dbg_evalfile >&${_Dbg_fdi}
   else
       _Dbg_set_dol_q $_Dbg_debugged_exit_code
       . $_Dbg_evalfile
   fi

Somehow in that context no output appears even though output may be
explicitly written to a terminal file descriptor in the first branch.
I've also have tried using just the "else" branch above and still no
output. Finally, you can remove the call to _Dbg_set_dol_q which is
just setting $? before source'ing the file and that still doesn't
cause output to reappear.

So there seems to be something funky with I/O inside a backtick
subshell. I don't get that problem inside a () subshell, even if
output has been redirected on that, e.g.

( x=1)>/dev/null
because the debugger output goes to _Dbg_fdi.
> --
> Peter Stephenson <pws@csr.com>                  Software Engineer
> CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
> Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070
>

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

In that last email it looks like stuff I had written before figuring
out what was wrong was inadvertently keep in the email. I mean to send
just the initial text, not the inline comments.

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Peter Stephenson]

On Tue, 30 Sep 2008 13:59:43 -0400
"Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
> My mistake. You are correct. This bug was introduced in paring down
> the program and removing an initial truncate output (leaving the
> subsequent append outputs). And I now see the answer to why output was
> disappearing in the subshell which was my initial concern.

OK, so it seems there's currently nothing for me to look at here.

> Any thoughts on marking subshell level inside one of the stack traces
> or having return inside trap DEBUG with a negative number cause an
> immediate return?

You can already force a return from the enclosing function from trap '...'
DEBUG just by executing "return".  You can use return from within enclosing
functions to trigger this, e.g.

  fn() {
    return 3
  }
  trap 'fn || return $?' DEBUG

(if you need to return status 0, offset the status return value from fn by
1 and use 'fn || return $(( $? - 1 ))').  For example

  foo() {
    emulate -L zsh
    trap '[[ $ZSH_DEBUG_CMD == *bar* ]] && return 1' DEBUG
    echo foo
    echo bar
  }

when executed (with DEBUG_BEFORE_CMD assumed set by default) prints "foo"
but not "bar" and should return status 1 from foo.  However --- Surprise!
--- there's a bug and although it does return from foo the status gets
lost.  The fix is below.

Let us know either if this isn't working properly or you need something
more specific.

Index: Src/exec.c
===================================================================
RCS file: /cvsroot/zsh/zsh/Src/exec.c,v
retrieving revision 1.158
diff -u -r1.158 exec.c
--- Src/exec.c	29 Sep 2008 21:46:58 -0000	1.158
+++ Src/exec.c	1 Oct 2008 11:24:43 -0000
@@ -1091,7 +1091,8 @@
 	    exiting = donetrap;
 	    ret = lastval;
 	    dotrap(SIGDEBUG);
-	    lastval = ret;
+	    if (!retflag)
+		lastval = ret;
 	    donetrap = exiting;
 	    noerrexit = oldnoerrexit;
 	    /*
@@ -1230,7 +1231,8 @@
 	    exiting = donetrap;
 	    ret = lastval;
 	    dotrap(SIGDEBUG);
-	    lastval = ret;
+	    if (!retflag)
+		lastval = ret;
 	    donetrap = exiting;
 	    noerrexit = oldnoerrexit;
 	    opts[ERREXIT] = oerrexit_opt;
Index: Test/C05debug.ztst
===================================================================
RCS file: /cvsroot/zsh/zsh/Test/C05debug.ztst,v
retrieving revision 1.2
diff -u -r1.2 C05debug.ztst
--- Test/C05debug.ztst	5 Sep 2008 09:05:23 -0000	1.2
+++ Test/C05debug.ztst	1 Oct 2008 11:24:43 -0000
@@ -137,3 +137,13 @@
 >9: 'fn2'
 >0: 'echo wow'
 >wow
+
+  foo() {
+    emulate -L zsh; setopt debugbeforecmd
+    trap '[[ $ZSH_DEBUG_CMD == *bar* ]] && return 2' DEBUG
+    echo foo
+    echo bar
+  }
+  foo
+2:Status of forced return from eval-style DEBUG trap
+>foo


-- 
Peter Stephenson <pws@csr.com>                  Software Engineer
CSR PLC, Churchill House, Cambridge Business Park, Cowley Road
Cambridge, CB4 0WZ, UK                          Tel: +44 (0)1223 692070

Re: Help me track down a tough bug? (probably funcfiletrace, subshells and possibly I/O redirection)

[Rocky Bernstein]

On Wed, Oct 1, 2008 at 7:31 AM, Peter Stephenson <pws@csr.com> wrote:
> On Tue, 30 Sep 2008 13:59:43 -0400
> "Rocky Bernstein" <rocky.bernstein@gmail.com> wrote:
>> My mistake. You are correct. This bug was introduced in paring down
>> the program and removing an initial truncate output (leaving the
>> subsequent append outputs). And I now see the answer to why output was
>> disappearing in the subshell which was my initial concern.
>
> OK, so it seems there's currently nothing for me to look at here.

Yep. Thanks for the help though.

>
>> Any thoughts on marking subshell level inside one of the stack traces
>> or having return inside trap DEBUG with a negative number cause an
>> immediate return?
>
> You can already force a return from the enclosing function from trap '...'
> DEBUG just by executing "return".  ...

Ok. I've just committed a gdb-style "return" statement then.

Thoughts about being able to see subshell nexting inside the various
traces? (The level number really isn't needed, just a bit to indicate
whether a new subshell was entered.)

Thanks.