Improved logging abstraction

This also gets rid of --log-type, since the nested log type isn't
useful in a multi-threaded situation, and nobody cares about the
"pretty" log type.

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>

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

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

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

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,
+            Activity act(*logger, lvlDebug, "evaluating list element");
-                format("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);

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 {
 

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

src/libmain/shared.cc

@@ -111,8 +111,7 @@ void initNix()
     std::cerr.rdbuf()->pubsetbuf(buf, sizeof(buf));
 #endif
 
-    if (getEnv("IN_SYSTEMD") == "1")
+    logger = makeDefaultLogger();
-        logType = ltSystemd;
 
     /* Initialise OpenSSL locking. */
     opensslLocks = std::vector<std::mutex>(CRYPTO_num_locks());

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,
+        Activity act(*logger, lvlTalkative, format("scanning for references inside ‘%1%’") % path);
-            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);
 

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

src/libstore/globals.hh

@@ -1,6 +1,7 @@
 #pragma once
 
 #include "types.hh"
+#include "logging.hh"
 
 #include <map>
 #include <sys/types.h>

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

src/libstore/remote-store.cc

@@ -121,7 +121,7 @@ void RemoteStore::setOptions(ref<Connection> conn)
         conn->to << settings.useBuildHook;
     if (GET_PROTOCOL_MINOR(conn->daemonVersion) >= 4)
         conn->to << settings.buildVerbosity
-           << logType
+                 << 0 // obsolete log type
                  << settings.printBuildTrace;
     if (GET_PROTOCOL_MINOR(conn->daemonVersion) >= 6)
         conn->to << settings.buildCores;
@@ -561,10 +561,8 @@ void RemoteStore::Connection::processStderr(Sink * sink, Source * source)
             writeString(buf, source->read(buf, len), to);
             to.flush();
         }
-        else {
+        else
-            string s = readString(from);
+            printMsg(lvlError, chomp(readString(from)));
-            writeToStderr(s);
-        }
     }
     if (msg == STDERR_ERROR) {
         string error = readString(from);

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();
+}
+
+}

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);
+
+}

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

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,
+    Activity act(*logger, lvlDebug, format("recursively deleting path ‘%1%’") % path);
-        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)

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

src/nix-daemon/nix-daemon.cc

@@ -33,19 +33,23 @@ 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
+/* Logger that forwards log messages to the client, *if* we're in a
-   stderr.  If we're in a state where the protocol allows it (i.e.,
+   state where the protocol allows it (i.e., when canSendStderr is
-   when canSendStderr), send the message to the client over the
+   true). */
-   socket. */
+class TunnelLogger : public Logger
-static void tunnelStderr(const unsigned char * buf, size_t count)
 {
+    void log(Verbosity lvl, const FormatOrString & fs) override
+    {
+        if (lvl > verbosity) return;
+
         if (canSendStderr) {
             try {
-            to << STDERR_NEXT;
+                to << STDERR_NEXT << (fs.s + "\n");
-            writeString(buf, count, to);
                 to.flush();
             } catch (...) {
                 /* Write failed; that means that the other side is
@@ -54,9 +58,19 @@ static void tunnelStderr(const unsigned char * buf, size_t count)
                 throw;
             }
         } else
-        writeFull(STDERR_FILENO, buf, count);
+            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
    want to send out stderr to the client. */
@@ -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);

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() &&

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("."));
 }
 

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};
+        logger->setExpected(copiedLabel, storePaths.size());
-        std::atomic<size_t> total{storePaths.size()};
-
-        auto showProgress = [&]() {
-            return (format("[%d/%d copied]") % done % total).str();
-        };
-
-        progressBar.updateStatus(showProgress());
 
         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--;
+                    logger->incExpected(copiedLabel, -1);
-
-                progressBar.updateStatus(showProgress());
             });
 
         pool.process();
-
-        progressBar.done();
     }
 };
 

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();
 }

src/nix/path-info.cc

@@ -1,5 +1,4 @@
 #include "command.hh"
-#include "progress-bar.hh"
 #include "shared.hh"
 #include "store-api.hh"
 

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) {
+private:
-        auto state_(state.lock());
+
-        assert(!state_->done);
+    struct ActInfo
-        std::cerr << "\r\e[K" << std::string((const char *) buf, count);
+    {
-        render(*state_);
+        Activity * activity;
+        Verbosity lvl;
+        std::string s;
     };
-}
 
-ProgressBar::~ProgressBar()
+    struct Progress
     {
-    done();
+        uint64_t expected = 0, progress = 0;
-}
+    };
 
-void ProgressBar::updateStatus(const std::string & s)
+    struct State
     {
-    auto state_(state.lock());
+        std::list<ActInfo> activities;
-    assert(!state_->done);
+        std::map<Activity *, std::list<ActInfo>::iterator> its;
-    state_->status = s;
+        std::map<std::string, Progress> progress;
-    render(*state_);
+    };
-}
 
