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.

5 files changed, 165 insertions, 168 deletions

diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc
new file mode 100644
index 000000000..15bb1e175
--- /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 000000000..277dff280
--- /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 33aaf5fc9..bd192b850 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 8ffa6973d..d73800905 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 dabfafa7f..6e5ab55e3 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);