Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
kripken wants to merge 10 commits into
base: main
Choose a base branch
from
+15 −7
Open

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

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
2f5fe79
Testing: Add verbose logging feature, and stop excessive spec logging
kripken May 8, 2026
1291974
Merge remote-tracking branch 'origin/main' into verbose.log
kripken May 8, 2026
d114c3b
fix
kripken May 8, 2026
134b87e
feedback
kripken May 8, 2026
7f5b2c2
ruff
kripken May 8, 2026
63e6f5a
fix
kripken May 8, 2026
20c32b3
Revert "fix"
kripken May 11, 2026
29b0d0d
Revert "ruff"
kripken May 11, 2026
f6ff35e
Revert "feedback"
kripken May 11, 2026
dae3414
feedback
kripken May 11, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions check.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -192,7 +192,7 @@ def run_opt_test(wast, stdout=None):
def check_expected(actual, expected, stdout=None):
if expected and os.path.exists(expected):
expected = open(expected).read()
print(' (using expected output)', file=stdout)
shared.verbose_log(' (using expected output)', file=stdout)
actual = actual.strip()
expected = expected.strip()
if actual != expected:
Expand Down Expand Up @@ -229,7 +229,7 @@ def run_one_spec_test(wast: Path, stdout=None):
actual = run_spec_test(str(wast), stdout=stdout)
except Exception as e:
if ('wasm-validator error' in str(e) or 'error: ' in str(e)) and '.fail.' in test_name:
print('<< test failed as expected >>', file=stdout)
shared.verbose_log('<< test failed as expected >>', file=stdout)
return # don't try all the binary format stuff TODO
else:
shared.fail_with_error(str(e))
Expand All @@ -249,7 +249,7 @@ def run_one_spec_test(wast: Path, stdout=None):
if not module:
# Skip any initial assertions that don't have a module
continue
print(f' testing split module {i}', file=stdout)
shared.verbose_log(f' testing split module {i}', file=stdout)
split_name = base_name + f'_split{i}.wast'
support.write_wast(split_name, module)
run_opt_test(split_name, stdout=stdout) # also that our optimizer doesn't break on it
Expand Down
16 changes: 12 additions & 4 deletions scripts/test/shared.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,9 @@ def parse_args(args):
action='store_false', default=True,
help='Disables the automatic selection of important initial contents '
'in fuzzer.')
parser.add_argument(
'--verbose', action='store_true', default=False,
help='Enables verbose logging.')

return parser.parse_args(args)

Expand All @@ -118,6 +121,11 @@ def print_heading(msg):
print(f'[ {msg} ]')


def verbose_log(*args, **kwargs):
if options.verbose:
print(*args, **kwargs)


# setup

# Locate Binaryen build artifacts directory (bin/ by default)
Expand Down Expand Up @@ -472,24 +480,24 @@ def binary_format_check(wast, verify_final_result=True, base_name=None, stdout=N
as_file = f"{base_name}-a.wasm" if base_name is not None else "a.wasm"
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)
Copy link
Copy Markdown
Member

@sbc100 sbc100 May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lets drop file=stdout in all these calls too?

Copy link
Copy Markdown
Member

@stevenfontanella stevenfontanella May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Member Author

@kripken kripken May 8, 2026 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Member

@sbc100 sbc100 May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Copy Markdown
Member Author

@kripken kripken May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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?

Copy link
Copy Markdown
Member

@sbc100 sbc100 May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Member

@stevenfontanella stevenfontanella May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Member

@sbc100 sbc100 May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Member Author

@kripken kripken May 11, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, I reverted the batching removal.

cmd = WASM_AS + [wast, '-o', as_file, '-all', '-g']
print(' ', ' '.join(cmd), file=stdout)
verbose_log(' ', ' '.join(cmd), file=stdout)
if os.path.exists(as_file):
os.unlink(as_file)
subprocess.check_call(cmd, stdout=subprocess.PIPE)
assert os.path.exists(as_file)

cmd = WASM_DIS + [as_file, '-o', disassembled_file, '-all']
print(' ', ' '.join(cmd), file=stdout)
verbose_log(' ', ' '.join(cmd), file=stdout)
if os.path.exists(disassembled_file):
os.unlink(disassembled_file)
subprocess.check_call(cmd, stdout=subprocess.PIPE)
assert os.path.exists(disassembled_file)

# make sure it is a valid wast
cmd = WASM_OPT + [disassembled_file, '-all', '-q']
print(' ', ' '.join(cmd), file=stdout)
verbose_log(' ', ' '.join(cmd), file=stdout)
subprocess.check_call(cmd, stdout=subprocess.PIPE)

if verify_final_result:
Expand Down
4 changes: 3 additions & 1 deletion scripts/test/support.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,8 @@
import re
import subprocess

from . import shared

QUOTED = re.compile(r'\(module\s*(\$\S*)?\s+(quote|binary)')

MODULE_DEFINITION_OR_INSTANCE = re.compile(r'(?m)\(module\s+(instance|definition)')
Expand Down Expand Up @@ -147,7 +149,7 @@ def run_command(cmd, expected_status=0, stdout=None, stderr=None,
assert stderr == subprocess.PIPE or stderr is None, \
"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)
Copy link
Copy Markdown
Member

@sbc100 sbc100 May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't this one kind of important?

Copy link
Copy Markdown
Member Author

@kripken kripken May 8, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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...


out, err, code = _subprocess_run(cmd, stdout=subprocess.PIPE, stderr=stderr, encoding='UTF-8')

Expand Down
Loading