Rely's output format doesn't look good when using dune runtest

[tmattio]

I'm trying to use Rely in combinaison with dune runtest.

Here's my dune file:

(library
 (name Spin_test)
 (public_name spin.test)
 (flags -open Base -linkall -g -w -9)
 ; Make the library optional to skip building test on Opam
 (optional)
 (libraries base rely.lib spin.lib)
 (modules
  (:standard \ test_runner)))

(test
 (name test_runner)
 (modules test_runner)
 (libraries base spin.test)
 (flags -open Base)
 (action
  (run %{test} -q --color=always)))

(include_subdirs unqualified)

When I use the test stanza and run dune runtest, the output format looks like this:

It's hard to see what's failing.

In comparison, the output for the same test suite when using a normal executable looks like this:

Is there anything I can do to improve the output format with dune?

Thanks!

[kyldvs]

Do you have an example repo I can clone and try it out? It wasn't immediately trivial for me to set up dune runtest in an example repo I had

[tmattio]

Sure! I've created a repo here: https://github.com/tmattio/dune-rely-demo

git clone [email protected]:tmattio/dune-rely-demo.git
cd dune-rely-demo
esy

Then I've added two scripts:

• esy test-dune to run the test with dune runtest
• esy test-exe to run the test with an executable

Here's the diff I have on my machine:

[bandersongit]

The default Rely reporter is optimized for running directly in the terminal as opposed to with dune runtest (which captures stdout for diffing purposes and I imagine is getting tripped up by the ANSI escape sequences we use to give cleaner terminal output).

If you want to use dune test stanzas and aren't using Pastel you could add Pastel.setMode(Disabled) to the top of your TestFramework file (or setting the FORCE_COLOR env variable to false).

In the long term, if you were interested in creating a reporter that was optimized for Dune Runtest that would be a welcome contribution. You can look at the TerminalReporter implementation in this repo or the CustomReporter API for the basics/I'd be happy to answer any questions you might have.

[tmattio]

Thanks @bandersongit!
Adding Pastel.setMode(Disabled) didn't work, but setting FORCE_COLOR to false did.

I'm loosing the color, but at least the output is readable!

I might take a look at implementing a custom reporter yes, I'm trying to support releasing packages on Opam that use Rely, and using a test stanza is the only solution I've found. Would be cool to keep the colors as well 😄

[kyldvs]

Thanks for the repo, that was helpful! I did some experimenting on this as well, basically the same findings as Ben.

Quick fix is to use Pastel.setMode(Disabled) at the top of test_dune/support/test_runner.re (this worked for me).

This definitely has to do with escape codes, but it is also hard for me to debug to see how dune is affecting the escape codes. Due to their own color detection turning off colors when you start piping it places, and because it's using stderr not stdout.

For example I can see exactly how Rely prints with color by using this command:

esy test-exe | sed -n l