-void ProgressBar::done()
+    Sync<State> state_;
+
+public:
+
+    ~ProgressBar()
     {
-    _writeToStderr = decltype(_writeToStderr)();
+        auto state(state_.lock());
-    auto state_(state.lock());
+        assert(state->activities.empty());
-    assert(state_->activities.empty());
+        writeToStderr("\r\e[K");
-    state_->done = true;
-    std::cerr << "\r\e[K";
-    std::cerr.flush();
     }
 
-void ProgressBar::render(State & state_)
+    void log(Verbosity lvl, const FormatOrString & fs) override
     {
-    std::cerr << '\r' << state_.status;
+        auto state(state_.lock());
-    if (!state_.activities.empty()) {
+        log(*state, lvl, fs.s);
-        if (!state_.status.empty()) std::cerr << ' ';
-        std::cerr << *state_.activities.rbegin();
-    }
-    std::cerr << "\e[K";
-    std::cerr.flush();
     }
 
-
+    void log(State & state, Verbosity lvl, const std::string & s)
-ProgressBar::Activity ProgressBar::startActivity(const FormatOrString & fs)
     {
-    return Activity(*this, fs);
+        writeToStderr("\r\e[K" + s + "\n");
+        update(state);
     }
 
-ProgressBar::Activity::Activity(ProgressBar & pb, const FormatOrString & fs)
+    void startActivity(Activity & activity, Verbosity lvl, const FormatOrString & fs) override
-    : pb(pb)
     {
-    auto state_(pb.state.lock());
+        if (lvl > verbosity) return;
-    state_->activities.push_back(fs.s);
+        auto state(state_.lock());
-    it = state_->activities.end(); --it;
+        state->activities.emplace_back(ActInfo{&activity, lvl, fs.s});
-    pb.render(*state_);
+        state->its.emplace(&activity, std::prev(state->activities.end()));
+        update(*state);
     }
 
-ProgressBar::Activity::~Activity()
+    void stopActivity(Activity & activity) override
     {
-    auto state_(pb.state.lock());
+        auto state(state_.lock());
-    state_->activities.erase(it);
+        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;
+    }
+};
+
+StartProgressBar::StartProgressBar()
+{
+    if (isatty(STDERR_FILENO)) {
+        prev = logger;
+        logger = new ProgressBar();
+    }
+}
+
+StartProgressBar::~StartProgressBar()
+{
+    if (prev) {
+        auto bar = logger;
+        logger = prev;
+        delete bar;
+    }
 }
 
 }

src/nix/progress-bar.hh

@@ -1,49 +1,15 @@
 #pragma once
 
-#include "sync.hh"
+#include "logging.hh"
-#include "util.hh"
 
 namespace nix {
 
-class ProgressBar
+class StartProgressBar
 {
-private:
+    Logger * prev = 0;
-    struct State
-    {
-        std::string status;
-        bool done = false;
-        std::list<std::string> activities;
-    };
-
-    Sync<State> state;
-
 public:
-
+    StartProgressBar();
-    ProgressBar();
+    ~StartProgressBar();
-
-    ~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_);
-
 };
 
 }

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 = [&]() {
+        logger->setExpected(doneLabel, storePaths.size());
-            return (format("[%d/%d done]") % done % storePaths.size()).str();
-        };
-
-        progressBar.updateStatus(showProgress());
 
         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++;
+            logger->incProgress(doneLabel);
-            progressBar.updateStatus(showProgress());
         };
 
         for (auto & storePath : storePaths)
@@ -92,8 +84,6 @@ struct CmdCopySigs : StorePathsCommand
 
         pool.process();
 
-        progressBar.done();
-
         printMsg(lvlInfo, format("imported %d signatures") % added);
     }
 };

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;
+        std::string doneLabel("paths checked");
-
+        std::string untrustedLabel("untrusted");
-        auto showProgress = [&](bool final) {
+        std::string corruptedLabel("corrupted");
-            std::string s;
+        std::string failedLabel("failed");
-            if (final)
+        logger->setExpected(doneLabel, storePaths.size());
-                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));
 
         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, format("%d paths checked, %d untrusted, %d corrupted, %d failed")
-
+            % done % untrusted % corrupted % failed);
-        printMsg(lvlInfo, showProgress(true));
 
         throw Exit(
             (corrupted ? 1 : 0) |

tests/logging.sh

@@ -2,16 +2,7 @@ source common.sh
 
 clearStore
 
-# Produce an escaped log file.
+path=$(nix-build dependencies.nix --no-out-link)
-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
 
 # Test nix-store -l.
 [ "$(nix-store -l $path)" = FOO ]