qcheck icon indicating copy to clipboard operation
qcheck copied to clipboard

Strange colored output

Open favonia opened this issue 4 years ago • 3 comments

With colors being true but long and verbose being false, the output of run_tests_main is somehow strange. Here is the captured output with control characters being escaped (except for line feeds). For some reasons, random was repeated.

^[[2K^Mrandom seed: 356596957^[[0m^M
^[[2K^Mrandom================================================================================^[[0m^M
^[[2K^Mrando;32;1msuccess^[[0m (ran 12 tests)^M

I have tried different shells and terminal emulators, and the behavior seems to be the same.

favonia avatar Mar 07 '22 03:03 favonia

I've tried: dune exec example/QCheck_runner_test.exe -- --colors but I don't see any escaped control character. Would you mind providing a more specific repro? :)

c-cube avatar Mar 07 '22 05:03 c-cube

I discovered that directly running dune exec in my case would have the correct output. However, dune test would screw up the control sequences. The control sequences in the first post were captured by script and then converted so that I can report the issue on GitHub. Because dune exec and dune test seem to differ, it's quite possible that qcheck is actually fine and the bug lies somewhere else.

~~Anyways, the most reliable reproducible step is to check out https://github.com/RedPRL/yuujinchou/tree/qcheck-bug, install the dependencies, and run dune test -f.~~ I am removing the branch because @jmid made a great minimum working example below.

favonia avatar Mar 07 '22 14:03 favonia

I looked at this a bit to create a small repro:

repro/dune:

(test
 (name test)
 (libraries qcheck-core qcheck-core.runner))

repro/test.ml:

let test =
  QCheck2.Test.make ~name:"name" QCheck2.Gen.int (fun _ -> true)

let _ = QCheck_base_runner.run_tests (*~colors:true*)  [test]

With dune exec there is no issue - while dune test (aka dune runtest aka ...) confuses the output:

$ dune exec repro/test.exe -f
random seed: 283984449
================================================================================
success (ran 1 tests)
$ dune runtest repro/ -f
        test alias repro/runtest
random seed: 4234572
random================================================================================
rando;32;1msuccess (ran 1 tests)

The problem goes away if using dune runtest repro/ -f --no-buffer instead. The idea is that dune runs things in parallel while buffering each task's output. Using --no-buffer writes the output straight to the terminal - with a risk of interleaved/mangled output (unless it is combined with -j 1). Alternatively you can pass --colors:false to run_test in QCheck to avoid control characters.

This seems to be a known issue with dune: https://github.com/ocaml/dune/issues/3160 There's another description of how dune parses the escape codes here: https://github.com/ocaml/dune/issues/2664#issuecomment-534047785 The code for implementing the parsing is moved here: https://github.com/ocaml/dune/blob/main/otherlibs/stdune/ansi_color.ml AFAICS it handles only colors - and not the ANSI escape code for "Erase in Line" (clearing a line) that we use for printing the initial "random seed" line: https://github.com/c-cube/qcheck/blob/be9a0e78eadb663b5b2f9cb16e692ae93fb1cb68/src/runner/QCheck_base_runner.ml#L40

I'm wondering whether we need to clear the line before the first "random seed" print out?

jmid avatar Mar 07 '22 23:03 jmid

Closing as this should be fixed in ocaml/dune#5528 released with dune 3.5.0

jmid avatar Nov 07 '22 08:11 jmid