std.Build: better handling of stderr of child processes

With this commit, the build runner now communicates progress towards
completion of the step graph to the terminal, while also printing the
stderr of child processes as soon as possible, without clobbering each
other, and without clobbering the CLI progress output.

lib/build_runner.zig

@@ -243,14 +243,22 @@ pub fn main() !void {
         }
     }
 
+    var progress: std.Progress = .{};
+    const main_progress_node = progress.start("", 0);
+    defer main_progress_node.end();
+
     builder.debug_log_scopes = debug_log_scopes.items;
     builder.resolveInstallPrefix(install_prefix, dir_list);
-    try builder.runBuild(root);
+    {
+        var prog_node = main_progress_node.start("user build.zig logic", 0);
+        defer prog_node.end();
+        try builder.runBuild(root);
+    }
 
     if (builder.validateUserInputDidItFail())
         usageAndErr(builder, true, stderr_stream);
 
-    runStepNames(builder, targets.items) catch |err| {
+    runStepNames(builder, targets.items, main_progress_node) catch |err| {
         switch (err) {
             error.UncleanExit => process.exit(1),
             else => return err,
@@ -258,7 +266,11 @@ pub fn main() !void {
     };
 }
 
-fn runStepNames(b: *std.Build, step_names: []const []const u8) !void {
+fn runStepNames(
+    b: *std.Build,
+    step_names: []const []const u8,
+    parent_prog_node: *std.Progress.Node,
+) !void {
     var step_stack = ArrayList(*Step).init(b.allocator);
     defer step_stack.deinit();
 
@@ -289,6 +301,9 @@ fn runStepNames(b: *std.Build, step_names: []const []const u8) !void {
     defer thread_pool.deinit();
 
     {
+        var step_prog = parent_prog_node.start("run steps", step_stack.items.len);
+        defer step_prog.end();
+
         var wait_group: std.Thread.WaitGroup = .{};
         defer wait_group.wait();
 
@@ -301,8 +316,9 @@ fn runStepNames(b: *std.Build, step_names: []const []const u8) !void {
             const step = step_stack.items[i];
 
             wait_group.start();
-            thread_pool.spawn(workerMakeOneStep, .{ &wait_group, &thread_pool, b, step }) catch
-                @panic("OOM");
+            thread_pool.spawn(workerMakeOneStep, .{
+                &wait_group, &thread_pool, b, step, &step_prog,
+            }) catch @panic("OOM");
         }
     }
 
@@ -312,14 +328,18 @@ fn runStepNames(b: *std.Build, step_names: []const []const u8) !void {
         switch (s.state) {
             .precheck_unstarted => unreachable,
             .precheck_started => unreachable,
-            .precheck_done => unreachable,
             .running => unreachable,
-            .dependency_failure => continue,
+            // precheck_done is equivalent to dependency_failure in the case of
+            // transitive dependencies. For example:
+            // A -> B -> C (failure)
+            // B will be marked as dependency_failure, while A may never be queued, and thus
+            // remain in the initial state of precheck_done.
+            .dependency_failure, .precheck_done => continue,
             .success => continue,
             .failure => {
                 any_failed = true;
-                std.debug.print("{s}: {s}\n{s}", .{
-                    s.name, @errorName(s.result.err_code), s.result.stderr,
+                std.debug.print("{s}: {s}\n", .{
+                    s.name, @errorName(s.result.err_code),
                 });
             },
         }
@@ -371,6 +391,7 @@ fn workerMakeOneStep(
     thread_pool: *std.Thread.Pool,
     b: *std.Build,
     s: *Step,
+    prog_node: *std.Progress.Node,
 ) void {
     defer wg.finish();
 
@@ -399,6 +420,10 @@ fn workerMakeOneStep(
         return;
     }
 
+    var sub_prog_node = prog_node.start(s.name, 0);
+    sub_prog_node.activate();
+    defer sub_prog_node.end();
+
     // I suspect we will want to pass `b` to make() in a future modification.
     // For example, CompileStep does some sus things with modifying the saved
     // *Build object in install header steps that might be able to be removed
@@ -406,6 +431,13 @@ fn workerMakeOneStep(
     s.make() catch |err| {
         s.result.err_code = err;
         @atomicStore(Step.State, &s.state, .failure, .SeqCst);
+
+        sub_prog_node.context.lock_stderr();
+        defer sub_prog_node.context.unlock_stderr();
+
+        for (s.result.error_msgs.items) |msg| {
+            std.io.getStdErr().writeAll(msg) catch return;
+        }
         return;
     };
 
@@ -414,7 +446,9 @@ fn workerMakeOneStep(
     // Successful completion of a step, so we queue up its dependants as well.
     for (s.dependants.items) |dep| {
         wg.start();
-        thread_pool.spawn(workerMakeOneStep, .{ wg, thread_pool, b, dep }) catch @panic("OOM");
+        thread_pool.spawn(workerMakeOneStep, .{
+            wg, thread_pool, b, dep, prog_node,
+        }) catch @panic("OOM");
     }
 }
 

lib/std/Build.zig

@@ -1417,59 +1417,43 @@ pub fn execFromStep(b: *Build, argv: []const []const u8, s: *Step) ![]u8 {
     }
 
     if (!process.can_spawn) {
-        s.result.stderr = b.fmt("Unable to spawn the following command: cannot spawn child processes\n{s}", .{
+        try s.result.error_msgs.append(b.allocator, b.fmt("Unable to spawn the following command: cannot spawn child processes\n{s}", .{
             try allocPrintCmd(b.allocator, null, argv),
-        });
+        }));
         return error.CannotSpawnProcesses;
     }
 
-    var code: u8 = undefined;
-    const result = unwrapExecResult(&code, std.ChildProcess.exec(.{
+    const result = std.ChildProcess.exec(.{
         .allocator = b.allocator,
         .argv = argv,
         .env_map = b.env_map,
         .max_output_bytes = 10 * 1024 * 1024,
-    })) catch |err| switch (err) {
-        error.FileNotFound => {
-            s.result.stderr = b.fmt("unable to spawn the following command: file not found\n{s}", .{
-                try allocPrintCmd(b.allocator, null, argv),
-            });
-            return error.ExecFailed;
-        },
-        error.ExitCodeFailure => {
-            s.result.stderr = b.fmt("the following command exited with error code {d}:\n{s}", .{
-                code, try allocPrintCmd(b.allocator, null, argv),
-            });
-            return error.ExecFailed;
-        },
-        error.ProcessTerminated => {
-            s.result.stderr = b.fmt("the following command terminated unexpectedly:\n{s}", .{
-                try allocPrintCmd(b.allocator, null, argv),
-            });
-            return error.ExecFailed;
-        },
-        else => |e| return e,
+    }) catch |err| {
+        try s.result.error_msgs.append(b.allocator, b.fmt("unable to spawn the following command: {s}\n{s}", .{
+            @errorName(err), try allocPrintCmd(b.allocator, null, argv),
+        }));
+        return error.ExecFailed;
     };
 
-    s.result.stderr = result.stderr;
-    return result.stdout;
-}
+    if (result.stderr.len != 0) {
+        try s.result.error_msgs.append(b.allocator, result.stderr);
+    }
 
-fn unwrapExecResult(
-    code_ptr: *u8,
-    wrapped: std.ChildProcess.ExecError!std.ChildProcess.ExecResult,
-) !std.ChildProcess.ExecResult {
-    const result = try wrapped;
     switch (result.term) {
         .Exited => |code| {
-            code_ptr.* = code;
             if (code != 0) {
+                try s.result.error_msgs.append(b.allocator, b.fmt("the following command exited with error code {d}:\n{s}", .{
+                    code, try allocPrintCmd(b.allocator, null, argv),
+                }));
                 return error.ExitCodeFailure;
             }
-            return result;
+            return result.stdout;
         },
         .Signal, .Stopped, .Unknown => |code| {
             _ = code;
+            try s.result.error_msgs.append(b.allocator, b.fmt("the following command terminated unexpectedly:\n{s}", .{
+                try allocPrintCmd(b.allocator, null, argv),
+            }));
             return error.ProcessTerminated;
         },
     }

lib/std/Build/Step.zig

@@ -9,7 +9,7 @@ state: State,
 /// Populated only if state is success.
 result: struct {
     err_code: anyerror,
-    stderr: []u8,
+    error_msgs: std.ArrayListUnmanaged([]const u8),
 },
 /// The return addresss associated with creation of this step that can be useful
 /// to print along with debugging messages.
@@ -96,7 +96,7 @@ pub fn init(allocator: Allocator, options: Options) Step {
         .state = .precheck_unstarted,
         .result = .{
             .err_code = undefined,
-            .stderr = &.{},
+            .error_msgs = .{},
         },
         .debug_stack_trace = addresses,
     };
@@ -133,6 +133,28 @@ pub fn cast(step: *Step, comptime T: type) ?*T {
     return null;
 }
 
+/// For debugging purposes, prints identifying information about this Step.
+pub fn dump(step: *Step) void {
+    std.debug.getStderrMutex().lock();
+    defer std.debug.getStderrMutex().unlock();
+
+    const stderr = std.io.getStdErr();
+    const w = stderr.writer();
+    const tty_config = std.debug.detectTTYConfig(stderr);
+    const debug_info = std.debug.getSelfDebugInfo() catch |err| {
+        w.print("Unable to dump stack trace: Unable to open debug info: {s}\n", .{
+            @errorName(err),
+        }) catch {};
+        return;
+    };
+    const ally = debug_info.allocator;
+    w.print("name: '{s}'. creation stack trace:\n", .{step.name}) catch {};
+    std.debug.writeStackTrace(step.getStackTrace(), w, ally, debug_info, tty_config) catch |err| {
+        stderr.writer().print("Unable to dump stack trace: {s}\n", .{@errorName(err)}) catch {};
+        return;
+    };
+}
+
 const Step = @This();
 const std = @import("../std.zig");
 const Build = std.Build;