logging.jl

# This file is a part of Julia. License is MIT: https://julialang.org/license

using Base.CoreLogging
import Base.CoreLogging: BelowMinLevel, Debug, Info, Warn, Error,
    handle_message, shouldlog, min_enabled_level, catch_exceptions

import Test: collect_test_logs, TestLogger
using Base.Printf: @sprintf

#-------------------------------------------------------------------------------
@testset "Logging" begin

@testset "Basic logging" begin
    @test_logs (Debug, "a") min_level=Debug @debug "a"
    @test_logs (Info,  "a") @info  "a"
    @test_logs (Warn,  "a") @warn  "a"
    @test_logs (Error, "a") @error "a"
end

#-------------------------------------------------------------------------------
# Front end

@testset "Log message formatting" begin
    @test_logs (Info, "sum(A) = 16.0") @info begin
        A = fill(1.0, 4, 4)
        "sum(A) = $(sum(A))"
    end
    x = 10.50
    @test_logs (Info, "10.5") @info "$x"
    @test_logs (Info, "10.500") @info @sprintf("%.3f", x)
end

@testset "Programmatically defined levels" begin
    level = Info
    @test_logs (Info, "X") @logmsg level "X"
    level = Warn
    @test_logs (Warn, "X") @logmsg level "X"
end

@testset "Structured logging with key value pairs" begin
    foo_val = 10
    bar_val = 100
    logs,_ = collect_test_logs() do
        @info "test"  bar_val  progress=0.1  foo=foo_val  2*3  real_line=(@__LINE__)
        @info begin
            value_in_msg_block = 1000.0
            "test2"
        end value_in_msg_block
        test_splatting(;kws...) = @info "test3" kws...
        test_splatting(a=1,b=2.0)
    end
    @test length(logs) == 3

    record = logs[1]
    kwargs = record.kwargs

    # Builtin metadata
    @test record._module == @__MODULE__
    @test record.file == Base.source_path()
    @test record.line == kwargs[:real_line]
    @test record.id isa Symbol
    @test occursin(r"^.*logging_[[:xdigit:]]{8}$", String(record.id))

    # User-defined metadata
    @test kwargs[:bar_val] === bar_val
    @test kwargs[:progress] == 0.1
    @test kwargs[:foo] === foo_val
    @test kwargs[Symbol(:(2*3))] === 6

    # Keyword values accessible from message block
    record2 = logs[2]
    @test occursin((Info, "test2"), record2)
    kwargs = record2.kwargs
    @test kwargs[:value_in_msg_block] === 1000.0

    # Splatting of keywords
    record3 = logs[3]
    @test occursin((Info, "test3"), record3)
    kwargs = record3.kwargs
    @test sort(collect(keys(kwargs))) == [:a, :b]
    @test kwargs[:a] === 1
    @test kwargs[:b] === 2.0
end

@testset "Log message exception handling" begin
    # Exceptions in message creation are caught by default
    @test_logs (Error,Test.Ignored(),Test.Ignored(),:logevent_error) catch_exceptions=true  @info "foo $(1÷0)"
    # Exceptions propagate if explicitly disabled for the logger (by default
    # for the test logger)
    @test_throws DivideError collect_test_logs() do
        @info  "foo $(1÷0)"
    end
end

@testset "Special keywords" begin
    logger = TestLogger()
    with_logger(logger) do
        @info "foo" _module=Base.Core _id=:asdf _group=:somegroup _file="/a/file" _line=-10
    end
    @test length(logger.logs) == 1
    record = logger.logs[1]
    @test record._module == Base.Core
    @test record.group == :somegroup
    @test record.id == :asdf
    @test record.file == "/a/file"
    @test record.line == -10
    # Test consistency with shouldlog() function arguments
    @test record.level   == logger.shouldlog_args[1]
    @test record._module == logger.shouldlog_args[2]
    @test record.group   == logger.shouldlog_args[3]
    @test record.id      == logger.shouldlog_args[4]
end


#-------------------------------------------------------------------------------
# Early log level filtering

