build runner prints "failed command" when step has non-failure stderr #31077

Link to comment describing the enhancement which should be made: #31077 (comment)

Original issue text is below.

Zig Version

0.16.0-dev.2349+204fa8959

Steps to Reproduce and Observed Behavior

I am learning Zig, so apologies if I missed something obvious.

test.zig:

const std = @import("std");
test "crash reproduction" {
 std.debug.print("This output to stderr might cause a crash.\n", .{});
}

When running zig build test I get:

test
└─ run test w
This output to stderr might cause a crash.
failed command: ./.zig-cache/o/24e009cdb31905b1832151517d512a8e/test --cache-dir=./.zig-cache --seed=0x7ca33b43 --listen=-

If I remove the debug statement the problem disappears. I tested with Zig 0.15.2, and it doesn't have this problem.

Note that std.debug.print only outputs to stderr, not stdout (I verified with shell redirection), so this isn't a duplicate of the known issue with stdout: https://github.com/ziglang/zig/issues/15091

Expected Behavior

• No "failed command" warning.
• No output when running 'zig build test' (because no failing test). [EDIT: ignore this part, I understand that it is not how it is supposed to work]

Also, I think that the test runner is supposed to capture stderr and only show it in case of failure?

Working as designed. Unit tests should avoid printing to stderr in success cases.

May I ask why? Even for unit tests having debug logging can be useful, particularly if tests fail. Why prohibit any output on both stdout and stderr? This is not very user friendly, IMO (and it worked in Zig 0.15).

I mean, what would you want to happen when you write to stderr from a unit test? According to your "expected behavior", you want the build system to completely swallow stderr from a test if it doesn't report failure. That doesn't seem reasonable; stderr is useful for reporting non-fatal failure conditions such as memory leaks (and this is exactly what will happen if you leak memory from std.testing.allocator). More generally, why print to stderr at all if you're not interested in the output?

To be clear, this is not causing the test process or build system to crash. It's not even marking a test as failed or causing zig build to exit with a non-zero status---it's just forwarding the stderr output to you. If you really do want logging output from your tests, then you can leave it in and still use the build system just fine! It's just that your logs will be, well, logged :P

OK, I can understand the part about not swallowing stderr and outputting in case of failure. I thought that it was how it was supposed to work, but it is fine if it doesn't do that.

Did you see the part that it outputs a "failed command" line? That's what actually confused me and the actual problem.

I am reopening one last time because I think that the report was misunderstood (I won't reopen it again after that).

Hm, okay, I can see how that could cause confusion. The command line should definitely still be printed, but that part could be reworded in the case where the step has output messages but is not considered to have failed. Perhaps it should print "from command: ..." instead of "failed command: ..." in that case.

imo it printing "failed command" isn't something that necessarily should be fixed because had it not been printed you never would have reached out and learned that what you were doing was illegal to do in a test

Writing to stdout is illegal, writing to stderr isn't (AFAIK).

i was under the understanding using stderr is only legal if you go through std.log

@nektro wrote in #31077 (comment):

i was under the understanding using stderr is only legal if you go through std.log

From my own tests, I believe the difference in 0.16.0 is that now std.log.warn will fail a test wheres it didn't in 0.15.2. When I change my warn's to info's my tests pass.

I think it would be nice if the test failure mentioned "logged to stderr" was the reason for the test failure, or something to that effect. I can see why that behavior makes sense, but I don't think it's super common among test runners. When my tests failed after migrating my code to 0.16.0, my first thought was: "I see some logs, but where's the error?". It took me a while to understand why the failure was happening.

@mlugg wrote in #31077 (comment):

Working as designed. Unit tests should avoid printing to stderr in success cases.

How can I test functions of dependency code, which output to stderr?

How can I test expected failure?

I have same problem, but std.debug.print was inside tested function. And failed command: did go away after commenting print statement out

pub fn take(self: SchedulerRandom) !Task {
 const amount = try self.bus.inbox.get(self.io, self.buf, 1);
 const needle = self.random_engine.intRangeAtMost(u64, 0, amount);
 std.debug.print("needle {}\n", .{needle}); // here was the problem
 assert(0 <= needle and needle <= amount);
 return self.buf[needle];
}

Test itself

test "test fixed random scheduler" {
 var fixed_random_engine = FixedRandom{ .value = 0 };
 const random_engine = fixed_random_engine.random();
 var inbox_buf: [3]Task = undefined;
 var outbox_buf: [3]Task = undefined;
 var bus = try Bus.init(testing.io, &inbox_buf, &outbox_buf);
 defer bus.close();
 const args: []const []const u8 = &.{"hel"};
 const expected_task = Task{
 .command = .get,
 .args = args,
 .conn_writer = undefined,
 };
 try bus.inbox.putOne(testing.io, expected_task);
 var buf: [3]Task = undefined;
 var s = SchedulerRandom.init(random_engine, &bus, testing.io, &buf);
 const task = try s.take();
 try testing.expectEqual(expected_task.command, task.command);
 try testing.expectEqualSlices(u8, expected_task.args[0], task.args[0]);
}

@jasperw wrote in #31077 (comment):

From my own tests, I believe the difference in 0.16.0 is that now std.log.warn will fail a test wheres it didn't in 0.15.2. When I change my warn's to info's my tests pass.

I think it would be nice if the test failure mentioned "logged to stderr" was the reason for the test failure, or something to that effect. [...]

This is closely tied with std.testing.log_level, so you could alternatively also set that to .err and only error logs would fail your tests. And setting it to .debug will cause this failure on any log level.

That being said, I think the existence of this dedicated global and its options should be respected in the encompassing framework. If there's a flag to control the expected log level, how should that log level not be acceptable. The current docs mention a github thread where the idea of logs in tests via flag was also mentioned.

test "simple math" {
 std.testing.log_level = .debug;
 std.log.info("Simple math info.", .{});
 try std.testing.expectEqual(@as(u8, 2), @as(u8, 1) + 1);
}

image

For me simply renaming the 'failed' to 'from' as suggested is fine by me and maybe the red w to a blue i assuming w stand for warning ?

PS Looking at https://codeberg.org/ziglang/zig/src/branch/master/lib/compiler/Maker.zig#L1656 seems like this simple change is a significant refactor? As in a complete new 'pub fn printInfoMessages(...' and rewrite everything around it?