Ergonomics of :verbose

[evnu]

I sometimes encounter users struggling with PropCheck when debugging properties if exceptions are present. Such errors are hard to debug if the :verbose flag is not set, as the stack traces are hidden, and new users do not necessarily have that in mind. I wonder if there is something that can be done here. For example, the following requires :verbose so that the exception is printed:

  property "failing", [:verbose] do
    forall _ <- nat() do
      raise "this will not work"
    end
  end

It would be nice if we were able to detect that the test failed due to an exception. The least we should be able to do if such a detection is possible at all would be to output an additional warning: "Failed due to exception. Add :verbose to see stack traces".

[alfert]

💚 Yes, this would really be nice and I fall into the same hole once here and there.

[evnu]

#111 is a first step in making :verbose more ergonomic.

[evnu]

I played around with the :to_file option of PropEr. This option allows to store all PropEr-output in a file. Note that this file can be a memory-backed StringIO. Using this option requires the property to be in :verbose mode. PropEr will not write anything to the IO device otherwise.

Using this approach then allows to grep for An exception was raised and therefore simple detection of exceptions. This does not work for ExUnit assertions (#48), as they are not written by PropEr. If we decide to go down this lane, we need to write those exceptions into that IO device as well.

[evnu]

I implemented a simple proof-of-concept for the comment in this branch. This does not yet handle ExUnit assertions. To try it, run mix test test/assert_test.exs. For the property failing raise, a message An exception was detected. is output.

[evnu]

@alfert what do you think about the poc?

[alfert]

@evnu , I think we should solve it differently.

I suggest tp push it to forall_impl in propcheck.ex. There is also the handling of ExUnit assertion, so we have clear point of intercepting stuff. Using the option to_file feels like hack, therefore I would suggest that we introduce a new option silence_exceptions which is per default false. This option is for PropCheck only and is evaluated in forall_impl to out put any stack traces.

Do I miss something? I am currently lacking time to look deeper into this and I am not sure whether PropEr will gobble all the output to stdout we are doing.

[evnu]

Using the option to_file feels like hack, therefore I would suggest that we introduce a new option silence_exceptions which is per default false. This option is for PropCheck only and is evaluated in forall_impl to out put any stack traces.

That makes sense.

I am not sure whether PropEr will gobble all the output to stdout we are doing.

Yes, I am wondering about that as well. I don't know enough of the PropEr-internal specifics to judge that.

[evnu]

@alfert I added your suggestions in evnu@351365e. This kind-of-works, it detects exceptions and errors. Alas, the output is not written exactly before or after a test (both would be fine I think, as long as it is consistent), but may be split. Maybe there is a way to make ExUnit write the actual output? We might need that in order force flushing the output for the detection before or after a failed test.

Note that I did not yet implement the silence_exceptions flag.

[alfert]

Hmm. I assume that the split comes from running tests in parallel, what is the default for ExUnit. What happens if you run the tests in trace mode or with async: false? Then they are executed in a sequential manner.

If this does not help, I assume we have to dig into Proper or ExUnit. For Proper, it would be nice to have the possibility to format the output as Elixir code or values instead of the Erlang notation. What do you think?

[evnu]

--trace does not help:

mix test test/assert_test.exs --trace
Compiling 20 files (.ex)
Generated propcheck app

AssertTest
  * property failing raisePropCheck detected an error
** (RuntimeError) raise-fail
    test/assert_test.exs:7: anonymous fn/2 in AssertTest."property failing raise"/1
    (proper) src/proper.erl:1543: :proper.apply_args/4
    (proper) src/proper.erl:1133: :proper.retry/3
    (propcheck) lib/properties.ex:168: PropCheck.Properties.execute_property/4
    test/assert_test.exs:5: AssertTest."property failing raise"/1
    (ex_unit) lib/ex_unit/runner.ex:355: ExUnit.Runner.exec_test/1
    (stdlib) timer.erl:166: :timer.tc/1
    (ex_unit) lib/ex_unit/runner.ex:306: anonymous fn/4 in ExUnit.Runner.spawn_test_monitor/4

  * property failing raise (17.5ms)

  1) property failing raise (AssertTest)
     test/assert_test.exs:5
     Property Elixir.AssertTest.property failing raise() failed. Counter-Example is:
     [1]

     Consider running `MIX_ENV=test mix propcheck.clean` if a bug in a generator was
     identified and fixed. PropCheck cannot identify changes to generators. See
     https://github.com/alfert/propcheck/issues/30 for more details.

     code: nil
     stacktrace:
       (propcheck) lib/properties.ex:217: PropCheck.Properties.handle_check_results/4
       test/assert_test.exs:5: (test)
...

With async: false, the output is still not consistent.

If this does not help, I assume we have to dig into Proper or ExUnit.

I think so too. I did some digging into how ExUnit actually prints its output back when I developed https://github.com/evnu/docception. I faintly remember that it was hard to make ExUnit flush its output before the program stopped. Alas, I don't remember if ExUnit uses its own port to write to stdout, or if it buffers the output, or what else is happening with output there.

[alfert]

I faintly remember that it was hard to make ExUnit flush its output before the program stopped.

This is because ExUnit runs normally in the shutdown handler of the Erlang VM.