From e753581df796c46bc57ebdebc5851bc59d4fe724 Mon Sep 17 00:00:00 2001 From: Mahmoud Al-Qudsi Date: Tue, 2 Oct 2018 11:19:56 -0500 Subject: [PATCH] Bring some consistency and rationale to debug log levels * Debug level 3: describe all commands being executed (this is, after all, a shell and one can argue that this is the most important debug information avaliable) * Debug level 4: details of execution, mainly fork vs no-fork and io handling Also introduced j->preview() to print a short descriptor of the job based on the head of the first process so we don't overwhelm with needless repitition, but also so that we don't have to rely on distinguishing between repeated, non-unique/non-monotonic job ids that are often recycled within a single "execution cycle" (pressing enter once). --- src/env.cpp | 10 +++++----- src/exec.cpp | 19 ++++++++++--------- src/parse_productions.cpp | 3 ++- src/path.cpp | 4 ++-- src/proc.cpp | 8 ++++---- src/proc.h | 9 +++++++++ 6 files changed, 32 insertions(+), 21 deletions(-) diff --git a/src/env.cpp b/src/env.cpp index c3e8b97be..68f9d0f5d 100644 --- a/src/env.cpp +++ b/src/env.cpp @@ -375,22 +375,22 @@ static void init_locale() { const auto var = env_get(var_name, ENV_EXPORT); const std::string &name = wcs2string(var_name); if (var.missing_or_empty()) { - debug(2, L"locale var %s missing or empty", name.c_str()); + debug(5, L"locale var %s missing or empty", name.c_str()); unsetenv(name.c_str()); } else { const std::string value = wcs2string(var->as_string()); - debug(2, L"locale var %s='%s'", name.c_str(), value.c_str()); + debug(5, L"locale var %s='%s'", name.c_str(), value.c_str()); setenv(name.c_str(), value.c_str(), 1); } } char *locale = setlocale(LC_ALL, ""); fish_setlocale(); - debug(2, L"init_locale() setlocale(): '%s'", locale); + debug(5, L"init_locale() setlocale(): '%s'", locale); const char *new_msg_locale = setlocale(LC_MESSAGES, NULL); - debug(3, L"old LC_MESSAGES locale: '%s'", old_msg_locale); - debug(3, L"new LC_MESSAGES locale: '%s'", new_msg_locale); + debug(5, L"old LC_MESSAGES locale: '%s'", old_msg_locale); + debug(5, L"new LC_MESSAGES locale: '%s'", new_msg_locale); #ifdef HAVE__NL_MSG_CAT_CNTR if (strcmp(old_msg_locale, new_msg_locale)) { // Make change known to GNU gettext. diff --git a/src/exec.cpp b/src/exec.cpp index e4d63b073..2cd1057c1 100644 --- a/src/exec.cpp +++ b/src/exec.cpp @@ -423,7 +423,7 @@ static bool fork_child_for_process(job_t *j, process_t *p, const io_chain_t &io_ // This is the parent process. Store away information on the child, and // possibly give it control over the terminal. - debug(2, L"Fork #%d, pid %d: %s for '%ls'", g_fork_count, pid, fork_type, p->argv0()); + debug(4, L"Fork #%d, pid %d: %s for '%ls'", g_fork_count, pid, fork_type, p->argv0()); p->pid = pid; on_process_created(j, p->pid); @@ -573,7 +573,7 @@ static bool handle_builtin_output(job_t *j, process_t *p, io_chain_t *io_chain, if (!stdout_discarded && no_stdout_output && no_stderr_output) { // The builtin produced no output and is not inside of a pipeline. No // need to fork or even output anything. - debug(3, L"Skipping fork: no output for internal builtin '%ls'", p->argv0()); + debug(4, L"Skipping fork: no output for internal builtin '%ls'", p->argv0()); fork_was_skipped = true; } else if (no_stderr_output && stdout_is_to_buffer) { // The builtin produced no stderr, and its stdout is going to an @@ -585,14 +585,14 @@ static bool handle_builtin_output(job_t *j, process_t *p, io_chain_t *io_chain, // through to the io buffer. We're getting away with this because the only // thing that can output exp-sep output is `string split0` which doesn't // also produce stderr. - debug(3, L"Skipping fork: buffered output for internal builtin '%ls'", p->argv0()); + debug(4, L"Skipping fork: buffered output for internal builtin '%ls'", p->argv0()); io_buffer_t *io_buffer = static_cast(stdout_io.get()); io_buffer->append_from_stream(stdout_stream); fork_was_skipped = true; } else if (stdout_io.get() == NULL && stderr_io.get() == NULL) { // We are writing to normal stdout and stderr. Just do it - no need to fork. - debug(3, L"Skipping fork: ordinary output for internal builtin '%ls'", p->argv0()); + debug(4, L"Skipping fork: ordinary output for internal builtin '%ls'", p->argv0()); const std::string outbuff = wcs2string(stdout_stream.contents()); const std::string errbuff = wcs2string(stderr_stream.contents()); bool builtin_io_done = @@ -610,7 +610,7 @@ static bool handle_builtin_output(job_t *j, process_t *p, io_chain_t *io_chain, if (fork_was_skipped) { p->completed = 1; if (p->is_last_in_job) { - debug(3, L"Set status of %ls to %d using short circuit", j->command_wcstr(), p->status); + debug(4, L"Set status of job %d (%ls) to %d using short circuit", j->job_id, j->preview().c_str(), p->status); int status = p->status; proc_set_last_status(j->get_flag(JOB_NEGATE) ? (!status) : status); @@ -698,7 +698,7 @@ static bool exec_external_command(job_t *j, process_t *p, const io_chain_t &proc // 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(2, L"Fork #%d, pid %d: spawn external command '%s' from '%ls'", g_fork_count, pid, + debug(4, L"Fork #%d, pid %d: spawn external command '%s' from '%ls'", g_fork_count, pid, actual_cmd, file ? file : L""); if (pid == 0) { job_mark_process_as_failed(j, p); @@ -996,8 +996,6 @@ void exec_job(parser_t &parser, job_t *j) { return; } - debug(4, L"Exec job '%ls' with id %d", j->command_wcstr(), j->job_id); - // Verify that all IO_BUFFERs are output. We used to support a (single, hacked-in) magical input // IO_BUFFER used by fish_pager, but now the claim is that there are no more clients and it is // removed. This assertion double-checks that. @@ -1062,7 +1060,7 @@ void exec_job(parser_t &parser, job_t *j) { exit_without_destructors(0); } else { // Parent - debug(2, L"Fork #%d, pid %d: keepalive fork for '%ls'", g_fork_count, keepalive.pid, + debug(4, L"Fork #%d, pid %d: keepalive fork for '%ls'", g_fork_count, keepalive.pid, j->command_wcstr()); on_process_created(j, keepalive.pid); set_child_group(j, keepalive.pid); @@ -1092,6 +1090,9 @@ void exec_job(parser_t &parser, job_t *j) { } pipe_next_read.close(); + + debug(3, L"Created job %d from command '%ls' with pgrp %d", j->job_id, j->command_wcstr(), j->pgid); + // The keepalive process is no longer needed, so we terminate it with extreme prejudice. if (needs_keepalive) { kill(keepalive.pid, SIGKILL); diff --git a/src/parse_productions.cpp b/src/parse_productions.cpp index d7f276446..4718d826a 100644 --- a/src/parse_productions.cpp +++ b/src/parse_productions.cpp @@ -362,7 +362,8 @@ const production_element_t *parse_productions::production_for_token(parse_token_ const parse_token_t &input1, const parse_token_t &input2, parse_node_tag_t *out_tag) { - debug(5, "Resolving production for %ls with input token <%ls>", + // this is **extremely** chatty + debug(6, "Resolving production for %ls with input token <%ls>", token_type_description(node_type), input1.describe().c_str()); // Fetch the function to resolve the list of productions. diff --git a/src/path.cpp b/src/path.cpp index 4ed4e0c20..ed427af11 100644 --- a/src/path.cpp +++ b/src/path.cpp @@ -33,7 +33,7 @@ const wcstring_list_t dflt_pathsv({L"/bin", L"/usr/bin", PREFIX L"/bin"}); static bool path_get_path_core(const wcstring &cmd, wcstring *out_path, const maybe_t &bin_path_var) { - debug(3, L"path_get_path( '%ls' )", cmd.c_str()); + debug(5, L"path_get_path( '%ls' )", cmd.c_str()); // If the command has a slash, it must be an absolute or relative path and thus we don't bother // looking for a matching command. @@ -124,7 +124,7 @@ bool path_get_path(const wcstring &cmd, wcstring *out_path) { } wcstring_list_t path_get_paths(const wcstring &cmd) { - debug(3, L"path_get_paths('%ls')", cmd.c_str()); + debug(5, L"path_get_paths('%ls')", cmd.c_str()); wcstring_list_t paths; // If the command has a slash, it must be an absolute or relative path and thus we don't bother diff --git a/src/proc.cpp b/src/proc.cpp index d5c5654ff..3178afc51 100644 --- a/src/proc.cpp +++ b/src/proc.cpp @@ -384,7 +384,7 @@ static bool process_mark_finished_children(bool block_on_fg) { // A job can have pgrp INVALID_PID if it consists solely of builtins that perform no IO if (j->pgid == INVALID_PID || !j->get_flag(JOB_CONSTRUCTED)) { // Job has not been fully constructed yet - debug(4, "Skipping wait on incomplete job %d", j->pgid); + debug(5, "Skipping wait on incomplete job %d (%ls)", j->job_id, j->preview().c_str()); continue; } @@ -724,7 +724,7 @@ static int select_try(job_t *j) { // fwprintf( stderr, L"fd %d on job %ls\n", fd, j->command ); FD_SET(fd, &fds); maxfd = maxi(maxfd, fd); - debug(3, L"select_try on %d", fd); + debug(4, L"select_try on %d", fd); } } @@ -737,7 +737,7 @@ static int select_try(job_t *j) { retval = select(maxfd + 1, &fds, 0, 0, &tv); if (retval == 0) { - debug(3, L"select_try hit timeout"); + debug(4, L"select_try hit timeout"); } return retval > 0; } @@ -761,7 +761,7 @@ static void read_try(job_t *j) { } if (buff) { - debug(3, L"proc::read_try('%ls')", j->command_wcstr()); + debug(4, L"proc::read_try('%ls')", j->command_wcstr()); while (1) { char b[BUFFER_SIZE]; long len = read_blocked(buff->pipe_fd[0], b, BUFFER_SIZE); diff --git a/src/proc.h b/src/proc.h index aac296af2..718280ab9 100644 --- a/src/proc.h +++ b/src/proc.h @@ -192,6 +192,15 @@ class job_t { /// Sets the command. void set_command(const wcstring &cmd) { command_str = cmd; } + /// Returns a truncated version of the job string. Used when a message has already been emitted + /// containing the full job string and job id, but using the job id alone would be confusing + /// due to reuse of freed job ids. Prevents overloading the debug comments with the full, + /// untruncated job string when we don't care what the job is, only which of the currently + /// running jobs it is. + wcstring preview() const { + return processes.empty() ? L"" : processes[0]->argv0() + wcstring(L" ..."); + } + /// All the processes in this job. process_list_t processes;