diff options
Diffstat (limited to 'src/libmain')
-rw-r--r-- | src/libmain/common-args.cc | 9 | ||||
-rw-r--r-- | src/libmain/loggers.cc | 52 | ||||
-rw-r--r-- | src/libmain/loggers.hh | 20 | ||||
-rw-r--r-- | src/libmain/progress-bar.cc | 491 | ||||
-rw-r--r-- | src/libmain/progress-bar.hh | 13 | ||||
-rw-r--r-- | src/libmain/shared.cc | 42 | ||||
-rw-r--r-- | src/libmain/shared.hh | 6 | ||||
-rw-r--r-- | src/libmain/stack.cc | 2 |
8 files changed, 618 insertions, 17 deletions
diff --git a/src/libmain/common-args.cc b/src/libmain/common-args.cc index 2bcad9f7b..eb3319c59 100644 --- a/src/libmain/common-args.cc +++ b/src/libmain/common-args.cc @@ -1,5 +1,6 @@ #include "common-args.hh" #include "globals.hh" +#include "loggers.hh" namespace nix { @@ -41,6 +42,14 @@ MixCommonArgs::MixCommonArgs(const string & programName) }); addFlag({ + .longName = "log-format", + .description = "format of log output; \"raw\", \"internal-json\", \"bar\" " + "or \"bar-with-logs\"", + .labels = {"format"}, + .handler = {[](std::string format) { setLogFormat(format); }}, + }); + + addFlag({ .longName = "max-jobs", .shortName = 'j', .description = "maximum number of parallel builds", diff --git a/src/libmain/loggers.cc b/src/libmain/loggers.cc new file mode 100644 index 000000000..c44bb6408 --- /dev/null +++ b/src/libmain/loggers.cc @@ -0,0 +1,52 @@ +#include "loggers.hh" +#include "progress-bar.hh" + +namespace nix { + +LogFormat defaultLogFormat = LogFormat::raw; + +LogFormat parseLogFormat(const std::string & logFormatStr) { + if (logFormatStr == "raw") + return LogFormat::raw; + else if (logFormatStr == "raw-with-logs") + return LogFormat::rawWithLogs; + else if (logFormatStr == "internal-json") + return LogFormat::internalJson; + else if (logFormatStr == "bar") + return LogFormat::bar; + else if (logFormatStr == "bar-with-logs") + return LogFormat::barWithLogs; + throw Error("option 'log-format' has an invalid value '%s'", logFormatStr); +} + +Logger * makeDefaultLogger() { + switch (defaultLogFormat) { + case LogFormat::raw: + return makeSimpleLogger(false); + case LogFormat::rawWithLogs: + return makeSimpleLogger(true); + case LogFormat::internalJson: + return makeJSONLogger(*makeSimpleLogger()); + case LogFormat::bar: + return makeProgressBar(); + case LogFormat::barWithLogs: + return makeProgressBar(true); + default: + abort(); + } +} + +void setLogFormat(const std::string & logFormatStr) { + setLogFormat(parseLogFormat(logFormatStr)); +} + +void setLogFormat(const LogFormat & logFormat) { + defaultLogFormat = logFormat; + createDefaultLogger(); +} + +void createDefaultLogger() { + logger = makeDefaultLogger(); +} + +} diff --git a/src/libmain/loggers.hh b/src/libmain/loggers.hh new file mode 100644 index 000000000..cada03110 --- /dev/null +++ b/src/libmain/loggers.hh @@ -0,0 +1,20 @@ +#pragma once + +#include "types.hh" + +namespace nix { + +enum class LogFormat { + raw, + rawWithLogs, + internalJson, + bar, + barWithLogs, +}; + +void setLogFormat(const std::string & logFormatStr); +void setLogFormat(const LogFormat & logFormat); + +void createDefaultLogger(); + +} diff --git a/src/libmain/progress-bar.cc b/src/libmain/progress-bar.cc new file mode 100644 index 000000000..c2c8cac6b --- /dev/null +++ b/src/libmain/progress-bar.cc @@ -0,0 +1,491 @@ +#include "progress-bar.hh" +#include "util.hh" +#include "sync.hh" +#include "store-api.hh" +#include "names.hh" + +#include <atomic> +#include <map> +#include <thread> +#include <iostream> + +namespace nix { + +static std::string getS(const std::vector<Logger::Field> & fields, size_t n) +{ + assert(n < fields.size()); + assert(fields[n].type == Logger::Field::tString); + return fields[n].s; +} + +static uint64_t getI(const std::vector<Logger::Field> & fields, size_t n) +{ + assert(n < fields.size()); + assert(fields[n].type == Logger::Field::tInt); + return fields[n].i; +} + +static std::string_view storePathToName(std::string_view path) +{ + auto base = baseNameOf(path); + auto i = base.find('-'); + return i == std::string::npos ? base.substr(0, 0) : base.substr(i + 1); +} + +class ProgressBar : public Logger +{ +private: + + struct ActInfo + { + std::string s, lastLine, phase; + ActivityType type = ActivityType::Unknown; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t running = 0; + uint64_t failed = 0; + std::map<ActivityType, uint64_t> expectedByType; + bool visible = true; + ActivityId parent; + std::optional<std::string> name; + }; + + struct ActivitiesByType + { + std::map<ActivityId, std::list<ActInfo>::iterator> its; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t failed = 0; + }; + + struct State + { + std::list<ActInfo> activities; + std::map<ActivityId, std::list<ActInfo>::iterator> its; + + std::map<ActivityType, ActivitiesByType> activitiesByType; + + uint64_t filesLinked = 0, bytesLinked = 0; + + uint64_t corruptedPaths = 0, untrustedPaths = 0; + + bool active = true; + bool haveUpdate = true; + }; + + Sync<State> state_; + + std::thread updateThread; + + std::condition_variable quitCV, updateCV; + + bool printBuildLogs; + bool isTTY; + +public: + + ProgressBar(bool printBuildLogs, bool isTTY) + : printBuildLogs(printBuildLogs) + , isTTY(isTTY) + { + state_.lock()->active = isTTY; + updateThread = std::thread([&]() { + auto state(state_.lock()); + while (state->active) { + if (!state->haveUpdate) + state.wait(updateCV); + draw(*state); + state.wait_for(quitCV, std::chrono::milliseconds(50)); + } + }); + } + + ~ProgressBar() + { + stop(); + updateThread.join(); + } + + void stop() override + { + auto state(state_.lock()); + if (!state->active) return; + state->active = false; + writeToStderr("\r\e[K"); + updateCV.notify_one(); + quitCV.notify_one(); + } + + bool isVerbose() override { + return printBuildLogs; + } + + void log(Verbosity lvl, const FormatOrString & fs) override + { + auto state(state_.lock()); + log(*state, lvl, fs.s); + } + + void logEI(const ErrorInfo &ei) override + { + auto state(state_.lock()); + + std::stringstream oss; + oss << ei; + + log(*state, ei.level, oss.str()); + } + + void log(State & state, Verbosity lvl, const std::string & s) + { + if (state.active) { + writeToStderr("\r\e[K" + filterANSIEscapes(s, !isTTY) + ANSI_NORMAL "\n"); + draw(state); + } else { + auto s2 = s + ANSI_NORMAL "\n"; + if (!isTTY) s2 = filterANSIEscapes(s2, true); + writeToStderr(s2); + } + } + + void startActivity(ActivityId act, Verbosity lvl, ActivityType type, + const std::string & s, const Fields & fields, ActivityId parent) override + { + auto state(state_.lock()); + + if (lvl <= verbosity && !s.empty() && type != ActivityType::BuildWaiting) + log(*state, lvl, s + "..."); + + state->activities.emplace_back(ActInfo()); + auto i = std::prev(state->activities.end()); + i->s = s; + i->type = type; + i->parent = parent; + state->its.emplace(act, i); + state->activitiesByType[type].its.emplace(act, i); + + if (type == ActivityType::Build) { + std::string name(storePathToName(getS(fields, 0))); + if (hasSuffix(name, ".drv")) + name = name.substr(0, name.size() - 4); + i->s = fmt("building " ANSI_BOLD "%s" ANSI_NORMAL, name); + auto machineName = getS(fields, 1); + if (machineName != "") + i->s += fmt(" on " ANSI_BOLD "%s" ANSI_NORMAL, machineName); + auto curRound = getI(fields, 2); + auto nrRounds = getI(fields, 3); + if (nrRounds != 1) + i->s += fmt(" (round %d/%d)", curRound, nrRounds); + i->name = DrvName(name).name; + } + + if (type == ActivityType::Substitute) { + auto name = storePathToName(getS(fields, 0)); + auto sub = getS(fields, 1); + i->s = fmt( + hasPrefix(sub, "local") + ? "copying " ANSI_BOLD "%s" ANSI_NORMAL " from %s" + : "fetching " ANSI_BOLD "%s" ANSI_NORMAL " from %s", + name, sub); + } + + if (type == ActivityType::PostBuildHook) { + auto name = storePathToName(getS(fields, 0)); + if (hasSuffix(name, ".drv")) + name = name.substr(0, name.size() - 4); + i->s = fmt("post-build " ANSI_BOLD "%s" ANSI_NORMAL, name); + i->name = DrvName(name).name; + } + + if (type == ActivityType::QueryPathInfo) { + auto name = storePathToName(getS(fields, 0)); + i->s = fmt("querying " ANSI_BOLD "%s" ANSI_NORMAL " on %s", name, getS(fields, 1)); + } + + if ((type == ActivityType::Download && hasAncestor(*state, ActivityType::CopyPath, parent)) + || (type == ActivityType::Download && hasAncestor(*state, ActivityType::QueryPathInfo, parent)) + || (type == ActivityType::CopyPath && hasAncestor(*state, ActivityType::Substitute, parent))) + i->visible = false; + + update(*state); + } + + /* Check whether an activity has an ancestore with the specified + type. */ + bool hasAncestor(State & state, ActivityType type, ActivityId act) + { + while (act != 0) { + auto i = state.its.find(act); + if (i == state.its.end()) break; + if (i->second->type == type) return true; + act = i->second->parent; + } + return false; + } + + void stopActivity(ActivityId act) override + { + auto state(state_.lock()); + + auto i = state->its.find(act); + if (i != state->its.end()) { + + auto & actByType = state->activitiesByType[i->second->type]; + actByType.done += i->second->done; + actByType.failed += i->second->failed; + + for (auto & j : i->second->expectedByType) + state->activitiesByType[j.first].expected -= j.second; + + actByType.its.erase(act); + state->activities.erase(i->second); + state->its.erase(i); + } + + update(*state); + } + + void result(ActivityId act, ResultType type, const std::vector<Field> & fields) override + { + auto state(state_.lock()); + + if (type == ResultType::FileLinked) { + state->filesLinked++; + state->bytesLinked += getI(fields, 0); + update(*state); + } + + else if (type == ResultType::BuildLogLine || type == ResultType::PostBuildLogLine) { + auto lastLine = trim(getS(fields, 0)); + if (!lastLine.empty()) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo info = *i->second; + if (printBuildLogs) { + auto suffix = "> "; + if (type == ResultType::PostBuildLogLine) { + suffix = " (post)> "; + } + log(*state, Verbosity::Info, ANSI_FAINT + info.name.value_or("unnamed") + suffix + ANSI_NORMAL + lastLine); + } else { + state->activities.erase(i->second); + info.lastLine = lastLine; + state->activities.emplace_back(info); + i->second = std::prev(state->activities.end()); + update(*state); + } + } + } + + else if (type == ResultType::UntrustedPath) { + state->untrustedPaths++; + update(*state); + } + + else if (type == ResultType::CorruptedPath) { + state->corruptedPaths++; + update(*state); + } + + else if (type == ResultType::SetPhase) { + auto i = state->its.find(act); + assert(i != state->its.end()); + i->second->phase = getS(fields, 0); + update(*state); + } + + else if (type == ResultType::Progress) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo & actInfo = *i->second; + actInfo.done = getI(fields, 0); + actInfo.expected = getI(fields, 1); + actInfo.running = getI(fields, 2); + actInfo.failed = getI(fields, 3); + update(*state); + } + + else if (type == ResultType::SetExpected) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo & actInfo = *i->second; + auto type = (ActivityType) getI(fields, 0); + auto & j = actInfo.expectedByType[type]; + state->activitiesByType[type].expected -= j; + j = getI(fields, 1); + state->activitiesByType[type].expected += j; + update(*state); + } + } + + void update(State & state) + { + state.haveUpdate = true; + updateCV.notify_one(); + } + + void draw(State & state) + { + state.haveUpdate = false; + if (!state.active) return; + + std::string line; + + std::string status = getStatus(state); + if (!status.empty()) { + line += '['; + line += status; + line += "]"; + } + + if (!state.activities.empty()) { + if (!status.empty()) line += " "; + auto i = state.activities.rbegin(); + + while (i != state.activities.rend() && (!i->visible || (i->s.empty() && i->lastLine.empty()))) + ++i; + + if (i != state.activities.rend()) { + line += i->s; + if (!i->phase.empty()) { + line += " ("; + line += i->phase; + line += ")"; + } + if (!i->lastLine.empty()) { + if (!i->s.empty()) line += ": "; + line += i->lastLine; + } + } + } + + auto width = getWindowSize().second; + if (width <= 0) width = std::numeric_limits<decltype(width)>::max(); + + writeToStderr("\r" + filterANSIEscapes(line, false, width) + "\e[K"); + } + + std::string getStatus(State & state) + { + auto MiB = 1024.0 * 1024.0; + + std::string res; + + auto renderActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { + auto & act = state.activitiesByType[type]; + uint64_t done = act.done, expected = act.done, running = 0, failed = act.failed; + for (auto & j : act.its) { + done += j.second->done; + expected += j.second->expected; + running += j.second->running; + failed += j.second->failed; + } + + expected = std::max(expected, act.expected); + + std::string s; + + if (running || done || expected || failed) { + if (running) + if (expected != 0) + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + running / unit, done / unit, expected / unit); + else + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL, + running / unit, done / unit); + else if (expected != done) + if (expected != 0) + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + done / unit, expected / unit); + else + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL, done / unit); + else + s = fmt(done ? ANSI_GREEN + numberFmt + ANSI_NORMAL : numberFmt, done / unit); + s = fmt(itemFmt, s); + + if (failed) + s += fmt(" (" ANSI_RED "%d failed" ANSI_NORMAL ")", failed / unit); + } + + return s; + }; + + auto showActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { + auto s = renderActivity(type, itemFmt, numberFmt, unit); + if (s.empty()) return; + if (!res.empty()) res += ", "; + res += s; + }; + + showActivity(ActivityType::Builds, "%s built"); + + auto s1 = renderActivity(ActivityType::CopyPaths, "%s copied"); + auto s2 = renderActivity(ActivityType::CopyPath, "%s MiB", "%.1f", MiB); + + if (!s1.empty() || !s2.empty()) { + if (!res.empty()) res += ", "; + if (s1.empty()) res += "0 copied"; else res += s1; + if (!s2.empty()) { res += " ("; res += s2; res += ')'; } + } + + showActivity(ActivityType::Download, "%s MiB DL", "%.1f", MiB); + + { + auto s = renderActivity(ActivityType::OptimiseStore, "%s paths optimised"); + if (s != "") { + s += fmt(", %.1f MiB / %d inodes freed", state.bytesLinked / MiB, state.filesLinked); + if (!res.empty()) res += ", "; + res += s; + } + } + + // FIXME: don't show "done" paths in green. + showActivity(ActivityType::VerifyPaths, "%s paths verified"); + + if (state.corruptedPaths) { + if (!res.empty()) res += ", "; + res += fmt(ANSI_RED "%d corrupted" ANSI_NORMAL, state.corruptedPaths); + } + + if (state.untrustedPaths) { + if (!res.empty()) res += ", "; + res += fmt(ANSI_RED "%d untrusted" ANSI_NORMAL, state.untrustedPaths); + } + + return res; + } + + void writeToStdout(std::string_view s) override + { + auto state(state_.lock()); + if (state->active) { + std::cerr << "\r\e[K"; + Logger::writeToStdout(s); + draw(*state); + } else { + Logger::writeToStdout(s); + } + } +}; + +Logger * makeProgressBar(bool printBuildLogs) +{ + return new ProgressBar( + printBuildLogs, + isatty(STDERR_FILENO) && getEnv("TERM").value_or("dumb") != "dumb" + ); +} + +void startProgressBar(bool printBuildLogs) +{ + logger = makeProgressBar(printBuildLogs); +} + +void stopProgressBar() +{ + auto progressBar = dynamic_cast<ProgressBar *>(logger); + if (progressBar) progressBar->stop(); + +} + +} diff --git a/src/libmain/progress-bar.hh b/src/libmain/progress-bar.hh new file mode 100644 index 000000000..7f0dafecf --- /dev/null +++ b/src/libmain/progress-bar.hh @@ -0,0 +1,13 @@ +#pragma once + +#include "logging.hh" + +namespace nix { + +Logger * makeProgressBar(bool printBuildLogs = false); + +void startProgressBar(bool printBuildLogs = false); + +void stopProgressBar(); + +} diff --git a/src/libmain/shared.cc b/src/libmain/shared.cc index d0e7f4eb1..3e6b44ee7 100644 --- a/src/libmain/shared.cc +++ b/src/libmain/shared.cc @@ -2,6 +2,7 @@ #include "shared.hh" #include "store-api.hh" #include "util.hh" +#include "loggers.hh" #include <algorithm> #include <cctype> @@ -47,7 +48,10 @@ void printMissing(ref<Store> store, const StorePathSet & willBuild, unsigned long long downloadSize, unsigned long long narSize, Verbosity lvl) { if (!willBuild.empty()) { - printMsg(lvl, "these derivations will be built:"); + if (willBuild.size() == 1) + printMsg(lvl, fmt("this derivation will be built:")); + else + printMsg(lvl, fmt("these %d derivations will be built:", willBuild.size())); auto sorted = store->topoSortPaths(willBuild); reverse(sorted.begin(), sorted.end()); for (auto & i : sorted) @@ -55,9 +59,18 @@ void printMissing(ref<Store> store, const StorePathSet & willBuild, } if (!willSubstitute.empty()) { - printMsg(lvl, fmt("these paths will be fetched (%.2f MiB download, %.2f MiB unpacked):", - downloadSize / (1024.0 * 1024.0), - narSize / (1024.0 * 1024.0))); + const float downloadSizeMiB = downloadSize / (1024.f * 1024.f); + const float narSizeMiB = narSize / (1024.f * 1024.f); + if (willSubstitute.size() == 1) { + printMsg(lvl, fmt("this path will be fetched (%.2f MiB download, %.2f MiB unpacked):", + downloadSizeMiB, + narSizeMiB)); + } else { + printMsg(lvl, fmt("these %d paths will be fetched (%.2f MiB download, %.2f MiB unpacked):", + willSubstitute.size(), + downloadSizeMiB, + narSizeMiB)); + } for (auto & i : willSubstitute) printMsg(lvl, fmt(" %s", store->printStorePath(i))); } @@ -75,7 +88,7 @@ string getArg(const string & opt, Strings::iterator & i, const Strings::iterator & end) { ++i; - if (i == end) throw UsageError(format("'%1%' requires an argument") % opt); + if (i == end) throw UsageError("'%1%' requires an argument", opt); return *i; } @@ -169,7 +182,7 @@ LegacyArgs::LegacyArgs(const std::string & programName, .longName = "no-build-output", .shortName = 'Q', .description = "do not show build output", - .handler = {&settings.verboseBuild, false}, + .handler = {[&]() {setLogFormat(LogFormat::raw); }}, }); addFlag({ @@ -234,7 +247,7 @@ bool LegacyArgs::processArgs(const Strings & args, bool finish) Strings ss(args); auto pos = ss.begin(); if (!parseArg(pos, ss.end())) - throw UsageError(format("unexpected argument '%1%'") % args.front()); + throw UsageError("unexpected argument '%1%'", args.front()); return true; } @@ -281,7 +294,7 @@ void showManPage(const string & name) restoreSignals(); setenv("MANPATH", settings.nixManDir.c_str(), 1); execlp("man", "man", name.c_str(), nullptr); - throw SysError(format("command 'man %1%' failed") % name.c_str()); + throw SysError("command 'man %1%' failed", name.c_str()); } @@ -289,6 +302,8 @@ int handleExceptions(const string & programName, std::function<void()> fun) { ReceiveInterrupts receiveInterrupts; // FIXME: need better place for this + ErrorInfo::programName = baseNameOf(programName); + string error = ANSI_RED "error:" ANSI_NORMAL " "; try { try { @@ -304,12 +319,13 @@ int handleExceptions(const string & programName, std::function<void()> fun) } catch (Exit & e) { return e.status; } catch (UsageError & e) { - printError( - format(error + "%1%\nTry '%2% --help' for more information.") - % e.what() % programName); + logError(e.info()); + printError("Try '%1% --help' for more information.", programName); return 1; } catch (BaseError & e) { - printError(format(error + "%1%%2%") % (settings.showTrace ? e.prefix() : "") % e.msg()); + if (settings.showTrace && e.prefix() != "") + printError(e.prefix()); + logError(e.info()); if (e.prefix() != "" && !settings.showTrace) printError("(use '--show-trace' to show detailed location information)"); return e.status; @@ -346,7 +362,7 @@ RunPager::RunPager() execlp("pager", "pager", nullptr); execlp("less", "less", nullptr); execlp("more", "more", nullptr); - throw SysError(format("executing '%1%'") % pager); + throw SysError("executing '%1%'", pager); }); pid.setKillSignal(SIGINT); diff --git a/src/libmain/shared.hh b/src/libmain/shared.hh index 96d001ec3..3e3a73278 100644 --- a/src/libmain/shared.hh +++ b/src/libmain/shared.hh @@ -56,7 +56,7 @@ template<class N> N getIntArg(const string & opt, Strings::iterator & i, const Strings::iterator & end, bool allowUnit) { ++i; - if (i == end) throw UsageError(format("'%1%' requires an argument") % opt); + if (i == end) throw UsageError("'%1%' requires an argument", opt); string s = *i; N multiplier = 1; if (allowUnit && !s.empty()) { @@ -66,13 +66,13 @@ template<class N> N getIntArg(const string & opt, else if (u == 'M') multiplier = 1ULL << 20; else if (u == 'G') multiplier = 1ULL << 30; else if (u == 'T') multiplier = 1ULL << 40; - else throw UsageError(format("invalid unit specifier '%1%'") % u); + else throw UsageError("invalid unit specifier '%1%'", u); s.resize(s.size() - 1); } } N n; if (!string2Int(s, n)) - throw UsageError(format("'%1%' requires an integer argument") % opt); + throw UsageError("'%1%' requires an integer argument", opt); return n * multiplier; } diff --git a/src/libmain/stack.cc b/src/libmain/stack.cc index e6224de7d..b0a4a4c5d 100644 --- a/src/libmain/stack.cc +++ b/src/libmain/stack.cc @@ -1,4 +1,4 @@ -#include "types.hh" +#include "error.hh" #include <cstring> #include <cstddef> |