fix fork debug printf() calls

The fork (create new process) related debugging messages rely on an
undocumented env var and use `printf()` rather than `debug()`. There are
also errors in how the fork count is tracked that this fixes.

Fixes #2995

4 files changed, 25 insertions, 52 deletions

diff --git a/src/env.cpp b/src/env.cpp
index 6d5e2ab8..12eef036 100644
--- a/src/env.cpp
+++ b/src/env.cpp
@@ -46,7 +46,6 @@
 /// At init, we read all the environment variables from this array.
 extern char **environ;
 
-bool g_log_forks = false;
 bool g_use_posix_spawn = false;  // will usually be set to true
 
 /// Struct representing one level in the function variable stack.
@@ -392,10 +391,6 @@ void env_init(const struct config_paths_t *paths /* or NULL */) {
     s_universal_variables = new env_universal_t(L"");
     s_universal_variables->load();
 
-    // Set g_log_forks.
-    env_var_t log_forks = env_get_string(L"fish_log_forks");
-    g_log_forks = !log_forks.missing_or_empty() && from_string<bool>(log_forks);
-
     // Set g_use_posix_spawn. Default to true.
     env_var_t use_posix_spawn = env_get_string(L"fish_use_posix_spawn");
     g_use_posix_spawn =
diff --git a/src/env.h b/src/env.h
index 682cf88d..e758a594 100644
--- a/src/env.h
+++ b/src/env.h
@@ -193,9 +193,7 @@ class env_vars_snapshot_t {
     static const wchar_t *const completing_keys[];
 };
 
-extern bool g_log_forks;
 extern int g_fork_count;
-
 extern bool g_use_posix_spawn;
 
 /// A variable entry. Stores the value of a variable and whether it should be exported.
diff --git a/src/exec.cpp b/src/exec.cpp
index 79f461d1..24a9af05 100644
--- a/src/exec.cpp
+++ b/src/exec.cpp
@@ -485,19 +485,17 @@ void exec_job(parser_t &parser, job_t *j) {
 
     if (needs_keepalive) {
         // Call fork. No need to wait for threads since our use is confined and simple.
-        if (g_log_forks) {
-            printf("fork #%d: Executing keepalive fork for '%ls'\n", g_fork_count,
-                   j->command_wcstr());
-        }
         keepalive.pid = execute_fork(false);
         if (keepalive.pid == 0) {
-            /* Child */
+            // Child
             keepalive.pid = getpid();
             set_child_group(j, &keepalive, 1);
             pause();
             exit_without_destructors(0);
         } else {
-            /* Parent */
+            // Parent
+            debug(2, L"Fork #%d, pid %d: keepalive fork for '%ls'", g_fork_count, keepalive.pid,
+                  j->command_wcstr());
             set_child_group(j, &keepalive, 0);
         }
     }
@@ -870,10 +868,6 @@ void exec_job(parser_t &parser, job_t *j) {
 
                 if (block_output_io_buffer->out_buffer_size() > 0) {
                     // We don't have to drain threads here because our child process is simple.
-                    if (g_log_forks) {
-                        printf("Executing fork for internal block or function for '%ls'\n",
-                               p->argv0());
-                    }
                     pid = execute_fork(false);
                     if (pid == 0) {
                         // This is the child process. Write out the contents of the pipeline.
@@ -884,6 +878,8 @@ void exec_job(parser_t &parser, job_t *j) {
                     } else {
                         // 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: internal block or function for '%ls'",
+                              g_fork_count, pid, p->argv0());
                         p->pid = pid;
                         set_child_group(j, p, 0);
                     }
@@ -929,23 +925,15 @@ void exec_job(parser_t &parser, job_t *j) {
                         if (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.
-                            if (g_log_forks) {
-                                // This one is very wordy.
-                                // printf("fork #-: Skipping fork due to no output for internal
-                                // builtin for '%ls'\n", p->argv0());
-                            }
+                            debug(3, 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
                             // internal buffer. There is no need to fork. This helps out the
                             // performance quite a bit in complex completion code.
-                            if (g_log_forks) {
-                                printf(
-                                    "fork #-: Skipping fork due to buffered output for internal "
-                                    "builtin for '%ls'\n",
-                                    p->argv0());
-                            }
-
+                            debug(3, L"Skipping fork: buffered output for internal builtin '%ls'",
+                                  p->argv0());
                             CAST_INIT(io_buffer_t *, io_buffer, stdout_io.get());
                             const std::string res = wcs2string(builtin_io_streams->out.buffer());
                             io_buffer->out_buffer_append(res.data(), res.size());
@@ -953,12 +941,8 @@ void exec_job(parser_t &parser, job_t *j) {
                         } 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.
-                            if (g_log_forks) {
-                                printf(
-                                    "fork #-: Skipping fork due to ordinary output for internal "
-                                    "builtin for '%ls'\n",
-                                    p->argv0());
-                            }
+                            debug(3, L"Skipping fork: ordinary output for internal builtin '%ls'",
+                                  p->argv0());
                             const std::string outbuff = wcs2string(stdout_buffer);
                             const std::string errbuff = wcs2string(stderr_buffer);
                             bool builtin_io_done = do_builtin_io(outbuff.data(), outbuff.size(),
@@ -997,10 +981,6 @@ void exec_job(parser_t &parser, job_t *j) {
 
                     fflush(stdout);
                     fflush(stderr);
-                    if (g_log_forks) {
-                        printf("fork #%d: Executing fork for internal builtin for '%ls'\n",
-                               g_fork_count, p->argv0());
-                    }
                     pid = execute_fork(false);
                     if (pid == 0) {
                         // This is the child process. Setup redirections, print correct output to
@@ -1012,6 +992,8 @@ void exec_job(parser_t &parser, job_t *j) {
                     } else {
                         // 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: internal builtin for '%ls'", g_fork_count, pid,
+                              p->argv0());
                         p->pid = pid;
 
                         set_child_group(j, p, 0);
@@ -1040,16 +1022,13 @@ void exec_job(parser_t &parser, job_t *j) {
                 const char *actual_cmd = actual_cmd_str.c_str();
 
                 const wchar_t *reader_current_filename(void);
-                if (g_log_forks) {
-                    const wchar_t *file = reader_current_filename();
-                    printf("fork #%d: forking for '%s' in '%ls'\n", g_fork_count, actual_cmd,
-                           file ? file : L"");
-                }
+                const wchar_t *file = reader_current_filename();
 
 #if FISH_USE_POSIX_SPAWN
                 // Prefer to use posix_spawn, since it's faster on some systems like OS X.
                 bool use_posix_spawn = g_use_posix_spawn && can_use_posix_spawn_for_job(j, p);
                 if (use_posix_spawn) {
+                    g_fork_count++;  // spawn counts as a fork+exec
                     // Create posix spawn attributes and actions.
                     posix_spawnattr_t attr = posix_spawnattr_t();
                     posix_spawn_file_actions_t actions = posix_spawn_file_actions_t();
@@ -1079,6 +1058,8 @@ void exec_job(parser_t &parser, job_t *j) {
 
                     // 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'\n",
+                          g_fork_count, pid, actual_cmd, file ? file : L"<no file>");
                     if (pid == 0) {
                         job_mark_process_as_failed(j, p);
                         exec_error = true;
@@ -1094,9 +1075,13 @@ void exec_job(parser_t &parser, job_t *j) {
                         safe_launch_process(p, actual_cmd, argv, envv);
                         // safe_launch_process _never_ returns...
                         assert(0 && "safe_launch_process should not have returned");
-                    } else if (pid < 0) {
-                        job_mark_process_as_failed(j, p);
-                        exec_error = true;
+                    } else {
+                        debug(2, L"Fork #%d, pid %d: external command '%s' from '%ls'\n",
+                              g_fork_count, pid, p->argv0(), file ? file : L"<no file>");
+                        if (pid < 0) {
+                            job_mark_process_as_failed(j, p);
+                            exec_error = true;
+                        }
                     }
                 }
 
diff --git a/src/fish.cpp b/src/fish.cpp
index dcad6c8b..d8192c86 100644
--- a/src/fish.cpp
+++ b/src/fish.cpp
@@ -440,8 +440,6 @@ int main(int argc, char **argv) {
 
     parser_t &parser = parser_t::principal_parser();
 
-    if (g_log_forks) printf("%d: g_fork_count: %d\n", __LINE__, g_fork_count);
-
     const io_chain_t empty_ios;
     if (read_init(paths)) {
         // Stomp the exit status of any initialization commands (issue #635).
@@ -515,9 +513,6 @@ int main(int argc, char **argv) {
     builtin_destroy();
     reader_destroy();
     event_destroy();
-
-    if (g_log_forks) printf("%d: g_fork_count: %d\n", __LINE__, g_fork_count);
-
     exit_without_destructors(exit_status);
     return EXIT_FAILURE;  // above line should always exit
 }