tree-wide: log commands executed at --debug --quiet

Fixes: https://git.lix.systems/lix-project/lix/issues/973

Information about which commands were executed is really valuable to
debug Lix and is much more user relevant than the vast majority of the
e.g. build loop junk printed at debug level. Currently we have a *whole
lot* of call sites where we call execv* which should probably be cleaned
up, but that's future work.

I chose to print argv0 rather than the executable path if these differ,
since the code is shorter and since the command could be a fully
resolved symlink or so where argv0 is the actual command name being run.
However, it's not exactly *hard* to write std::ranges::drop_view(args,
1).

Change-Id: I73c3abb20b229d5e2d64277aa29cbbeed7764bab

doc/manual/src/contributing/cli-guideline.md

@@ -661,8 +661,8 @@ Verbosity levels are:
 
 The default level that the command starts is `ERROR`. The simplest way to
 increase the verbosity by stacking `-v` option (eg: `-vvv == level 3 == INFO`).
-There are also two shortcuts, `--debug` to run in `DEBUG` verbosity level and
-`--quiet` to run in `ERROR` verbosity level.
+Use `--quiet` to decrease verbosity by one level.
+There is one shortcut, `--debug` to run in `DEBUG` verbosity level.
 
 ----------
 

lix/legacy/nix-build.cc

@@ -544,6 +544,8 @@ static void main_nix_build(AsyncIoRoot & aio, std::string programName, Strings a
 
         logger->pause();
 
+        printMsg(lvlChatty, "running shell: %s", concatMapStringsSep(" ", args, shellEscape));
+
         execvp(shell->c_str(), argPtrs.data());
 
         throw SysError("executing shell '%s'", *shell);

lix/libstore/build/hook-instance.cc

@@ -37,6 +37,8 @@ try {
 
     auto [selfRPC, hookRPC] = SocketPair::stream();
 
+    printMsg(lvlChatty, "running build hook: %s", concatMapStringsSep(" ", args, shellEscape));
+
     /* Fork the hook. */
     auto pid = startProcess([&]() {
         if (dup2(fromHook_.writeSide.get(), STDERR_FILENO) == -1)

lix/libstore/ssh.cc

@@ -62,6 +62,21 @@ std::unique_ptr<SSH::Connection> SSH::startCommand(const std::string & command)
         resumeLoggerDefer.emplace([&]() { logger->resume(); });
     }
 
+    Strings args;
+
+    // We specifically spawn bash here, to (hopefully) get
+    // reasonably POSIX-y semantics for the things we're about
+    // to do next.
+    if (fakeSSH) {
+        args = {"bash", "-c", command};
+    } else {
+        args = {"ssh", host.c_str(), "-x", "-T"};
+        addCommonSSHOpts(args);
+        args.push_back(command);
+    }
+
+    printMsg(lvlChatty, "running ssh: %s", concatMapStringsSep(" ", args, shellEscape));
+
     conn->sshPid = startProcess([&]() {
         restoreProcessContext();
 
@@ -73,20 +88,8 @@ std::unique_ptr<SSH::Connection> SSH::startCommand(const std::string & command)
         if (dup2(child.get(), STDOUT_FILENO) == -1) {
             throw SysError("duping over stdout");
         }
-        if (logFD != -1 && dup2(logFD, STDERR_FILENO) == -1)
+        if (logFD != -1 && dup2(logFD, STDERR_FILENO) == -1) {
             throw SysError("duping over stderr");
-
-        Strings args;
-
-        // We specifically spawn bash here, to (hopefully) get
-        // reasonably POSIX-y semantics for the things we're about
-        // to do next.
-        if (fakeSSH) {
-            args = { "bash", "-c", command };
-        } else {
-            args = { "ssh", host.c_str(), "-x", "-T" };
-            addCommonSSHOpts(args);
-            args.push_back(command);
         }
 
         execvp(args.begin()->c_str(), stringsToCharPtrs(args).data());

lix/libutil/args.cc

@@ -598,6 +598,11 @@ bool ExternalCommand::processArgs(const Strings & args, bool finish)
 }
 
 void ExternalCommand::run() {
+    printMsg(
+        lvlChatty,
+        "running external command: %s",
+        concatMapStringsSep(" ", externalArgv, shellEscape)
+    );
     execv(absoluteBinaryPath.c_str(), stringsToCharPtrs(externalArgv).data());
 
     throw SysError(errno, "failed to execute external command '%1%'", absoluteBinaryPath);

lix/libutil/processes.cc

@@ -323,6 +323,8 @@ RunningProgram runProgram2(const RunOptions & options)
         );
     }
 
+    printMsg(lvlChatty, "running command: %s", concatMapStringsSep(" ", options.args, shellEscape));
+
     /* Fork. */
     Pid pid{startProcess([&]() {
         if (options.environment)
@@ -414,7 +416,6 @@ RunningProgram runProgram2(const RunOptions & options)
 
     out.writeSide.close();
 
-    debug("Running %s %s", shellEscape(options.program), concatMapStringsSep(" ", options.args, shellEscape));
     return RunningProgram{
         options.program,
         std::move(pid),

lix/nix/edit.cc

@@ -49,6 +49,8 @@ struct CmdEdit : InstallableCommand
 
         restoreProcessContext();
 
+        printMsg(lvlChatty, "running editor: %s", concatMapStringsSep(" ", args, shellEscape));
+
         execvp(args.front().c_str(), stringsToCharPtrs(args).data());
 
         std::string command;

lix/nix/run.cc

@@ -32,6 +32,10 @@ void runProgramInStore(ref<Store> store,
 
     restoreProcessContext();
 
+    printMsg(
+        lvlChatty, "running command in store: %s", concatMapStringsSep(" ", args, shellEscape)
+    );
+
     /* If this is a diverted store (i.e. its "logical" location
        (typically /nix/store) differs from its "physical" location
        (e.g. /home/eelco/nix/store), then run the command in a