Testing: Add verbose logging feature, and stop excessive spec logging by kripken · Pull Request #8684 · WebAssembly/binaryen

kripken · 2026-05-08T17:04:37Z

New logging:

$ ./check.py spec
[ checking wasm-shell spec testcases... ]
Running with 14 workers
.. address-offset-range.fail.wast
.. binary.wast
.. break-drop.wast
.. atomics.wast

Old logging, available with --verbose:

$ ./check.py spec --verbose
[ checking wasm-shell spec testcases... ]
Running with 14 workers
.. address-offset-range.fail.wast
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/address-offset-range.fail.wast
<< test failed as expected >>
.. binary.wast
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/binary.wast
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-binary.transformed
.. break-drop.wast
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/break-drop.wast
        testing split module 0
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-break-drop_split0.wast -O -all -q
         (binary format check)
             /home/azakai/Dev/2-binaryen/bin/wasm-as test-spec-break-drop_split0.wast -o test-spec-break-drop-a.wasm -all -g
             /home/azakai/Dev/2-binaryen/bin/wasm-dis test-spec-break-drop-a.wasm -o test-spec-break-drop-ab.wast -all
             /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-break-drop-ab.wast -all -q
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-break-drop.transformed
.. bulk-array.wast
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/bulk-array.wast
        testing split module 0
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-bulk-array_split0.wast -O -all -q
         (binary format check)
             /home/azakai/Dev/2-binaryen/bin/wasm-as test-spec-bulk-array_split0.wast -o test-spec-bulk-array-a.wasm -all -g
             /home/azakai/Dev/2-binaryen/bin/wasm-dis test-spec-bulk-array-a.wasm -o test-spec-bulk-array-ab.wast -all
             /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-bulk-array-ab.wast -all -q
executing:  /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-bulk-array.transformed

kripken · 2026-05-08T17:16:40Z

If this seems good I would like to improve other test suites than spec as well. Though let's make sure to agree on the best practice here first.

stevenfontanella · 2026-05-08T17:19:48Z

Looks great to me. Looks like there's no change to the logging if there's a failure, right? i.e. it will still print the same error message as before?

kripken · 2026-05-08T17:28:01Z

Yes. Example output after I turned a should-be-invalid module into a valid one in e.g. cont-validation.wast:

$ ./check.py spec
[ checking wasm-shell spec testcases... ]
Running with 14 workers
.. address-offset-range.fail.wast
.. binary.wast
.. break-drop.wast
.. atomics.wast
.. br_on_cast_desc_eq.wast
.. br_if.wast
run_command `/home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/cont-validation.wast` failed (1) 0 CHECKING [line: 5]
[wasm-validator error in function 0] unexpected false: ref.test cannot cast to invalid type, on 
(ref.test contref
 (unreachable)
)
1 CHECKING [line: 11]
expected invalid module

Aborted spec test suite execution after first failure. Set --no-fail-fast to disable this.
Failed tests:
.. cont-validation.wast

This is essentially unchanged from before.

kripken · 2026-05-08T17:30:11Z

Hmm, the import of shared from support seems to break the lit tests... 😞

sbc100 · 2026-05-08T17:58:53Z

    disassembled_file = f"{base_name}-ab.wast" if base_name is not None else "ab.wast"

-    print('         (binary format check)', file=stdout)
+    verbose_log('         (binary format check)', file=stdout)


Lets drop file=stdout in all these calls too?

This isn't sys.stdout, we need to thread this through so that the threads can capture the stdout and write it in batches

Done. edit: raced with comment above, this was for sbc100

Oh I see. In that case I think we should perhaps revisit how this works.

If stdout is being captured then its find to print as much as we want there.

I guess the problem is that some of these functions are run both in stdout-capturing and not-stdout-capturing modes?

Would it make more sense for the capturing to be done via global sys.stdout = <buffering_thing> rather than threading this stdout through like this?

@stevenfontanella is that batching necessary? I'm not sure I see a difference after removing it, which, I admit, I did without understanding what it was 😄 - but things seem to work now?

Yes, its an important part of the parallelism in the spec running I think. You don't want stdout/stderr from the different tests to be interleaved so you need to capture and present it (or hide) atomically.

re:

If stdout is being captured then its find to print as much as we want there.

If we want the output to be less verbose, I think we still want the logic to be the same either way? The stdout is captured but still output to the terminal, just in batches.

re:

is that batching necessary?

+1 to Sam, it's still necessary as long as each test may output more than 1 line, which definitely seems to be the case at least in verbose mode after this PR. Maybe you didn't see any interleaving because you weren't running in verbose mode?

re:

Would it make more sense for the capturing to be done via global sys.stdout = <buffering_thing> rather than threading this stdout through like this?

Overwriting sys.stdout isn't quite enough because globals are shared among all threads and we want each thread to have its own buffer. I asked Gemini at one point and it come up with this, that could be a potential thing to look into. Another more clear fix is to move things into classes and just pass in a logging abstraction per-thread.

Ah, yes I forget, this approach works in emscripten because we use multiprocessing rather than multi-threading. I suppose we could do that here too, although I'm not sure it worth it.

sbc100 · 2026-05-08T17:59:16Z

            "Can't redirect stderr if using expected_err"
        stderr = subprocess.PIPE
-    print('executing: ', ' '.join(cmd), file=stdout)
+    shared.verbose_log('executing: ', ' '.join(cmd), file=stdout)


Isn't this one kind of important?

I actually would like to remove this because of all the noise, but maybe you're right, and it is why the lit tests broke... I removed this part. Output now looks like this:

$ ./check.py spec [ checking wasm-shell spec testcases... ] Running with 14 workers .. address-offset-range.fail.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/address-offset-range.fail.wast .. binary.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/binary.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-binary.transformed .. br_on_cast_desc_eq.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/br_on_cast_desc_eq.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-br_on_cast_desc_eq_split0.wast -O -all -q executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-br_on_cast_desc_eq.transformed .. break-drop.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell /home/azakai/Dev/2-binaryen/test/spec/break-drop.wast executing: /home/azakai/Dev/2-binaryen/bin/wasm-opt test-spec-break-drop_split0.wast -O -all -q executing: /home/azakai/Dev/2-binaryen/bin/wasm-shell test-spec-break-drop.transformed

This is worse than the lit output, but better than before...

kripken added 3 commits May 8, 2026 10:01

Testing: Add verbose logging feature, and stop excessive spec logging

2f5fe79

Merge remote-tracking branch 'origin/main' into verbose.log

1291974

fix

d114c3b

kripken requested a review from sbc100 May 8, 2026 17:04

kripken requested a review from a team as a code owner May 8, 2026 17:04

kripken requested review from stevenfontanella and removed request for a team May 8, 2026 17:04

stevenfontanella approved these changes May 8, 2026

View reviewed changes

sbc100 reviewed May 8, 2026

View reviewed changes

kripken added 3 commits May 8, 2026 11:56

feedback

134b87e

ruff

7f5b2c2

fix

63e6f5a

Conversation

kripken commented May 8, 2026

Uh oh!

kripken commented May 8, 2026

Uh oh!

stevenfontanella commented May 8, 2026

Uh oh!

kripken commented May 8, 2026

Uh oh!

kripken commented May 8, 2026

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kripken May 8, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

kripken May 8, 2026 •

edited

Loading