daemon: Support multiplexed build output.

This allows clients to tell whether output comes from the daemon or, if
it comes from a builder, from which builder it comes.  The latter is
particularly useful when MAX-BUILD-JOBS > 1.

* nix/libstore/build.cc (DerivationGoal::tryBuildHook)
(DerivationGoal::startBuilder): Print the child's PID in "@ build-started"
traces.
(DerivationGoal::handleChildOutput): Define 'prefix', pass it to
'writeToStderr'.
* nix/libstore/globals.cc (Settings:Settings): Initialize
'multiplexedBuildOutput'.
(Settings::update): Likewise.
* nix/libstore/globals.hh (Settings)[multiplexedBuildOutput]: New field.
Update 'printBuildTrace' documentation.
* nix/libstore/worker-protocol.hh (PROTOCOL_VERSION): Bump to 0.163.
* nix/nix-daemon/nix-daemon.cc (performOp) <wopSetOptions>: Special-case
"multiplexed-build-output" and remove "use-ssh-substituter".
* guix/store.scm (set-build-options): Add #:multiplexed-build-output?
and honor it.
(%protocol-version): Bump to #x163.
* tests/store.scm ("multiplexed-build-output"): New test.

fixlet

7 files changed, 108 insertions, 10 deletions

diff --git a/guix/store.scm b/guix/store.scm
index 8b35fc8d7a..b1bdbf3813 100644
--- a/guix/store.scm
+++ b/guix/store.scm
@@ -155,7 +155,7 @@
             derivation-log-file
             log-file))
 
