std.Build.Step.Test.setExecCmd no longer does anything

[gcoakes]

Zig Version

0.12.0-dev.1264+d1230842a

Steps to Reproduce and Observed Behavior

1. zig init-lib
2. Apply the following change:

diff --git a/build.zig b/build.zig
index cacab1f..db1abfe 100644
--- a/build.zig
+++ b/build.zig
@@ -36,6 +36,7 @@ pub fn build(b: *std.Build) void {
         .target = target,
         .optimize = optimize,
     });
+    main_tests.setExecCmd(&[_]?[]const u8{ "sh", "-c", "echo worked > did-it.txt", null });
 
     const run_main_tests = b.addRunArtifact(main_tests);
 

3. Observe did-it.txt was not created implying sh was never run.

This was observed while trying to add a coverage flag to my build.zig. So, in my case, it would have looked more like:

diff --git a/build.zig b/build.zig
index cacab1f..3ddac03 100644
--- a/build.zig
+++ b/build.zig
@@ -36,6 +36,7 @@ pub fn build(b: *std.Build) void {
         .target = target,
         .optimize = optimize,
     });
+    main_tests.setExecCmd(&[_]?[]const u8{ "kcov", "kcov-out", null });
 
     const run_main_tests = b.addRunArtifact(main_tests);
 

This behavior is only observed when --listen=- is present in the arguments for zig test. I can copy the arguments from zig build test --verbose and run them without --listen=-. In that case, it works:

$ zig test /home/gcoakes/src/repro/src/main.zig --cache-dir /home/gcoakes/src/repro/zig-cache --global-cache-dir /home/gcoakes/.cache/zig --name test --test-cmd kcov --test-cmd kcov-out --test-cmd-bin
All 1 tests passed.
$ ls
build.zig  kcov-out  LICENSE  README.md  src  zig-cache  zig-out

Expected Behavior

The test executable to be run using the specified command/arguments.

[andrewrk]

It's not really intended for users to pass --listen=- - this is for a parent process to pass when it wants to communicate over stdio with the child process, and take over the responsibility of executing the test via some command.

[xdBronch]

this isnt about passing it manually, --listen=- is passed by the build system so --test-cmd (or more like the build system equivalent) does nothing

[gcoakes]

@xdBronch, correct. I frankly don't want the whole RPC being used if I could help it (I would disable the TTY line erasing also if I could find out how). I even added this to my tests, and it's still using the RPC:

    unit_tests.test_server_mode = false;

@andrewrk, I only mentioned the command line arguments because that's as far as I tracked it. I got lost somewhere in Zig's src/main.zig trying to find out why the exec args seemingly were getting lost:

https://github.com/ziglang/zig/blob/5257643d3ddd35b0fb40b82988a9ccf9f859a779/src/main.zig#L3800

[andrewrk]

Ah, setExecCmd. I got confused by the title, sorry.

[andrewrk]

I'd appreciate a more detailed explanation of your problem with the communication channel between the build runner and the test runner.

As for progress output, I agree a "quiet" flag would be nice to have, although I don't understand the problem, since it only shows up when stderr is a tty. You don't want to know the progress of the build?

[gcoakes]

@andrewrk, I just preferred the old output from zig build test where the names of the tests and their results would spew out to the terminal. That was a tangent from the core issue. Sorry for that.

i.e.:

$ zig build test 2>&1 | cat
1/1 test.hello... 1/5 test_0... OK
2/5 test.request parsing... OK
All 1 tests passed.
OK
3/5 test.response writing... OK
4/5 test.fuzz chunked round trip... OK
5/5 decltest.stringToEnumIgnoreCase... OK
All 5 tests passed.

I can get it to act how I want with some bash trickery (zig build test 2>&1 | cat) and changes to my build.zig. I just figured it was a meaningless personal preference.

The core issue is that setExecCmd doesn't seem to get applied in some circumstances. Aside from my mess of a build.zig, the issue can be minimally reproduced with zig init-lib and the diff from the first comment.

[andrewrk]

I just preferred the old output from zig build test where the names of the tests and their results would spew out to the terminal.

