ZSH_XTRACE_FILE (instead of ZSH_XTRACEFD)

[Charles Blake <charlechaud@xxxxxxxxx>]

So, there seems to have been a stalled patch effort from Timothée
Mazzucotelli on ZSH_XTRACEFD back in September 2020.  Attached is a
proposal that just uses a filename.  mkfifo is always an alternative
for more complex scenarios, but having the interface be a simple path
seems more user-friendly to me.

The patch is small and includes both docs and tests.  It seems that
the code to abstract `stderr` into `xtrerr` for trace log purposes

has been around since a 2000-02-19 Peter Stephenson change.  This new

ZSH_XTRACE_FILE variable seems like a natural conclusion to that work.

I don't think there are any file descriptor leaks.  E.g., `for i in
{1..50000};ZSH_XTRACE_FILE=/tmp/$i` works fine for me.  An off-to-
the side strace shows no increase in file descriptor numbers during

such.  As in the attached patch, the variable is not local-izable

to shell functions.  This may be a minor annoyance but does not seem

like a deal-breaker problem since, in some sense, fd 2 for a process

is already an "even more global" destination (ultimately the very

motivation for a new destination for trace logs!).

Let me know if you see any problems.

Best,

cblake

diff --git a/Doc/Zsh/params.yo b/Doc/Zsh/params.yo
index dcd37aa6e..e59584dd9 100644
--- a/Doc/Zsh/params.yo
+++ b/Doc/Zsh/params.yo
@@ -1830,6 +1830,16 @@ item(tt(WORDCHARS) <S>)(
 A list of non-alphanumeric characters considered part of a word
 by the line editor.
 )
+vindex(ZSH_XTRACE_FILE)
+item(tt(ZSH_XTRACE_FILE))(
+Specifies a file where execution trace output is appended.  This avoids mixing
+trace logs with non-trace stderr output.  A later tt(unset) (or setting to files
+not immediately openable for append) restores default tt(stderr) output.
+
+E.g., tt(set -x; PS4='%D{%s.%N} ' ZSH_XTRACE_FILE=file script) makes a clean log
+of tt(script) activity with high-resolution time stamps.  Differences can even
+yield primitive wall clock profiles, but see also the tt(zsh/zprof) module.
+)
 vindex(ZBEEP)
 item(tt(ZBEEP))(
 If set, this gives a string of characters, which can use all the same codes
diff --git a/Src/exec.c b/Src/exec.c
index 7a928a316..79f0ba72c 100644
--- a/Src/exec.c
+++ b/Src/exec.c
@@ -5570,6 +5570,7 @@ execshfunc(Shfunc shf, LinkList args)
     LinkList last_file_list = NULL;
     unsigned char *ocs;
     int ocsp, osfc;
+    extern char *xtracefile;
 
     if (errflag)
 	return;
@@ -5603,7 +5604,8 @@ execshfunc(Shfunc shf, LinkList args)
     cmdsp = 0;
     if ((osfc = sfcontext) == SFC_NONE)
 	sfcontext = SFC_DIRECT;
-    xtrerr = stderr;
+    /* ZSH_XTRACE_FILE is not localizable.  Global logs seem the right idea. */
+    if (!xtracefile || !*xtracefile) xtrerr = stderr;
 
     doshfunc(shf, args, 0);
 
diff --git a/Src/init.c b/Src/init.c
index 20b8cc7fd..97824a793 100644
--- a/Src/init.c
+++ b/Src/init.c
@@ -623,7 +623,7 @@ init_io(char *cmd)
 	SHTTY = -1;
     }
 
-    /* Send xtrace output to stderr -- see execcmd() */
+    /* Send xtrace output to stderr -- see execcmd() & xtracefile */
     xtrerr = stderr;
 
     /* Make sure the tty is opened read/write. */
@@ -1330,6 +1330,8 @@ setupvals(char *cmd, char *runscript, char *zsh_name)
 	    setsparam("ZSH_EXEPATH", metafy(mypath, -1, META_REALLOC));
 	}
     }
+    if ((ptr = getsparam("ZSH_XTRACE_FILE")) && *ptr)
+	setsparam("ZSH_XTRACE_FILE", ztrdup(ptr));
     if (cmd)
 	setsparam("ZSH_EXECUTION_STRING", ztrdup(cmd));
     if (runscript)
diff --git a/Src/loop.c b/Src/loop.c
index db78f00c7..77f234a06 100644
--- a/Src/loop.c
+++ b/Src/loop.c
@@ -71,6 +71,7 @@ execfor(Estate state, int do_exec)
 	    untokenize(str2);
 	    printprompt4();
 	    fprintf(xtrerr, "%s\n", str2);
+	    zsfree(str2);   /* free copy made to untokenize */
 	    fflush(xtrerr);
 	}
 	if (!errflag) {
diff --git a/Src/params.c b/Src/params.c
index 3199fd17b..64734ac32 100644
--- a/Src/params.c
+++ b/Src/params.c
@@ -238,6 +238,8 @@ static const struct gsu_scalar terminfo_gsu =
 { terminfogetfn, terminfosetfn, stdunsetfn };
 static const struct gsu_scalar terminfodirs_gsu =
 { terminfodirsgetfn, terminfodirssetfn, stdunsetfn };
+static const struct gsu_scalar xtracefile_gsu =
+{ xtracefilegetfn, xtracefilesetfn, stdunsetfn };
 static const struct gsu_scalar wordchars_gsu =
 { wordcharsgetfn, wordcharssetfn, stdunsetfn };
 static const struct gsu_scalar ifs_gsu =
@@ -289,6 +291,7 @@ typedef struct iparam {
     int level;			/* if (old != NULL), level of localness  */
 } initparam;
 #endif
+char *xtracefile;   /* $ZSH_XTRACE_FILE */
 
 static initparam special_params[] ={
 #define GSU(X) BR((GsuScalar)(void *)(&(X)))
@@ -314,6 +317,7 @@ IPDEF2("HOME", home_gsu, PM_UNSET),
 IPDEF2("TERM", term_gsu, PM_UNSET),
 IPDEF2("TERMINFO", terminfo_gsu, PM_UNSET),
 IPDEF2("TERMINFO_DIRS", terminfodirs_gsu, PM_UNSET),
+IPDEF2("ZSH_XTRACE_FILE", xtracefile_gsu, PM_UNSET),
 IPDEF2("WORDCHARS", wordchars_gsu, 0),
 IPDEF2("IFS", ifs_gsu, PM_DONTIMPORT | PM_RESTRICTED),
 IPDEF2("_", underscore_gsu, PM_DONTIMPORT),
@@ -5238,6 +5242,41 @@ terminfodirssetfn(Param pm, char *x)
 
     term_reinit_from_pm();
 }
+/* gsu.getfn for `ZSH_XTRACE_FILE' */
+
+/**/
+static char *
+xtracefilegetfn(UNUSED(Param pm))
+{
+    return xtracefile ? xtracefile : dupstring("");
+}
+
+/* gsu.setfn for `ZSH_XTRACE_FILE' */
+
+/**/
+static void
+xtracefilesetfn(Param pm, char *x)
+{
+    zsfree(xtracefile); /* Clean-up existing. */
+    if (xtrerr && xtrerr != stderr) {
+	fdtable[fileno(xtrerr)] = FDT_UNUSED;
+	fclose(xtrerr);
+	xtrerr = stderr; /* Set to safe value for failed|unrequested open. */
+    }
+    xtracefile = x; /* Maybe adjust from usual default of stderr. */
+    if (x) { /* stdunsetfn calls with x == NULL */
+	/* No exec-inherit, append for logs, alternate tty log IS thinkable. */
+	int fd = open(x, O_WRONLY|O_CREAT|O_CLOEXEC|O_APPEND|O_NOCTTY, 0666);
+	if (fd < 0)
+	    zwarn("XTRACE to stderr since cannot open \"%s\": %e", x, errno);
+	else {
+	    xtrerr = fdopen(fd, "a");
+	    fdtable[fd] = FDT_XTRACE;
+	}
+	if ((pm->node.flags & PM_EXPORTED))
+	    addenv(pm, x);
+    }
+}
 /* Function to get value for special parameter `pipestatus' */
 
 /**/
