Add support for fish_trace variable to trace execution

This adds support for `fish_trace`, a new variable intended to serve the
same purpose as `set -x` as in bash. Setting this variable to anything
non-empty causes execution to be traced. In the future we may give more
specific meaning to the value of the variable.

The user's prompt is not traced unless you run it explicitly. Events are
also not traced because it is noisy; however autoloading is.

Fixes #3427

CHANGELOG.md

@@ -22,6 +22,7 @@
 - `commandline -p` and `commandline -j` now split on `&&` and `||` in addition to `;` and `&` (#6214).
 - `fish` now correctly handles CDPATH entries that starts with `..` (#6220).
 - New redirections `&>` and `&|` may be used to redirect or pipe stdout, and also redirect stderr to stdout (#6192).
+- The `fish_trace` variable may be set to trace execution. This performs a similar role as `set -x`.
 
 ### Syntax changes and new commands
 - Brace expansion now only takes place if the braces include a "," or a variable expansion, meaning common commands such as `git reset HEAD@{0}` do not require escaping (#5869).

CMakeLists.txt

@@ -111,7 +111,7 @@ SET(FISH_SRCS
     src/signal.cpp src/tinyexpr.cpp src/tnode.cpp src/tokenizer.cpp src/utf8.cpp src/util.cpp
     src/wcstringutil.cpp src/wgetopt.cpp src/wildcard.cpp src/wutil.cpp
     src/future_feature_flags.cpp src/redirection.cpp src/topic_monitor.cpp
-    src/flog.cpp
+    src/flog.cpp src/trace.cpp
 )
 
 # Header files are just globbed.

sphinx_doc_src/cmds/fish.rst

@@ -23,7 +23,7 @@ The following options are available:
 
 - ``-d`` or ``--debug=CATEGORY_GLOB`` enables debug output and specifies a glob for matching debug categories (like ``fish -d``). Defaults to empty.
 
-- ``-o`` or ``--debug-output=path`` Specify a file path to receive the debug output. The default is stderr.
+- ``-o`` or ``--debug-output=path`` Specify a file path to receive the debug output, including categories and ``fish_trace``. The default is stderr.
 
 - ``-i`` or ``--interactive`` specify that fish is to run in interactive mode
 

sphinx_doc_src/index.rst

@@ -1224,6 +1224,8 @@ The user can change the settings of ``fish`` by changing the values of certain v
   empty string, history is not saved to disk (but is still available within the interactive
   session).
 
+- ``fish_trace``, if set and not empty, will cause fish to print commands before they execute, similar to `set -x` in bash. The trace is printed to the path given by the :ref:`--debug-output <cmd-fish>` option to fish (stderr by default).
+
 - ``fish_user_paths``, a list of directories that are prepended to ``PATH``. This can be a universal variable.
 
 - ``umask``, the current file creation mask. The preferred way to change the umask variable is through the :ref:`umask <cmd-umask>` function. An attempt to set umask to an invalid value will always fail.

src/event.cpp

@@ -246,6 +246,9 @@ static void event_fire_internal(parser_t &parser, const event_t &event) {
     assert(ld.is_event >= 0 && "is_event should not be negative");
     scoped_push<decltype(ld.is_event)> inc_event{&ld.is_event, ld.is_event + 1};
 
+    // Suppress fish_trace during events.
+    scoped_push<bool> suppress_trace{&ld.suppress_fish_trace, true};
+
     // Capture the event handlers that match this event.
     event_handler_list_t fire;
     for (const auto &handler : *s_event_handlers.acquire()) {

src/exec.cpp

@@ -44,6 +44,7 @@
 #include "reader.h"
 #include "redirection.h"
 #include "signal.h"
+#include "trace.h"
 #include "wutil.h"  // IWYU pragma: keep
 
 /// File descriptor redirection error message.
@@ -899,6 +900,12 @@ static bool exec_process_in_job(parser_t &parser, process_t *p, std::shared_ptr<
     // which depends on the redirection being evaluated before the pipe. So the write end of the
     // pipe comes first, the read pipe of the pipe comes last. See issue #966.
 
+    // Maybe trace this process.
+    // TODO: 'and' and 'or' will not show.
+    if (trace_enabled(parser)) {
+        trace_argv(parser, nullptr, p->get_argv_array().to_list());
+    }
+
     // The IO chain for this process.
     io_chain_t process_net_io_chain = j->block_io_chain();
     if (pipes.write.valid()) {

src/flog.cpp

@@ -94,6 +94,8 @@ void activate_flog_categories_by_pattern(const wcstring &inwc) {
 
 void set_flog_output_file(FILE *f) { g_logger.acquire()->set_file(f); }
 
+void log_extra_to_flog_file(const wcstring &s) { g_logger.acquire()->log_extra(s.c_str()); }
+
 std::vector<const category_t *> get_flog_categories() {
     std::vector<const category_t *> result(s_all_categories.begin(), s_all_categories.end());
     std::sort(result.begin(), result.end(), [](const category_t *a, const category_t *b) {

src/flog.h

@@ -125,6 +125,9 @@ class logger_t {
 
     void log_fmt(const category_t &cat, const wchar_t *fmt, ...);
     void log_fmt(const category_t &cat, const char *fmt, ...);
+
+    // Log outside of the usual flog usage.
+    void log_extra(const wchar_t *s) { log1(s); }
 };
 
 extern owning_lock<logger_t> g_logger;
@@ -141,6 +144,10 @@ void set_flog_output_file(FILE *f);
 /// \return a list of all categories, sorted by name.
 std::vector<const flog_details::category_t *> get_flog_categories();
 
+/// Print some extra stuff to the flog file (stderr by default).
+/// This is used by the tracing machinery.
+void log_extra_to_flog_file(const wcstring &s);
+
 /// Output to the fish log a sequence of arguments, separated by spaces, and ending with a newline.
 #define FLOG(wht, ...)                                                        \
     do {                                                                      \

src/parse_execution.cpp

@@ -45,6 +45,7 @@
 #include "reader.h"
 #include "tnode.h"
 #include "tokenizer.h"
+#include "trace.h"
 #include "util.h"
 #include "wildcard.h"
 #include "wutil.h"
@@ -250,6 +251,10 @@ parse_execution_result_t parse_execution_context_t::run_if_statement(
     tnode_t<g::job_list> job_list_to_execute;
     tnode_t<g::if_clause> if_clause = statement.child<0>();
     tnode_t<g::else_clause> else_clause = statement.child<1>();
+
+    // We start with the 'if'.
+    trace_if_enabled(*parser, L"if");
+
     for (;;) {
         if (should_cancel_execution(associated_block)) {
             result = parse_execution_cancelled;
@@ -286,10 +291,12 @@ parse_execution_result_t parse_execution_context_t::run_if_statement(
                 if_clause = maybe_if_clause;
                 else_clause = else_cont.try_get_child<g::else_clause, 1>();
                 assert(else_clause && "Expected to have an else clause");
+                trace_if_enabled(*parser, L"else if");
             } else {
                 // It's the final 'else', we're done.
                 job_list_to_execute = else_cont.try_get_child<g::job_list, 1>();
                 assert(job_list_to_execute && "Should have a job list");
+                trace_if_enabled(*parser, L"else");
                 break;
             }
         }
@@ -308,6 +315,8 @@ parse_execution_result_t parse_execution_context_t::run_if_statement(
         parser->set_last_statuses(statuses_t::just(STATUS_CMD_OK));
     }
 
+    trace_if_enabled(*parser, L"end if");
+
     // It's possible there's a last-minute cancellation (issue #1297).
     if (should_cancel_execution(associated_block)) {
         result = parse_execution_cancelled;
@@ -320,10 +329,11 @@ parse_execution_result_t parse_execution_context_t::run_if_statement(
 parse_execution_result_t parse_execution_context_t::run_begin_statement(
     tnode_t<g::job_list> contents) {
     // Basic begin/end block. Push a scope block, run jobs, pop it
+    trace_if_enabled(*parser, L"begin");
     block_t *sb = parser->push_block(block_t::scope_block(BEGIN));
     parse_execution_result_t ret = run_job_list(contents, sb);
     parser->pop_block(sb);
-
+    trace_if_enabled(*parser, L"end begin");
     return ret;
 }
 
@@ -339,6 +349,7 @@ parse_execution_result_t parse_execution_context_t::run_function_statement(
     if (result != parse_execution_success) {
         return result;
     }
+    trace_if_enabled(*parser, L"function", arguments);
     io_streams_t streams(0);  // no limit on the amount of output from builtin_function()
     int err = builtin_function(*parser, streams, arguments, pstree, body);
     parser->set_last_statuses(statuses_t::just(err));
@@ -418,6 +429,7 @@ parse_execution_result_t parse_execution_context_t::run_for_statement(
         return parse_execution_errored;
     }
 
+    trace_if_enabled(*parser, L"for", arguments);
     block_t *fb = parser->push_block(block_t::for_block());
 
     // Now drive the for loop.
@@ -446,6 +458,7 @@ parse_execution_result_t parse_execution_context_t::run_for_statement(
     }
 
     parser->pop_block(fb);
+    trace_if_enabled(*parser, L"end for");
     return ret;
 }
 
@@ -562,6 +575,8 @@ parse_execution_result_t parse_execution_context_t::run_while_statement(
     tnode_t<g::job_conjunction> condition_head = header.child<1>();
     tnode_t<g::andor_job_list> condition_boolean_tail = header.child<3>();
 
+    trace_if_enabled(*parser, L"while");
+
     // Run while the condition is true.
     for (;;) {
         // Save off the exit status if it came from the loop body. We'll restore it if the condition
@@ -596,6 +611,7 @@ parse_execution_result_t parse_execution_context_t::run_while_statement(
         // Push a while block and then check its cancellation reason.
         auto &ld = parser->libdata();
         ld.loop_status = loop_status_t::normals;
+
         block_t *wb = parser->push_block(block_t::while_block());
         this->run_job_list(contents, wb);
         auto cancel_reason = this->cancellation_reason(wb);
@@ -618,6 +634,7 @@ parse_execution_result_t parse_execution_context_t::run_while_statement(
             break;
         }
     }
+    trace_if_enabled(*parser, L"end while");
     return ret;
 }
 

src/parser.h

@@ -158,6 +158,10 @@ struct library_data_t {
     /// Whether we are currently interactive.
     bool is_interactive{false};
 
+    /// Whether to suppress fish_trace output. This occurs in the prompt, event handlers, and key
+    /// bindings.
+    bool suppress_fish_trace{false};
+
     /// Whether we should break or continue the current loop.
     enum loop_status_t loop_status { loop_status_t::normals };
 

src/proc.h

@@ -197,6 +197,7 @@ class process_t {
 
     /// Returns argv.
     wchar_t **get_argv() { return argv_array.get(); }
+    const wchar_t *const *get_argv() const { return argv_array.get(); }
     const null_terminated_array_t<wchar_t> &get_argv_array() const { return argv_array; }
 
     /// Returns argv[idx].

src/reader.cpp

@@ -860,6 +860,7 @@ void reader_write_title(const wcstring &cmd, parser_t &parser, bool reset_cursor
     if (!term_supports_setting_title()) return;
 
     scoped_push<bool> noninteractive{&parser.libdata().is_interactive, false};
+    scoped_push<bool> in_title(&parser.libdata().suppress_fish_trace, true);
 
     wcstring fish_title_command = DEFAULT_TITLE;
     if (function_exists(L"fish_title", parser)) {
@@ -907,6 +908,9 @@ void reader_data_t::exec_prompt() {
     left_prompt_buff.clear();
     right_prompt_buff.clear();
 
+    // Suppress fish_trace while in the prompt.
+    scoped_push<bool> in_prompt(&parser().libdata().suppress_fish_trace, true);
+
     // Do not allow the exit status of the prompts to leak through.
     const bool apply_exit_status = false;
 
@@ -2561,10 +2565,10 @@ void reader_data_t::handle_readline_command(readline_cmd_t c, readline_loop_stat
                                                              completion_request_t::fuzzy_match};
                 complete_func(buffcpy, &rls.comp, complete_flags, vars, parser_ref);
 
-
-                // User-supplied completions may have changed the commandline - prevent buffer overflow.
+                // User-supplied completions may have changed the commandline - prevent buffer
+                // overflow.
                 if (token_begin > buff + el->text.size()) token_begin = buff + el->text.size();
-                if (token_end   > buff + el->text.size()) token_end   = buff + el->text.size();
+                if (token_end > buff + el->text.size()) token_end = buff + el->text.size();
 
                 // Munge our completions.
                 completions_sort_and_prioritize(&rls.comp);
@@ -3200,6 +3204,10 @@ maybe_t<wcstring> reader_data_t::readline(int nchars_or_0) {
     readline_loop_state_t rls{};
     struct termios old_modes;
 
+    // Suppress fish_trace during executing key bindings.
+    // This is simply to reduce noise.
+    scoped_push<bool> in_title(&parser().libdata().suppress_fish_trace, true);
+
     // If nchars_or_0 is positive, then that's the maximum number of chars. Otherwise keep it at
     // SIZE_MAX.
     if (nchars_or_0 > 0) {

src/trace.cpp

@@ -0,0 +1,36 @@
+#include "config.h"
+
+#include "trace.h"
+
+#include "common.h"
+#include "flog.h"
+#include "parser.h"
+
+bool trace_enabled(const parser_t &parser) {
+    auto &ld = parser.libdata();
+    if (ld.suppress_fish_trace) return false;
+    // TODO: this variable lookup is somewhat expensive, consider how to make this cheaper.
+    return !parser.vars().get(L"fish_trace").missing_or_empty();
+}
+
+/// Trace an "argv": a list of arguments where the first is the command.
+void trace_argv(const parser_t &parser, const wchar_t *command, const wcstring_list_t &argv) {
+    // Format into a string to prevent interleaving with flog in other threads.
+    // Add the + prefix.
+    wcstring trace_text(parser.block_count(), '+');
+
+    if (command && command[0]) {
+        trace_text.push_back(L' ');
+        trace_text.append(command);
+    }
+    for (const wcstring &arg : argv) {
+        trace_text.push_back(L' ');
+        trace_text.append(escape_string(arg, ESCAPE_ALL));
+    }
+    trace_text.push_back('\n');
+    log_extra_to_flog_file(trace_text);
+}
+
+void trace_if_enabled(const parser_t &parser, const wchar_t *command, const wcstring_list_t &argv) {
+    if (trace_enabled(parser)) trace_argv(parser, command, argv);
+}

src/trace.h

@@ -0,0 +1,23 @@
+/// Support for fish_trace.
+#ifndef FISH_TRACE_H
+#define FISH_TRACE_H
+
+#include "config.h"  // IWYU pragma: keep
+
+#include "common.h"
+
+class parser_t;
+class process_t;
+
+/// Trace an "argv": a list of arguments. Each argument is escaped.
+/// If \p command is not null, it is traced first (and not escaped)
+void trace_argv(const parser_t &parser, const wchar_t *command, const wcstring_list_t &argv);
+
+/// \return whether tracing is enabled.
+bool trace_enabled(const parser_t &parser);
+
+/// Convenience helper to trace a single string if tracing is enabled.
+void trace_if_enabled(const parser_t &parser, const wchar_t *command,
+                      const wcstring_list_t &argv = {});
+
+#endif

tests/checks/trace.fish

@@ -0,0 +1,72 @@
+# RUN: %fish %s
+
+echo untraced
+# CHECK: untraced
+
+set fish_trace 1
+
+for i in 1 2 3
+    echo $i
+end
+
+# CHECK: 1
+# CHECK: 2
+# CHECK: 3
+
+# CHECKERR: + for 1 2 3
+# CHECKERR: ++ echo 1
+# CHECKERR: ++ echo 2
+# CHECKERR: ++ echo 3
+# CHECKERR: + end for
+
+while true
+    and true
+    echo inside
+    break
+end
+
+# CHECK: inside
+
+# CHECKERR: + while
+# CHECKERR: + true
+# CHECKERR: + true
+# CHECKERR: ++ echo inside
+# CHECKERR: ++ break
+# CHECKERR: + end while
+
+while true && true
+    echo inside2
+    break
+end
+
+# CHECK: inside2
+
+# CHECKERR: + while
+# CHECKERR: + true
+# CHECKERR: + true
+# CHECKERR: ++ echo inside2
+# CHECKERR: ++ break
+# CHECKERR: + end while
+
+if true && false
+else if false || true
+    echo inside3
+else if will_not_execute
+end
+
+# CHECK: inside3
+
+# CHECKERR: + if
+# CHECKERR: + true
+# CHECKERR: + false
+# CHECKERR: + else if
+# CHECKERR: + false
+# CHECKERR: + true
+# CHECKERR: ++ echo inside3
+# CHECKERR: + end if
+
+set -e fish_trace
+# CHECKERR: + set -e fish_trace
+
+echo untraced
+# CHECK: untraced