Test output is repeated with every dependency name prefixed

japhb commented 1 year ago

When zef is testing a module with multiple dependencies, that also need to be tested and installed, it will repeat every test message with the marker prefix for every dependency that has already been reached. For example, this is just one tiny part of the test output for App::Rak::Complete, from just after the Fetch and Extraction phases:

===> Testing: as-cli-arguments:ver<0.0.7>:auth<zef:lizmat>
[as-cli-arguments] t/01-basic.rakutest ... ok
[as-cli-arguments] t/02-nameds.rakutest .. ok
[as-cli-arguments] All tests successful.
[as-cli-arguments] Files=2, Tests=18,  3 wallclock secs ( 0.02 usr  0.00 sys +  3.54 cusr  0.51 csys =  4.07 CPU)
[as-cli-arguments] Result: PASS
===> Testing [OK] for as-cli-arguments:ver<0.0.7>:auth<zef:lizmat>
===> Testing: Backtrace::Files:ver<0.0.3>:auth<zef:lizmat>
[as-cli-arguments] t/01-basic.rakutest ................ ok
[Backtrace::Files] t/01-basic.rakutest ................ ok
[as-cli-arguments] t/02-selective-importing.rakutest .. ok
[Backtrace::Files] t/02-selective-importing.rakutest .. ok
[as-cli-arguments] t/03-add-source-lines.rakutest ..... ok
[Backtrace::Files] t/03-add-source-lines.rakutest ..... ok
[as-cli-arguments] All tests successful.
[Backtrace::Files] All tests successful.
[as-cli-arguments] Files=3, Tests=15,  1 wallclock secs ( 0.02 usr  0.00 sys +  1.60 cusr  0.17 csys =  1.79 CPU)
[Backtrace::Files] Files=3, Tests=15,  1 wallclock secs ( 0.02 usr  0.00 sys +  1.60 cusr  0.17 csys =  1.79 CPU)
[as-cli-arguments] Result: PASS
[Backtrace::Files] Result: PASS
===> Testing [OK] for Backtrace::Files:ver<0.0.3>:auth<zef:lizmat>
===> Testing: CLI::Version:ver<0.0.8>:auth<zef:lizmat>
[as-cli-arguments] t/01-basic.rakutest .. ok
[Backtrace::Files] t/01-basic.rakutest .. ok
[CLI::Version] t/01-basic.rakutest .. ok
[as-cli-arguments] All tests successful.
[Backtrace::Files] All tests successful.
[CLI::Version] All tests successful.
[as-cli-arguments] Files=1, Tests=1,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.74 cusr  0.08 csys =  0.83 CPU)
[Backtrace::Files] Files=1, Tests=1,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.74 cusr  0.08 csys =  0.83 CPU)
[CLI::Version] Files=1, Tests=1,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.74 cusr  0.08 csys =  0.83 CPU)
[as-cli-arguments] Result: PASS
[Backtrace::Files] Result: PASS
[CLI::Version] Result: PASS
===> Testing [OK] for CLI::Version:ver<0.0.8>:auth<zef:lizmat>
===> Testing: has-word:ver<0.0.3>:auth<zef:lizmat>
[as-cli-arguments] t/01-basic.rakutest .. ok
[Backtrace::Files] t/01-basic.rakutest .. ok
[CLI::Version] t/01-basic.rakutest .. ok
[has-word] t/01-basic.rakutest .. ok
[as-cli-arguments] All tests successful.
[Backtrace::Files] All tests successful.
[CLI::Version] All tests successful.
[has-word] All tests successful.
[as-cli-arguments] Files=1, Tests=25,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.87 cusr  0.08 csys =  0.96 CPU)
[Backtrace::Files] Files=1, Tests=25,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.87 cusr  0.08 csys =  0.96 CPU)
[CLI::Version] Files=1, Tests=25,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.87 cusr  0.08 csys =  0.96 CPU)
[has-word] Files=1, Tests=25,  1 wallclock secs ( 0.01 usr  0.00 sys +  0.87 cusr  0.08 csys =  0.96 CPU)
[as-cli-arguments] Result: PASS
[Backtrace::Files] Result: PASS
[CLI::Version] Result: PASS
[has-word] Result: PASS

Context

Note in the above snippet how every line of the testing output for each module is duplicated with not only its own prefix, but all previous modules' prefixes. This results in a quadratic test output and rapidly becomes nearly unreadable for large dependency trees.

Expected Behavior

Test output lines should only appear once each, with the correct distro name prefix.

Actual Behavior

See snippet in description.

Steps to Reproduce

$ zef -v install App::Rak::Complete

Your Environment

Raku versions: many recent ones, including v2022.12-763-g7e69a6de5 and v2022.12-1116-g500508664 Zef versions: several recent ones, including v0.14.4 and v0.14.6 (currently HEAD)

ugexe commented 1 year ago

Wow, I'm surprised this hasn't been noticed yet! That messaging is done with Supply so I suppose its related to one of https://github.com/ugexe/zef/blob/9779091b7997468257ce3037f8bc0e9c65d1f974/lib/Zef/Test.rakumod#L102-L108 https://github.com/ugexe/zef/blob/9779091b7997468257ce3037f8bc0e9c65d1f974/lib/Zef/CLI.rakumod#L1182-L1202

ugexe commented 1 year ago

I think this was introduced with https://github.com/ugexe/zef/commit/f4c0ba9d09fe8a26445b3f00ec93d22620ae31f0 which cached loaded plugins (like the wrapper around prove) such that the repository plugins didn't have to reload JSON for each query. However, for e.g. test plugins it seems to have exposed a bug in how the Suppliers used to pass messages are used/created - particularly the $.stdout / $.stderr attributes of e.g. Zef::Service::Shell::prove (which are provided by role Messenger { } from lib/Zef.rakumod). For instance, disabling that plugin loading caching like below results in the expected test output:

diff --git a/lib/Zef.rakumod b/lib/Zef.rakumod
index 4aebf7c..4971521 100644
--- a/lib/Zef.rakumod
+++ b/lib/Zef.rakumod
@@ -131,7 +131,7 @@ package Zef {
         has $!list-plugins-lock = Lock.new;
         method !list-plugins(@backends = @!backends) {
             $!list-plugins-lock.protect: {
-                return $!plugins if $!plugins.so;
+                #return $!plugins if $!plugins.so;

                 # @backends used to only be an array of hash. However now the ::Repository
                 # section of the config an an array of an array of hash and thus the logic

ugexe / zef