the build runner is a multiplexer. it concurrently runs multiple test suites, so they can't print to stderr or they would clobber each other.

For example:

$ stage3/bin/zig build test-behavior -fqemu -fwasmtime -Dskip-release --summary all
Build Summary: 65/78 steps succeeded; 13 skipped; 42100/45014 tests passed; 2914 skipped
test-behavior success
├─ run test behavior-native-skylake-Debug 1785 passed 93 skipped 448ms MaxRSS:19M
│  └─ zig test Debug native success 1m MaxRSS:445M
├─ run test behavior-native-skylake-Debug-libc 1785 passed 93 skipped 462ms MaxRSS:21M
│  └─ zig test Debug native success 15s MaxRSS:463M
├─ run test behavior-native-skylake-Debug-single 1785 passed 93 skipped 464ms MaxRSS:19M
│  └─ zig test Debug native success 1m MaxRSS:433M
├─ run test behavior-native-skylake-Debug-libc-cbe 1741 passed 127 skipped 50ms MaxRSS:21M
│  └─ zig build-exe behavior-native-skylake-Debug-libc-cbe Debug native success 41s MaxRSS:793M
│     └─ zig test Debug native success 3s MaxRSS:147M
├─ run test behavior-x86_64-linux-none-x86_64-Debug-selfhosted-no-lld 1670 passed 198 skipped 31ms MaxRSS:18M
│  └─ zig test Debug x86_64-linux-none success 47s MaxRSS:243M
├─ run test behavior-x86_64-linux-none-x86_64_v2-Debug-selfhosted-no-lld 1677 passed 191 skipped 22ms MaxRSS:23M
│  └─ zig test Debug x86_64-linux-none success 2m MaxRSS:243M
├─ run test behavior-x86_64-linux-none-x86_64_v3-Debug-selfhosted-no-lld 1683 passed 185 skipped 18ms MaxRSS:23M
│  └─ zig test Debug x86_64-linux-none success 2m MaxRSS:242M
├─ run test behavior-wasm32-wasi-generic-Debug-selfhosted-no-lld 1608 passed 264 skipped 1s MaxRSS:100M
│  └─ zig test Debug wasm32-wasi success 1m MaxRSS:255M
├─ run test behavior-x86_64-macos-none-x86_64-Debug-selfhosted-no-lld skipped
│  └─ zig test Debug x86_64-macos-none success 2m MaxRSS:237M
├─ run test behavior-x86_64-windows-gnu-x86_64-Debug-selfhosted-no-lld skipped
│  └─ zig test Debug x86_64-windows-gnu success 49s MaxRSS:260M
├─ run test behavior-wasm32-wasi-generic-Debug 1758 passed 114 skipped 3s MaxRSS:141M
│  └─ zig test Debug wasm32-wasi success 28s MaxRSS:698M
├─ run test behavior-wasm32-wasi-generic-Debug-libc 1758 passed 114 skipped 2s MaxRSS:129M
│  └─ zig test Debug wasm32-wasi success 36s MaxRSS:817M
├─ run test behavior-x86_64-linux-none-x86_64-Debug 1784 passed 94 skipped 514ms MaxRSS:21M
│  └─ zig test Debug x86_64-linux-none success 32s MaxRSS:432M
├─ run test behavior-x86_64-linux-gnu-x86_64-Debug-libc skipped
│  └─ zig test Debug x86_64-linux-gnu success 34s MaxRSS:511M
├─ run test behavior-x86_64-linux-musl-x86_64-Debug-libc 1784 passed 94 skipped 341ms MaxRSS:19M
│  └─ zig test Debug x86_64-linux-musl cached 49s MaxRSS:54M
├─ run test behavior-x86_64-linux-musl-x86_64-Debug-libc-no-lld cached
│  └─ zig test Debug x86_64-linux-musl success 2m MaxRSS:511M
├─ run test behavior-x86-linux-none-pentium4-Debug 1779 passed 99 skipped 29ms MaxRSS:22M
│  └─ zig test Debug x86-linux-none success 49s MaxRSS:509M
├─ run test behavior-x86-linux-musl-pentium4-Debug-libc 1779 passed 99 skipped 50ms MaxRSS:19M
│  └─ zig test Debug x86-linux-musl success 1m MaxRSS:527M
├─ run test behavior-x86-linux-gnu-pentium4-Debug-libc skipped
│  └─ zig test Debug x86-linux-gnu success 29s MaxRSS:535M
├─ run test behavior-aarch64-linux-none-generic-Debug 1772 passed 106 skipped 3s MaxRSS:40M
│  └─ zig test Debug aarch64-linux-none success 35s MaxRSS:524M
├─ run test behavior-aarch64-linux-musl-generic-Debug-libc 1772 passed 106 skipped 1s MaxRSS:39M
│  └─ zig test Debug aarch64-linux-musl success 33s MaxRSS:535M
├─ run test behavior-aarch64-linux-gnu-generic-Debug-libc skipped
│  └─ zig test Debug aarch64-linux-gnu success 36s MaxRSS:532M
├─ run test behavior-aarch64-windows-gnu-generic-Debug-libc skipped
│  └─ zig test Debug aarch64-windows-gnu success 47s MaxRSS:402M
├─ run test behavior-arm-linux-none-generic-Debug 1772 passed 106 skipped 1s MaxRSS:38M
│  └─ zig test Debug arm-linux-none success 46s MaxRSS:457M
├─ run test behavior-arm-linux-musleabihf-generic-Debug-libc 1772 passed 106 skipped 669ms MaxRSS:39M
│  └─ zig test Debug arm-linux-musleabihf success 58s MaxRSS:474M
├─ run test behavior-powerpc-linux-none-ppc-Debug 1767 passed 111 skipped 499ms MaxRSS:41M
│  └─ zig test Debug powerpc-linux-none success 2m MaxRSS:447M
├─ run test behavior-powerpc-linux-musl-ppc-Debug-libc 1767 passed 111 skipped 575ms MaxRSS:43M
│  └─ zig test Debug powerpc-linux-musl success 2m MaxRSS:456M
├─ run test behavior-powerpc64le-linux-none-ppc64le-Debug 1776 passed 102 skipped 1s MaxRSS:39M
│  └─ zig test Debug powerpc64le-linux-none success 1m MaxRSS:432M
├─ run test behavior-powerpc64le-linux-musl-ppc64le-Debug-libc 1776 passed 102 skipped 514ms MaxRSS:39M
│  └─ zig test Debug powerpc64le-linux-musl success 2m MaxRSS:435M
├─ run test behavior-powerpc64le-linux-gnu-ppc64le-Debug-libc skipped
│  └─ zig test Debug powerpc64le-linux-gnu success 36s MaxRSS:439M
├─ run test behavior-riscv64-linux-none-baseline_rv64-Debug 1775 passed 103 skipped 466ms MaxRSS:35M
│  └─ zig test Debug riscv64-linux-none success 55s MaxRSS:494M
├─ run test behavior-riscv64-linux-musl-baseline_rv64-Debug-libc 1775 passed 103 skipped 340ms MaxRSS:38M
│  └─ zig test Debug riscv64-linux-musl success 1m MaxRSS:512M
├─ run test behavior-x86_64-macos-none-x86_64-Debug skipped
│  └─ zig test Debug x86_64-macos-none success 26s MaxRSS:421M
├─ run test behavior-aarch64-macos-none-generic-Debug skipped
│  └─ zig test Debug aarch64-macos-none success 38s MaxRSS:525M
├─ run test behavior-x86-windows-msvc-pentium4-Debug skipped
│  └─ zig test Debug x86-windows-msvc success 46s MaxRSS:478M
├─ run test behavior-x86_64-windows-msvc-x86_64-Debug skipped
│  └─ zig test Debug x86_64-windows-msvc success 32s MaxRSS:457M
├─ run test behavior-x86-windows-gnu-pentium4-Debug-libc skipped
│  └─ zig test Debug x86-windows-gnu success 1m MaxRSS:499M
└─ run test behavior-x86_64-windows-gnu-x86_64-Debug-libc skipped
   └─ zig test Debug x86_64-windows-gnu success 1m MaxRSS:474M

