In #[test]s, stop assert(); swallowing all println(); output, add assert(); template message strings and default parameter output

[tsujp]

Problem

I feel using assert(); in #[test]s and generally testing in Noir is frustrating currently in all but the most trivial of cases, context:

• assert(); swallows all printable output before it prints meaning the only way to inspect intermediate values is to comment the assert(); and stub the test with something like assert(0 == 0);. This may be fine for very trivial cases but if tests are done over arrays of data it results in a lot of noise. Proposed fix: assert(); should NOT stop println(); from outputting and should respect it's place within source files instead of being (what I assume is) optimistically executed and/or blocking said output regardless.

// ... logic
println(f"State {foo} / {bar}"); // Until a better debugging story.
assert(foo == bar); // If this triggers the above println gets swallowed. Comment this line to get it back, now do that for every single failing test every single time they fail just to be able to see the values.

• assert(); can now take optional assertion messages. These are nice but I posit only useful in trivial circumstances because they only accept literal string values. This is intimately tied to the next problem.

assert(foo == bar, f"Expected equal integer values {foo} == {bar}"); // Cannot do this, it's not a string literal. Cannot `println` it as those are swallowed.

• assert(); does not show the failed constraint values in tests. This is the big one. Swallowing println(); statements would be fine, and assert(); only accepting string literal message values would be fine if it showed the values that failed assertion. If you have a literal assert as follows: assert(5 == 2); then this is no issue as it is extremely obvious that 5 does not equal 2. Now imagine one of those values is a parameter or a variable assert(foo == 2);. Still mostly fine, it's obvious that foo does not equal 2. What value is foo though? You cannot get this information. You cannot println(); this information without commenting out the assert. You cannot message this information via assert(foo == 2, f"Expected {foo} to equal 2"); as that's not a string literal. Now imagine you have two computed values assert(foo == bar);. What values are these? Impossible to tell unless you make aforementioned significant modifications to your code simply to inspect a failing test case where said modifications are mutually exclusive with having a test in the first place! Proposed fix: when an assert(); fails in a #[test] it should print the values of it's parameters.

Happy Case

Template assertion messages

This code:

let foo = 5;
let bar = 2;
assert(foo == bar, f"Expected equal integer values {foo} == {bar}");

Should compile and print in the existing assertion error format:

[big_project] Testing something_foo_bar... error: Expected equal integer values 5 == 2
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------

and NOT:

[big_project] Testing something_foo_bar... error: Failed constraint
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------

Assertion parameter values output by default

let foo = 5;
let bar = 2;
assert(foo == bar);

Should print in the existing assertion error format:

[big_project] Testing something_foo_bar... error: Failed constraint
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------
     = Parameter values:
       foo: 5
       bar: 2
     = Call stack:
       1. /path/to/source/code.nr:420:11
       2. /path/to/source/code.nr:1337:69

and NOT:

[big_project] Testing something_foo_bar... error: Failed constraint
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------

Assertion should NOT swallow println output

let foo = 5;
let bar = 2;
println("Blah blah");
println(f"My foo is {foo} and my bar is {bar}");
assert(foo == bar);

Should print a better assertion failure as already described and keep the println output:

Blah blah
My foo is 5 and my bar is 2
[big_project] Testing something_foo_bar... error: Failed constraint
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------
     = Parameter values:
       foo: 5
       bar: 2
     = Call stack:
       1. /path/to/source/code.nr:420:11
       2. /path/to/source/code.nr:1337:69

and NOT:

[big_project] Testing something_foo_bar... error: Failed constraint
     ┌─ /path/to/source/code.nr:1337:69
     │
1337 │         assert(foo == bar);
     │                ----------

Alternatives Considered

I augment a script I have to produce saner Noir output but it requires stubbing out assert() since using assert() destroys everything. Script here: https://github.com/tsujp/tikan/blob/master/circuit/lib/test.sh

Additional Context

No response

Would you like to submit a PR for this Issue?

Maybe

Support Needs

No response

[tsujp]

For the given Noir code:

