zig icon indicating copy to clipboard operation
zig copied to clipboard

prevent confusing debugging experience when users write garbage to stdout, interfering with the build runner / test runner protocol

Open gitusel opened this issue 2 years ago • 26 comments

Zig Version

0.11.0-dev.2297+28d6dd75a

Steps to Reproduce and Observed Behavior

1/ zig init-lib 2/ Correct test_step.dependOn(&main_tests.step); to test_step.dependOn(&main_tests.run().step); 3/ src/main.zig const std = @import("std"); test "t" { const writer = std.io.getStdOut().writer(); var buffered_writer = std.io.bufferedWriter(writer); var stdout_writer = buffered_writer.writer(); stdout_writer.print("TEST: t\n", .{}) catch @panic("PANIC!\n"); buffered_writer.flush() catch @panic("PANIC!\n"); }

4/ run zig build test. The test stalled and you need to exit using ctrl+c.

Expected Behavior

The test should run and exit.

If using stdErr, e.g. changing const writer = std.io.getStdOut().writer(); to const writer = std.io.getStdErr().writer(); will make it passed.

gitusel avatar Mar 27 '23 18:03 gitusel

After the build parallel changes, stdout is now used to communicate progress to the build exe so that it can display aggregate progress for all simultaneously running test processes. Do you have a specific use case for writing to stdout instead of stderr from a test?

jacobly0 avatar Mar 27 '23 20:03 jacobly0

If for any reason a function is displaying something then it will be blocked, e.g.: const std = @import("std"); fn t() u8 { const writer = std.io.getStdOut().writer(); var buffered_writer = std.io.bufferedWriter(writer); var stdout_writer = buffered_writer.writer(); stdout_writer.print("TEST: t\n", .{}) catch @panic("PANIC!\n"); buffered_writer.flush() catch @panic("PANIC!\n"); return 0; }

test "t" { try std.testing.expect(t() == 0); }

will also never exit.

gitusel avatar Mar 27 '23 21:03 gitusel

By use case, I mean a specific motivating example, not "any reason". This involves more of an explanation for why the function is required to write to standard out and why it benefits from being tested than necessarily specific code. Based on the example, it vaguely suggests that the function just wants to print some testing status to stdout, which if even this were allowed, wouldn't work very well now that multiple test processes can be running at the same time. The current behavior is to collect all stderr and print it after the test runs, which is useful for descriptions of test failures, but not very useful for live status updates.

I do have an idea for addressing the hanging issue. At least on linux, stdout could be dup'd and closed when used by the test runner so that other code can't accidentally write to it. The descriptor could even be replaced with a handle to /dev/null so that bad code that does use it at least won't error (and to avoid it getting replaced with another open'd descriptior I guess), but I'm not sure which behavior is more desirable.

jacobly0 avatar Mar 27 '23 21:03 jacobly0

Not sure to understand what you are looking for. But for instance, simple logging to stdOut. The code shared is a simplified version to show the issue. The solution to leverage stdOut as an internal channel between a test and build exe does not appear viable.

gitusel avatar Mar 27 '23 21:03 gitusel

A reduced example is very valuable for demonstrating the issue, and in this case I agree that the example doesn't work as expected and so that has served its purpose. However, by reducing the example, there tends to be a lot of lost context that can be filled in by an explanation of what you were trying to accomplish when you ran into the issue. If the answer is that you don't specifically need stdout to work, but you just wanted to log something and happened to use stdout, expecting it to work, then that is a perfectly valid use case, and you are just missing a description of what you wanted to log (test progress, test result status, failure description, debug prints, actually testing a "log something to stdout" function, etc) and why logging to stderr instead does not solve this use case. Note that std.log uses stderr by default, so there's nothing inherent about the term "logging" that implies a requirement to use stdout in this context.

jacobly0 avatar Mar 27 '23 22:03 jacobly0

(Un)fortunately, in this particular case, the library I translated is using its own logging framework and it relies on stdout. I think that the IPC between the build exe and the test RunStep has to be private.

gitusel avatar Mar 27 '23 23:03 gitusel

It is not confusion but test run never exits.

gitusel avatar Apr 16 '23 01:04 gitusel

I just ran into this too.

Do you have a specific use case for writing to stdout instead of stderr from a test

It doesn't have to be the test that writes to stdout for it to hang, it can be the code under test. For example, this hangs

fn echo(data: []const u8) !void {
	try std.io.getStdOut().writeAll(data);
}

