Introduce the fish log, a replacement for debug()

This adds a new mechanism for logging, intended to replace debug().

The entry points are FLOG and FLOGF. FLOG can be used to log a sequence of
arguments, FLOGF is for printf-style formatted strings.

Each call to FLOG and FLOGF requires a category. If logging for a category
is not enabled, there is no effect (and arguments are not evaluated).

Categories may be enabled on the command line via the -d option.

CHANGELOG.md

@@ -14,6 +14,7 @@
 - `eval` is now implemented internally rather than being a function; as such, the evaluated code now shares the same argument scope as `eval` rather than being executed in a new scope (#4443).
 - An issue resulting in a certain class of parser errors not resulting in a non-zero `$status` has been corrected (3e055f).
 - fish now underlines every valid entered path instead of just the last one.
+- The `--debug` option has been extended to allow specifying categories. Categories may be listed via `fish --print-debug-categories`.
 
 ### Syntax changes and new commands
 - Brace expansion now only takes place if the braces include a "," or a variable expansion, so things like `git reset HEAD@{0}` now work (#5869).

CMakeLists.txt

@@ -89,6 +89,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
 )
 
 # Header files are just globbed.

sphinx_doc_src/cmds/fish.rst

@@ -22,6 +22,8 @@ The following options are available:
 
 - ``-d`` or ``--debug-level=DEBUG_LEVEL`` specify the verbosity level of fish. A higher number means higher verbosity. The default level is 1.
 
+- ``-o`` or ``--debug-output=path`` Specify a file path to receive the debug output. The default is stderr.
+
 - ``-i`` or ``--interactive`` specify that fish is to run in interactive mode
 
 - ``-l`` or ``--login`` specify that fish is to run as a login shell
@@ -32,6 +34,8 @@ The following options are available:
 
 - ``--print-rusage-self`` when fish exits, output stats from getrusage
 
+- ``--print-debug-categories`` outputs the list of debug categories, and then exits.
+
 - ``-v`` or ``--version`` display version and exit
 
 - ``-D`` or ``--debug-stack-frames=DEBUG_LEVEL`` specify how many stack frames to display when debug messages are written. The default is zero. A value of 3 or 4 is usually sufficient to gain insight into how a given debug call was reached but you can specify a value up to 128.

src/fish.cpp

@@ -44,6 +44,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA
 #include "expand.h"
 #include "fallback.h"  // IWYU pragma: keep
 #include "fish_version.h"
+#include "flog.h"
 #include "function.h"
 #include "future_feature_flags.h"
 #include "history.h"
@@ -61,6 +62,8 @@ class fish_cmd_opts_t {
    public:
     // Future feature flags values string
     wcstring features;
+    // File path for debug output.
+    std::string debug_output;
     // Commands to be executed in place of interactive shell.
     std::vector<std::string> batch_cmds;
     // Commands to execute after the shell's config has been read.
@@ -263,11 +266,13 @@ static int fish_parse_opt(int argc, char **argv, fish_cmd_opts_t *opts) {
                                               {"init-command", required_argument, NULL, 'C'},
                                               {"features", required_argument, NULL, 'f'},
                                               {"debug-level", required_argument, NULL, 'd'},
+                                              {"debug-output", required_argument, NULL, 'o'},
                                               {"debug-stack-frames", required_argument, NULL, 'D'},
                                               {"interactive", no_argument, NULL, 'i'},
                                               {"login", no_argument, NULL, 'l'},
                                               {"no-execute", no_argument, NULL, 'n'},
                                               {"print-rusage-self", no_argument, NULL, 1},
+                                              {"print-debug-categories", no_argument, NULL, 2},
                                               {"profile", required_argument, NULL, 'p'},
                                               {"private", no_argument, NULL, 'P'},
                                               {"help", no_argument, NULL, 'h'},
@@ -295,11 +300,14 @@ static int fish_parse_opt(int argc, char **argv, fish_cmd_opts_t *opts) {
                 if (tmp >= 0 && tmp <= 10 && !*end && !errno) {
                     debug_level = (int)tmp;
                 } else {
-                    std::fwprintf(stderr, _(L"Invalid value '%s' for debug-level flag"), optarg);
-                    exit(1);
+                    activate_flog_categories_by_pattern(str2wcstring(optarg));
                 }
                 break;
             }
+            case 'o': {
+                opts->debug_output = optarg;
+                break;
+            }
             case 'f': {
                 opts->features = str2wcstring(optarg);
                 break;
@@ -324,6 +332,22 @@ static int fish_parse_opt(int argc, char **argv, fish_cmd_opts_t *opts) {
                 opts->print_rusage_self = true;
                 break;
             }
+            case 2: {
+                auto cats = get_flog_categories();
+                // Compute width of longest name.
+                int name_width = 0;
+                for (const auto *cat : cats) {
+                    name_width = std::max(name_width, (int)wcslen(cat->name));
+                }
+                // A little extra space.
+                name_width += 2;
+                for (const auto *cat : cats) {
+                    // Negating the name width left-justifies.
+                    printf("%*ls %ls\n", -name_width, cat->name, _(cat->description));
+                }
+                exit(0);
+                break;
+            }
             case 'p': {
                 s_profiling_output_filename = optarg;
                 g_profiling_active = true;
@@ -396,6 +420,20 @@ int main(int argc, char **argv) {
     fish_cmd_opts_t opts{};
     my_optind = fish_parse_opt(argc, argv, &opts);
 
+    // Direct any debug output right away.
+    FILE *debug_output = nullptr;
+    if (!opts.debug_output.empty()) {
+        debug_output = fopen(opts.debug_output.c_str(), "w");
+        if (!debug_output) {
+            fprintf(stderr, "Could not open file %s\n", opts.debug_output.c_str());
+            perror("fopen");
+            exit(-1);
+        }
+        set_cloexec(fileno(debug_output));
+        setlinebuf(debug_output);
+        set_flog_output_file(debug_output);
+    }
+
     // No-exec is prohibited when in interactive mode.
     if (opts.is_interactive_session && opts.no_exec) {
         debug(1, _(L"Can not use the no-execute mode when running an interactive session"));
@@ -501,6 +539,9 @@ int main(int argc, char **argv) {
     if (opts.print_rusage_self) {
         print_rusage_self(stderr);
     }
+    if (debug_output) {
+        fclose(debug_output);
+    }
     exit_without_destructors(exit_status);
     return EXIT_FAILURE;  // above line should always exit
 }

src/flog.cpp

@@ -0,0 +1,94 @@
+// fish logging
+#include "config.h"
+
+#include "flog.h"
+#include "global_safety.h"
+
+#include "common.h"
+#include "enum_set.h"
+#include "parse_util.h"
+#include "wildcard.h"
+
+#include <vector>
+
+namespace flog_details {
+
+// Note we are relying on the order of global initialization within this file.
+// It is important that 'all' be initialized before 'g_categories', because g_categories wants to
+// append to all in the ctor.
+/// This is not modified after initialization.
+static std::vector<category_t *> s_all_categories;
+
+/// When a category is instantiated it adds itself to the 'all' list.
+category_t::category_t(const wchar_t *name, const wchar_t *desc, bool enabled)
+    : name(name), description(desc), enabled(enabled) {
+    s_all_categories.push_back(this);
+}
+
+/// Instantiate all categories.
+/// This is deliberately leaked to avoid pointless destructor registration.
+category_list_t *const category_list_t::g_instance = new category_list_t();
+
+logger_t::logger_t() : file_(stderr) {}
+
+owning_lock<logger_t> g_logger;
+
+void logger_t::log1(const wchar_t *s) { std::fputws(s, file_); }
+void logger_t::log1(const char *s) { std::fputs(s, file_); }
+
+void logger_t::log1(wchar_t c) { std::fputwc(c, file_); }
+void logger_t::log1(char c) { std::fputc(c, file_); }
+
+void logger_t::log_fmt(const category_t &cat, const wchar_t *fmt, ...) {
+    va_list va;
+    va_start(va, fmt);
+    log1(cat.name);
+    log1(": ");
+    std::vfwprintf(file_, fmt, va);
+    log1('\n');
+    va_end(va);
+}
+
+void logger_t::log_fmt(const category_t &cat, const char *fmt, ...) {
+    va_list va;
+    va_start(va, fmt);
+    log1(cat.name);
+    log1(": ");
+    std::vfprintf(file_, fmt, va);
+    log1('\n');
+    va_end(va);
+}
+
+}  // namespace flog_details
+
+using namespace flog_details;
+
+/// For each category, if its name matches the wildcard, set its enabled to the given sense.
+static void apply_one_wildcard(const wcstring &wc_esc, bool sense) {
+    wcstring wc = parse_util_unescape_wildcards(wc_esc);
+    for (category_t *cat : s_all_categories) {
+        if (wildcard_match(cat->name, wc)) {
+            cat->enabled = sense;
+        }
+    }
+}
+
+void activate_flog_categories_by_pattern(const wcstring &wc) {
+    for (const wcstring &s : split_string(wc, L',')) {
+        if (string_prefixes_string(s, L"-")) {
+            apply_one_wildcard(s.substr(1), false);
+        } else {
+            apply_one_wildcard(s, true);
+        }
+    }
+}
+
+void set_flog_output_file(FILE *f) { g_logger.acquire()->set_file(f); }
+
+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) {
+        return wcscmp(a->name, b->name) < 0;
+    });
+    return result;
+}

src/flog.h

@@ -0,0 +1,133 @@
+/// The flogger: debug logging support for fish.
+#ifndef FISH_FLOG_H
+#define FISH_FLOG_H
+
+#include "config.h"  // IWYU pragma: keep
+
+#include "global_safety.h"
+
+#include <stdio.h>
+#include <string>
+#include <type_traits>
+#include <utility>
+
+using wcstring = std::wstring;
+using wcstring_list_t = std::vector<wcstring>;
+
+template <typename T>
+class owning_lock;
+
+namespace flog_details {
+
+class category_list_t;
+class category_t {
+    friend category_list_t;
+    category_t(const wchar_t *name, const wchar_t *desc, bool enabled = false);
+
+   public:
+    /// The name of this category.
+    const wchar_t *const name;
+
+    /// A (non-localized) description of the category.
+    const wchar_t *const description;
+
+    /// Whether the category is enabled.
+    relaxed_atomic_bool_t enabled;
+};
+
+class category_list_t {
+    category_list_t() = default;
+
+   public:
+    /// The singleton global category list instance.
+    static category_list_t *const g_instance;
+
+    /// What follows are the actual logging categories.
+    /// To add a new category simply define a new field, following the pattern.
+
+    category_t error{L"error", L"Serious unexpected errors (on by default)", true};
+
+    category_t debug{L"debug", L"Debugging aid (on by default)", true};
+};
+
+/// The class responsible for logging.
+/// This is protected by a lock.
+class logger_t {
+    FILE *file_;
+
+    void log1(const wchar_t *);
+    void log1(const char *);
+    void log1(wchar_t);
+    void log1(char);
+
+    void log1(const wcstring &s) { log1(s.c_str()); }
+    void log1(const std::string &s) { log1(s.c_str()); }
+
+    template <typename T,
+              typename Enabler = typename std::enable_if<std::is_integral<T>::value>::type>
+    void log1(const T &v) {
+        log1(to_string(v));
+    }
+
+    template <typename T>
+    void log_args_impl(const T &arg) {
+        log1(arg);
+    }
+
+    template <typename T, typename... Ts>
+    void log_args_impl(const T &arg, const Ts &... rest) {
+        log1(arg);
+        log1(' ');
+        log_args_impl<Ts...>(rest...);
+    }
+
+   public:
+    void set_file(FILE *f) { file_ = f; }
+
+    logger_t();
+
+    template <typename... Args>
+    void log_args(const category_t &cat, const Args &... args) {
+        log1(cat.name);
+        log1(": ");
+        log_args_impl(args...);
+        log1('\n');
+    }
+
+    void log_fmt(const category_t &cat, const wchar_t *fmt, ...);
+    void log_fmt(const category_t &cat, const char *fmt, ...);
+};
+
+extern owning_lock<logger_t> g_logger;
+
+}  // namespace flog_details
+
+/// Set the active flog categories according to the given wildcard \p wc.
+void activate_flog_categories_by_pattern(const wcstring &wc);
+
+/// Set the file that flog should output to.
+/// flog does not close this file.
+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();
+
+/// Output to the fish log a sequence of arguments, separated by spaces, and ending with a newline.
+#define FLOG(wht, ...)                                                        \
+    do {                                                                      \
+        if (flog_details::category_list_t::g_instance->wht.enabled) {         \
+            flog_details::g_logger.acquire()->log_args(                       \
+                flog_details::category_list_t::g_instance->wht, __VA_ARGS__); \
+        }                                                                     \
+    } while (0)
+
+/// Output to the fish log a printf-style formatted string.
+#define FLOGF(wht, ...)                                                       \
+    do {                                                                      \
+        if (flog_details::category_list_t::g_instance->wht.enabled) {         \
+            flog_details::g_logger.acquire()->log_fmt(                        \
+                flog_details::category_list_t::g_instance->wht, __VA_ARGS__); \
+        }                                                                     \
+    } while (0)
+
+#endif