XTRACE output -- I thought we'd fixed this?

XTRACE output -- I thought we'd fixed this?

[Bart Schaefer]

bash-3.2$ set -x
bash-3.2$ echo hello 2>/dev/null
+ echo hello
hello
bash-3.2$ 

torch% set -x
torch% echo hello 2>/dev/null
hello
torch% echo hello
+Src/zsh:3> echo hello
hello
torch% 

Stderr redirection isn't supposed to redirect the xtrace descriptor unless
you use a { ... } construct.  There's even this in exec.c:execcmd():

    /* Make a copy of stderr for xtrace output before redirecting */
    fflush(xtrerr);
    if (isset(XTRACE) && xtrerr == stderr &&
	(type < WC_SUBSH || type == WC_TIMED)) {
	if ((newxtrerr = fdopen(movefd(dup(fileno(stderr))), "w"))) {
	    xtrerr = newxtrerr;
	    fdtable[fileno(xtrerr)] = FDT_XTRACE;
	}
    }

Yet E02xtrace.ztst appears to expect this (wrong?) behavior, so I must be
mis-remembering something.

Re: XTRACE output -- I thought we'd fixed this?

[Peter Stephenson]

On Mon, 16 May 2011 14:28:43 -0700
Bart Schaefer <schaefer@brasslantern.com> wrote:
> Stderr redirection isn't supposed to redirect the xtrace descriptor
> unless you use a { ... } construct.  There's even this in
> exec.c:execcmd():
> 
>     /* Make a copy of stderr for xtrace output before redirecting */
>     fflush(xtrerr);
>     if (isset(XTRACE) && xtrerr == stderr &&
> 	(type < WC_SUBSH || type == WC_TIMED)) {
> 	if ((newxtrerr = fdopen(movefd(dup(fileno(stderr))), "w"))) {
> 	    xtrerr = newxtrerr;
> 	    fdtable[fileno(xtrerr)] = FDT_XTRACE;
> 	}
>     }
> 
> Yet E02xtrace.ztst appears to expect this (wrong?) behavior, so I
> must be mis-remembering something.

I've been very confused by this, so it's quite possible something is
still wrong.

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


Member of the CSR plc group of companies. CSR plc registered in England and Wales, registered number 4187346, registered office Churchill House, Cambridge Business Park, Cowley Road, Cambridge, CB4 0WZ, United Kingdom

Re: XTRACE output -- I thought we'd fixed this?

[Bart Schaefer]

On May 23, 10:14am, Peter Stephenson wrote:
} Subject: Re: XTRACE output -- I thought we'd fixed this?
}
} On Mon, 16 May 2011 14:28:43 -0700
} Bart Schaefer <schaefer@brasslantern.com> wrote:
} > Stderr redirection isn't supposed to redirect the xtrace descriptor
} > unless you use a { ... } construct.  There's even this in
} > exec.c:execcmd():
} > 
} >     /* Make a copy of stderr for xtrace output before redirecting */
} 
} I've been very confused by this, so it's quite possible something is
} still wrong.

The code to create a newxtrerr exec.c after line 2867 does get run,
and then the redirections happen, but then at line 3082 after closing
all the mnodes, we restore xtrerr to stderr again.  This was added
in the same patch that introduced the newxtrerr copy of xtrerr.  The
www.zsh.org web server is down so I can't check the archive; commit
log says:

revision 1.132
date: 2008/06/11 09:27:55;  author: pws;  state: Exp;  lines: +8 -7
25145: make sure XTRACE output is redirected with stderr

At this point, I'm also confused.  It appears zsh is deliberately
redirecting xtrace with stderr, whereas bash appears not to do so.

PATCH (1 of 2): Re: XTRACE output -- I thought we'd fixed this?

[Bart Schaefer]

On May 23,  8:19am, Bart Schaefer wrote:
}
} The code to create a newxtrerr exec.c after line 2867 does get run,
} and then the redirections happen, but then at line 3082 after closing
} all the mnodes, we restore xtrerr to stderr again.  This was added
} in the same patch that introduced the newxtrerr copy of xtrerr.  The
} www.zsh.org web server is down so I can't check the archive

