Merge branch 'flog'

This merges support for FLOG, a replacement for debug().

Fixes #5879
This commit is contained in:
ridiculousfish 2019-05-27 18:20:22 -07:00
commit b9ef8797f1
28 changed files with 410 additions and 100 deletions

View File

@ -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).

View File

@ -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.

View File

@ -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.

View File

@ -66,6 +66,7 @@
#include "complete.h"
#include "exec.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "intern.h"
#include "io.h"
#include "parse_constants.h"
@ -469,7 +470,7 @@ proc_status_t builtin_run(parser_t &parser, int job_pgid, wchar_t **argv, io_str
return proc_status_t::from_exit_code(ret);
}
debug(0, UNKNOWN_BUILTIN_ERR_MSG, argv[0]);
FLOGF(error, UNKNOWN_BUILTIN_ERR_MSG, argv[0]);
return proc_status_t::from_exit_code(STATUS_CMD_ERROR);
}

View File

@ -52,6 +52,7 @@
#include "env.h"
#include "expand.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "future_feature_flags.h"
#include "global_safety.h"
#include "proc.h"
@ -2121,8 +2122,8 @@ int create_directory(const wcstring &d) {
}
[[gnu::noinline]] void bugreport() {
debug(0, _(L"This is a bug. Break on 'bugreport' to debug."));
debug(0, _(L"If you can reproduce it, please report: %s."), PACKAGE_BUGREPORT);
FLOG(error, _(L"This is a bug. Break on 'bugreport' to debug."));
FLOG(error, _(L"If you can reproduce it, please report: "), PACKAGE_BUGREPORT, '.');
}
wcstring format_size(long long sz) {
@ -2314,24 +2315,24 @@ bool is_main_thread() {
void assert_is_main_thread(const char *who) {
if (!is_main_thread() && !thread_asserts_cfg_for_testing) {
debug(0, "%s called off of main thread.", who);
debug(0, "Break on debug_thread_error to debug.");
FLOGF(error, "%s called off of main thread.", who);
FLOGF(error, "Break on debug_thread_error to debug.");
debug_thread_error();
}
}
void assert_is_not_forked_child(const char *who) {
if (is_forked_child()) {
debug(0, "%s called in a forked child.", who);
debug(0, "Break on debug_thread_error to debug.");
FLOGF(error, "%s called in a forked child.", who);
FLOGF(error, "Break on debug_thread_error to debug.");
debug_thread_error();
}
}
void assert_is_background_thread(const char *who) {
if (is_main_thread() && !thread_asserts_cfg_for_testing) {
debug(0, "%s called on the main thread (may block!).", who);
debug(0, "Break on debug_thread_error to debug.");
FLOGF(error, "%s called on the main thread (may block!).", who);
FLOGF(error, "Break on debug_thread_error to debug.");
debug_thread_error();
}
}
@ -2342,8 +2343,8 @@ void assert_is_locked(void *vmutex, const char *who, const char *caller) {
// Note that std::mutex.try_lock() is allowed to return false when the mutex isn't
// actually locked; fortunately we are checking the opposite so we're safe.
if (mutex->try_lock()) {
debug(0, "%s is not locked when it should be in '%s'", who, caller);
debug(0, "Break on debug_thread_error to debug.");
FLOGF(error, "%s is not locked when it should be in '%s'", who, caller);
FLOGF(error, "Break on debug_thread_error to debug.");
debug_thread_error();
mutex->unlock();
}
@ -2436,10 +2437,10 @@ void redirect_tty_output() {
/// Display a failed assertion message, dump a stack trace if possible, then die.
[[noreturn]] void __fish_assert(const char *msg, const char *file, size_t line, int error) {
if (error) {
debug(0, L"%s:%zu: failed assertion: %s: errno %d (%s)", file, line, msg, error,
std::strerror(error));
FLOG(error, L"%s:%zu: failed assertion: %s: errno %d (%s)", file, line, msg, error,
std::strerror(error));
} else {
debug(0, L"%s:%zu: failed assertion: %s", file, line, msg);
FLOG(error, L"%s:%zu: failed assertion: %s", file, line, msg);
}
show_stackframe(L'E', 99, 1);
abort();

View File

@ -904,7 +904,7 @@ bool completer_t::complete_param(const wcstring &cmd_orig, const wcstring &popt,
}
};
// debug(0, L"\nThinking about looking up completions for %ls\n", cmd.c_str());
// FLOG(error, L"\nThinking about looking up completions for %ls\n", cmd.c_str());
bool head_exists = builtin_exists(cmd);
// Only reload environment variables if builtin_exists returned false, as an optimization
if (head_exists == false) {

View File

@ -24,6 +24,7 @@
#include "event.h"
#include "fallback.h" // IWYU pragma: keep
#include "fish_version.h"
#include "flog.h"
#include "global_safety.h"
#include "history.h"
#include "input.h"
@ -139,7 +140,7 @@ void fix_colon_delimited_var(const wcstring &var_name, env_stack_t &vars) {
std::replace(newstrs.begin(), newstrs.end(), empty, wcstring(L"."));
int retval = vars.set(var_name, ENV_DEFAULT | ENV_USER, std::move(newstrs));
if (retval != ENV_OK) {
debug(0, L"fix_colon_delimited_var failed unexpectedly with retval %d", retval);
FLOG(error, L"fix_colon_delimited_var failed unexpectedly with retval %d", retval);
}
}
}
@ -1351,8 +1352,8 @@ wcstring env_get_runtime_path() {
}
if (!uname || check_runtime_path(tmpdir.c_str()) != 0) {
debug(0, L"Runtime path not available.");
debug(0, L"Try deleting the directory %s and restarting fish.", tmpdir.c_str());
FLOG(error, L"Runtime path not available.");
FLOG(error, L"Try deleting the directory %s and restarting fish.", tmpdir.c_str());
return result;
}

View File

@ -38,6 +38,7 @@
#include "env_universal_common.h"
#include "event.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "function.h"
#include "global_safety.h"
#include "history.h"
@ -498,22 +499,22 @@ static void init_locale(const environment_t &vars) {
const auto var = vars.get(var_name, ENV_EXPORT);
const std::string &name = wcs2string(var_name);
if (var.missing_or_empty()) {
debug(5, L"locale var %s missing or empty", name.c_str());
FLOGF(env_locale, L"locale var %s missing or empty", name.c_str());
unsetenv_lock(name.c_str());
} else {
const std::string value = wcs2string(var->as_string());
debug(5, L"locale var %s='%s'", name.c_str(), value.c_str());
FLOGF(env_locale, L"locale var %s='%s'", name.c_str(), value.c_str());
setenv_lock(name.c_str(), value.c_str(), 1);
}
}
char *locale = setlocale(LC_ALL, "");
fish_setlocale();
debug(5, L"init_locale() setlocale(): '%s'", locale);
FLOGF(env_locale, L"init_locale() setlocale(): '%s'", locale);
const char *new_msg_locale = setlocale(LC_MESSAGES, NULL);
debug(5, L"old LC_MESSAGES locale: '%s'", old_msg_locale);
debug(5, L"new LC_MESSAGES locale: '%s'", new_msg_locale);
FLOGF(env_locale, L"old LC_MESSAGES locale: '%s'", old_msg_locale);
FLOGF(env_locale, L"new LC_MESSAGES locale: '%s'", new_msg_locale);
#ifdef HAVE__NL_MSG_CAT_CNTR
if (std::strcmp(old_msg_locale, new_msg_locale)) {
// Make change known to GNU gettext.

View File

@ -40,6 +40,7 @@
#include "env.h"
#include "env_universal_common.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "path.h"
#include "utf8.h"
#include "util.h" // IWYU pragma: keep
@ -195,11 +196,11 @@ static bool append_file_entry(env_var_t::env_var_flags_t flags, const wcstring &
// Append variable name like "fish_color_cwd".
if (!valid_var_name(key_in)) {
debug(0, L"Illegal variable name: '%ls'", key_in.c_str());
FLOG(error, L"Illegal variable name: '%ls'", key_in.c_str());
success = false;
}
if (success && !append_utf8(key_in, result, storage)) {
debug(0, L"Could not convert %ls to narrow character string", key_in.c_str());
FLOG(error, L"Could not convert %ls to narrow character string", key_in.c_str());
success = false;
}
@ -210,7 +211,7 @@ static bool append_file_entry(env_var_t::env_var_flags_t flags, const wcstring &
// Append value.
if (success && !append_utf8(full_escape(val_in), result, storage)) {
debug(0, L"Could not convert %ls to narrow character string", val_in.c_str());
FLOG(error, L"Could not convert %ls to narrow character string", val_in.c_str());
success = false;
}
@ -447,7 +448,8 @@ bool env_universal_t::write_to_fd(int fd, const wcstring &path) {
std::string contents = serialize_with_vars(vars);
if (write_loop(fd, contents.data(), contents.size()) < 0) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to write to universal variables file '%ls': %s"), path.c_str(), error);
FLOG(error, _(L"Unable to write to universal variables file '%ls': %s"), path.c_str(),
error);
success = false;
}
@ -462,8 +464,8 @@ bool env_universal_t::move_new_vars_file_into_place(const wcstring &src, const w
int ret = wrename(src, dst);
if (ret != 0) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to rename file from '%ls' to '%ls': %s"), src.c_str(), dst.c_str(),
error);
FLOG(error, _(L"Unable to rename file from '%ls' to '%ls': %s"), src.c_str(), dst.c_str(),
error);
}
return ret == 0;
}
@ -525,7 +527,7 @@ bool env_universal_t::open_temporary_file(const wcstring &directory, wcstring *o
if (!success) {
const char *error = std::strerror(saved_errno);
debug(0, _(L"Unable to open temporary file '%ls': %s"), out_path->c_str(), error);
FLOG(error, _(L"Unable to open temporary file '%ls': %s"), out_path->c_str(), error);
}
return success;
}
@ -587,7 +589,8 @@ bool env_universal_t::open_and_acquire_lock(const wcstring &path, int *out_fd) {
}
#endif
const char *error = std::strerror(errno);
debug(0, _(L"Unable to open universal variable file '%ls': %s"), path.c_str(), error);
FLOG(error, _(L"Unable to open universal variable file '%ls': %s"), path.c_str(),
error);
break;
}
@ -1058,7 +1061,7 @@ class universal_notifier_shmem_poller_t : public universal_notifier_t {
int fd = shm_open(path, O_RDWR | O_CREAT, 0600);
if (fd < 0) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to open shared memory with path '%s': %s"), path, error);
FLOG(error, _(L"Unable to open shared memory with path '%s': %s"), path, error);
errored = true;
}
@ -1068,8 +1071,8 @@ class universal_notifier_shmem_poller_t : public universal_notifier_t {
struct stat buf = {};
if (fstat(fd, &buf) < 0) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to fstat shared memory object with path '%s': %s"), path,
error);
FLOG(error, _(L"Unable to fstat shared memory object with path '%s': %s"), path,
error);
errored = true;
}
size = buf.st_size;
@ -1079,7 +1082,8 @@ class universal_notifier_shmem_poller_t : public universal_notifier_t {
bool set_size = !errored && size < (off_t)sizeof(universal_notifier_shmem_t);
if (set_size && ftruncate(fd, sizeof(universal_notifier_shmem_t)) < 0) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to truncate shared memory object with path '%s': %s"), path, error);
FLOG(error, _(L"Unable to truncate shared memory object with path '%s': %s"), path,
error);
errored = true;
}
@ -1089,8 +1093,8 @@ class universal_notifier_shmem_poller_t : public universal_notifier_t {
MAP_SHARED, fd, 0);
if (addr == MAP_FAILED) {
const char *error = std::strerror(errno);
debug(0, _(L"Unable to memory map shared memory object with path '%s': %s"), path,
error);
FLOG(error, _(L"Unable to memory map shared memory object with path '%s': %s"),
path, error);
this->region = NULL;
} else {
this->region = static_cast<universal_notifier_shmem_t *>(addr);
@ -1495,7 +1499,7 @@ void universal_notifier_named_pipe_t::make_pipe(const wchar_t *test_path) {
if (mkfifo_status == -1 && errno != EEXIST) {
const char *error = std::strerror(errno);
const wchar_t *errmsg = _(L"Unable to make a pipe for universal variables using '%ls': %s");
debug(0, errmsg, vars_path.c_str(), error);
FLOG(error, errmsg, vars_path.c_str(), error);
pipe_fd = -1;
return;
}
@ -1504,7 +1508,7 @@ void universal_notifier_named_pipe_t::make_pipe(const wchar_t *test_path) {
if (fd < 0) {
const char *error = std::strerror(errno);
const wchar_t *errmsg = _(L"Unable to open a pipe for universal variables using '%ls': %s");
debug(0, errmsg, vars_path.c_str(), error);
FLOG(error, errmsg, vars_path.c_str(), error);
pipe_fd = -1;
return;
}

View File

@ -32,6 +32,7 @@
#include "env.h"
#include "exec.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "function.h"
#include "io.h"
#include "iothread.h"
@ -61,7 +62,7 @@ void exec_close(int fd) {
// This may be called in a child of fork(), so don't allocate memory.
if (fd < 0) {
debug(0, L"Called close on invalid file descriptor ");
FLOG(error, L"Called close on invalid file descriptor ");
return;
}
@ -451,7 +452,7 @@ static bool fork_child_for_process(const std::shared_ptr<job_t> &job, process_t
// This is the parent process. Store away information on the child, and
// possibly give it control over the terminal.
debug(4, L"Fork #%d, pid %d: %s for '%ls'", g_fork_count, pid, fork_type, p->argv0());
FLOGF(exec_fork, L"Fork #%d, pid %d: %s for '%ls'", g_fork_count, pid, fork_type, p->argv0());
p->pid = pid;
on_process_created(job, p->pid);
@ -613,20 +614,20 @@ static bool handle_builtin_output(parser_t &parser, const std::shared_ptr<job_t>
if (write_loop(STDOUT_FILENO, outbuff.data(), outbuff.size()) < 0) {
if (errno != EPIPE) {
did_err = true;
debug(0, "Error while writing to stdout");
FLOG(error, "Error while writing to stdout");
wperror(L"write_loop");
}
}
if (write_loop(STDERR_FILENO, errbuff.data(), errbuff.size()) < 0) {
if (errno != EPIPE && !did_err) {
did_err = true;
debug(0, "Error while writing to stderr");
FLOG(error, "Error while writing to stderr");
wperror(L"write_loop");
}
}
if (did_err) {
redirect_tty_output(); // workaround glibc bug
debug(0, "!builtin_io_done and errno != EPIPE");
FLOG(error, "!builtin_io_done and errno != EPIPE");
show_stackframe(L'E');
}
// Clear the buffers to indicate we finished.
@ -639,8 +640,8 @@ static bool handle_builtin_output(parser_t &parser, const std::shared_ptr<job_t>
// TODO: factor this job-status-setting stuff into a single place.
p->completed = 1;
if (p->is_last_in_job) {
debug(4, L"Set status of job %d (%ls) to %d using short circuit", j->job_id,
j->preview().c_str(), p->status);
FLOGF(exec_job_status, L"Set status of job %d (%ls) to %d using short circuit",
j->job_id, j->preview().c_str(), p->status);
parser.set_last_statuses(j->get_statuses());
}
return true;
@ -714,7 +715,7 @@ static bool exec_external_command(parser_t &parser, const std::shared_ptr<job_t>
// A 0 pid means we failed to posix_spawn. Since we have no pid, we'll never get
// told when it's exited, so we have to mark the process as failed.
debug(4, L"Fork #%d, pid %d: spawn external command '%s' from '%ls'", g_fork_count, pid,
FLOGF(exec_fork, L"Fork #%d, pid %d: spawn external command '%s' from '%ls'", g_fork_count, pid,
actual_cmd, file ? file : L"<no file>");
if (pid == 0) {
job_mark_process_as_failed(j, p);
@ -788,7 +789,7 @@ static bool exec_block_or_func_process(parser_t &parser, std::shared_ptr<job_t>
const wcstring func_name = p->argv0();
auto props = function_get_properties(func_name);
if (!props) {
debug(0, _(L"Unknown function '%ls'"), p->argv0());
FLOG(error, _(L"Unknown function '%ls'"), p->argv0());
return false;
}
@ -1096,8 +1097,8 @@ bool exec_job(parser_t &parser, shared_ptr<job_t> j) {
}
}
debug(3, L"Created job %d from command '%ls' with pgrp %d", j->job_id, j->command_wcstr(),
j->pgid);
FLOG(exec_job_exec, "Executed job", j->job_id, "from command", j->command_wcstr(), "with pgrp",
j->pgid);
j->set_flag(job_flag_t::CONSTRUCTED, true);
if (!j->is_foreground()) {

View File

@ -222,7 +222,7 @@ static size_t parse_slice(const wchar_t *in, wchar_t **end_ptr, std::vector<long
}
// debug( 0, L"Push range idx %d %d", i1, i2 );
for (long jjj = i1; jjj * direction <= i2 * direction; jjj += direction) {
// debug(0, L"Expand range [subst]: %i\n", jjj);
// FLOG(error, L"Expand range [subst]: %i\n", jjj);
idx.push_back(jjj);
}
continue;

View File

@ -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
}

97
src/flog.cpp Normal file
View File

@ -0,0 +1,97 @@
// 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 &inwc) {
// Normalize underscores to dashes, allowing the user to be sloppy.
wcstring wc = inwc;
std::replace(wc.begin(), wc.end(), L'_', L'-');
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;
}

145
src/flog.h Normal file
View File

@ -0,0 +1,145 @@
/// 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};
category_t exec_job_status{L"exec-job-status", L"Jobs changing status"};
category_t exec_job_exec{L"exec-job-exec", L"Jobs being executed"};
category_t exec_fork{L"exec-fork", L"Calls to fork()"};
category_t proc_job_run{L"proc-job-run", L"Jobs getting started or continued"};
category_t proc_termowner{L"proc-termowner", L"Terminal ownership events"};
category_t env_locale{L"env-locale", L"Changes to locale variables"};
};
/// 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

View File

@ -1237,7 +1237,7 @@ bool history_t::rewrite_to_temporary_file(int existing_fd, int dst_fd) const {
const history_item_t old_item = decode_item(*local_file, offset);
if (old_item.empty() || deleted_items.count(old_item.str()) > 0) {
// debug(0, L"Item is deleted : %s\n", old_item.str().c_str());
// FLOG(error, L"Item is deleted : %s\n", old_item.str().c_str());
continue;
}
// Add this old item.

View File

@ -15,6 +15,7 @@
#include <queue>
#include "common.h"
#include "flog.h"
#include "global_safety.h"
#include "iothread.h"
#include "wutil.h"
@ -201,7 +202,7 @@ void iothread_service_completion() {
} else if (wakeup_byte == IO_SERVICE_RESULT_QUEUE) {
iothread_service_result_queue();
} else {
debug(0, "Unknown wakeup byte %02x in %s", wakeup_byte, __FUNCTION__);
FLOG(error, "Unknown wakeup byte %02x in %s", wakeup_byte, __FUNCTION__);
}
}

View File

@ -27,6 +27,7 @@
#include "common.h"
#include "env.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "output.h"
#include "wutil.h" // IWYU pragma: keep
@ -528,7 +529,7 @@ void writembs_check(outputter_t &outp, const char *mbs, const char *mbs_name, bo
const wchar_t *fmt =
_(L"Tried to use terminfo string %s on line %ld of %s, which is "
L"undefined in terminal of type \"%ls\". Please report this error to %s");
debug(0, fmt, mbs_name, line, file, term ? term->as_string().c_str() : L"",
PACKAGE_BUGREPORT);
FLOG(error, fmt, mbs_name, line, file, term ? term->as_string().c_str() : L"",
PACKAGE_BUGREPORT);
}
}

View File

@ -8,7 +8,7 @@
#define PARSE_ASSERT(a) assert(a)
#define PARSER_DIE() \
do { \
debug(0, "Parser dying!"); \
FLOG(error, "Parser dying!"); \
exit_without_destructors(-1); \
} while (0)

View File

@ -31,6 +31,7 @@
#include "event.h"
#include "exec.h"
#include "expand.h"
#include "flog.h"
#include "function.h"
#include "io.h"
#include "maybe.h"
@ -358,7 +359,7 @@ parse_execution_result_t parse_execution_context_t::run_block_statement(
} else if (auto header = bheader.try_get_child<g::begin_header, 0>()) {
ret = run_begin_statement(contents);
} else {
debug(0, L"Unexpected block header: %ls\n", bheader.node()->describe().c_str());
FLOG(error, L"Unexpected block header: %ls\n", bheader.node()->describe().c_str());
PARSER_DIE();
}
return ret;
@ -635,7 +636,7 @@ parse_execution_result_t parse_execution_context_t::report_errors(
const parse_error_list_t &error_list) const {
if (!parser->cancellation_requested) {
if (error_list.empty()) {
debug(0, "Error reported but no error text found.");
FLOG(error, "Error reported but no error text found.");
}
// Get a backtrace.
@ -1076,8 +1077,8 @@ parse_execution_result_t parse_execution_context_t::populate_job_process(
break;
}
default: {
debug(0, L"'%ls' not handled by new parser yet.",
specific_statement.describe().c_str());
FLOG(error, L"'%ls' not handled by new parser yet.",
specific_statement.describe().c_str());
PARSER_DIE();
break;
}
@ -1380,8 +1381,8 @@ parse_execution_result_t parse_execution_context_t::eval_node(tnode_t<g::stateme
} else if (auto switchstat = statement.try_get_child<g::switch_statement, 0>()) {
status = this->run_switch_statement(switchstat);
} else {
debug(0, "Unexpected node %ls found in %s", statement.node()->describe().c_str(),
__FUNCTION__);
FLOG(error, "Unexpected node %ls found in %s", statement.node()->describe().c_str(),
__FUNCTION__);
abort();
}
return status;

View File

@ -3,6 +3,7 @@
#include <stdio.h>
#include "common.h"
#include "flog.h"
#include "parse_constants.h"
#include "parse_grammar.h"
#include "parse_productions.h"
@ -402,21 +403,21 @@ const production_element_t *parse_productions::production_for_token(parse_token_
case parse_token_type_oror:
case parse_token_type_end:
case parse_token_type_terminate: {
debug(0, "Terminal token type %ls passed to %s", token_type_description(node_type),
__FUNCTION__);
FLOG(error, "Terminal token type %ls passed to %s", token_type_description(node_type),
__FUNCTION__);
PARSER_DIE();
break;
}
case parse_special_type_parse_error:
case parse_special_type_tokenizer_error:
case parse_special_type_comment: {
debug(0, "Special type %ls passed to %s\n", token_type_description(node_type),
__FUNCTION__);
FLOG(error, "Special type %ls passed to %s\n", token_type_description(node_type),
__FUNCTION__);
PARSER_DIE();
break;
}
case token_type_invalid: {
debug(0, "token_type_invalid passed to %s", __FUNCTION__);
FLOG(error, "token_type_invalid passed to %s", __FUNCTION__);
PARSER_DIE();
break;
}

View File

@ -13,6 +13,7 @@
#include "common.h"
#include "fallback.h"
#include "flog.h"
#include "parse_constants.h"
#include "parse_productions.h"
#include "parse_tree.h"
@ -256,7 +257,7 @@ static inline parse_token_type_t parse_token_type_from_tokenizer_token(
case TOK_COMMENT:
return parse_special_type_comment;
}
debug(0, "Bad token type %d passed to %s", (int)tokenizer_token_type, __FUNCTION__);
FLOG(error, "Bad token type %d passed to %s", (int)tokenizer_token_type, __FUNCTION__);
DIE("bad token type");
return token_type_invalid;
}

View File

@ -18,6 +18,7 @@
#include "env.h"
#include "expand.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "path.h"
#include "wutil.h" // IWYU pragma: keep
@ -267,17 +268,17 @@ static void maybe_issue_path_warning(const wcstring &which_dir, const wcstring &
}
vars.set_one(warning_var_name, ENV_GLOBAL | ENV_EXPORT, L"1");
debug(0, custom_error_msg.c_str());
FLOG(error, custom_error_msg.c_str());
if (path.empty()) {
debug(0, _(L"Unable to locate the %ls directory."), which_dir.c_str());
debug(0, _(L"Please set the %ls or HOME environment variable before starting fish."),
xdg_var.c_str());
FLOG(error, _(L"Unable to locate the %ls directory."), which_dir.c_str());
FLOG(error, _(L"Please set the %ls or HOME environment variable before starting fish."),
xdg_var.c_str());
} else {
const wchar_t *env_var = using_xdg ? xdg_var.c_str() : L"HOME";
debug(0, _(L"Unable to locate %ls directory derived from $%ls: '%ls'."), which_dir.c_str(),
env_var, path.c_str());
debug(0, _(L"The error was '%s'."), std::strerror(saved_errno));
debug(0, _(L"Please set $%ls to a directory where you have write access."), env_var);
FLOG(error, _(L"Unable to locate %ls directory derived from $%ls: '%ls'."),
which_dir.c_str(), env_var, path.c_str());
FLOG(error, _(L"The error was '%s'."), std::strerror(saved_errno));
FLOG(error, _(L"Please set $%ls to a directory where you have write access."), env_var);
}
ignore_result(write(STDERR_FILENO, "\n", 1));
}

View File

@ -15,6 +15,7 @@
#include "common.h"
#include "exec.h"
#include "flog.h"
#include "io.h"
#include "iothread.h"
#include "postfork.h"
@ -143,7 +144,7 @@ bool maybe_assign_terminal(const job_t *j) {
// this can cause an EPERM error. In addition, if we've given control of the terminal to
// a process group, attempting to call tcsetpgrp from the background will cause SIGTTOU
// to be sent to everything in our process group (unless we handle it).
debug(4, L"Process group %d already has control of terminal\n", j->pgid);
FLOGF(proc_termowner, L"Process group %d already has control of terminal", j->pgid);
} else {
// No need to duplicate the code here, a function already exists that does just this.
return terminal_give_to_job(j, false /*new job, so not continuing*/);
@ -373,7 +374,7 @@ void safe_report_exec_error(int err, const char *actual_cmd, const char *const *
const char *err = safe_strerror(errno);
debug_safe(0, "exec: %s", err);
// debug(0, L"The file '%ls' is marked as an executable but could not be run by the
// FLOG(error, L"The file '%ls' is marked as an executable but could not be run by the
// operating system.", p->actual_cmd);
break;
}

View File

@ -38,6 +38,7 @@
#include "common.h"
#include "event.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "global_safety.h"
#include "io.h"
#include "output.h"
@ -685,7 +686,7 @@ void proc_update_jiffies(parser_t &parser) {
// restoring a previously-stopped job, in which case we need to restore terminal attributes.
bool terminal_give_to_job(const job_t *j, bool restore_attrs) {
if (j->pgid == 0) {
debug(2, "terminal_give_to_job() returning early due to no process group");
FLOG(proc_termowner, "terminal_give_to_job() returning early due to no process group");
return true;
}
@ -700,10 +701,10 @@ bool terminal_give_to_job(const job_t *j, bool restore_attrs) {
// to hand over control of the terminal to this process group, which is a no-op if it's already
// been done.
if (j->pgid == INVALID_PID || tcgetpgrp(STDIN_FILENO) == j->pgid) {
debug(4, L"Process group %d already has control of terminal\n", j->pgid);
FLOGF(proc_termowner, L"Process group %d already has control of terminal", j->pgid);
} else {
debug(4,
L"Attempting to bring process group to foreground via tcsetpgrp for job->pgid %d\n",
FLOGF(proc_termowner,
L"Attempting to bring process group to foreground via tcsetpgrp for job->pgid %d",
j->pgid);
// The tcsetpgrp(2) man page says that EPERM is thrown if "pgrp has a supported value, but
@ -716,7 +717,7 @@ bool terminal_give_to_job(const job_t *j, bool restore_attrs) {
// guarantee the process isn't going to exit while we wait (which would cause us to possibly
// block indefinitely).
while (tcsetpgrp(STDIN_FILENO, j->pgid) != 0) {
debug(3, "tcsetpgrp failed: %d", errno);
FLOGF(proc_termowner, "tcsetpgrp failed: %d", errno);
bool pgroup_terminated = false;
// No need to test for EINTR as we are blocking signals
@ -842,8 +843,9 @@ void job_t::continue_job(parser_t &parser, bool reclaim_foreground_pgrp, bool se
parser.job_promote(this);
set_flag(job_flag_t::NOTIFIED, false);
debug(4, L"%ls job %d, gid %d (%ls), %ls, %ls", send_sigcont ? L"Continue" : L"Start", job_id,
pgid, command_wcstr(), is_completed() ? L"COMPLETED" : L"UNCOMPLETED",
FLOGF(proc_job_run, L"%ls job %d, gid %d (%ls), %ls, %ls",
send_sigcont ? L"Continue" : L"Start", job_id, pgid, command_wcstr(),
is_completed() ? L"COMPLETED" : L"UNCOMPLETED",
is_interactive ? L"INTERACTIVE" : L"NON-INTERACTIVE");
// Make sure we retake control of the terminal before leaving this function.
@ -912,8 +914,8 @@ void proc_sanity_check(const parser_t &parser) {
// More than one foreground job?
if (j->is_foreground() && !(j->is_stopped() || j->is_completed())) {
if (fg_job) {
debug(0, _(L"More than one job in foreground: job 1: '%ls' job 2: '%ls'"),
fg_job->command_wcstr(), j->command_wcstr());
FLOG(error, _(L"More than one job in foreground: job 1: '%ls' job 2: '%ls'"),
fg_job->command_wcstr(), j->command_wcstr());
sanity_lose();
}
fg_job = j.get();
@ -926,14 +928,14 @@ void proc_sanity_check(const parser_t &parser) {
validate_pointer(p->argv0(), _(L"Process name"), null_ok);
if ((p->stopped & (~0x00000001)) != 0) {
debug(0, _(L"Job '%ls', process '%ls' has inconsistent state \'stopped\'=%d"),
j->command_wcstr(), p->argv0(), p->stopped);
FLOG(error, _(L"Job '%ls', process '%ls' has inconsistent state \'stopped\'=%d"),
j->command_wcstr(), p->argv0(), p->stopped);
sanity_lose();
}
if ((p->completed & (~0x00000001)) != 0) {
debug(0, _(L"Job '%ls', process '%ls' has inconsistent state \'completed\'=%d"),
j->command_wcstr(), p->argv0(), p->completed);
FLOG(error, _(L"Job '%ls', process '%ls' has inconsistent state \'completed\'=%d"),
j->command_wcstr(), p->argv0(), p->completed);
sanity_lose();
}
}

View File

@ -52,6 +52,7 @@
#include "exec.h"
#include "expand.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "function.h"
#include "global_safety.h"
#include "highlight.h"
@ -1749,7 +1750,7 @@ static void reader_interactive_init() {
if (shell_pgid == 0) {
shell_pgid = getpid();
if (setpgid(shell_pgid, shell_pgid) < 0) {
debug(0, _(L"Failed to assign shell to its own process group"));
FLOG(error, _(L"Failed to assign shell to its own process group"));
wperror(L"setpgid");
exit_without_destructors(1);
}
@ -1759,7 +1760,7 @@ static void reader_interactive_init() {
if (errno == ENOTTY) {
redirect_tty_output();
}
debug(0, _(L"Failed to take control of the terminal"));
FLOG(error, _(L"Failed to take control of the terminal"));
wperror(L"tcsetpgrp");
exit_without_destructors(1);
}

View File

@ -5,6 +5,7 @@
#include "common.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "global_safety.h"
#include "history.h"
#include "kill.h"
@ -16,19 +17,19 @@
static relaxed_atomic_bool_t insane{false};
void sanity_lose() {
debug(0, _(L"Errors detected, shutting down. Break on sanity_lose() to debug."));
FLOG(error, _(L"Errors detected, shutting down. Break on sanity_lose() to debug."));
insane = true;
}
void validate_pointer(const void *ptr, const wchar_t *err, int null_ok) {
// Test if the pointer data crosses a segment boundary.
if ((0x00000003l & (intptr_t)ptr) != 0) {
debug(0, _(L"The pointer '%ls' is invalid"), err);
FLOG(error, _(L"The pointer '%ls' is invalid"), err);
sanity_lose();
}
if ((!null_ok) && (ptr == 0)) {
debug(0, _(L"The pointer '%ls' is null"), err);
FLOG(error, _(L"The pointer '%ls' is null"), err);
sanity_lose();
}
}

View File

@ -243,7 +243,7 @@ tok_t tokenizer_t::read_string() {
} else {
msg.push_back(L'\n');
}
debug(0, msg.c_str(), c, c, int(mode_begin), int(mode));
FLOG(error, msg.c_str(), c, c, int(mode_begin), int(mode));
#endif
this->buff++;

View File

@ -27,6 +27,7 @@
#include "common.h"
#include "fallback.h" // IWYU pragma: keep
#include "flog.h"
#include "wutil.h" // IWYU pragma: keep
typedef std::string cstring;
@ -130,7 +131,7 @@ const wcstring wgetcwd() {
return str2wcstring(res);
}
debug(0, _(L"getcwd() failed with errno %d/%s"), errno, std::strerror(errno));
FLOG(error, _(L"getcwd() failed with errno %d/%s"), errno, std::strerror(errno));
return wcstring();
}