Merge pull request #3073 from tweag/machine-logs

Add an option to print the logs in a machine-readable format

doc/manual/command-ref/opt-common-syn.xml

@@ -1,5 +1,5 @@
 <nop xmlns="http://docbook.org/ns/docbook">
-  
+
 <arg><option>--help</option></arg>
 <arg><option>--version</option></arg>
 <arg rep='repeat'>
@@ -11,6 +11,10 @@
 <arg>
   <arg choice='plain'><option>--quiet</option></arg>
 </arg>
+<arg>
+  <option>--log-format</option>
+  <replaceable>format</replaceable>
+</arg>
 <arg>
   <group choice='plain'>
     <arg choice='plain'><option>--no-build-output</option></arg>

doc/manual/command-ref/opt-common.xml

@@ -92,6 +92,37 @@
 </varlistentry>
 
 
+<varlistentry xml:id="opt-log-format"><term><option>--log-format</option> <replaceable>format</replaceable></term>
+
+  <listitem>
+
+  <para>This option can be used to change the output of the log format, with
+  <replaceable>format</replaceable> being one of:</para>
+
+  <variablelist>
+
+    <varlistentry><term>raw</term>
+    <listitem><para>This is the raw format, as outputted by nix-build.</para></listitem>
+    </varlistentry>
+
+    <varlistentry><term>internal-json</term>
+    <listitem><para>Outputs the logs in a structured manner. NOTE: the json schema is not guarantees to be stable between releases.</para></listitem>
+    </varlistentry>
+
+    <varlistentry><term>bar</term>
+    <listitem><para>Only display a progress bar during the builds.</para></listitem>
+    </varlistentry>
+
+    <varlistentry><term>bar-with-logs</term>
+    <listitem><para>Display the raw logs, with the progress bar at the bottom.</para></listitem>
+    </varlistentry>
+
+  </variablelist>
+
+  </listitem>
+
+</varlistentry>
+
 <varlistentry><term><option>--no-build-output</option> / <option>-Q</option></term>
 
   <listitem><para>By default, output written by builders to standard

src/libmain/common-args.cc

@@ -1,5 +1,6 @@
 #include "common-args.hh"
 #include "globals.hh"
+#include "loggers.hh"
 
 namespace nix {
 
@@ -38,6 +39,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',

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

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

src/nix/progress-bar.cc → src/libmain/progress-bar.cc

@@ -106,7 +106,7 @@ class ProgressBar : public Logger
         updateThread.join();
     }
 
-    void stop()
+    void stop() override
     {
         auto state(state_.lock());
         if (!state->active) return;
@@ -119,6 +119,10 @@ class ProgressBar : public Logger
         quitCV.notify_one();
     }
 
+    bool isVerbose() override {
+        return printBuildLogs;
+    }
+
     void log(Verbosity lvl, const FormatOrString & fs) override
     {
         auto state(state_.lock());
@@ -457,11 +461,17 @@ class ProgressBar : public Logger
     }
 };
 
-void startProgressBar(bool printBuildLogs)
+Logger * makeProgressBar(bool printBuildLogs)
 {
-    logger = new ProgressBar(
+    return new ProgressBar(
         printBuildLogs,
-        isatty(STDERR_FILENO) && getEnv("TERM").value_or("dumb") != "dumb");
+        isatty(STDERR_FILENO) && getEnv("TERM").value_or("dumb") != "dumb"
+    );
+}
+
+void startProgressBar(bool printBuildLogs)
+{
+    logger = makeProgressBar(printBuildLogs);
 }
 
 void stopProgressBar()

src/nix/progress-bar.hh → src/libmain/progress-bar.hh