diff --git a/Src/utils.c b/Src/utils.c
index a1d7c8cc2..55c4a1615 100644
--- a/Src/utils.c
+++ b/Src/utils.c
@@ -1711,14 +1711,12 @@ checkmailpath(char **s)
 /* This prints the XTRACE prompt. */
 
 /**/
-FILE *xtrerr = 0;
+FILE *xtrerr; /* init.c:init_io sets to a maybe-run-time-value stderr. */
 
 /**/
 void
 printprompt4(void)
 {
-    if (!xtrerr)
-	xtrerr = stderr;
     if (prompt4) {
 	int l, t = opts[XTRACE];
 	char *s = dupstring(prompt4);
diff --git a/Test/E02xtrace.ztst b/Test/E02xtrace.ztst
index 56bc20f1a..a07c1d4ea 100644
--- a/Test/E02xtrace.ztst
+++ b/Test/E02xtrace.ztst
@@ -261,3 +261,49 @@ F:The `4' on the second line is incorrect; see workers/48594.
 F:If this test fails, the new behaviour may be 
 F:workers/48591.
 
+ PS4='+%N:%i> '
+ ZSH_XTRACE_FILE=x.log
+ set -x
+ print 'Tracing: to file'
+ xtf 'function to file'
+ set +x
+ unset ZSH_XTRACE_FILE
+ cat x.log
+0:xtrace to ZSH_XTRACE_FILE
+>Tracing: to file
+>function to file
+>+(eval):4> print 'Tracing: to file'
+>+(eval):5> xtf 'function to file'
+>+xtf:1> local regression_test_dummy_variable
+>+xtf:2> print 'function to file'
+>+(eval):6> set +x
+
+ PS4='+%N:%i> '
+ rm -f x.log
+ ZSH_XTRACE_FILE=x.log
+ set -x
+ print 'Tracing: to file'
+ xtf 'function to file'
+ print 'not xtrace' 1>&2
+ unset ZSH_XTRACE_FILE
+ print 'Tracing: to stderr again'
+ xtf 'function to stderr again'
+ set +x
+ cat x.log
+0:xtrace to ZSH_XTRACE_FILE then back to stderr
+>Tracing: to file
+>function to file
+>Tracing: to stderr again
+>function to stderr again
+>+(eval):5> print 'Tracing: to file'
+>+(eval):6> xtf 'function to file'
+>+xtf:1> local regression_test_dummy_variable
+>+xtf:2> print 'function to file'
+>+(eval):7> print 'not xtrace'
+>+(eval):8> unset ZSH_XTRACE_FILE
+?not xtrace
+?+(eval):9> print 'Tracing: to stderr again'
+?+(eval):10> xtf 'function to stderr again'
+?+xtf:1> local regression_test_dummy_variable
+?+xtf:2> print 'function to stderr again'
+?+(eval):11> set +x