Dune runtest incorrectly changes escape codes related to cursor movement

[kyldvs]

Expected Behavior

Rely has nice output with dune runtest

Actual Behavior

Rely has bad output with dune runtest

Reproduction

When setting up Rely to work with dune runtest we notice that the output is very bad compared to normal. This appears to be an issue with how dune handles escape codes in the output.

From what I can deduce, it looks like dune processes output and does this with escape codes:

1. Split up output into contiguous chunks of text and escape codes
2. The print all prior escape codes that apply
3. Print the text
4. Then always reset at the end (seemingly fine since you reapply all prior escape codes)

This breaks down though because escape codes can have side-effects such as moving the cursor, or deleting parts of the line. Following the same approach as above with these kinds of escape codes in the output everything gets messed up and a jumbled mess gets printed. That is what I believe to be happening to Rely's output.

In the below example you can see \033[50D\033[K being applied many times in dune runtest output compared to running the exe like normal.

---

This repo should be an easy way to repro the issue if you want to see specifics: https://github.com/tmattio/dune-rely-demo

After cloning the repo (and esy install && esy build) these commands will highlight the problem:

• esy test-dune gives bad output
• esy test-exe gives good output (doesn't use dune runtest, just normal exe)

To figure out the difference in error codes I used these commands:

esy test-exe | sed -n l (good output):

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

(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 (bad output):

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$

[ghost]

Related to #2664. Do you know why Rely is outputting cursor movement? That seems unnecessary to me if you just want to print a static image.

[kyldvs]

We don't typically want to print a static image. We want to communicate that the tests are running so we print the "title" of the currently running test, then clear it out as we move on to the next one as there can be thousands of tests.

[ghost]

Oh I see. Dune buffers the output of command to avoid interleaving when running tests in parallel. So I'm not too sure how we can make this work :/

[ghost]

However, you can run dune with --no-buffer and the command will have direct access to the terminal. In this case you should also run dune with -j1 to avoid interleaving.

[kyldvs]

Okay we can update our recommendations to include these flags, they seem to work! We are also looking at a reporter for test results that doesn't need to move the cursor and just prints everything, it will be a worse experience in the general case but may be preferable here.

[ghost]

I guess what we need here is some kind of protocol between the build system and the test framework, so that the test could instruct dune that it wants to run in "interactive" mode.

[ghost]

I wrote a RFC for this: #3464

If you are interested in helping, I'm happy to give some pointers.