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.

7 files changed, 165 insertions, 148 deletions

diff --git a/src/nix/copy.cc b/src/nix/copy.cc
index b5bd362d63a6..be51fee62712 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 2005ec5f9a6d..dae5d925d72a 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 9347795f1cb9..c61fe7ff1e00 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 746b891a78df..659d6572ad93 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 2dda24346c90..d2e44f7c4fd9 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 69073d8847f2..9932aa4a9eb0 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 20ce26fa7d21..fd904f465687 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) |