test "echo" {
	try echo("hello");
}

This is obviously a minimal example to reproduce the issue. But I don't think it's an edge-case that code under test, maybe through a library and maybe directly, might want to use stdout.

karlseguin avatar Apr 26 '23 04:04 karlseguin

@andrewrk I guess I can see how being able to use stdout is considered an enhancement. But "zig build test" hanging when a function in the standard library is used should surely be classified as a bug?

karlseguin avatar Apr 26 '23 04:04 karlseguin

std.testing.expectEqualStrings() is currently unusable as of this

edit: the test part works, specifically the debugging output that makes it more useful than expect(std.mem.eql(a, b))

nektro avatar May 16 '23 17:05 nektro

Hi @andrewrk. Any progress on runner and builder communication design? It is very problematic to me that this issue is not recognized as a fundamental flaw in the current test framework. It is also the very first time that a test framework is imposing to me the way my program should communicate with its user.

gitusel avatar May 21 '23 04:05 gitusel

I started learning the language today and was really confused by my very simple test hanging when trying to print to stdout.

Printing with std.debug.print() (or directly to stderr) adds an error: prefix, which can also be pretty confusing (because I'm trying to log a value, not an error) so it's definitely not desirable for my use-case.

HeCorr avatar Jun 01 '23 02:06 HeCorr

@gitusel this seems to be an issue with running the tests with zig build test.

A Reddit user suggested trying zig test instead and it did work for me. Could you try that?

HeCorr avatar Jun 02 '23 04:06 HeCorr

@HeCorr, zig test and zig build test are not exactly the same. https://zig.news/slimsag/my-hopes-and-dreams-for-zig-test-2pkh

gitusel avatar Jun 04 '23 21:06 gitusel

I have the same problem #16916, As I was using the tests to test language features and my code implementation (rather than testing an already written code). Since it's not a use case, as I figured out, it's should be an error to print to stdout during test. Or there should be a warning about Undefined Behavior in the documentation or even the compile.

As for external libraries using stdout, it's a dipper problem.

Lking03x avatar Aug 25 '23 17:08 Lking03x

There's an easy way to understand who owns standard in and standard out. Whichever component has the main() function. In the case of zig unit testing, the unit test themselves are not part of an application that has a main() function. It is the test runner that has the main function, and it is the test runner that gets to decide what to do with stdin and stdout.

stderr, on the other hand, is available to write things to, although I would recommend std.log instead so that the test runner can handle those messages appropriately.

Don't write to stdout if you are not the main application!

andrewrk avatar Oct 31 '23 23:10 andrewrk

So no code that is invoked indirectly by a test case can write to stdout either? That seems very limiting. Especially when the failure mode is a silent hang.

It is also surprising and confusing for tests that work under zig test to hang under zig build test.

EDIT: std.debug.print goes to stderr, ignore this:

This design also precludes adding a std.debug.print to debug test failures.

AFAICT, the test runner itself can write to stdout in rare cases:

            else => {
                std.debug.print("unsupported message: {x}", .{@intFromEnum(hdr.tag)});
                std.process.exit(1);
            },

If you want to keep stdout for the test runner's protocol, would you accept changes that make the stdout writer panic (to stderr!) if they're used during a test?

rootbeer avatar Nov 01 '23 01:11 rootbeer

So no code that is invoked indirectly by a test case can write to stdout either? That seems very limiting. Especially when the failure mode is a silent hang.

It is also surprising and confusing for tests that work under zig test to hang under zig build test.

This design also precludes adding a std.debug.print to debug test failures.

AFAICT, the test runner itself can write to stdout in rare cases:

            else => {
                std.debug.print("unsupported message: {x}", .{@intFromEnum(hdr.tag)});
                std.process.exit(1);
            },

If you want to keep stdout for the test runner's protocol, would you accept changes that make std.debug.print() and the stdout writer panic (to stderr!) if they're used during a test?

std.debug.print already uses stderr https://github.com/ziglang/zig/blob/46062f1c13d8ee9eebf49806660c2271f2acc613/lib/std/debug.zig#L82

Beyley avatar Nov 01 '23 02:11 Beyley

Ack, sorry to confuse things. You're right.

rootbeer avatar Nov 01 '23 02:11 rootbeer

There's an easy way to understand who owns standard in and standard out.

More fundamentally, why stdout was chosen as communication channel for the test runner protocol in the first place? Why not some other non-standard file descriptor like fd=3? In this case stdout will be available to the user alongside stderr. Am I missing something?

slonik-az avatar Nov 26 '23 23:11 slonik-az

afaik changing the behavior is planned, but its because unit tests are not supposed to have side effects and using std.log does still work

nektro avatar Nov 26 '23 23:11 nektro

afaik changing the behavior is planned, but its because unit tests are not supposed to have side effects and using std.log does still work

Changing file descriptor from fd=1 (stdout) to unassigned one (like fd=3) will not introduce any side effects and existing tests should run exactly the same way as before.

slonik-az avatar Nov 27 '23 02:11 slonik-az

Once again, it has nothing to do with "unit tests which are not supposed to have side effects" or "who has the main() function decides". It has to do with 1/ it worked before the introduction of parallel test runners, 2/ the framework assumes that all std file descriptors are available, which to me is a major design flaw, 3/ it doesn't fail but hang resulting in blocking CI pipelines, 4/ The documentation never states that the framework is only intended for unit testing and in addition for functions without side effects on at least stdout (and may be more - who knows?).

gitusel avatar Nov 30 '23 04:11 gitusel

Ran into this issue and unfortunately not only does it lead one to chase dead ends trying to debug it (zig build test just hangs), it's not necessarily clear in the docs (particularly the testing section) that it will hang when writing to stdout.

It should probably be documented with some kind of warning in the docs.

For anyone wanting a quick solution, the following one liner will get you some of the way (drop it in a Makefile/Justfile/taskrunner of choice):

find src -name '*.zig' -exec zig test {} \;

Or, refactor your code to use a generic writer (e.g: writer: anytype) and pass in something else in tests. One advantage is that in unit tests you can pass in a writer of your choice (e.g: from std.io.FixedBufferStream) to ensure your writing functions are doing what they're supposed to do.

aalbacetef avatar Feb 02 '24 20:02 aalbacetef

The bug is here. As you can see, evalZigTest tries to read stdout directly into the Header struct. This is incorrect, because the Zig build system does not control the contents of stdout.

As you read down, you'll see that, when it receives spurious data, no further tests are requested. So we have a deadlock: the test process waits for the requestNextTest, which it never receives, and so we get an endless polling loop until the user sends a ^C.

There is a relatively simple fix available: instead of presuming that the header will be sent immediately, which will not, in full generality, happen, the polling can look for a magic string, such as a UUID. The test runner will send this string, followed by the header and payload.

Since the nature of a UUID is such that it cannot be sent accidentally, this will work unless the user decides to spoof the build system (which is already possible). This is not a case which needs to be accounted for.

Anything before each magic string is user data: this can put put onto another FIFO, or, if the doctrine that impure effectful use of stdout must not be rewarded is upheld, silently discarded. Given that various stderr printings are permitted, it seems reasonable to me to do the former, and batch up "garbage to stdout", to print once the test completes.

Either way, this fixes the build system bug, where it hangs due to invalid parsing. A testing system should hang under one circumstance only: when the code it is testing hangs.

My suggestion is that, rather than treating this as an enhancement, it get the bug and Contributor Friendly label.

mnemnion avatar Jul 01 '24 02:07 mnemnion

@andrewrk

Don't write to stdout if you are not the main application!

This suggests that if you're the main application, it's acceptable to write to stdout. However, doing so means you can no longer unit test your application properly! Does that sound reasonable to you? Honestly, it’s a strange behavior.

The Zig team should improve this design. A potential solution is to ignore all stdout lines, except those starting with a prefix (or set of prefixes) recognized by zig build.

For example (say ZIG_BUILD_TEST:: is a prefix understood by zig build):

stdout.print("ZIG_BUILD_TEST:: Hello Test\n", .{}); // understood by `zig build`

stdout.print("Hello world\n", .{}); // ignored by `zig build` as it does not have the prefix

This could resolve this weird issue.

snawaz avatar Oct 11 '24 23:10 snawaz

@snawaz et. al, as a workaround in the meantime, you can set a custom test runner which will not trigger this issue.

I wrote one which creates TAP output, called ZTAP. It has about three useful features: TAP is near-universally understood, by nature it prints all test names along with their status, and it will not deadlock stdout.

Writing to stdout during testing is discouraged in TAP circles also, for the record. But the standard specifies that harnesses ignore output they don't understand.

Even if it doesn't suit your specific needs, it's a reasonable guide to how to go about setting such a thing up. There isn't much to it.

mnemnion avatar Oct 18 '24 17:10 mnemnion