Ahh, it's back.  In workers/25145, PWS is attempting to fix a reported
bug where

 zsh -xc 'f() { { echo a; } 2> /dev/null; }; f'

fails to properly redirect the trace of "echo a;".  PWS traces this to
workers/9792, where I patched some xtrace bugs but I also noted:

  There is still one problem with this: The xtrace output of ( ...)
  and { ... } constructs is NOT redirected with stderr, which it
  should be. I suspect that's a matter of restoring xtrerr = stderr
  in entersubsh(), but I wasn't sure exactly where.

However, I *believed* I had fixed this in workers/9794, which may have
gotten missed at the time 25145 was being researched.  Apparently I
only fixed some simple cases of { ... } and there is a complication
that I missed back then regarding redirection inside function bodies.

To which PWS responded:

 Shouldn't we be able to do something like the following?  It
 unconditionally sets xtrerr to stderr after redirection, but also
 remembers if there was a temporary copy of xtrerr and restores
 xtrerr if there was.

Followed by a patch which fixes the problem with the function bodies
by breaking again some but not all of the things I fixed in 9792 and
9794.  Unfortunately the regression test cases I created in 9794 then
were updated to reflect the re-broken behavior, whereas if they'd been
left unchanged they would have revealed that 25145 was in fact not
the correct fix.

Ironically, the bug 25145 was supposed to fix isn't even represented
in the test cases that were added by the diffs in 25145.

Also in 25145, PWS inquires:

 I don't really understand why saving and restoring stderr (with
 no special variables apart from those used locally for saving and
 restoring) properly shouldn't automatically do the correct thing.
 Why does this need to be different from any other use of stderr?

No one ever followed up on that question.

The answer, I believe, is that zsh because doesn't actually fork
when doing a builtin command, particularly in { ... }, xtrace must
have a different fd.  Redirecting 2>something changes the meaning of
fd 2, it doesn't replace fd 2 with a different descriptor.  So any
FILE* in C that has fileno() == 2 will be (sometimes improperly)
redirected if it's not dup'd first.

So as nearly as I can tell, the following patch produces a correct
version of E02xtrace.ztst, including the bug 25145 was intended to
address.  Any failures this reveals need to be  fixed in the C code.
For which a proposed patch follows in my next message.

What may still be missing from this test case is a source'd file
that contains redirections.  I got lost trying to follow what bash
does with that.  More on this in the next message as well.

Index: Test/E02xtrace.ztst
===================================================================
diff -c -r1.5 E02xtrace.ztst
--- Test/E02xtrace.ztst	4 Nov 2008 04:47:53 -0000	1.5
+++ Test/E02xtrace.ztst	24 May 2011 06:07:20 -0000
@@ -7,6 +7,11 @@
     local regression_test_dummy_variable
     print "$*"
   }
+  function xtfx {
+    local regression_test_dummy_variable
+    print "Tracing: (){ builtin 2>file }" 2>>xtrace.err
+    { print "Tracing: (){ { builtin } 2>file }" } 2>>xtrace.err
+  }
   echo 'print "$*"' > xt.in
 
 %test
@@ -31,6 +36,7 @@
   repeat 1 do cat <<<'Tracing: do external done 2>file'; done 2>>xtrace.err
   xtf 'Tracing: function'
   xtf 'Tracing: function 2>file' 2>>xtrace.err
+  xtfx
   . ./xt.in 'Tracing: source'
   . ./xt.in 'Tracing: source 2>file' 2>>xtrace.err
   set +x
@@ -54,23 +60,23 @@
 >Tracing: do external done 2>file
 >Tracing: function
 >Tracing: function 2>file
+>Tracing: (){ builtin 2>file }
+>Tracing: (){ { builtin } 2>file }
 >Tracing: source
 >Tracing: source 2>file