@@ -4,6 +4,8 @@
 
 namespace nix {
 
+Logger * makeProgressBar(bool printBuildLogs = false);
+
 void startProgressBar(bool printBuildLogs = false);
 
 void stopProgressBar();

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>
@@ -169,7 +170,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({

src/libstore/build.cc

@@ -1642,7 +1642,7 @@ void DerivationGoal::buildDone()
                 worker.store.printStorePath(drvPath),
                 statusToString(status));
 
-            if (!settings.verboseBuild && !logTail.empty()) {
+            if (!logger->isVerbose() && !logTail.empty()) {
                 msg += (format("; last %d log lines:") % logTail.size()).str();
                 for (auto & line : logTail)
                     msg += "\n  " + line;
@@ -1691,11 +1691,7 @@ void DerivationGoal::buildDone()
                 }
 
                 void flushLine() {
-                    if (settings.verboseBuild) {
-                        printError("post-build-hook: " + currentLine);
-                    } else {
-                        act.result(resPostBuildLogLine, currentLine);
-                    }
+                    act.result(resPostBuildLogLine, currentLine);
                     currentLine.clear();
                 }
 
@@ -4155,13 +4151,8 @@ void DerivationGoal::flushLine()
         ;
 
     else {
-        if (settings.verboseBuild &&
-            (settings.printRepeatedBuilds || curRound == 1))
-            printError(currentLogLine);
-        else {
-            logTail.push_back(currentLogLine);
-            if (logTail.size() > settings.logLines) logTail.pop_front();
-        }
+        logTail.push_back(currentLogLine);
+        if (logTail.size() > settings.logLines) logTail.pop_front();
 
         act->result(resBuildLogLine, currentLogLine);
     }

src/libutil/logging.cc

@@ -18,7 +18,7 @@ void setCurActivity(const ActivityId activityId)
     curActivity = activityId;
 }
 
-Logger * logger = makeDefaultLogger();
+Logger * logger = makeSimpleLogger(true);
 
 void Logger::warn(const std::string & msg)
 {
@@ -35,13 +35,19 @@ class SimpleLogger : public Logger
 public:
 
     bool systemd, tty;
+    bool printBuildLogs;
 
-    SimpleLogger()
+    SimpleLogger(bool printBuildLogs)
+        : printBuildLogs(printBuildLogs)
     {
         systemd = getEnv("IN_SYSTEMD") == "1";
         tty = isatty(STDERR_FILENO);
     }
 
+    bool isVerbose() override {
+        return printBuildLogs;
+    }
+
     void log(Verbosity lvl, const FormatOrString & fs) override
     {
         if (lvl > verbosity) return;
@@ -70,6 +76,18 @@ class SimpleLogger : public Logger
         if (lvl <= verbosity && !s.empty())
             log(lvl, s + "...");
     }
+
+    void result(ActivityId act, ResultType type, const Fields & fields) override
+    {
+        if (type == resBuildLogLine && printBuildLogs) {
+            auto lastLine = fields[0].s;
+            printError(lastLine);
+        }
+        else if (type == resPostBuildLogLine && printBuildLogs) {
+            auto lastLine = fields[0].s;
+            printError("post-build-hook: " + lastLine);
+        }
+    }
 };
 
 Verbosity verbosity = lvlInfo;
@@ -94,9 +112,9 @@ void writeToStderr(const string & s)
     }
 }
 
-Logger * makeDefaultLogger()
+Logger * makeSimpleLogger(bool printBuildLogs)
 {
-    return new SimpleLogger();
+    return new SimpleLogger(printBuildLogs);
 }
 
 std::atomic<uint64_t> nextId{(uint64_t) getpid() << 32};
@@ -114,6 +132,10 @@ struct JSONLogger : Logger
 
     JSONLogger(Logger & prevLogger) : prevLogger(prevLogger) { }
 
+    bool isVerbose() override {
+        return true;
+    }
+
     void addFields(nlohmann::json & json, const Fields & fields)
     {
         if (fields.empty()) return;

src/libutil/logging.hh

@@ -63,6 +63,11 @@ public:
 
     virtual ~Logger() { }
 
+    virtual void stop() { };
+
+    // Whether the logger prints the whole build log
+    virtual bool isVerbose() { return false; }
+
     virtual void log(Verbosity lvl, const FormatOrString & fs) = 0;
 
     void log(const FormatOrString & fs)
@@ -141,7 +146,7 @@ struct PushActivity
 
 extern Logger * logger;
 
-Logger * makeDefaultLogger();
+Logger * makeSimpleLogger(bool printBuildLogs = true);
 
 Logger * makeJSONLogger(Logger & prevLogger);
 

src/libutil/util.cc

@@ -989,7 +989,7 @@ pid_t startProcess(std::function<void()> fun, const ProcessOptions & options)
 {
     auto wrapper = [&]() {
         if (!options.allowVfork)
-            logger = makeDefaultLogger();
+            logger = makeSimpleLogger();
         try {
 #if __linux__
             if (options.dieWithParent && prctl(PR_SET_PDEATHSIG, SIGKILL) == -1)

src/nix-build/nix-build.cc

@@ -472,6 +472,8 @@ static void _main(int argc, char * * argv)
 
         restoreSignals();
 
+        logger->stop();
+
         execvp(shell->c_str(), argPtrs.data());
 
         throw SysError("executing shell '%s'", *shell);
@@ -521,6 +523,8 @@ static void _main(int argc, char * * argv)
             if (auto store2 = store.dynamic_pointer_cast<LocalFSStore>())
                 store2->addPermRoot(store->parseStorePath(symlink.second), absPath(symlink.first), true);
 
+        logger->stop();
+
         for (auto & path : outPaths)
             std::cout << path << '\n';
     }

src/nix-env/nix-env.cc

@@ -1446,6 +1446,8 @@ static int _main(int argc, char * * argv)
 
         globals.state->printStats();
 
+        logger->stop();
+
         return 0;
     }
 }

src/nix-prefetch-url/nix-prefetch-url.cc

@@ -8,7 +8,7 @@
 #include "attr-path.hh"
 #include "finally.hh"
 #include "../nix/legacy.hh"
-#include "../nix/progress-bar.hh"
+#include "progress-bar.hh"
 #include "tarfile.hh"
 
 #include <iostream>