Proof of concept: allow Debug.log in fuzz tests

[drathier]

Proof of concept! Allow Debug.log to be used effectively in fuzz tests.

Idea: pass an extra argument to all fuzzer test functions { log : String -> a -> a }. This function is a no-op until we've found the simplest failing test case. The we run that simplest test case with a record that contains the real Debug.log function. Since it inherently works with side-effects, we can't easily capture and re-print stdout.

Fuzz tests:

all : Test
all =
    describe "Meta Debug.log"
        [ fuzz fuzzer "debug log for 1-arg fuzzer" <|
            \meta a ->
                meta.log (Debug.toString { desc = "fuzz1-meta-log", a = a }) <|
                    (a |> Expect.notEqual 5)
        , fuzz2 fuzzer fuzzer "debug log for 2-arg fuzzer" <|
            \meta a b ->
                meta.log (Debug.toString { desc = "fuzz2-meta-log", a = a, b = b }) <|
                    (( a, b ) |> Expect.notEqual ( 2, 5 ))
        , fuzz3 fuzzer fuzzer fuzzer "debug log for 3-arg fuzzer" <|
            \meta a b c ->
                meta.log (Debug.toString { desc = "fuzz3-meta-log", a = a, b = b, c = c }) <|
                    (( a, b, c ) |> Expect.notEqual ( 2, 3, 5 ))
        ]

fuzzer = intRange 2 5

Output:

{ a = 5, desc = "fuzz1-meta-log" }: Fail { description = "Expect.notEqual", given = Nothing, reason = Equality "5" "5" }
{ a = 2, b = 5, desc = "fuzz2-meta-log" }: Fail { description = "Expect.notEqual", given = Nothing, reason = Equality "(2,5)" "(2,5)" }
{ a = 2, b = 3, c = 5, desc = "fuzz3-meta-log" }: Fail { description = "Expect.notEqual", given = Nothing, reason = Equality "(2,3,5)" "(2,3,5)" }


↓ Meta Debug.log
✗ debug log for 1-arg fuzzer
Given 5

     
    5
    ╵
    │ |> Expect.notEqual
    ╷
    5
     


↓ Meta Debug.log
✗ debug log for 2-arg fuzzer
Given (2,5)

         
    (2,5)
    ╵
    │ |> Expect.notEqual
    ╷
    (2,5)
         


↓ Meta Debug.log
✗ debug log for 3-arg fuzzer
Given (2,3,5)

           
    (2,3,5)
    ╵
    │ |> Expect.notEqual
    ╷
    (2,3,5)
           


TEST RUN FAILED

Passed: 258
Failed: 3

[harrysarson]

Would we want to let the test runner hook into this in someway, so that it can provide a custom logging function? I guess this would require the function to return a Cmd (for port logging) so may not be possible.

[harrysarson]

This is really cool!

[avh4]

imo this puts an extremely high burden on the user... it seems like if they wanted to log something in their code, they would have to thread through the meta.log function all the way down to wherever they want to actually log something, or am I missing something about what this does or where it's headed? I wonder if there's a way to change the test runner to be able to do this without having to change the public API and put the burden on the user to learn a new way of logging for fuzz tests.

[harrysarson]

I guess the alternative is a Test.Log function. The kernel code backing this function would then need to read some global state to know what to do (log or not log)

[harrysarson]

The javascript test runner ava uses a logging function passed to each test when it is run (like we do in this PR) so there is precedent for @drathier's approach.

[avh4]

Is there a way to make it work without the user having to do anything special? elm-test controls the execution environment of each test, so I'd expect there'd be a way for it to set up Debug.log to do what it wants for each test run?

Wasn't there also some discussion about being able to capture the console logs for each test so that any output can be put next to the correct error message? If that were done, then wouldn't this basically be solved as well, as the console output for any individual run could be discarded at the runner's (in this case the fuzz test module's) discretion?

[drathier]

Yeah, this is the pure fp approach, but we do have kernel code available so we could have a collection mechanism for this instead, if the test runner does the actual collection, or replaces the js implementation of Debug.log. I prefer a non-pure approach, because it just works.

[drathier]

How about this then? We try to gather up log prints using help from kernel code and the test runner.

1. The test runner overwrites the Debug.log implementation in the compiled js code, instead storing the logs in an array for later.
2. We expose one kernel function that destructively clears that log array and returns the log entires that were in it.
3. This package can then gather up logs per failed test case, and present it nicely to the user.

[harrysarson]

Could we have an internal API like

capture: (a -> b) -> { output: b, logs: List (String, String) }

function _Test_capture(func) {
    assert(__Debug_divertLogsTo === null);
    _Debug_divertLogsTo = [];
    var output = func();
    var logs = __Debug_divertLogsTo ;
    __Debug_divertLogsTo  = null;
    return {
        __$output: output,
        __$logs: logs
    };
}

Although this API would require a patch to elm/core:Elm.Kernel.Debug to work.

[harrysarson]

Could we have an internal API like

capture: (a -> b) -> { output: b, logs: List (String, String) }

function _Test_capture(func) {
    assert(__Debug_divertLogsTo === null);
    _Debug_divertLogsTo = [];
    var output = func();
    var logs = __Debug_divertLogsTo ;
    __Debug_divertLogsTo  = null;
    return {
        __$output: output,
        __$logs: logs
    };
}

Although this API would require a patch to elm/core:Elm.Kernel.Debug to work.

[drathier]

That sounds good, yes. We should probably disable Debug.log outside of this function, just passing through values without printing or logging them, for performance reasons.

[harrysarson]

We should probably disable Debug.log outside of this function, just passing through values without printing or logging them,

If someone is logging outside of a test (I guess the only way to do this is to have log statements in the code that runs on load) then I think we should not do anything special with those logs.

[drathier]

When generating the log output for fuzz tests we'd do this:

1. run a fuzz test throwing away logs
2. on error, simplify the error, throwing away logs
3. run the simplest input through the fuzz test function one last time, this time collecting the Debug.log output into a list
4. fetch that list of logs and put it into the test failure data structure, for later use in error reporting

Steps 1 and 2 would generate a ton of unneeded log output and performance would be really bad. I'm expecting people to add log statements to their tests and just leave them in, expecting them to have zero performance impact on successful tests. That's at least how I would want to treat them.

[harrysarson]

Would what you are suggesting work as the following two APIs?

suppressLogs: (a -> b) -> b
captureLogs: (a -> b) -> { output: b, logs: List (String, String) }

[drathier]

It could, yes

[gampleman]

To solve the problem of people leaving logging in tests forever, you could mark tests containing logging as pending rather than passed.

[harrysarson]

Is it a problem if people leave logging in tests forever?

[drathier]

Why not let them leave the logging in?

[gampleman]

What's the point of logging that exists just to get discarded?

[harrysarson]

What is the point of a test that doesn't fail?

I guess the idea is that you can put logging in your tests and then debugging a test failure becomes much easier because the failure message comes with log messages.

[mpizenberg]

Just to chip in on the discussion. In elm-test-rs capturing calls to Debug.log is possible by capturing all stdout of a worker into a variable that gets flushed to the supervisor via worker thread parentPort.

https://github.com/mpizenberg/elm-test-rs/blob/b8192ac947837792c9da49b3eb3d841ddbabd297/templates/node_runner.js#L7-L9

It works well for unit tests, but isn't much useful with the huge amount of logging in fuzz tests. Having an alteration of the log function that would deactivate it except for the shrinked pass would be awesome.