-(define %protocol-version #x162)
+(define %protocol-version #x163)
 
 (define %worker-magic-1 #x6e697863)               ; "nixc"
 (define %worker-magic-2 #x6478696f)               ; "dxio"
@@ -709,6 +709,15 @@ encoding conversion errors."
                             ;; disabled by default.
                             print-extended-build-trace?
 
+                            ;; When true, the daemon prefixes builder output
+                            ;; with "@ build-log" traces so we can
+                            ;; distinguish it from daemon output, and we can
+                            ;; distinguish each builder's output
+                            ;; (PRINT-BUILD-TRACE must be true as well.)  The
+                            ;; latter is particularly useful when
+                            ;; MAX-BUILD-JOBS > 1.
+                            multiplexed-build-output?
+
                             build-cores
                             (use-substitutes? #t)
 
@@ -757,6 +766,10 @@ encoding conversion errors."
                            `(("print-extended-build-trace"
                               . ,(if print-extended-build-trace? "1" "0")))
                            '())
+                     ,@(if multiplexed-build-output?
+                           `(("multiplexed-build-output"
+                              . ,(if multiplexed-build-output? "true" "false")))
+                           '())
                      ,@(if timeout
                            `(("build-timeout" . ,(number->string timeout)))
                            '())
diff --git a/nix/libstore/build.cc b/nix/libstore/build.cc
index b2c319f00b..d7b8b0f0ca 100644
--- a/nix/libstore/build.cc
+++ b/nix/libstore/build.cc
@@ -1652,8 +1652,8 @@ HookReply DerivationGoal::tryBuildHook()
     worker.childStarted(shared_from_this(), hook->pid, fds, false, false);
 
     if (settings.printBuildTrace)
-        printMsg(lvlError, format("@ build-started %1% - %2% %3%")
-            % drvPath % drv.platform % logFile);
+        printMsg(lvlError, format("@ build-started %1% - %2% %3% %4%")
+            % drvPath % drv.platform % logFile % hook->pid);
 
     return rpAccept;
 }
@@ -2038,8 +2038,8 @@ void DerivationGoal::startBuilder()
     if (!msg.empty()) throw Error(msg);
 
     if (settings.printBuildTrace) {
-        printMsg(lvlError, format("@ build-started %1% - %2% %3%")
-            % drvPath % drv.platform % logFile);
+        printMsg(lvlError, format("@ build-started %1% - %2% %3% %4%")
+            % drvPath % drv.platform % logFile % pid);
     }
 
 }
@@ -2736,6 +2736,19 @@ void DerivationGoal::deleteTmpDir(bool force)
 
 void DerivationGoal::handleChildOutput(int fd, const string & data)
 {
+    string prefix;
+
+    if (settings.multiplexedBuildOutput) {
+	/* Print a prefix that allows clients to determine whether a message
+	   comes from the daemon or from a build process, and in the latter
+	   case, which build process it comes from.  The PID here matches the
+	   one given in "@ build-started" traces; it's shorter that the
+	   derivation file name, hence this choice.  */
+	prefix = "@ build-log "
+	    + std::to_string(pid < 0 ? hook->pid : pid)
+	    + " " + std::to_string(data.size()) + "\n";
+    }
+
     if ((hook && fd == hook->builderOut.readSide) ||
         (!hook && fd == builderOut.readSide))
     {
@@ -2748,7 +2761,7 @@ void DerivationGoal::handleChildOutput(int fd, const string & data)
             return;
         }
         if (verbosity >= settings.buildVerbosity)
-            writeToStderr(data);
+            writeToStderr(prefix + data);
 
 	if (gzLogFile) {
 	    if (data.size() > 0) {
@@ -2767,7 +2780,7 @@ void DerivationGoal::handleChildOutput(int fd, const string & data)
     }
 
     if (hook && fd == hook->fromHook.readSide)
-        writeToStderr(data);
+        writeToStderr(prefix + data);
 }
 
 
diff --git a/nix/libstore/globals.cc b/nix/libstore/globals.cc
index 94c2e516f8..4b5b485e65 100644
--- a/nix/libstore/globals.cc
+++ b/nix/libstore/globals.cc
@@ -36,6 +36,7 @@ Settings::Settings()
     buildTimeout = 0;
     useBuildHook = true;
     printBuildTrace = false;
+    multiplexedBuildOutput = false;
     reservedSize = 8 * 1024 * 1024;
     fsyncMetadata = true;
     useSQLiteWAL = true;
@@ -120,6 +121,7 @@ void Settings::update()
     _get(maxBuildJobs, "build-max-jobs");
     _get(buildCores, "build-cores");
     _get(thisSystem, "system");
+    _get(multiplexedBuildOutput, "multiplexed-build-output");
     _get(maxSilentTime, "build-max-silent-time");
     _get(buildTimeout, "build-timeout");
     _get(reservedSize, "gc-reserved-space");
diff --git a/nix/libstore/globals.hh b/nix/libstore/globals.hh
index 4c142e6933..a6935c3337 100644
--- a/nix/libstore/globals.hh
+++ b/nix/libstore/globals.hh
@@ -127,7 +127,7 @@ struct Settings {
        a fixed format to allow its progress to be monitored.  Each
        line starts with a "@".  The following are defined:
 
-       @ build-started <drvpath> <outpath> <system> <logfile>
+       @ build-started <drvpath> <outpath> <system> <logfile> <pid>
        @ build-failed <drvpath> <outpath> <exitcode> <error text>
        @ build-succeeded <drvpath> <outpath>
        @ substituter-started <outpath> <substituter>
@@ -139,6 +139,13 @@ struct Settings {
        builders. */
     bool printBuildTrace;
 
+    /* When true, 'buildDerivations' prefixes lines coming from builders so
+       that clients know exactly which line comes from which builder, and
+       which line comes from the daemon itself.  The prefix for data coming
+       from builders is "log:PID:LEN:DATA" where PID uniquely identifies the
+       builder (PID is given in "build-started" traces.)  */
+    bool multiplexedBuildOutput;
+
     /* Amount of reserved space for the garbage collector
        (/nix/var/nix/db/reserved). */
     off_t reservedSize;
diff --git a/nix/libstore/worker-protocol.hh b/nix/libstore/worker-protocol.hh
index 103d60a8c2..ea67b10a5b 100644
--- a/nix/libstore/worker-protocol.hh
+++ b/nix/libstore/worker-protocol.hh
@@ -6,7 +6,7 @@ namespace nix {
 #define WORKER_MAGIC_1 0x6e697863
 #define WORKER_MAGIC_2 0x6478696f
 
-#define PROTOCOL_VERSION 0x162
+#define PROTOCOL_VERSION 0x163
 #define GET_PROTOCOL_MAJOR(x) ((x) & 0xff00)
 #define GET_PROTOCOL_MINOR(x) ((x) & 0x00ff)
 
diff --git a/nix/nix-daemon/nix-daemon.cc b/nix/nix-daemon/nix-daemon.cc
index 782e4acfc5..2939422172 100644
--- a/nix/nix-daemon/nix-daemon.cc
+++ b/nix/nix-daemon/nix-daemon.cc
@@ -594,7 +594,7 @@ static void performOp(bool trusted, unsigned int clientVersion,
                 if (name == "build-timeout" || name == "build-max-silent-time"
                     || name == "build-max-jobs" || name == "build-cores"
                     || name == "build-repeat"
-                    || name == "use-ssh-substituter")
+                    || name == "multiplexed-build-output")
                     settings.set(name, value);
                 else
                     settings.set(trusted ? name : "untrusted-" + name, value);
diff --git a/tests/store.scm b/tests/store.scm
index 2858369706..3ff526cdcf 100644
--- a/tests/store.scm
+++ b/tests/store.scm
@@ -31,6 +31,7 @@
   #:use-module (gnu packages)
   #:use-module (gnu packages bootstrap)
   #:use-module (ice-9 match)
+  #:use-module (ice-9 regex)
   #:use-module (rnrs bytevectors)
   #:use-module (rnrs io ports)
   #:use-module (web uri)
@@ -1021,4 +1022,66 @@
                  (call-with-input-file (derivation->output-path drv2)
                    read))))))
 
+(test-equal "multiplexed-build-output"
+  '("Hello from first." "Hello from second.")
+  (with-store store
+    (let* ((build  (add-text-to-store store "build.sh"
+                                      "echo Hello from $NAME.; echo > $out"))
+           (bash   (add-to-store store "bash" #t "sha256"
+                                 (search-bootstrap-binary "bash"
+                                                          (%current-system))))
+           (drv1   (derivation store "one" bash
+                               `("-e" ,build)
+                               #:inputs `((,bash) (,build))
+                               #:env-vars `(("NAME" . "first")
+                                            ("x" . ,(random-text)))))
+           (drv2   (derivation store "two" bash
+                               `("-e" ,build)
+                               #:inputs `((,bash) (,build))
+                               #:env-vars `(("NAME" . "second")
+                                            ("x" . ,(random-text))))))
+      (set-build-options store
+                         #:print-build-trace #t
+                         #:multiplexed-build-output? #t
+                         #:max-build-jobs 10)
+      (let ((port (open-output-string)))
+        ;; Send the build log to PORT.
+        (parameterize ((current-build-output-port port))
+          (build-derivations store (list drv1 drv2)))
+
+        ;; Retrieve the build log; make sure it contains valid "@ build-log"
+        ;; traces that allow us to retrieve each builder's output (we assume
+        ;; there's exactly one "build-output" trace for each builder, which is
+        ;; reasonable.)
+        (let* ((log     (get-output-string port))
+               (started (fold-matches
+                         (make-regexp "@ build-started ([^ ]+) - ([^ ]+) ([^ ]+) ([0-9]+)")
+                         log '() cons))
+               (done    (fold-matches
+                         (make-regexp "@ build-succeeded (.*) - (.*) (.*) (.*)")
+                         log '() cons))
+               (output  (fold-matches
+                         (make-regexp "@ build-log ([[:digit:]]+) ([[:digit:]]+)\n([A-Za-z .*]+)\n")
+                         log '() cons))
+               (drv-pid (lambda (name)
+                          (lambda (m)
+                            (let ((drv (match:substring m 1))
+                                  (pid (string->number
+                                        (match:substring m 4))))
+                              (and (string-suffix? name drv) pid)))))
+               (pid-log (lambda (pid)
+                          (lambda (m)
+                            (let ((n   (string->number
+                                        (match:substring m 1)))
+                                  (len (string->number
+                                        (match:substring m 2)))
+                                  (str (match:substring m 3)))
+                              (and (= pid n)
+                                   (= (string-length str) (- len 1))
+                                   str)))))
+               (pid1    (any (drv-pid "one.drv") started))
+               (pid2    (any (drv-pid "two.drv") started)))
+          (list (any (pid-log pid1) output)
+                (any (pid-log pid2) output)))))))
+
 (test-end "store")