[gcoakes]

Thank you! I didn't know about --summary all. That's much better than what I was doing. Before I would run zig build test, and I would just end up with a new terminal line. i.e.:

$ zig build test
$

It was really frustrating because I wanted to see positive confirmation that something actually ran.

[xdBronch]

btw i have run into this problem as well. i was trying to teach someone how you could debug zig tests and --test-cmd with gdb worked great but when i tried to apply it to the build script nothing happened. maybe it'd be an anti-pattern for something like gdb to run in the middle of a zig build test run but its always nice to have everything contained in a single build.zig

[andrewrk]

@xdBronch that's a good use case, let's try to improve things to make that handy 👍

[gcoakes]

I think I found something interesting. It looks like the server code exits the process immediately following the serve loop: https://github.com/ziglang/zig/blob/13c7aa5fefef9b1338951cf0d01c04345201d996/src/main.zig#L3583-L3594

Without --listen=-, the zig test process would normally enter into this area where the arguments are properly applied: https://github.com/ziglang/zig/blob/13c7aa5fefef9b1338951cf0d01c04345201d996/src/main.zig#L3675-L3694

I used setExecCmd(&[_]?[]const u8{ "echo", null }) and strace'd the whole build process (strace -y -o strace.log --follow-forks --output-separately -s 8192 zig build test-unit). Using that I could observe the client-server interactions in the read/write system calls.