fn check_bb_from_fen(board: Board, check_bbs: [u64; 8]) {
    let mut idx = 0;
    
    for bb in board.pieces {
        // FIXME: No expressions in template strings so pollution with temp
        //        values is required.
        let bb_data = bb.data;
        let check_bb = check_bbs[idx];

        // assert(bb_data == check_bb);
        if bb_data == check_bb {
            println(f"t-0x01");
        } else {
            println(f"t-0x00 Expected values to be equal: '{bb_data}' == '{check_bb}' / bb index: u-{idx}");
        }

        idx += 1;
    }
}

The output if using that commented assert(bb_data == check_bb); line is:

Remember, any print-based debugging is destroyed by the assertion failure. What values are bb_data and check_bb? Who knows. Want to find out? Remove the assert each and every time you want to find out. Don't forget to add it back of course!

My wrapping script which I hope is temporary only shows this output:

Now I can actually see what is going on.

[jfecher]

I think the main issue here is for asserts we issue an error if the constraint is known to always be false before running the program. Since printlns are only run at execution time, their output will only show if the assert in question is using values known only at runtime (execution time).

We can probably move the failed assert message to a warning (if at all?) at compile time and keep the runtime error for these asserts. That way the program will still run after the warning and any printlns will be issued.

[jfecher]

When I create a new file containing the example:

#[test]
fn main() {
    let foo = 5;
    let bar = 2;
    println("Blah blah");
    println(f"My foo is {foo} and my bar is {bar}");
    assert(foo == bar);
}

And run it via nargo execute, It does produce the output with the printouts:

"Blah blah"                                                                                                                                                                                                                       
My foo is 0x05 and my bar is 0x02                                                                                                                                                                                                 
Cannot satisfy constraint

Running with nargo test however, does by default hides the printouts unless the --show-output flag is passed. This matches cargo test's behavior of hiding test output by default, although we do not show it if the test errors afterward.

[tsujp]

And run it via nargo execute, It does produce the output with the printouts:

I suppose my first followup is this: why is nargo execute running tests? I feel like it should not being that otherwise what is the purpose of the #[test] attribute? Indeed, what is the purpose of nargo test even. Also this brings about another question I had in the back of my mind: are functions with attribute #[test] statically removed from the actual circuit to which the answer is probably no given your example. Why?

Secondly that works if your circuit is a bin but not if it's a lib, so now you must consume your library externally just to test it like that as any internal tests via nargo test which does work with lib will swallow all output.

Running with nargo test however, does by default hides the printouts unless the --show-output flag is passed. This matches cargo test's behavior of hiding test output by default, although we do not show it if the test errors afterward.

Hiding the output without passing --show-output is fine, and I realise I forgot to mention in my OP that I am running the command: nargo test --show-output in all cases here. As you say, we do not show it if the test errors afterward. -- that is precisely the time when you would want to see more information (if --show-output is given).

[jfecher]

I suppose my first followup is this: why is nargo execute running tests?

Because in my example I named the function main, and nargo execute executes the main function. It doesn't run all tests so it and nargo test are still functionally separate.

are functions with attribute #[test] statically removed from the actual circuit to which the answer is probably no given your example.

The answer is yes, actually. Unless a function is actually called in your program it will never be in your resulting circuit. The reasoning is when compiling a program to a circuit, there is no such thing as functions in our ACIR backend circuit representation. Thus, to compile a program we are forced to inline every single function call (also unroll all loops). This is why loops and recursion must be known to terminate at compile-time and you'll get an error otherwise (the "error" for unbounded recursion is just a panic though, unfortunately).

Secondly that works if your circuit is a bin but not if it's a lib, so now you must consume your library externally just to test it like that as any internal tests via nargo test which does work with lib will swallow all output.

Hmm, I think I was wrong in my last test. I'm getting that the output was eaten in a bin target as well now. For context I was originally able to replicate this and had a fix in a pull request, but seemed to have been getting the output again even after reverting the changes, so I closed the pull request. Sometimes the caching of the program in the target directly can make things more difficult to test. I'll re-open the PR since trying it again now it does bring back the output for me.

As you say, we do not show it if the test errors afterward. -- that is precisely the time when you would want to see more information (if --show-output is given).

Right - I don't dispute this. It looks like it's being hidden for the same reason as the bin target was, so my PR should fix both cases once merged. As for why --show-output isn't implied at least once an error occurs, I believe this is because we currently do not collect the output. So if an error occurs we cannot retrieve any already suppressed output at the moment. It's an open issue to change this as well, but it would be a larger change than my existing small PR to fix the output being eaten.