Enabling logging within testsets

[danielsoutar]

Hi there,

I'm trying to use ReTest with an existing codebase, primarily for the parallel execution of tests. This codebase uses logging extensively, and the tests themselves may also include logging statements.

Obviously, logging naively can be problematic for threaded or distributed settings, as the outputs of multiple things at the same time might trample over each other. Hence, I'd like to do something like this (which is a minor edit of the example in the docs):

module MyPackageTests
using MyPackage, ReTest

using Logging, Distributed

id = myid()

rm("log-$(id).txt"; force=true)
io = open("log-$(id).txt", "w+")

# Create a logger and set it as the global logger for this process.
logger = SimpleLogger(io)
global_logger(logger)

@testset "more greet" verbose=true begin
    @testset "concatenation" verbose=true begin
        @info("Hello from worker $(id), in `concatenation`.")
        @test MyPackage.greet()^2 == "Hello World!Hello World!"
    end
    # ...
end
# ...

# Close the file and flush remaining writes.
close(io)

end  # module

If I run this in the REPL as follows:

julia> using Distributed; addprocs(2, exeflags="--project=$(Base.active_project())"); @everywhere include("test/MyPackageTests.jl"); MyPackageTests.runtests();
...

The files get created, the tests are run and pass, but nothing is printed. If I use println(global_logger()) in the test module after setting the logger I get the expected result. But it seems like @testset silently consumes/captures the output from logging and prevents anything being written to a file.

I would say this is a significant enhancement - lots of code may use logging, and setting up a simple logger this way would allow that functionality to be at least partially retained with minimal changes to the majority of the codebase (just some small set-up for a logger per module).

I am running with the latest version of ReTest as of writing (0.3.2) and on an Ubuntu VM (Focal Fossa, 20.04.3 LTS).

[danielsoutar]

FWIW, I played around with logging a bit more and realise this is likely hitting the following issue mentioned in the docs:

Toplevel testsets (which are not nested within other testsets), when run, are evaled at the toplevel of their parent
module, which means that they can't depend on local variables for example.

As a result, I could do something like the following:

# MyPackage.jl
function greet()
    @info("Calling greet()!")
    "Hello World!"
end
...

# MyPackageTests.jl
...
@testset "more greet" verbose=true begin
    @testset "concatenation" verbose=true begin
        id = myid()
        filename = "more-greet-concatenation-log-$(id).txt"
        rm(filename; force=true)  # clear the file if present to ensure no over-writing
        io = open(filename, "w+")
        logger = SimpleLogger(io)
        global_logger(logger)  # set logger for this process, means subsequent logging statements need no modification
        @info("Hello from worker $(id), in `concatenation`.")
        @test TestReTest.greet()^2 == "Hello World!Hello World!"
    end
    ...
end
...
# Output
# more-greet-concatenation-log-2.txt
┌ Info: Hello from worker 2, in `concatenation`.
└ @ Main.MyPackageTests /path/to/MyPackage/test/MyPackageTests.jl:16
┌ Info: Calling greet()!
└ @ MyPackage /path/toMyPackage/src/MyPackage.jl:5

It's not too bad, but this does mean that logging needs to be initialized in every testset, which is not ideal either from a performance standpoint (due to many files needing opening and writing) or a developer standpoint (due to duplicate set-up in potentially many nested testsets). It would be nice if the library had a feature to do something like this automatically or semi-automatically, and then gather all of the test log files at the end of execution to then combine in a single log file, if the user specifically enabled logging. Or if there was a way of hooking all the testsets in a file to write to a single log file (although this would likely have issues with locking).

[rfourquet]

Thanks for the feature request! That makes sense.