Julia: `Logging.@warn` broke `Test.@test_nowarn`?

[vtjnash]

julia> @test_nowarn @warn "this should not print"
[ Warning: this should not print                                                                                                                                                              @ Main REPL[11]:1

[c42f]

@test_logs the new generic tool for matching log events, and can be used to match zero or more log events - all types, not just warnings. If you want to match the output of @warn this is the thing to use. If you want to suppress the output of @warn or other logging during testing, you can use with_logger(NullLogger()) do ... end.

As for @test_warn / @test_nowarn - these are tools for matching strings on STDERR (warnings among many other things). I haven't been able to deprecate them because they're still in use for matching various STDERR output, mainly from subprocesses or the runtime. Arguably they're poorly named, especially now.

[stevengj]

@test_stderr and @test_nostderr?

[tk3369]

Also see https://discourse.julialang.org/t/test-warn-doesnt-work-with-warn-in-0-7/9001?u=tk3369

[stevengj]

Note that fixing #26798 will fix this problem, at least with the default logger.

[mbauman]

Bump! This is rather confusing, and @test_warn is also broken for the same reason:

julia> @test_warn "broken" @warn "broken"
┌ Warning: broken
└ @ Main REPL[4]:1
Test Failed at /home/mbauman/julia/usr/share/julia/stdlib/v0.7/Test/src/Test.jl:606
  Expression: contains_warn(read(fname, String), $(Expr(:escape, "broken")))
ERROR: There was an error during testing

Just for posterity, the current workarounds are:

# Test that a specific warning is thrown with one tuple argument
julia> @test_logs (:warn, "correct") @warn "correct"

# Test that no warnings are thrown by passing no tuple arguments:
julia> @test_logs sqrt(1)
1.0

julia> @test_logs @warn "unexpected warning"
Log Test Failed at REPL[19]:1
  Expression: #= REPL[19]:1 =# @warn "unexpected warning"
  Log Pattern:
  Captured Logs:
    Test.LogRecord(Warn, "unexpected warning", Main, Symbol("REPL[19]"), :Main_76293138, "REPL[19]", 1, Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}())

ERROR: There was an error during testing

[KristofferC]

So should we just delete @test_warn? It's kinda silly to have it when it literally doesn't work at all.

[c42f]

I think It's still useful, just terribly poorly named? Maybe a soft deprecation to @test_stderr would make sense?

[KristofferC]

Yeah, makes sense to me. If @test_nowarn @warn "lol" passes, then something has to be done.

[c42f]

Yeah it slipped through the cracks alright. Not my proudest moment :grimacing:

Note that this was always rather fragile though regardless of the logging changes, and renaming to @test_stderr would not fix that fragility. For instance, we have

julia> my_stderr = stderr
Base.TTY(RawFD(0x0000000f) open, 0 bytes waiting)

julia> @test_warn "Surprise" println(my_stderr, "Surprise")  # soon to be `@test_stderr` ???
Surprise
Test Failed at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.2/Test/src/Test.jl:639
  Expression: contains_warn(read(fname, String), $(Expr(:escape, "Surprise")))
ERROR: There was an error during testing

That is, whenever the program takes an explicit reference to stderr and stashes it somewhere in a data structure, the mechanism used by @test_warn (soon to be @test_stderr?) will not work.

[c42f]

To expand... what @test_warn actually checks (IIRC) is that a piece of code does two things:

1. Resolve GlobalRef(Base, :stderr)
2. Write something to it.

This is different from what you'd (or at least I'd) expect or like, which is that the process' real stderr stream itself would be somehow captured at a low level, which would cut out step 1 entirely and make the whole thing a lot less surprising. Whether that's at all feasible requires knowing more about IO than I currently do.

[MatFi]

Is this a related bug?
```julia
julia> @test_logs (:warn, "correct") @warn "correct" # passes

julia> @test_logs (:warn, "correct") (@warn "correct"; @warn "brakes") # fails but should pass as well
```

[c42f]

No, this isn't related. You need to configure @test_logs a bit (it is expecting a full list of all warnings):

@test_logs (:warn, "correct") match_mode=:any (@warn "correct"; @warn "no problem")

[MatFi]

Ah true.. Thanks! This option is hidden in the doc's, I skipped the text and went straight to the example which show a similar case and claim to work without this option.

[c42f]

The docs are correct but confusing because they try to cover all the functionality in one example. Would you consider making a doc PR to add an extra function example for the match_mode option?