Re: Improving xtrace output from subshells

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On 25/04/2019 16:55, Vadim Zeitlin wrote:
  Hello,

  dash currently has a problem with output from "-x" option being
non-deterministic when subshells are used (e.g. whenever pipelines are).
This was reported a long time ago as a Debian bug[1] but AFAICS has never
been posted here, so at the very least I'd like to do it and, ideally, also
fix it. But first let me describe the bug in more details:

  When you run the following command:

	$ dash -xc 'z=`echo | cut -f1 | sort`'

the following output would be expected:

	+ echo
	+ cut -f1
	+ sort
	+ z=

And, indeed, this is what you usually get. However the output is
non-deterministic and you can also get weirder things, with the output from
different subshells intermixed together. A simple way to see it is to run
the following loop:

	$ while true; do dash -xc 'z=`echo | cut -f1 | sort`' 2>&1 | grep cut; done | fgrep -vx '+ cut -f1'

which is not supposed to output anything, but in practice it does quickly
give some output, e.g. here is what I see when running it with the latest
dash version from git (48875c1201930d1e71d358eb1cf3eacc166795be):

	cut -f1
	+ + cut -f1
	+ cut+  -f1
	+ cut+  -f1
	+ cut+  -f1
	cut -f1
	+ + echocut
	cut -f1
	cut -f1
	+ + cutsort
	+ cut -f1+

I don't believe there is any requirement for your expectation and several other shells share this behaviour, but agreed that it would be a nice improvement to avoid this.

In practice, this is very annoying as it makes it difficult to compare the
logs of the same script run using "-x" as for any non-trivial amount of
output there will always be spurious differences between the output
produced by the different runs.


  As the comment from Tomi Ollila in the Debian bug report says, the problem
is due to using several different write() calls for output. Looking at the
sources, this happens inside "if (xflag)" block in evalcommand() function
starting at the line 854 in eval.c, where outstr(), eprintlist() twice, and
outcslow() are used for the single line of output.

Please keep in mind that even without this, you would not have deterministic output. The commands in a pipeline could be output in any order, even if each command would be output on its own line.

  To fix the problem we need to use only a single call instead and I see 2
possibilities here: first the obvious one which would be to output
everything in a temporary memory buffer and output the entire buffer at
once to preverrout at the end. This approach has some problems, however:

1. It would consume some extra memory and while this should be negligible
    in practice, it's arguably still better to avoid it.

2. Support for memory output is disabled using "#ifdef notyet" in the
    current sources and enabling it would enable quite a few other things,
    so I'm not sure if it's really a good idea.

3. Without enabling memory output, the code would need to be changed
    relatively extensively and I'd need to either refactor mkinit.c to
    extract "struct text" and the related addstr()/addchar() functions
    from it and make it possible to reuse it from eval.c, or reimplement
    something quite close to it, which is not appealing.

The #ifdef notyet is more than is needed for this. The output mechanism already supports buffering. It's easy to adapt this to work for xtrace output as well. You'd only run into issues if you have a command string that's larger than the buffer size, but I think that should be considered acceptable.

As a proof of concept that should clearly not be committed in its current form, please see the attached patch.

The other (and the only other, AFAICS) possibility would be to use writev()
to output everything at once instead. This avoids (1) (but, again, I don't
think it's really worth avoiding it that much), but would also require
making rather extensive changes to the code. I'm also not sure if writev()
is supported on all platforms targeted by dash, but hopefully it should be,
in 2019.

  I'd appreciate your advice about what kind of approach would be the most
appropriate and most likely to be accepted. Personally, I think of enabling
support for memory-backed output structs (only, i.e. without touching all
the rest of the code guarded by "#ifdef notyet") and using it here, but if
this is undesirable, for whatever reason, I'd go with writev() because as
long as we need to change the code structure anyhow, it's not really more
complicated than using a temporary buffer.

  Thanks in advance!
VZ

[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=567648

--- a/src/eval.c
+++ b/src/eval.c
@@ -861,9 +861,7 @@ bail:
 		sep = eprintlist(out, varlist.list, sep);
 		eprintlist(out, osp, sep);
 		outcslow('\n', out);
-#ifdef FLUSHERR
 		flushout(out);
-#endif
 	}
 
 	/* Now locate the command. */
--- a/src/output.c
+++ b/src/output.c
@@ -88,7 +88,9 @@ struct output output = {
 struct output errout = {
 	.nextc = 0, .end = 0, .buf = 0, .bufsize = 0, .fd = 2, .flags = 0
 };
-struct output preverrout;
+struct output preverrout = {
+	.bufsize = OUTBUFSIZ
+};
 #ifdef notyet
 struct output memout = {
 	.nextc = 0, .end = 0, .buf = 0, .bufsize = 0, .fd = MEM_OUT, .flags = 0

[Index of Archives]     [LARTC]     [Bugtraq]     [Yosemite Forum]     [Photo]

  Powered by Linux