From f4bdddf0fdaabc68546cf561c5343b83d95d2466 Mon Sep 17 00:00:00 2001 From: Jade Lovelace Date: Thu, 21 Aug 2025 14:07:10 -0700 Subject: [PATCH] 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 | 4 +-- lix/legacy/nix-build.cc | 2 ++ lix/libstore/build/hook-instance.cc | 2 ++ lix/libstore/ssh.cc | 29 +++++++++++--------- lix/libutil/args.cc | 5 ++++ lix/libutil/processes.cc | 3 +- lix/nix/edit.cc | 2 ++ lix/nix/run.cc | 4 +++ 8 files changed, 35 insertions(+), 16 deletions(-) diff --git a/doc/manual/src/contributing/cli-guideline.md b/doc/manual/src/contributing/cli-guideline.md index f170e5e8f..b27f7a00c 100644 --- a/doc/manual/src/contributing/cli-guideline.md +++ b/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. ---------- diff --git a/lix/legacy/nix-build.cc b/lix/legacy/nix-build.cc index 240721539..d9ab74931 100644 --- a/lix/legacy/nix-build.cc +++ b/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); diff --git a/lix/libstore/build/hook-instance.cc b/lix/libstore/build/hook-instance.cc index 6b71d2599..325a84591 100644 --- a/lix/libstore/build/hook-instance.cc +++ b/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) diff --git a/lix/libstore/ssh.cc b/lix/libstore/ssh.cc index ab3ec5a20..c314d4211 100644 --- a/lix/libstore/ssh.cc +++ b/lix/libstore/ssh.cc @@ -62,6 +62,21 @@ std::unique_ptr 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::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()); diff --git a/lix/libutil/args.cc b/lix/libutil/args.cc index 6c58e6821..5560d3bc5 100644 --- a/lix/libutil/args.cc +++ b/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); diff --git a/lix/libutil/processes.cc b/lix/libutil/processes.cc index d75488651..25f40eb5e 100644 --- a/lix/libutil/processes.cc +++ b/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), diff --git a/lix/nix/edit.cc b/lix/nix/edit.cc index dcc9170eb..ace8d0029 100644 --- a/lix/nix/edit.cc +++ b/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; diff --git a/lix/nix/run.cc b/lix/nix/run.cc index 9bb929b30..6ba99a9aa 100644 --- a/lix/nix/run.cc +++ b/lix/nix/run.cc @@ -32,6 +32,10 @@ void runProgramInStore(ref 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