@testset "Early log filtering" begin
    @testset "Log filtering, per task logger" begin
        @test_logs (Warn, "c") min_level=Warn begin
            @info "b"
            @warn "c"
        end
    end

    @testset "Log level filtering - global flag" begin
        # Test utility: Log once at each standard level
        function log_each_level()
            @debug "a"
            @info  "b"
            @warn  "c"
            @error "d"
        end

        disable_logging(BelowMinLevel)
        @test_logs (Debug, "a") (Info, "b") (Warn, "c") (Error, "d") min_level=Debug  log_each_level()

        disable_logging(Debug)
        @test_logs (Info, "b") (Warn, "c") (Error, "d") min_level=Debug  log_each_level()

        disable_logging(Info)
        @test_logs (Warn, "c") (Error, "d") min_level=Debug  log_each_level()

        disable_logging(Warn)
        @test_logs (Error, "d") min_level=Debug  log_each_level()

        disable_logging(Error)
        @test_logs log_each_level()

        # Reset to default
        disable_logging(BelowMinLevel)
    end

    @testset "Log level filtering - ENV" begin
        logger = TestLogger()
        with_logger(logger) do
            for (e, r) in (("", false),
                           (",,,,", false),
                           ("al", false),
                           ("all", true),
                           ("a,b,all,c", true),
                           ("a,b,,c", false),
                           ("Mainb", false),
                           ("aMain", false),
                           ("Main", true),
                           ("a,b,Main,c", true),
                           ("Base", true),
                           ("a,b,Base,c", true),
                           ("Filesystem", true),
                           ("a,b,Filesystem,c", true),
                           ("a,b,Base.Filesystem,c", false))
                ENV["JULIA_DEBUG"] = e
                @test CoreLogging.env_override_minlevel(:Main, Base.Filesystem) === r
                @test CoreLogging.current_logger_for_env(BelowMinLevel, :Main, Base.Filesystem) === (r ? logger : nothing)
                @test CoreLogging.current_logger_for_env(Info, :Main, Base.Filesystem) === logger
            end
        end
    end
    ENV["JULIA_DEBUG"] = ""
end

#-------------------------------------------------------------------------------

@eval module LogModuleTest
    function a()
        @info  "a"
    end

    module Submodule
        function b()
            @info  "b"
        end
    end
end

@testset "Capture of module information" begin
    @test_logs(
        (Info, "a", LogModuleTest),
        (Info, "b", LogModuleTest.Submodule),
        begin
            LogModuleTest.a()
            LogModuleTest.Submodule.b()
        end
    )
end


#-------------------------------------------------------------------------------
@testset "Logger installation and access" begin
    @testset "Global logger" begin
        logger1 = global_logger()
        logger2 = TestLogger()
        # global_logger() returns the previously installed logger
        @test logger1 === global_logger(logger2)
        # current logger looks up global logger by default.
        @test current_logger() === logger2
        global_logger(logger1) # Restore global logger
    end
end

#-------------------------------------------------------------------------------

# Custom log levels

@eval module LogLevelTest
    using Base.CoreLogging

    struct MyLevel
        level::Int
    end

    Base.convert(::Type{LogLevel}, l::MyLevel) = LogLevel(l.level)

    const critical = MyLevel(10000)
    const debug_verbose = MyLevel(-10000)
end

@testset "Custom log levels" begin
    @test_logs (LogLevelTest.critical, "blah") @logmsg LogLevelTest.critical "blah"
    logs,_ = collect_test_logs(min_level=Debug) do
        @logmsg LogLevelTest.debug_verbose "blah"
    end
    @test length(logs) == 0
end


#-------------------------------------------------------------------------------

@testset "SimpleLogger" begin
    # Log level limiting
    @test min_enabled_level(SimpleLogger(devnull, Debug)) == Debug
    @test min_enabled_level(SimpleLogger(devnull, Error)) == Error

    # Log limiting
    logger = SimpleLogger(devnull)
    @test shouldlog(logger, Info, Base, :group, :asdf) === true
    handle_message(logger, Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2)
    @test shouldlog(logger, Info, Base, :group, :asdf) === true
    handle_message(logger, Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2)
    @test shouldlog(logger, Info, Base, :group, :asdf) === false
    @test catch_exceptions(logger) === false

    # Log formatting
    function genmsg(level, message, _module, filepath, line; kws...)
        io = IOBuffer()
        logger = SimpleLogger(io, Debug)
        handle_message(logger, level, message, _module, :group, :id,
                       filepath, line; kws...)
        String(take!(io))
    end

    # Simple
    @test genmsg(Info, "msg", Main, "some/path.jl", 101) ==
    """
    ┌ Info: msg
    └ @ Main some/path.jl:101
    """

    # Multiline message
    @test genmsg(Warn, "line1\nline2", Main, "some/path.jl", 101) ==
    """
    ┌ Warning: line1
    │ line2
    └ @ Main some/path.jl:101
    """

    # Keywords
    @test genmsg(Error, "msg", Base, "other.jl", 101, a=1, b="asdf") ==
    """
    ┌ Error: msg
    │   a = 1
    │   b = asdf
    └ @ Base other.jl:101
    """
end

# Issue #26273
let m = Module(:Bare26273i, false)
    Core.eval(m, :(import Base: @error))
    @test_logs (:error, "Hello") Core.eval(m, quote
        @error "Hello"
    end)
end

end