Debugging a stuck OUnit test using qcheck

Ecosystem
,
1

I have been working on a hobby project SQL parser. I added some simple OUnit2 tests that run fine. However I wanted to get fancy and use qcheck to create a property that for any arbitrary SQL query outputs that to a query string and parses it back and the returned query should be the same as the original one.

However… this test never finishes running, so I figured maybe my generator implementation might have some infinite recursion problem. But I can’t find a way to figure out where my code is stuck. If I stick print_endline calls into my SQL qcheck generator or into the 'a -> bool function in my call to QCheck.Test.make they don’t show up in the command line so I’m guessing maybe OUnit is collecting the standard output of QCheck or something.

Any ideas how to debug this case?

2

The things I’d try include:

  • put print statements everywhere
  • try OUnit (not OUnit2), it might avoid capturing the output of the test function
  • write messages into a log file (instead of stdout)
3

Is it not possible to just run the bytecode version or something and then stop the execution and check the callstack?

4

Been trying some more stuff:

  • Running my test through ocamldebug in vscode. I had trouble getting any relevant breakpoints to get hit. At least when running in the debugger I can see some of the print_endlines that I couldn’t see when running from the command line
  • I could see the same line being repeated with a different number each time which seems to suggest that my property is endlessly generating queries
  • I changed the count parameter for my call to QCheck.Test.make to 1 and this way the test always runs to completion. However, just changing the count one step up to 2, causes the test program to go back into an infinite loop
5

Ok, finally a breakthrough:

  • Since I didn’t specify a seed for qcheck I was getting the default constant seed so my test was getting stuck every time
  • I noticed that my way of generating the query expression tree was not optimal, I underestimated how large the n parameter grows for sized, instead of calling self (n - 1), I started calling self (n / 2) as in the example on Github and noticed that there was not an infinite loop, I was just generating insanely large expressions
6

Now if only I could get these fail_report calls to work using the pinned version of qcheck.

7

Have you tried writing a test that directly calls fail_report (or fail_reportf) unconditionally?
What happens if you do? Also, if you could try with the other runners (the non-ounit ones), just to be sure, that would help

8

Put together a simple test case:

open OUnit2

let simple_qcheck =
    QCheck.Test.make
        ~count: 100
        QCheck.small_int
        (fun x -> QCheck.Test.fail_report "this will always fail")

let suite = "all tests" >:::
    [
        QCheck_runner.to_ounit2_test simple_qcheck
    ]

let () =
    ignore (QCheck_runner.run_tests [simple_qcheck]);
    run_test_tt_main suite

Running this will give the following output:

> jbuilder runtest
         ppx Simple_test.pp.ml
    ocamldep Simple_test.depends.ocamldep-output
      ocamlc Simple_test.{cmi,cmo,cmt}
      ocamlc Simple_test.bc
 Simple_test alias runtest (exit 1)
(cd _build/default && ./Simple_test.bc)
random seed: 123934987

--- Failure --------------------------------------------------------------------

Test anon_test_1 failed (6 shrink steps):

0

+++ Messages ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Messages for test anon_test_1:

this will always fail
================================================================================
failure (1 tests failed, 0 tests errored, ran 1 tests)
F
==============================================================================
Error: all tests:0:anon_test_1.

File "/Users/sam/projects/private/qcheck-test/_build/oUnit-all tests-Sams-MacBook.local#01.log", line 2, characters 1-1:
Error: all tests:0:anon_test_1 (in the log).

File "src/QCheck.ml", line 1359, characters 1-1:
Error: all tests:0:anon_test_1 (in the code).

  test `anon_test_1` failed on ≥ 1 cases: 0 (after 5 shrink steps)


------------------------------------------------------------------------------
Ran: 1 tests in: 0.14 seconds.
FAILED: Cases: 1 Tried: 1 Errors: 0 Failures: 1 Skip:  0 Todo: 0 Timeouts: 0.

In other words the fail_report message is not handled correctly in the OUnit2 case.