Running 1 test suite$
\r\033[7m\033[1m\033[33m RUNS \033[27m\033[22m\033[39m \033[97mUtils\033[39m\033[50D\033[K\033[7m\033[1m\033[32m PASS \033[27m\033[22m\033[39m \033[97mUtils\033[39m$
$
\033[1m\033[97mTest Suites: \033[22m\033[39m0 failed, \033[1m\033[32m1 passed\033[22m\033[39m, 1 total$
\033[1m\033[97mTests:       \033[22m\033[39m0 failed, \033[1m\033[32m2 passed\033[22m\033[39m, 2 total$
\033[1m\033[97mTime:        \033[22m\033[39m< 1ms$
$

But when trying with esy dune-test, no matter what I do I can't see what the actual error codes dune is converting too:

esy test-dune --force 2>&1 | sed -n l

 test_runner alias test_dune/runtest$
Running 1 test suite$
\r RUNS  Utils PASS  Utils$
$
Test Suites: 0 failed, 1 passed, 1 total$
Tests:       0 failed, 2 passed, 2 total$
Time:        < 1ms$
$

You can see all the color codes are removed already, even though there should be some in the output if dune didn't detect these pipes weren't a terminal. I figured the (run %{test} -q --color=always))) in the dune file would make it always print colors, but I guess not? 🤷

If you're able to play around with it and see exactly how dune is messing with the error codes we can debug it a bit further and it would probably help in setting up a custom printer/reporter to work with dune better.

[kyldvs]

Oh actually I was able to get the output, it is definitely doing something crazy with escape codes:

(Mac version of calling script to fake a tty according to stack overflow)

script -q /dev/null esy test-dune --force 2>&1 | sed -n l

Done: 0/0 (jobs: 0)\r                   \rDone: 41/43 (jobs\
: 1)\r                     \r\033[2;32m test_runner\033[0m \
alias test_dune/runtest\r$
Running 1 test suite\r$
\r\033[7;1;33m RUNS \033[0m\033[7;1;33;27;22;39m \033[0m\
\033[7;1;33;27;22;39;97mUtils\033[0m\033[7;1;33;27;22;39;97\
;39;50D\033[K\033[7;1;32m PASS \033[0m\033[7;1;33;27;22;39;\
97;39;50D\033[K\033[7;1;32;27;22;39m \033[0m\033[7;1;33;27;\
22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97mUtils\033[0m\r\
$
\r$
\033[7;1;33;27;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97\
;39;1;97mTest Suites: \033[0m\033[7;1;33;27;22;39;97;39;50D\
\033[K\033[7;1;32;27;22;39;97;39;1;97;22;39m0 failed, \033[\
0m\033[7;1;33;27;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;\
97;39;1;97;22;39;1;32m1 passed\033[0m\033[7;1;33;27;22;39;9\
7;39;50D\033[K\033[7;1;32;27;22;39;97;39;1;97;22;39;1;32;22\
;39m, 1 total\033[0m\r$
\033[7;1;33;27;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97\
;39;1;97;22;39;1;32;22;39;1;97mTests:       \033[0m\033[7;1\
;33;27;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97;39;1;97\
;22;39;1;32;22;39;1;97;22;39m0 failed, \033[0m\033[7;1;33;2\
7;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97;39;1;97;22;3\
9;1;32;22;39;1;97;22;39;1;32m2 passed\033[0m\033[7;1;33;27;\
22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97;39;1;97;22;39;\
1;32;22;39;1;97;22;39;1;32;22;39m, 2 total\033[0m\r$
\033[7;1;33;27;22;39;97;39;50D\033[K\033[7;1;32;27;22;39;97\
;39;1;97;22;39;1;32;22;39;1;97;22;39;1;32;22;39;1;97mTime: \
       \033[0m\033[7;1;33;27;22;39;97;39;50D\033[K\033[7;1;\
32;27;22;39;97;39;1;97;22;39;1;32;22;39;1;97;22;39;1;32;22;\
39;1;97;22;39m< 1ms\033[0m\r$
\r$
Done: 41/43 (jobs: 1)\r                     \r$

[kyldvs]

I think I see what dune is trying to do. It looks like it is trying to shorten/optimize the escape codes but doing so incorrectly, if you look at dune's (top) compared to corresponding normal escape codes (bottom):

\033[7;1;33m
\033[7m\033[1m\033[33m

Then it looks like in the next instance of "optimizing" it forgets to stop adding 7;1;33:

\033[7;1;33;27;22;39m
\033[27m\033[22m\033[39m

[kyldvs]

Okay I see what the issue is, I'll file a bug against dune. It keeps reapplying cursor movement escape codes.

In general what it's doing is not terrible. It collected error codes that apply to each section of text, resets them, then reapplies them all. I was missing the reset error codes from before:

\033[7m\033[1m\033[33m
\033[7;1;33m

Then:

\033[27m\033[22m\033[39m
# \033[0m is a reset, so 7;1;33 needs to be reapplied
\033[0m\033[7;1;33;27;22;39m 

In general this would be fine, but we use control sequences to move the cursor and delete text (\033[50D\033[K). These obviously have side effects and cannot be "escaped" then continuously reapplied. It would just keep moving the cursor to weird places and deleting text resulting in the weird output you see.

[kyldvs]

Hopefully they can fix this issue in dune: ocaml/dune#3160

It may also be worth adding a feature to Rely to not print any side-effect escape codes with cursor movement/line deletion.

[tmattio]

That's awesome @kyldvs, thanks a lot for looking into this!

I can look into adding a feature to remove these escape codes. Do you have any recommendation on how to implement it? Would it be part of another reporter?

[kyldvs]

Yeah I think you could almost use exactly the same TerminalReporter.

I think what needs to happen is we disable all of this runningDisplayLength and printing of \027[XXD, and \027[K escape codes: https://github.com/facebookexperimental/reason-native/blob/master/src/rely/reporters/TerminalReporter.re#L330,L355

(maybe needs to be replaced with new lines instead)

Since everything else can basically be the same, we can probably just extend the createTerminalReporter to have an additional option like onlyPrintDetailsForFailedSuites. I would suggest a name like ~simpleTerminalControlSequences or something: https://github.com/facebookexperimental/reason-native/blob/master/src/rely/reporters/TerminalReporter.re#L22

Then enable it in the CLI via some option: https://github.com/facebookexperimental/reason-native/blob/master/src/rely/RelyCLI.re#L18-L52

[kyldvs]

@tmattio It looks like another workaround can be to use --no-buffer when calling dune runtest! https://github.com/tmattio/dune-rely-demo/compare/master...kyldvs:master

(I don't know how to use base, but you want an extra newline before calling into Rely because dune prints some things first)

[tmattio]

Hi @kyldvs!

Sorry for the delay. I've tried this solution and it works really well, thanks a lot for deeping into this, it helped a lot!

I'm happy with this solution for my use case. Do you think Rely would still benefit from a custom reporter?

[kyldvs]

Yes I think it could still be beneficial! Perhaps as another format for CI or other non-interactive places.

(Also I believe along with --no-buffer the -j1 flag should be passed as well btw)

[tmattio]

Got it, I'll try to look into it 🙂