"leaky" error messages from `std.testing.expectEqual`

I’m getting strange traces from zig test when I write multiple tests which make use of std.testing.expectEqual() and I was wondering if anyone can help me understand and/or fix it?

I’ll try to demonstrate what I mean.

Normal Results

This first example executes completely as expected. I’m including it for context.

If I make a bare bones main.zig with the following failing test:

const std = @import("std");

pub fn main() u8 {
  return 0;
}

test "test 1" {
  try std.testing.expectEqual(1, 2);
}

Then I compile and run tests with the following command:

> zig test main.zig 2>&1

(the funky looking 2>&1 is just me redirecting stderr to stdout to fix an issue where passing test cases aren’t listed properly, in case you were wondering. It has no effect on the issue in question)

I get this output:

expected 1, found 2
1/1 main.test.test 1...FAIL (TestExpectedEqual)
C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:118:17: 0x7ff733804b3b in expectEqualInner__anon_66540 (test_zcu.obj)
                return error.TestExpectedEqual;
                ^
C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff733804b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\Software\Learning\zigtest\main.zig:8:3: 0x7ff733804bbe in test.test 1 (test_zcu.obj)
  try std.testing.expectEqual(1, 2);
  ^
0 passed; 0 skipped; 1 failed.
error: the following test command failed with exit code 1:
C:\Users\*****\AppData\Local\zig\o\e960dd39fac6fb43ffd67fdb86d457c0\test.exe --seed=0x865bbbb3

This is completely as expected.

Not Normal Results

Here’s what’s not expected.

If I now add multiple tests which also make use of std.testing.expectEqual(), I get a particular line of the error output repeated for the number of expectEqual() calls in the file: even if only one of them is actually inside of a failing test.

This is what I mean:

const std = @import("std");

pub fn main() u8 {
  return 0;
}

// This test passes and includes 10 passing (albeit comically redundant) calls to expectEqual()
test "test 1" {
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
  try std.testing.expectEqual(1, 1);
}

// This test fails with a single call
test "test 2" {
  try std.testing.expectEqual(1, 2);
}

Compile and run tests with the same command:

zig test main.zig 2>&1

Then I get this output:

1/2 main.test.test 1...OK
2/2 main.test.test 2...expected 1, found 2
FAIL (TestExpectedEqual)
C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:118:17: 0x7ff66f284b3b in expectEqualInner__anon_66540 (test_zcu.obj)
                return error.TestExpectedEqual;
                ^
C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\AppData\Local\Microsoft\WinGet\Packages\zig.zig_Microsoft.Winget.Source_8wekyb3d8bbwe\zig-x86_64-windows-0.16.0\lib\std\testing.zig:83: 0x7ff66f284b93 in expectEqual (test_zcu.obj)
    return expectEqualInner(T, expected, actual);

C:\Users\*****\Software\Learning\zigtest\main.zig:23:3: 0x7ff66f284bbe in test.test 2 (test_zcu.obj)
  try std.testing.expectEqual(1, 2);
  ^
1 passed; 0 skipped; 1 failed.
error: the following test command failed with exit code 1:
C:\Users\*****\AppData\Local\zig\o\1c0da9c05215d6e56a324b6346545089\test.exe --seed=0x373be51a

That’s 11 repetitions of the line mentioning return expectEqualInner(T, expected, actual);, matching the number of calls to std.testing.expectEqual despite only one of them actually being part of a failing test.

Am I just being a noob here?

I’ve only been learning Zig for a week or so now but after reading the implementation of expectEqual and expectEqualInner I can’t see anything that would be causing this behaviour.

I tried out several different input types to trigger different branches of the switch in expectEqualInner but the behaviour was the same regardless of the branch taken.

Additionally, this is the only function from the expect* family (that I’ve tried so far) exhibiting this weird “leaky” repetition issue. From the information I have and given that the issue appears to neglect test boundaries, I can only speculate that there’s some sort of an issue with the test builder or runner?

Any insight or suggestions would be greatly appreciated. If I’m doing something terribly stupid then by all means say that; I can take it.


EDIT:

For the record, if I change that last failing test so that it passes I get what you’d expect:

1/2 main.test.test 1...OK
2/2 main.test.test 2...OK
All 2 tests passed.

This only happens if at least one test that uses expectEqual fails.

I’ve reproduced this. Seems to be a problem with the printed Windows backtrace? I’m on Linux, and if I run your zig test main.zig locally I get a reasonable:

expected 1, found 2
2/2 main.test.test 2...FAIL (TestExpectedEqual)
/home/pat/projects/ziglang/zig/lib/std/testing.zig:118:17: 0x12388f1 in expectEqualInner__anon_43035 (std.zig)
                return error.TestExpectedEqual;
                ^
/home/pat/projects/ziglang/zig/lib/std/testing.zig:83:5: 0x123893a in expectEqual (main.zig)
    return expectEqualInner(T, expected, actual);
    ^
/home/pat/projects/ziglang/playground/ziggit-15702-expectequal-mess/main.zig:23:3: 0x1238981 in test.test 2 (main.zig)
  try std.testing.expectEqual(1, 2);
  ^
1 passed; 0 skipped; 1 failed.
error: the following test command failed with exit code 1:
/home/pat/projects/ziglang/playground/zig-cache/o/f4f964fc0e2b8ac2171891687afcdd07/test --seed=0x6aa136ee

But if I run it under Wine (and a quick shout out to how incredible Zig is, that running this test from my Linux box via Wine is a trivial command line change): zig test -target x86_64-windows --test-cmd wine --test-cmd-bin main.zig and I see the same output as you, with a bunch of extra stack frames in the error backtrace.

And if I edit “main.zig” to have fewer passing expects, then the backtrace gets correspondingly shorter.

This definitely seems like a bug to me. It seems to be Windows-specific. And I suspect its not so much about std.testing functions, but about the stack trace capturing code. So you might be able to reduce the test case even more? Though I think its probably okay to file this as a bug on the issue tracker, as is.

I’m using my locally built Zig “0.17.0-dev.10+08850cfcb”, but I built that more than a month ago. But its newer than the official 0.16.0 that you’re using.

This looks like https://codeberg.org/ziglang/zig/issues/35432

2 Likes

Yep, that looks like it. And there is even a patch in flight: https://codeberg.org/ziglang/zig/pulls/35438