Interpreting those messages, it looks like the client sends an .update and .exit message. Then, the server -- which is zig test --test-cmd ... -- responds with .zig_version, several .progress, and one .emit_bin_path. No further other interactions are observed along that pipe. The following is from the perspective of the client (build_runner.zig if I'm not mistaken):

write(10, "\1\0\0\0\0\0\0\0", 8) = 8
write(10, "\0\0\0\0\0\0\0\0", 8) = 8
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\0\0\0\0\31\0\0\0000.12.0-dev.1326+9ff9ea38e", 512) = 33
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\31\0\0\0Semantic Analysis [2003] ", 512) = 33
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\31\0\0\0Semantic Analysis [3204] ", 512) = 33
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\31\0\0\0Semantic Analysis [3784] ", 512) = 33
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\20\0\0\0LLVM Emit Object", 512) = 24
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\2\0\0\0\10\0\0\0LLD Link", 512) = 16
poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 2, 2147483647) = 1 ([{fd=11, revents=POLLIN}])
read(11, "\3\0\0\0I\0\0\0\0/home/gcoakes/src/watt/zig-cache/o/2f71fa0057d09110da90fe0d7c559f6b/test", 512) = 81

Basically, the process which has knowledge of the exec arguments doesn't actually run the test. It just reports the path to the binary, then exits. The process that actually forks into the test process is the client from above. Looking at that code (std.zig.Build.Step.Run.evalZigTest), it seems like it pulls it's argv from the run step, not the compile step. This is very obvious in retrospect, but then that begs the question: why is setExecCmd an option on the compilation step? Judging by the TODO in the server code, is it just not implemented yet? I think the server change looks somewhat simple, but I assume that entails much larger changes to std.zig.Build.Step.Run and std.zig.Build.Step.Compile. Am I correct on that?

[Snektron]

I'm running into this issue with the Zig SPIR-V test executor. Its a little unclear to me how exactly this serving architecture is supposed to work together with runnings tests. As I understand it, currently tests are supposed to be built and run separately (from https://ziglang.org/learn/build-system/#testing):

const test = b.addTest(...);
const run_test = b.addRunArtifact(test);
const test_step = b.step("test", "Run the tests");
test_step.dependOn(&run_test.step);

If this is the intended way that it will work in the future, then it seems sufficient to me to make addRunArtifact simply adhere the exec_cmd_args from the test, which is currently already done with test_server_mode.

This was observed while trying to add a coverage flag to my build.zig. So, in my case, it would have looked more like:

Note that you can always invoke the test by manually creating a run step:

const run_step = b.addSystemCommand(&.{"kcov", "kcov-out"});
run_step.addArtifactArg(my_test);