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).
This commit is contained in:
Mahmoud Al-Qudsi 2018-10-02 11:19:56 -05:00
parent 0ff24b35a1
commit e753581df7
6 changed files with 32 additions and 21 deletions

View File

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

View File

@ -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<io_buffer_t *>(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"<no file>");
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);

View File

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

View File

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

View File

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

View File

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