->+(eval):4> print 'Tracing: builtin 2>file'
->+(eval):6> cat
 >+(eval):8> print 'Tracing: ( builtin ) 2>file'
 >+(eval):10> cat
 >+(eval):12> print 'Tracing: { builtin } 2>file'
 >+(eval):14> cat
 >+(eval):16> print 'Tracing: do builtin done 2>file'
 >+(eval):18> cat
->+(eval):20> xtf 'Tracing: function 2>file'
 >+xtf:1> local regression_test_dummy_variable
 >+xtf:2> print 'Tracing: function 2>file'
->+(eval):22> . ./xt.in 'Tracing: source 2>file'
->+./xt.in:1> print 'Tracing: source 2>file'
+>+xtfx:3> print 'Tracing: (){ { builtin } 2>file }'
 ?+(eval):3> print 'Tracing: builtin'
+?+(eval):4> print 'Tracing: builtin 2>file'
 ?+(eval):5> cat
+?+(eval):6> cat
 ?+(eval):7> print 'Tracing: ( builtin )'
 ?+(eval):9> cat
 ?+(eval):11> print 'Tracing: { builtin }'
@@ -80,9 +86,15 @@
 ?+(eval):19> xtf 'Tracing: function'
 ?+xtf:1> local regression_test_dummy_variable
 ?+xtf:2> print 'Tracing: function'
-?+(eval):21> . ./xt.in 'Tracing: source'
+?+(eval):20> xtf 'Tracing: function 2>file'
+?+(eval):21> xtfx
+?+xtfx:1> local regression_test_dummy_variable
+?+xtfx:2> print 'Tracing: (){ builtin 2>file }'
+?+(eval):22> . ./xt.in 'Tracing: source'
 ?+./xt.in:1> print 'Tracing: source'
-?+(eval):23> set +x
+?+(eval):23> . ./xt.in 'Tracing: source 2>file'
+?+./xt.in:1> print 'Tracing: source 2>file'
+?+(eval):24> set +x
 
  typeset -ft xtf
  xtf 'Tracing: function'

PATCH (2 of 2): Re: XTRACE output -- I thought we'd fixed this?

[Bart Schaefer]

On May 23, 11:16pm, I wrote:
}
} So as nearly as I can tell, the following patch produces a correct
} version of E02xtrace.ztst, including the bug 25145 was intended to
} address.  Any failures this reveals need to be  fixed in the C code.
} For which a proposed patch follows in my next message.

So, here it is, very simple:

Index: Src/exec.c
--- ../current/Src/exec.c	2011-05-23 08:22:44.000000000 -0700
+++ Src/exec.c	2011-05-23 22:38:54.000000000 -0700
@@ -3079,7 +3079,6 @@
 	if (mfds[i] && mfds[i]->ct >= 2)
 	    closemn(mfds, i);
 
-    xtrerr = stderr;
     if (nullexec) {
 	if (nullexec == 1) {
 	    /*
@@ -4260,6 +4259,7 @@
     cmdsp = 0;
     if ((osfc = sfcontext) == SFC_NONE)
 	sfcontext = SFC_DIRECT;
+    xtrerr = stderr;
     doshfunc(shf, args, 0);
     sfcontext = osfc;
     free(cmdstack);

Just wait to restore xtrerr until immediately before entry to the
shell function.  This relies on the fact that nothing else prints
to xtrerr in execcmd() after execshfunc(), but because xtrace-ing
the function call itself happens *inside* execshfunc(), there's
no cleaner way to do this [except to *also* save/restore xtrerr
inside execshfunc(), which would be the paranoid thing to do].

In fact, possibly better is to save/restore xtrerr in doshfunc()
and not change execshfunc() at all.  I both mention this because,
and did not do it because, there are a whole lot of calls to
doshfunc() all over the sources.  It's not clear to me how all
those calls should be xtraced or whether they should [not] be
affected by redirection.

I suspect that the same might also be said of source() as compared
to bin_dot(), if it turns out that "set -x; . file" also has some
bugs.

--