diff options
29 files changed, 393 insertions, 455 deletions
diff --git a/doc/manual/command-ref/opt-common-syn.xml b/doc/manual/command-ref/opt-common-syn.xml index d65f4009ee..5b79363939 100644 --- a/doc/manual/command-ref/opt-common-syn.xml +++ b/doc/manual/command-ref/opt-common-syn.xml @@ -31,7 +31,6 @@ <arg><option>-K</option></arg> <arg><option>--fallback</option></arg> <arg><option>--readonly-mode</option></arg> -<arg><option>--log-type</option> <replaceable>type</replaceable></arg> <arg><option>--show-trace</option></arg> <arg> <option>-I</option> diff --git a/doc/manual/command-ref/opt-common.xml b/doc/manual/command-ref/opt-common.xml index c7e8ae1ed0..bc26a90616 100644 --- a/doc/manual/command-ref/opt-common.xml +++ b/doc/manual/command-ref/opt-common.xml @@ -201,61 +201,6 @@ </varlistentry> -<varlistentry xml:id="opt-log-type"><term><option>--log-type</option> -<replaceable>type</replaceable></term> - - <listitem> - - <para>This option determines how the output written to standard - error is formatted. Nix’s diagnostic messages are typically - <emphasis>nested</emphasis>. For instance, when tracing Nix - expression evaluation (<command>nix-env -vvvvv</command>, messages - from subexpressions are nested inside their parent expressions. Nix - builder output is also often nested. For instance, the Nix Packages - generic builder nests the various build tasks (unpack, configure, - compile, etc.), and the GNU Make in <literal>stdenv-linux</literal> - has been patched to provide nesting for recursive Make - invocations.</para> - - <para><replaceable>type</replaceable> can be one of the - following: - - <variablelist> - - <varlistentry><term><literal>pretty</literal></term> - - <listitem><para>Pretty-print the output, indicating different - nesting levels using spaces. This is the - default.</para></listitem> - - </varlistentry> - - <varlistentry><term><literal>escapes</literal></term> - - <listitem><para>Indicate nesting using escape codes that can be - interpreted by the <command>nix-log2xml</command> tool in the - Nix source distribution. The resulting XML file can be fed into - the <command>log2html.xsl</command> stylesheet to create an HTML - file that can be browsed interactively, using JavaScript to - expand and collapse parts of the output.</para></listitem> - - </varlistentry> - - <varlistentry><term><literal>flat</literal></term> - - <listitem><para>Remove all nesting.</para></listitem> - - </varlistentry> - - </variablelist> - - </para> - - </listitem> - -</varlistentry> - - <varlistentry><term><option>--arg</option> <replaceable>name</replaceable> <replaceable>value</replaceable></term> <listitem><para>This option is accepted by diff --git a/scripts/nix-build.in b/scripts/nix-build.in index b93e5ab139..78a69c94e5 100755 --- a/scripts/nix-build.in +++ b/scripts/nix-build.in @@ -110,13 +110,6 @@ for (my $n = 0; $n < scalar @ARGV; $n++) { $n += 2; } - elsif ($arg eq "--log-type") { - $n++; - die "$0: ‘$arg’ requires an argument\n" unless $n < scalar @ARGV; - push @instArgs, ($arg, $ARGV[$n]); - push @buildArgs, ($arg, $ARGV[$n]); - } - elsif ($arg eq "--option") { die "$0: ‘$arg’ requires two arguments\n" unless $n + 2 < scalar @ARGV; push @instArgs, ($arg, $ARGV[$n + 1], $ARGV[$n + 2]); @@ -124,7 +117,7 @@ for (my $n = 0; $n < scalar @ARGV; $n++) { $n += 2; } - elsif ($arg eq "--max-jobs" || $arg eq "-j" || $arg eq "--max-silent-time" || $arg eq "--log-type" || $arg eq "--cores" || $arg eq "--timeout" || $arg eq '--add-root') { + elsif ($arg eq "--max-jobs" || $arg eq "-j" || $arg eq "--max-silent-time" || $arg eq "--cores" || $arg eq "--timeout" || $arg eq '--add-root') { $n++; die "$0: ‘$arg’ requires an argument\n" unless $n < scalar @ARGV; push @buildArgs, ($arg, $ARGV[$n]); diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index 7ad9a4e46d..5a6428ca6b 100644 --- a/src/libexpr/eval.cc +++ b/src/libexpr/eval.cc @@ -641,7 +641,7 @@ void EvalState::evalFile(const Path & path, Value & v) return; } - startNest(nest, lvlTalkative, format("evaluating file ‘%1%’") % path2); + Activity act(*logger, lvlTalkative, format("evaluating file ‘%1%’") % path2); Expr * e = parseExprFromFile(checkSourcePath(path2)); try { eval(e, v); diff --git a/src/libexpr/get-drvs.cc b/src/libexpr/get-drvs.cc index 4889fe206a..b06c539de0 100644 --- a/src/libexpr/get-drvs.cc +++ b/src/libexpr/get-drvs.cc @@ -290,7 +290,7 @@ static void getDerivations(EvalState & state, Value & vIn, attrs.insert(std::pair<string, Symbol>(i.name, i.name)); for (auto & i : attrs) { - startNest(nest, lvlDebug, format("evaluating attribute ‘%1%’") % i.first); + Activity act(*logger, lvlDebug, format("evaluating attribute ‘%1%’") % i.first); string pathPrefix2 = addToPath(pathPrefix, i.first); Value & v2(*v.attrs->find(i.second)->value); if (combineChannels) @@ -310,8 +310,7 @@ static void getDerivations(EvalState & state, Value & vIn, else if (v.isList()) { for (unsigned int n = 0; n < v.listSize(); ++n) { - startNest(nest, lvlDebug, - format("evaluating list element")); + Activity act(*logger, lvlDebug, "evaluating list element"); string pathPrefix2 = addToPath(pathPrefix, (format("%1%") % n).str()); if (getDerivation(state, *v.listElems()[n], pathPrefix2, drvs, done, ignoreAssertionFailures)) getDerivations(state, *v.listElems()[n], pathPrefix2, autoArgs, drvs, done, ignoreAssertionFailures); diff --git a/src/libexpr/primops.cc b/src/libexpr/primops.cc index 51680ad62e..c2852629a0 100644 --- a/src/libexpr/primops.cc +++ b/src/libexpr/primops.cc @@ -124,7 +124,7 @@ static void prim_scopedImport(EvalState & state, const Pos & pos, Value * * args env->values[displ++] = attr.value; } - startNest(nest, lvlTalkative, format("evaluating file ‘%1%’") % path); + Activity act(*logger, lvlTalkative, format("evaluating file ‘%1%’") % path); Expr * e = state.parseExprFromFile(resolveExprPath(path), staticEnv); e->eval(state, *env, v); @@ -284,7 +284,7 @@ typedef list<Value *> ValueList; static void prim_genericClosure(EvalState & state, const Pos & pos, Value * * args, Value & v) { - startNest(nest, lvlDebug, "finding dependencies"); + Activity act(*logger, lvlDebug, "finding dependencies"); state.forceAttrs(*args[0], pos); @@ -457,7 +457,7 @@ void prim_valueSize(EvalState & state, const Pos & pos, Value * * args, Value & derivation. */ static void prim_derivationStrict(EvalState & state, const Pos & pos, Value * * args, Value & v) { - startNest(nest, lvlVomit, "evaluating derivation"); + Activity act(*logger, lvlVomit, "evaluating derivation"); state.forceAttrs(*args[0], pos); @@ -494,7 +494,7 @@ static void prim_derivationStrict(EvalState & state, const Pos & pos, Value * * for (auto & i : *args[0]->attrs) { if (i.name == state.sIgnoreNulls) continue; string key = i.name; - startNest(nest, lvlVomit, format("processing attribute ‘%1%’") % key); + Activity act(*logger, lvlVomit, format("processing attribute ‘%1%’") % key); try { diff --git a/src/libmain/common-args.cc b/src/libmain/common-args.cc index 9219f380c7..98693d78a7 100644 --- a/src/libmain/common-args.cc +++ b/src/libmain/common-args.cc @@ -18,15 +18,6 @@ MixCommonArgs::MixCommonArgs(const string & programName) verbosity = lvlDebug; }); - mkFlag1(0, "log-type", "type", "set logging format ('pretty', 'flat', 'systemd')", - [](std::string s) { - if (s == "pretty") logType = ltPretty; - else if (s == "escapes") logType = ltEscapes; - else if (s == "flat") logType = ltFlat; - else if (s == "systemd") logType = ltSystemd; - else throw UsageError("unknown log type"); - }); - mkFlag(0, "option", {"name", "value"}, "set a Nix configuration option (overriding nix.conf)", 2, [](Strings ss) { auto name = ss.front(); ss.pop_front(); diff --git a/src/libmain/shared.cc b/src/libmain/shared.cc index ed997052be..e9d000d41a 100644 --- a/src/libmain/shared.cc +++ b/src/libmain/shared.cc @@ -111,8 +111,7 @@ void initNix() std::cerr.rdbuf()->pubsetbuf(buf, sizeof(buf)); #endif - if (getEnv("IN_SYSTEMD") == "1") - logType = ltSystemd; + logger = makeDefaultLogger(); /* Initialise OpenSSL locking. */ opensslLocks = std::vector<std::mutex>(CRYPTO_num_locks()); diff --git a/src/libstore/build.cc b/src/libstore/build.cc index ae8078069d..82275c2691 100644 --- a/src/libstore/build.cc +++ b/src/libstore/build.cc @@ -1657,7 +1657,7 @@ void DerivationGoal::startBuilder() nrRounds > 1 ? "building path(s) %1% (round %2%/%3%)" : "building path(s) %1%"); f.exceptions(boost::io::all_error_bits ^ boost::io::too_many_args_bit); - startNest(nest, lvlInfo, f % showPaths(missingPaths) % curRound % nrRounds); + printMsg(lvlInfo, f % showPaths(missingPaths) % curRound % nrRounds); /* Right platform? */ if (!drv->canBuildLocally()) { @@ -2192,8 +2192,6 @@ void DerivationGoal::runChild() try { /* child */ - logType = ltFlat; - commonChildInit(builderOut); #if __linux__ @@ -2535,7 +2533,6 @@ void DerivationGoal::runChild() /* Execute the program. This should not return. */ if (drv->isBuiltin()) { try { - logType = ltFlat; if (drv->builder == "builtin:fetchurl") builtinFetchurl(*drv); else @@ -2667,8 +2664,7 @@ void DerivationGoal::registerOutputs() rewritten = true; } - startNest(nest, lvlTalkative, - format("scanning for references inside ‘%1%’") % path); + Activity act(*logger, lvlTalkative, format("scanning for references inside ‘%1%’") % path); /* Check that fixed-output derivations produced the right outputs (i.e., the content hash should match the specified @@ -2955,7 +2951,7 @@ void DerivationGoal::handleChildOutput(int fd, const string & data) return; } if (verbosity >= settings.buildVerbosity) - writeToStderr(filterANSIEscapes(data, true)); + printMsg(lvlError, filterANSIEscapes(data, true)); // FIXME if (bzLogFile) { int err; BZ2_bzWrite(&err, bzLogFile, (unsigned char *) data.data(), data.size()); @@ -2965,7 +2961,7 @@ void DerivationGoal::handleChildOutput(int fd, const string & data) } if (hook && fd == hook->fromHook.readSide) - writeToStderr(data); + printMsg(lvlError, data); // FIXME? } @@ -3388,7 +3384,8 @@ void SubstitutionGoal::finished() void SubstitutionGoal::handleChildOutput(int fd, const string & data) { assert(fd == logPipe.readSide); - if (verbosity >= settings.buildVerbosity) writeToStderr(data); + if (verbosity >= settings.buildVerbosity) + printMsg(lvlError, data); // FIXME /* Don't write substitution output to a log file for now. We probably should, though. */ } @@ -3586,7 +3583,7 @@ void Worker::run(const Goals & _topGoals) { for (auto & i : _topGoals) topGoals.insert(i); - startNest(nest, lvlDebug, format("entered goal loop")); + Activity act(*logger, lvlDebug, "entered goal loop"); while (1) { @@ -3804,8 +3801,6 @@ void Worker::markContentsGood(const Path & path) void LocalStore::buildPaths(const PathSet & drvPaths, BuildMode buildMode) { - startNest(nest, lvlDebug, format("building %1%") % showPaths(drvPaths)); - Worker worker(*this); Goals goals; @@ -3835,8 +3830,6 @@ void LocalStore::buildPaths(const PathSet & drvPaths, BuildMode buildMode) BuildResult LocalStore::buildDerivation(const Path & drvPath, const BasicDerivation & drv, BuildMode buildMode) { - startNest(nest, lvlDebug, format("building %1%") % showPaths({drvPath})); - Worker worker(*this); auto goal = worker.makeBasicDerivationGoal(drvPath, drv, buildMode); diff --git a/src/libstore/gc.cc b/src/libstore/gc.cc index 1536dcb590..9184620613 100644 --- a/src/libstore/gc.cc +++ b/src/libstore/gc.cc @@ -514,7 +514,7 @@ void LocalStore::tryToDelete(GCState & state, const Path & path) if (path == linksDir || path == state.trashDir) return; - startNest(nest, lvlDebug, format("considering whether to delete ‘%1%’") % path); + Activity act(*logger, lvlDebug, format("considering whether to delete ‘%1%’") % path); if (!isValidPath(path)) { /* A lock file belonging to a path that we're building right diff --git a/src/libstore/globals.hh b/src/libstore/globals.hh index 572fa7188c..9c175a5ae7 100644 --- a/src/libstore/globals.hh +++ b/src/libstore/globals.hh @@ -1,6 +1,7 @@ #pragma once #include "types.hh" +#include "logging.hh" #include <map> #include <sys/types.h> diff --git a/src/libstore/optimise-store.cc b/src/libstore/optimise-store.cc index 23cbe7e26b..ad7fe0e8be 100644 --- a/src/libstore/optimise-store.cc +++ b/src/libstore/optimise-store.cc @@ -228,7 +228,7 @@ void LocalStore::optimiseStore(OptimiseStats & stats) for (auto & i : paths) { addTempRoot(i); if (!isValidPath(i)) continue; /* path was GC'ed, probably */ - startNest(nest, lvlChatty, format("hashing files in ‘%1%’") % i); + Activity act(*logger, lvlChatty, format("hashing files in ‘%1%’") % i); optimisePath_(stats, i, inodeHash); } } diff --git a/src/libstore/remote-store.cc b/src/libstore/remote-store.cc index 1edf3662e8..184f07bfdf 100644 --- a/src/libstore/remote-store.cc +++ b/src/libstore/remote-store.cc @@ -121,8 +121,8 @@ void RemoteStore::setOptions(ref<Connection> conn) conn->to << settings.useBuildHook; if (GET_PROTOCOL_MINOR(conn->daemonVersion) >= 4) conn->to << settings.buildVerbosity - << logType - << settings.printBuildTrace; + << 0 // obsolete log type + << settings.printBuildTrace; if (GET_PROTOCOL_MINOR(conn->daemonVersion) >= 6) conn->to << settings.buildCores; if (GET_PROTOCOL_MINOR(conn->daemonVersion) >= 10) @@ -561,10 +561,8 @@ void RemoteStore::Connection::processStderr(Sink * sink, Source * source) writeString(buf, source->read(buf, len), to); to.flush(); } - else { - string s = readString(from); - writeToStderr(s); - } + else + printMsg(lvlError, chomp(readString(from))); } if (msg == STDERR_ERROR) { string error = readString(from); diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc new file mode 100644 index 0000000000..15bb1e175d --- /dev/null +++ b/src/libutil/logging.cc @@ -0,0 +1,79 @@ +#include "logging.hh" +#include "util.hh" + +namespace nix { + +Logger * logger = 0; + +class SimpleLogger : public Logger +{ +public: + + bool systemd, tty; + + SimpleLogger() + { + systemd = getEnv("IN_SYSTEMD") == "1"; + tty = isatty(STDERR_FILENO); + } + + void log(Verbosity lvl, const FormatOrString & fs) override + { + if (lvl > verbosity) return; + + std::string prefix; + + if (systemd) { + char c; + switch (lvl) { + case lvlError: c = '3'; break; + case lvlInfo: c = '5'; break; + case lvlTalkative: case lvlChatty: c = '6'; break; + default: c = '7'; + } + prefix = std::string("<") + c + ">"; + } + + writeToStderr(prefix + (tty ? fs.s : filterANSIEscapes(fs.s)) + "\n"); + } + + void startActivity(Activity & activity, Verbosity lvl, const FormatOrString & fs) override + { + log(lvl, fs); + } + + void stopActivity(Activity & activity) override + { + } +}; + +Verbosity verbosity = lvlInfo; + +void warnOnce(bool & haveWarned, const FormatOrString & fs) +{ + if (!haveWarned) { + printMsg(lvlError, format("warning: %1%") % fs.s); + haveWarned = true; + } +} + +void writeToStderr(const string & s) +{ + try { + writeFull(STDERR_FILENO, s); + } catch (SysError & e) { + /* Ignore failing writes to stderr if we're in an exception + handler, otherwise throw an exception. We need to ignore + write errors in exception handlers to ensure that cleanup + code runs to completion if the other side of stderr has + been closed unexpectedly. */ + if (!std::uncaught_exception()) throw; + } +} + +Logger * makeDefaultLogger() +{ + return new SimpleLogger(); +} + +} diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh new file mode 100644 index 0000000000..277dff2800 --- /dev/null +++ b/src/libutil/logging.hh @@ -0,0 +1,82 @@ +#pragma once + +#include "types.hh" + +namespace nix { + +typedef enum { + lvlError = 0, + lvlInfo, + lvlTalkative, + lvlChatty, + lvlDebug, + lvlVomit +} Verbosity; + +class Activity; + +class Logger +{ + friend class Activity; + +public: + + virtual ~Logger() { } + + virtual void log(Verbosity lvl, const FormatOrString & fs) = 0; + + void log(const FormatOrString & fs) + { + log(lvlInfo, fs); + } + + virtual void setExpected(const std::string & label, uint64_t value = 1) { } + virtual void setProgress(const std::string & label, uint64_t value = 1) { } + virtual void incExpected(const std::string & label, uint64_t value = 1) { } + virtual void incProgress(const std::string & label, uint64_t value = 1) { } + +private: + + virtual void startActivity(Activity & activity, Verbosity lvl, const FormatOrString & fs) = 0; + + virtual void stopActivity(Activity & activity) = 0; + +}; + +class Activity +{ +public: + Logger & logger; + + Activity(Logger & logger, Verbosity lvl, const FormatOrString & fs) + : logger(logger) + { + logger.startActivity(*this, lvl, fs); + } + + ~Activity() + { + logger.stopActivity(*this); + } +}; + +extern Logger * logger; + +Logger * makeDefaultLogger(); + +extern Verbosity verbosity; /* suppress msgs > this */ + +#define printMsg(level, f) \ + do { \ + if (level <= nix::verbosity) { \ + logger->log(level, (f)); \ + } \ + } while (0) + +#define debug(f) printMsg(lvlDebug, f) + +void warnOnce(bool & haveWarned, const FormatOrString & fs); + +void writeToStderr(const string & s); + +} diff --git a/src/libutil/types.hh b/src/libutil/types.hh index 33aaf5fc9c..bd192b8506 100644 --- a/src/libutil/types.hh +++ b/src/libutil/types.hh @@ -89,14 +89,4 @@ typedef list<Path> Paths; typedef set<Path> PathSet; -typedef enum { - lvlError = 0, - lvlInfo, - lvlTalkative, - lvlChatty, - lvlDebug, - lvlVomit -} Verbosity; - - } diff --git a/src/libutil/util.cc b/src/libutil/util.cc index 8ffa6973dd..d738009051 100644 --- a/src/libutil/util.cc +++ b/src/libutil/util.cc @@ -356,8 +356,7 @@ void deletePath(const Path & path) void deletePath(const Path & path, unsigned long long & bytesFreed) { - startNest(nest, lvlDebug, - format("recursively deleting path ‘%1%’") % path); + Activity act(*logger, lvlDebug, format("recursively deleting path ‘%1%’") % path); bytesFreed = 0; _deletePath(path, bytesFreed); } @@ -456,113 +455,6 @@ void replaceSymlink(const Path & target, const Path & link) } -LogType logType = ltPretty; -Verbosity verbosity = lvlInfo; - -static int nestingLevel = 0; - - -Nest::Nest() -{ - nest = false; -} - - -Nest::~Nest() -{ - close(); -} - - -static string escVerbosity(Verbosity level) -{ - return std::to_string((int) level); -} - - -void Nest::open(Verbosity level, const FormatOrString & fs) -{ - if (level <= verbosity) { - if (logType == ltEscapes) - std::cerr << "\033[" << escVerbosity(level) << "p" - << fs.s << "\n"; - else - printMsg_(level, fs); - nest = true; - nestingLevel++; - } -} - - -void Nest::close() -{ - if (nest) { - nestingLevel--; - if (logType == ltEscapes) - std::cerr << "\033[q"; - nest = false; - } -} - - -void printMsg_(Verbosity level, const FormatOrString & fs) -{ - checkInterrupt(); - if (level > verbosity) return; - - string prefix; - if (logType == ltPretty) - for (int i = 0; i < nestingLevel; i++) - prefix += "| "; - else if (logType == ltEscapes && level != lvlInfo) - prefix = "\033[" + escVerbosity(level) + "s"; - else if (logType == ltSystemd) { - char c; - switch (level) { - case lvlError: c = '3'; break; - case lvlInfo: c = '5'; break; - case lvlTalkative: case lvlChatty: c = '6'; break; - default: c = '7'; - } - prefix = string("<") + c + ">"; - } - - string s = (format("%1%%2%\n") % prefix % fs.s).str(); - if (!isatty(STDERR_FILENO)) s = filterANSIEscapes(s); - writeToStderr(s); -} - - -void warnOnce(bool & haveWarned, const FormatOrString & fs) -{ - if (!haveWarned) { - printMsg(lvlError, format("warning: %1%") % fs.s); - haveWarned = true; - } -} - - -void writeToStderr(const string & s) -{ - try { - if (_writeToStderr) - _writeToStderr((const unsigned char *) s.data(), s.size()); - else - writeFull(STDERR_FILENO, s); - } catch (SysError & e) { - /* Ignore failing writes to stderr if we're in an exception - handler, otherwise throw an exception. We need to ignore - write errors in exception handlers to ensure that cleanup - code runs to completion if the other side of stderr has - been closed unexpectedly. */ - if (!std::uncaught_exception()) throw; - } -} - - -std::function<void(const unsigned char * buf, size_t count)> _writeToStderr; - - void readFull(int fd, unsigned char * buf, size_t count) { while (count) { @@ -953,7 +845,8 @@ static pid_t doFork(bool allowVfork, std::function<void()> fun) pid_t startProcess(std::function<void()> fun, const ProcessOptions & options) { auto wrapper = [&]() { - if (!options.allowVfork) _writeToStderr = 0; + if (!options.allowVfork) + logger = makeDefaultLogger(); try { #if __linux__ if (options.dieWithParent && prctl(PR_SET_PDEATHSIG, SIGKILL) == -1) diff --git a/src/libutil/util.hh b/src/libutil/util.hh index dabfafa7fb..6e5ab55e31 100644 --- a/src/libutil/util.hh +++ b/src/libutil/util.hh @@ -1,6 +1,7 @@ #pragma once #include "types.hh" +#include "logging.hh" #include <sys/types.h> #include <sys/stat.h> @@ -125,54 +126,6 @@ T singleton(const A & a) } -/* Messages. */ - - -typedef enum { - ltPretty, /* nice, nested output */ - ltEscapes, /* nesting indicated using escape codes (for log2xml) */ - ltFlat, /* no nesting */ - ltSystemd, /* use systemd severity prefixes */ -} LogType; - -extern LogType logType; -extern Verbosity verbosity; /* suppress msgs > this */ - -class Nest -{ -private: - bool nest; -public: - Nest(); - ~Nest(); - void open(Verbosity level, const FormatOrString & fs); - void close(); -}; - -void printMsg_(Verbosity level, const FormatOrString & fs); - -#define startNest(varName, level, f) \ - Nest varName; \ - if (level <= verbosity) { \ - varName.open(level, (f)); \ - } - -#define printMsg(level, f) \ - do { \ - if (level <= nix::verbosity) { \ - nix::printMsg_(level, (f)); \ - } \ - } while (0) - -#define debug(f) printMsg(lvlDebug, f) - -void warnOnce(bool & haveWarned, const FormatOrString & fs); - -void writeToStderr(const string & s); - -extern std::function<void(const unsigned char * buf, size_t count)> _writeToStderr; - - /* Wrappers arount read()/write() that read/write exactly the requested number of bytes. */ void readFull(int fd, unsigned char * buf, size_t count); diff --git a/src/nix-daemon/nix-daemon.cc b/src/nix-daemon/nix-daemon.cc index efc67b6a87..39eb17bce1 100644 --- a/src/nix-daemon/nix-daemon.cc +++ b/src/nix-daemon/nix-daemon.cc @@ -33,29 +33,43 @@ using namespace nix; static FdSource from(STDIN_FILENO); static FdSink to(STDOUT_FILENO); -bool canSendStderr; +static bool canSendStderr; +static Logger * defaultLogger; -/* This function is called anytime we want to write something to - stderr. If we're in a state where the protocol allows it (i.e., - when canSendStderr), send the message to the client over the - socket. */ -static void tunnelStderr(const unsigned char * buf, size_t count) + +/* Logger that forwards log messages to the client, *if* we're in a + state where the protocol allows it (i.e., when canSendStderr is + true). */ +class TunnelLogger : public Logger { - if (canSendStderr) { - try { - to << STDERR_NEXT; - writeString(buf, count, to); - to.flush(); - } catch (...) { - /* Write failed; that means that the other side is - gone. */ - canSendStderr = false; - throw; - } - } else - writeFull(STDERR_FILENO, buf, count); -} + void log(Verbosity lvl, const FormatOrString & fs) override + { + if (lvl > verbosity) return; + + if (canSendStderr) { + try { + to << STDERR_NEXT << (fs.s + "\n"); + to.flush(); + } catch (...) { + /* Write failed; that means that the other side is + gone. */ + canSendStderr = false; + throw; + } + } else + defaultLogger->log(lvl, fs); + } + + void startActivity(Activity & activity, Verbosity lvl, const FormatOrString & fs) override + { + log(lvl, fs); + } + + void stopActivity(Activity & activity) override + { + } +}; /* startWork() means that we're starting an operation for which we @@ -430,7 +444,7 @@ static void performOp(ref<LocalStore> store, bool trusted, unsigned int clientVe settings.useBuildHook = readInt(from) != 0; if (GET_PROTOCOL_MINOR(clientVersion) >= 4) { settings.buildVerbosity = (Verbosity) readInt(from); - logType = (LogType) readInt(from); + readInt(from); // obsolete logType settings.printBuildTrace = readInt(from) != 0; } if (GET_PROTOCOL_MINOR(clientVersion) >= 6) @@ -557,7 +571,8 @@ static void processConnection(bool trusted) MonitorFdHup monitor(from.fd); canSendStderr = false; - _writeToStderr = tunnelStderr; + defaultLogger = logger; + logger = new TunnelLogger(); /* Exchange the greeting. */ unsigned int magic = readInt(from); diff --git a/src/nix-env/nix-env.cc b/src/nix-env/nix-env.cc index a9d1ed024d..6bc8d79bc1 100644 --- a/src/nix-env/nix-env.cc +++ b/src/nix-env/nix-env.cc @@ -996,7 +996,7 @@ static void opQuery(Globals & globals, Strings opFlags, Strings opArgs) try { if (i.hasFailed()) continue; - startNest(nest, lvlDebug, format("outputting query result ‘%1%’") % i.attrPath); + Activity act(*logger, lvlDebug, format("outputting query result ‘%1%’") % i.attrPath); if (globals.prebuiltOnly && validPaths.find(i.queryOutPath()) == validPaths.end() && diff --git a/src/nix-instantiate/nix-instantiate.cc b/src/nix-instantiate/nix-instantiate.cc index 81c1c8d563..7dce08400e 100644 --- a/src/nix-instantiate/nix-instantiate.cc +++ b/src/nix-instantiate/nix-instantiate.cc @@ -19,7 +19,7 @@ using namespace nix; static Expr * parseStdin(EvalState & state) { - startNest(nest, lvlTalkative, format("parsing standard input")); + Activity act(*logger, lvlTalkative, format("parsing standard input")); return state.parseExprFromString(drainFD(0), absPath(".")); } diff --git a/src/nix/copy.cc b/src/nix/copy.cc index b5bd362d63..be51fee627 100644 --- a/src/nix/copy.cc +++ b/src/nix/copy.cc @@ -1,5 +1,4 @@ #include "command.hh" -#include "progress-bar.hh" #include "shared.hh" #include "store-api.hh" #include "sync.hh" @@ -47,16 +46,9 @@ struct CmdCopy : StorePathsCommand ref<Store> srcStore = srcUri.empty() ? store : openStoreAt(srcUri); ref<Store> dstStore = dstUri.empty() ? store : openStoreAt(dstUri); - ProgressBar progressBar; + std::string copiedLabel = "copied"; - std::atomic<size_t> done{0}; - std::atomic<size_t> total{storePaths.size()}; - - auto showProgress = [&]() { - return (format("[%d/%d copied]") % done % total).str(); - }; - - progressBar.updateStatus(showProgress()); + logger->setExpected(copiedLabel, storePaths.size()); ThreadPool pool; @@ -71,7 +63,7 @@ struct CmdCopy : StorePathsCommand checkInterrupt(); if (!dstStore->isValidPath(storePath)) { - auto activity(progressBar.startActivity(format("copying ‘%s’...") % storePath)); + Activity act(*logger, lvlInfo, format("copying ‘%s’...") % storePath); StringSink sink; srcStore->exportPaths({storePath}, false, sink); @@ -79,16 +71,12 @@ struct CmdCopy : StorePathsCommand StringSource source(*sink.s); dstStore->importPaths(false, source, 0); - done++; + logger->incProgress(copiedLabel); } else - total--; - - progressBar.updateStatus(showProgress()); + logger->incExpected(copiedLabel, -1); }); pool.process(); - - progressBar.done(); } }; diff --git a/src/nix/main.cc b/src/nix/main.cc index 2005ec5f9a..dae5d925d7 100644 --- a/src/nix/main.cc +++ b/src/nix/main.cc @@ -7,6 +7,7 @@ #include "legacy.hh" #include "shared.hh" #include "store-api.hh" +#include "progress-bar.hh" namespace nix { @@ -42,6 +43,8 @@ void mainWrapped(int argc, char * * argv) assert(args.command); + StartProgressBar bar; + args.command->prepare(); args.command->run(); } diff --git a/src/nix/path-info.cc b/src/nix/path-info.cc index 9347795f1c..c61fe7ff1e 100644 --- a/src/nix/path-info.cc +++ b/src/nix/path-info.cc @@ -1,5 +1,4 @@ #include "command.hh" -#include "progress-bar.hh" #include "shared.hh" #include "store-api.hh" diff --git a/src/nix/progress-bar.cc b/src/nix/progress-bar.cc index 746b891a78..659d6572ad 100644 --- a/src/nix/progress-bar.cc +++ b/src/nix/progress-bar.cc @@ -1,72 +1,157 @@ #include "progress-bar.hh" +#include "util.hh" +#include "sync.hh" -#include <iostream> +#include <map> namespace nix { -ProgressBar::ProgressBar() +class ProgressBar : public Logger { - _writeToStderr = [&](const unsigned char * buf, size_t count) { - auto state_(state.lock()); - assert(!state_->done); - std::cerr << "\r\e[K" << std::string((const char *) buf, count); - render(*state_); +private: + + struct ActInfo + { + Activity * activity; + Verbosity lvl; + std::string s; }; -} -ProgressBar::~ProgressBar() -{ - done(); -} + struct Progress + { + uint64_t expected = 0, progress = 0; + }; -void ProgressBar::updateStatus(const std::string & s) -{ - auto state_(state.lock()); - assert(!state_->done); - state_->status = s; - render(*state_); -} + struct State + { + std::list<ActInfo> activities; + std::map<Activity *, std::list<ActInfo>::iterator> its; + std::map<std::string, Progress> progress; + }; -void ProgressBar::done() -{ - _writeToStderr = decltype(_writeToStderr)(); - auto state_(state.lock()); - assert(state_->activities.empty()); - state_->done = true; - std::cerr << "\r\e[K"; - std::cerr.flush(); -} + Sync<State> state_; -void ProgressBar::render(State & state_) -{ - std::cerr << '\r' << state_.status; - if (!state_.activities.empty()) { - if (!state_.status.empty()) std::cerr << ' '; - std::cerr << *state_.activities.rbegin(); +public: + + ~ProgressBar() + { + auto state(state_.lock()); + assert(state->activities.empty()); + writeToStderr("\r\e[K"); } - std::cerr << "\e[K"; - std::cerr.flush(); -} + void log(Verbosity lvl, const FormatOrString & fs) override + { + auto state(state_.lock()); + log(*state, lvl, fs.s); + } -ProgressBar::Activity ProgressBar::startActivity(const FormatOrString & fs) -{ - return Activity(*this, fs); -} + void log(State & state, Verbosity lvl, const std::string & s) + { + writeToStderr("\r\e[K" + s + "\n"); + update(state); + } + + void startActivity(Activity & activity, Verbosity lvl, const FormatOrString & fs) override + { + if (lvl > verbosity) return; + auto state(state_.lock()); + state->activities.emplace_back(ActInfo{&activity, lvl, fs.s}); + state->its.emplace(&activity, std::prev(state->activities.end())); + update(*state); + } + + void stopActivity(Activity & activity) override + { + auto state(state_.lock()); + auto i = state->its.find(&activity); + if (i == state->its.end()) return; + state->activities.erase(i->second); + state->its.erase(i); + update(*state); + } + + void setExpected(const std::string & label, uint64_t value) override + { + auto state(state_.lock()); + state->progress[label].expected = value; + } + + void setProgress(const std::string & label, uint64_t value) override + { + auto state(state_.lock()); + state->progress[label].progress = value; + } + + void incExpected(const std::string & label, uint64_t value) override + { + auto state(state_.lock()); + state->progress[label].expected += value; + } + + void incProgress(const std::string & label, uint64_t value) + { + auto state(state_.lock()); + state->progress[label].progress += value; + } + + void update() + { + auto state(state_.lock()); + } + + void update(State & state) + { + std::string line = "\r"; + + std::string status = getStatus(state); + if (!status.empty()) { + line += '['; + line += status; + line += "]"; + } + + if (!state.activities.empty()) { + if (!status.empty()) line += " "; + line += state.activities.rbegin()->s; + } + + line += "\e[K"; + writeToStderr(line); + } + + std::string getStatus(State & state) + { + std::string res; + for (auto & p : state.progress) + if (p.second.expected || p.second.progress) { + if (!res.empty()) res += ", "; + res += std::to_string(p.second.progress); + if (p.second.expected) { + res += "/"; + res += std::to_string(p.second.expected); + } + res += " "; res += p.first; + } + return res; + } +}; -ProgressBar::Activity::Activity(ProgressBar & pb, const FormatOrString & fs) - : pb(pb) +StartProgressBar::StartProgressBar() { - auto state_(pb.state.lock()); - state_->activities.push_back(fs.s); - it = state_->activities.end(); --it; - pb.render(*state_); + if (isatty(STDERR_FILENO)) { + prev = logger; + logger = new ProgressBar(); + } } -ProgressBar::Activity::~Activity() +StartProgressBar::~StartProgressBar() { - auto state_(pb.state.lock()); - state_->activities.erase(it); + if (prev) { + auto bar = logger; + logger = prev; + delete bar; + } } } diff --git a/src/nix/progress-bar.hh b/src/nix/progress-bar.hh index 2dda24346c..d2e44f7c4f 100644 --- a/src/nix/progress-bar.hh +++ b/src/nix/progress-bar.hh @@ -1,49 +1,15 @@ #pragma once -#include "sync.hh" -#include "util.hh" +#include "logging.hh" namespace nix { -class ProgressBar +class StartProgressBar { -private: - struct State - { - std::string status; - bool done = false; - std::list<std::string> activities; - }; - - Sync<State> state; - + Logger * prev = 0; public: - - ProgressBar(); - - ~ProgressBar(); - - void updateStatus(const std::string & s); - - void done(); - - class Activity - { - friend class ProgressBar; - private: - ProgressBar & pb; - std::list<std::string>::iterator it; - Activity(ProgressBar & pb, const FormatOrString & fs); - public: - ~Activity(); - }; - - Activity startActivity(const FormatOrString & fs); - -private: - - void render(State & state_); - + StartProgressBar(); + ~StartProgressBar(); }; } diff --git a/src/nix/sigs.cc b/src/nix/sigs.cc index 69073d8847..9932aa4a9e 100644 --- a/src/nix/sigs.cc +++ b/src/nix/sigs.cc @@ -1,5 +1,4 @@ #include "command.hh" -#include "progress-bar.hh" #include "shared.hh" #include "store-api.hh" #include "thread-pool.hh" @@ -38,21 +37,15 @@ struct CmdCopySigs : StorePathsCommand for (auto & s : substituterUris) substituters.push_back(openStoreAt(s)); - ProgressBar progressBar; - ThreadPool pool; - std::atomic<size_t> done{0}; + std::string doneLabel = "done"; std::atomic<size_t> added{0}; - auto showProgress = [&]() { - return (format("[%d/%d done]") % done % storePaths.size()).str(); - }; - - progressBar.updateStatus(showProgress()); + logger->setExpected(doneLabel, storePaths.size()); auto doPath = [&](const Path & storePath) { - auto activity(progressBar.startActivity(format("getting signatures for ‘%s’") % storePath)); + Activity act(*logger, lvlInfo, format("getting signatures for ‘%s’") % storePath); checkInterrupt(); @@ -83,8 +76,7 @@ struct CmdCopySigs : StorePathsCommand added += newSigs.size(); } - done++; - progressBar.updateStatus(showProgress()); + logger->incProgress(doneLabel); }; for (auto & storePath : storePaths) @@ -92,8 +84,6 @@ struct CmdCopySigs : StorePathsCommand pool.process(); - progressBar.done(); - printMsg(lvlInfo, format("imported %d signatures") % added); } }; diff --git a/src/nix/verify.cc b/src/nix/verify.cc index 20ce26fa7d..fd904f4656 100644 --- a/src/nix/verify.cc +++ b/src/nix/verify.cc @@ -1,5 +1,4 @@ #include "command.hh" -#include "progress-bar.hh" #include "shared.hh" #include "store-api.hh" #include "sync.hh" @@ -57,30 +56,16 @@ struct CmdVerify : StorePathsCommand auto publicKeys = getDefaultPublicKeys(); + std::atomic<size_t> done{0}; std::atomic<size_t> untrusted{0}; std::atomic<size_t> corrupted{0}; - std::atomic<size_t> done{0}; std::atomic<size_t> failed{0}; - ProgressBar progressBar; - - auto showProgress = [&](bool final) { - std::string s; - if (final) - s = (format("checked %d paths") % storePaths.size()).str(); - else - s = (format("[%d/%d checked") % done % storePaths.size()).str(); - if (corrupted > 0) - s += (format(", %d corrupted") % corrupted).str(); - if (untrusted > 0) - s += (format(", %d untrusted") % untrusted).str(); - if (failed > 0) - s += (format(", %d failed") % failed).str(); - if (!final) s += "]"; - return s; - }; - - progressBar.updateStatus(showProgress(false)); + std::string doneLabel("paths checked"); + std::string untrustedLabel("untrusted"); + std::string corruptedLabel("corrupted"); + std::string failedLabel("failed"); + logger->setExpected(doneLabel, storePaths.size()); ThreadPool pool; @@ -88,7 +73,7 @@ struct CmdVerify : StorePathsCommand try { checkInterrupt(); - auto activity(progressBar.startActivity(format("checking ‘%s’") % storePath)); + Activity act(*logger, lvlInfo, format("checking ‘%s’") % storePath); auto info = store->queryPathInfo(storePath); @@ -100,6 +85,7 @@ struct CmdVerify : StorePathsCommand auto hash = sink.finish(); if (hash.first != info->narHash) { + logger->incProgress(corruptedLabel); corrupted = 1; printMsg(lvlError, format("path ‘%s’ was modified! expected hash ‘%s’, got ‘%s’") @@ -147,18 +133,19 @@ struct CmdVerify : StorePathsCommand } if (!good) { + logger->incProgress(untrustedLabel); untrusted++; printMsg(lvlError, format("path ‘%s’ is untrusted") % info->path); } } + logger->incProgress(doneLabel); done++; - progressBar.updateStatus(showProgress(false)); - } catch (Error & e) { printMsg(lvlError, format(ANSI_RED "error:" ANSI_NORMAL " %s") % e.what()); + logger->incProgress(failedLabel); failed++; } }; @@ -168,9 +155,8 @@ struct CmdVerify : StorePathsCommand pool.process(); - progressBar.done(); - - printMsg(lvlInfo, showProgress(true)); + printMsg(lvlInfo, format("%d paths checked, %d untrusted, %d corrupted, %d failed") + % done % untrusted % corrupted % failed); throw Exit( (corrupted ? 1 : 0) | diff --git a/tests/logging.sh b/tests/logging.sh index 77b2337a9d..86f32bade9 100644 --- a/tests/logging.sh +++ b/tests/logging.sh @@ -2,16 +2,7 @@ source common.sh clearStore -# Produce an escaped log file. -path=$(nix-build --log-type escapes -vv dependencies.nix --no-out-link 2> $TEST_ROOT/log.esc) - -# Convert it to an XML representation. -nix-log2xml < $TEST_ROOT/log.esc > $TEST_ROOT/log.xml - -# Is this well-formed XML? -if test "$xmllint" != "false"; then - $xmllint --noout $TEST_ROOT/log.xml || fail "malformed XML" -fi +path=$(nix-build dependencies.nix --no-out-link) # Test nix-store -l. [ "$(nix-store -l $path)" = FOO ] |