From a7f1d2c0c702df8709e7206135121ec075ef2973 Mon Sep 17 00:00:00 2001 From: ridiculousfish Date: Fri, 18 Oct 2019 18:08:22 -0700 Subject: [PATCH] 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 | 1 + CMakeLists.txt | 2 +- sphinx_doc_src/cmds/fish.rst | 2 +- sphinx_doc_src/index.rst | 2 + src/event.cpp | 3 ++ src/exec.cpp | 7 ++++ src/flog.cpp | 2 + src/flog.h | 7 ++++ src/parse_execution.cpp | 19 +++++++++- src/parser.h | 4 ++ src/proc.h | 1 + src/reader.cpp | 14 +++++-- src/trace.cpp | 36 ++++++++++++++++++ src/trace.h | 23 ++++++++++++ tests/checks/trace.fish | 72 ++++++++++++++++++++++++++++++++++++ 15 files changed, 189 insertions(+), 6 deletions(-) create mode 100644 src/trace.cpp create mode 100644 src/trace.h create mode 100644 tests/checks/trace.fish diff --git a/CHANGELOG.md b/CHANGELOG.md index d05072e29..24fb54d96 100644 --- a/CHANGELOG.md +++ b/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). diff --git a/CMakeLists.txt b/CMakeLists.txt index 73ca4a860..c77d77641 100644 --- a/CMakeLists.txt +++ b/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. diff --git a/sphinx_doc_src/cmds/fish.rst b/sphinx_doc_src/cmds/fish.rst index 5063b3bd0..e0adc6bec 100644 --- a/sphinx_doc_src/cmds/fish.rst +++ b/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 diff --git a/sphinx_doc_src/index.rst b/sphinx_doc_src/index.rst index 16e1bb9b6..193df98a1 100644 --- a/sphinx_doc_src/index.rst +++ b/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 ` 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 ` function. An attempt to set umask to an invalid value will always fail. diff --git a/src/event.cpp b/src/event.cpp index 5e760f139..a60f25ae2 100644 --- a/src/event.cpp +++ b/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 inc_event{&ld.is_event, ld.is_event + 1}; + // Suppress fish_trace during events. + scoped_push 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()) { diff --git a/src/exec.cpp b/src/exec.cpp index f3403c9ce..21a190556 100644 --- a/src/exec.cpp +++ b/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()) { diff --git a/src/flog.cpp b/src/flog.cpp index ce25a1b7a..f46f22f2a 100644 --- a/src/flog.cpp +++ b/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 get_flog_categories() { std::vector result(s_all_categories.begin(), s_all_categories.end()); std::sort(result.begin(), result.end(), [](const category_t *a, const category_t *b) { diff --git a/src/flog.h b/src/flog.h index 4f417e3c5..d95ac7e98 100644 --- a/src/flog.h +++ 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 g_logger; @@ -141,6 +144,10 @@ void set_flog_output_file(FILE *f); /// \return a list of all categories, sorted by name. std::vector 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 { \ diff --git a/src/parse_execution.cpp b/src/parse_execution.cpp index 2a0f6c7bf..a742f57f5 100644 --- a/src/parse_execution.cpp +++ b/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 job_list_to_execute; tnode_t if_clause = statement.child<0>(); tnode_t 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(); 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(); 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 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 condition_head = header.child<1>(); tnode_t 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; } diff --git a/src/parser.h b/src/parser.h index 8dfff38f1..3ba18ab62 100644 --- a/src/parser.h +++ b/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 }; diff --git a/src/proc.h b/src/proc.h index 4b086011e..0678a899d 100644 --- a/src/proc.h +++ b/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 &get_argv_array() const { return argv_array; } /// Returns argv[idx]. diff --git a/src/reader.cpp b/src/reader.cpp index 3b743b19e..d27d52866 100644 --- a/src/reader.cpp +++ b/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 noninteractive{&parser.libdata().is_interactive, false}; + scoped_push 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 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 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 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) { diff --git a/src/trace.cpp b/src/trace.cpp new file mode 100644 index 000000000..03b6481db --- /dev/null +++ b/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); +} diff --git a/src/trace.h b/src/trace.h new file mode 100644 index 000000000..b0ba0abb7 --- /dev/null +++ b/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 diff --git a/tests/checks/trace.fish b/tests/checks/trace.fish new file mode 100644 index 000000000..e2396d702 --- /dev/null +++ b/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