From c5edd8b7f87f8432bbf058b3456393793118906e Mon Sep 17 00:00:00 2001 From: Andrew Kelley Date: Thu, 16 Feb 2023 15:04:10 -0700 Subject: [PATCH] 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 | 54 ++++++++++++++++++++++++++++++++++-------- lib/std/Build.zig | 52 ++++++++++++++-------------------------- lib/std/Build/Step.zig | 26 ++++++++++++++++++-- 3 files changed, 86 insertions(+), 46 deletions(-) diff --git a/lib/build_runner.zig b/lib/build_runner.zig index 6ba583c59d..c1af3798ff 100644 --- a/lib/build_runner.zig +++ b/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"); } } diff --git a/lib/std/Build.zig b/lib/std/Build.zig index 75fa7ec1dd..92ace4e60b 100644 --- a/lib/std/Build.zig +++ b/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; }, } diff --git a/lib/std/Build/Step.zig b/lib/std/Build/Step.zig index 7bab2d9ae4..42698f2190 100644 --- a/lib/std/Build/Step.zig +++ b/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;