diff --git a/NEWS.md b/NEWS.md index 7fed73e627ab8..7b976a7e7e3b4 100644 --- a/NEWS.md +++ b/NEWS.md @@ -312,6 +312,12 @@ This section lists changes that do not have deprecation warnings. `AbstractArray` types that specialized broadcasting using the old internal API will need to switch to the new API. ([#20740]) + * The logging system has been redesigned - `info` and `warn` are deprecated + and replaced with the logging macros `@info`, `@warn`, `@debug` and + `@error`. The `logging` function is also deprecated and replaced with + `AbstractLogger` and the functions from the new standard `Logging` library. + ([#24490]) + * The `RevString` type has been removed from the language; `reverse(::String)` returns a `String` with code points (or fragments thereof) in reverse order. In general, `reverse(s)` should return a string of the same type and encoding as `s` with code diff --git a/base/bitarray.jl b/base/bitarray.jl index 8e786b68e91d6..f969a10cb9b20 100644 --- a/base/bitarray.jl +++ b/base/bitarray.jl @@ -88,20 +88,6 @@ const _msk64 = ~UInt64(0) @inline _msk_end(B::BitArray) = _msk_end(length(B)) num_bit_chunks(n::Int) = _div64(n+63) -function _check_bitarray_consistency(B::BitArray{N}) where N - n = length(B) - if N ≠ 1 - all(d ≥ 0 for d in B.dims) || (warn("negative d in dims: $(B.dims)"); return false) - prod(B.dims) ≠ n && (warn("inconsistent dims/len: prod(dims)=$(prod(B.dims)) len=$n"); return false) - end - Bc = B.chunks - nc = length(Bc) - nc == num_bit_chunks(n) || (warn("incorrect chunks length for length $n: expected=$(num_bit_chunks(n)) actual=$nc"); return false) - n == 0 && return true - Bc[end] & _msk_end(n) == Bc[end] || (warn("nonzero bits in chunk after BitArray end"); return false) - return true -end - @inline get_chunks_id(i::Integer) = _div64(Int(i)-1)+1, _mod64(Int(i)-1) function glue_src_bitchunks(src::Vector{UInt64}, k::Int, ks1::Int, msk_s0::UInt64, ls0::Int) diff --git a/base/boot.jl b/base/boot.jl index b7cdf2ad8ec25..8ebcfb4c10af9 100644 --- a/base/boot.jl +++ b/base/boot.jl @@ -110,10 +110,14 @@ #mutable struct Task # parent::Task # storage::Any -# consumers -# started::Bool -# done::Bool -# runnable::Bool +# state::Symbol +# consumers::Any +# donenotify::Any +# result::Any +# exception::Any +# backtrace::Any +# logstate::Any +# code::Any #end export diff --git a/base/client.jl b/base/client.jl index 1d73468ca7fcc..26014d026a668 100644 --- a/base/client.jl +++ b/base/client.jl @@ -137,12 +137,6 @@ function repl_cmd(cmd, out) end function display_error(io::IO, er, bt) - if !isempty(bt) - st = stacktrace(bt) - if !isempty(st) - io = redirect(io, log_error_to, st[1]) - end - end print_with_color(Base.error_color(), io, "ERROR: "; bold = true) # remove REPL-related frames from interactive printing eval_ind = findlast(addr->Base.REPL.ip_matches_func(addr, :eval), bt) @@ -284,7 +278,7 @@ function process_options(opts::JLOptions) elseif cmd == 'L' # nothing else - warn("unexpected command -$cmd'$arg'") + @warn "Unexpected command -$cmd'$arg'" end end @@ -396,7 +390,7 @@ function _start() banner && REPL.banner(term,term) if term.term_type == "dumb" active_repl = REPL.BasicREPL(term) - quiet || warn("Terminal not fully functional") + quiet || @warn "Terminal not fully functional" else active_repl = REPL.LineEditREPL(term, have_color, true) active_repl.history_file = history_file diff --git a/base/deprecated.jl b/base/deprecated.jl index 5f48ad7e237e3..c675247b97188 100644 --- a/base/deprecated.jl +++ b/base/deprecated.jl @@ -28,7 +28,7 @@ macro deprecate(old, new, ex=true) ex ? Expr(:export, esc(old)) : nothing, :(function $(esc(old))(args...) $meta - depwarn($"$old is deprecated, use $new instead.", $oldmtname) + depwarn($"`$old` is deprecated, use `$new` instead.", $oldmtname) $(esc(new))(args...) end), :(const $oldmtname = Core.Typeof($(esc(old))).name.mt.name)) @@ -53,7 +53,7 @@ macro deprecate(old, new, ex=true) ex ? Expr(:export, esc(oldsym)) : nothing, :($(esc(old)) = begin $meta - depwarn($"$oldcall is deprecated, use $newcall instead.", $oldmtname) + depwarn($"`$oldcall` is deprecated, use `$newcall` instead.", $oldmtname) $(esc(new)) end), :(const $oldmtname = Core.Typeof($(esc(oldsym))).name.mt.name)) @@ -64,21 +64,27 @@ end function depwarn(msg, funcsym) opts = JLOptions() - if opts.depwarn > 0 - bt = backtrace() - _depwarn(msg, opts, bt, firstcaller(bt, funcsym)) - end - nothing -end -function _depwarn(msg, opts, bt, caller) - ln = Int(unsafe_load(cglobal(:jl_lineno, Cint))) - fn = unsafe_string(unsafe_load(cglobal(:jl_filename, Ptr{Cchar}))) - if opts.depwarn == 1 # raise a warning - warn(msg, once=(caller != StackTraces.UNKNOWN), key=(caller,fn,ln), bt=bt, - filename=fn, lineno=ln) - elseif opts.depwarn == 2 # raise an error + if opts.depwarn == 2 throw(ErrorException(msg)) end + deplevel = opts.depwarn == 1 ? CoreLogging.Warn : CoreLogging.BelowMinLevel + @logmsg( + deplevel, + msg, + _module=begin + bt = backtrace() + frame, caller = firstcaller(bt, funcsym) + # TODO: Is it reasonable to attribute callers without linfo to Core? + caller.linfo isa Core.MethodInstance ? caller.linfo.def.module : Core + end, + _file=String(caller.file), + _line=caller.line, + _id=(frame,funcsym), + _group=:depwarn, + caller=caller, + maxlog=1 + ) + nothing end firstcaller(bt::Vector, funcsym::Symbol) = firstcaller(bt, (funcsym,)) @@ -86,13 +92,17 @@ function firstcaller(bt::Vector, funcsyms) # Identify the calling line found = false lkup = StackTraces.UNKNOWN + found_frame = Ptr{Void}(0) for frame in bt lkups = StackTraces.lookup(frame) for outer lkup in lkups if lkup == StackTraces.UNKNOWN continue end - found && @goto found + if found + found_frame = frame + @goto found + end found = lkup.func in funcsyms # look for constructor type name if !found && lkup.linfo isa Core.MethodInstance @@ -105,9 +115,9 @@ function firstcaller(bt::Vector, funcsyms) end end end - return StackTraces.UNKNOWN + return found_frame, StackTraces.UNKNOWN @label found - return lkup + return found_frame, lkup end deprecate(m::Module, s::Symbol, flag=1) = ccall(:jl_deprecate_binding, Void, (Any, Any, Cint), m, s, flag) @@ -2984,6 +2994,193 @@ end @deprecate merge!(repo::LibGit2.GitRepo, args...; kwargs...) LibGit2.merge!(repo, args...; kwargs...) +# 24490 - warnings and messages +const log_info_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() +const log_warn_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() +const log_error_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() + +function _redirect(io::IO, log_to::Dict, sf::StackTraces.StackFrame) + (sf.linfo isa Core.MethodInstance) || return io + mod = sf.linfo.def + isa(mod, Method) && (mod = mod.module) + fun = sf.func + if haskey(log_to, (mod,fun)) + return log_to[(mod,fun)] + elseif haskey(log_to, (mod,nothing)) + return log_to[(mod,nothing)] + elseif haskey(log_to, (nothing,nothing)) + return log_to[(nothing,nothing)] + else + return io + end +end + +function _redirect(io::IO, log_to::Dict, fun::Symbol) + clos = string("#",fun,"#") + kw = string("kw##",fun) + local sf + break_next_frame = false + for trace in backtrace() + stack::Vector{StackFrame} = StackTraces.lookup(trace) + filter!(frame -> !frame.from_c, stack) + for frame in stack + (frame.linfo isa Core.MethodInstance) || continue + sf = frame + break_next_frame && (@goto skip) + mod = frame.linfo.def + isa(mod, Method) && (mod = mod.module) + mod === Base || continue + sff = string(frame.func) + if frame.func == fun || startswith(sff, clos) || startswith(sff, kw) + break_next_frame = true + end + end + end + @label skip + _redirect(io, log_to, sf) +end + +@inline function redirect(io::IO, log_to::Dict, arg::Union{Symbol,StackTraces.StackFrame}) + if isempty(log_to) + return io + else + if length(log_to)==1 && haskey(log_to,(nothing,nothing)) + return log_to[(nothing,nothing)] + else + return _redirect(io, log_to, arg) + end + end +end + +""" + logging(io [, m [, f]][; kind=:all]) + logging([; kind=:all]) + +Stream output of informational, warning, and/or error messages to `io`, +overriding what was otherwise specified. Optionally, divert stream only for +module `m`, or specifically function `f` within `m`. `kind` can be `:all` (the +default), `:info`, `:warn`, or `:error`. See `Base.log_{info,warn,error}_to` +for the current set of redirections. Call `logging` with no arguments (or just +the `kind`) to reset everything. +""" +function logging(io::IO, m::Union{Module,Void}=nothing, f::Union{Symbol,Void}=nothing; + kind::Symbol=:all) + depwarn("""`logging()` is deprecated, use `with_logger` instead to capture + messages from `Base`""", :logging) + (kind==:all || kind==:info) && (log_info_to[(m,f)] = io) + (kind==:all || kind==:warn) && (log_warn_to[(m,f)] = io) + (kind==:all || kind==:error) && (log_error_to[(m,f)] = io) + nothing +end + +function logging(; kind::Symbol=:all) + depwarn("""`logging()` is deprecated, use `with_logger` instead to capture + messages from `Base`""", :logging) + (kind==:all || kind==:info) && empty!(log_info_to) + (kind==:all || kind==:warn) && empty!(log_warn_to) + (kind==:all || kind==:error) && empty!(log_error_to) + nothing +end + +""" + info([io, ] msg..., [prefix="INFO: "]) + +Display an informational message. +Argument `msg` is a string describing the information to be displayed. +The `prefix` keyword argument can be used to override the default +prepending of `msg`. + +# Examples +```jldoctest +julia> info("hello world") +INFO: hello world + +julia> info("hello world"; prefix="MY INFO: ") +MY INFO: hello world +``` + +See also [`logging`](@ref). +""" +function info(io::IO, msg...; prefix="INFO: ") + depwarn("`info()` is deprecated, use `@info` instead.", :info) + buf = IOBuffer() + iob = redirect(IOContext(buf, io), log_info_to, :info) + print_with_color(info_color(), iob, prefix; bold = true) + println_with_color(info_color(), iob, chomp(string(msg...))) + print(io, String(take!(buf))) + return +end +info(msg...; prefix="INFO: ") = info(STDERR, msg..., prefix=prefix) + +# print a warning only once + +const have_warned = Set() + +warn_once(io::IO, msg...) = warn(io, msg..., once=true) +warn_once(msg...) = warn(STDERR, msg..., once=true) + +""" + warn([io, ] msg..., [prefix="WARNING: ", once=false, key=nothing, bt=nothing, filename=nothing, lineno::Int=0]) + +Display a warning. Argument `msg` is a string describing the warning to be +displayed. Set `once` to true and specify a `key` to only display `msg` the +first time `warn` is called. If `bt` is not `nothing` a backtrace is displayed. +If `filename` is not `nothing` both it and `lineno` are displayed. + +See also [`logging`](@ref). +""" +function warn(io::IO, msg...; + prefix="WARNING: ", once=false, key=nothing, bt=nothing, + filename=nothing, lineno::Int=0) + depwarn("`warn()` is deprecated, use `@warn` instead.", :warn) + str = chomp(string(msg...)) + if once + if key === nothing + key = str + end + (key in have_warned) && return + push!(have_warned, key) + end + buf = IOBuffer() + iob = redirect(IOContext(buf, io), log_warn_to, :warn) + print_with_color(warn_color(), iob, prefix; bold = true) + print_with_color(warn_color(), iob, str) + if bt !== nothing + show_backtrace(iob, bt) + end + if filename !== nothing + print(iob, "\nin expression starting at $filename:$lineno") + end + println(iob) + print(io, String(take!(buf))) + return +end + +""" + warn(msg) + +Display a warning. Argument `msg` is a string describing the warning to be displayed. + +# Examples +```jldoctest +julia> warn("Beep Beep") +WARNING: Beep Beep +``` +""" +warn(msg...; kw...) = warn(STDERR, msg...; kw...) + +warn(io::IO, err::Exception; prefix="ERROR: ", kw...) = + warn(io, sprint(showerror, err), prefix=prefix; kw...) + +warn(err::Exception; prefix="ERROR: ", kw...) = + warn(STDERR, err, prefix=prefix; kw...) + +info(io::IO, err::Exception; prefix="ERROR: ", kw...) = + info(io, sprint(showerror, err), prefix=prefix; kw...) + +info(err::Exception; prefix="ERROR: ", kw...) = + info(STDERR, err, prefix=prefix; kw...) + # issue #24019 @deprecate similar(a::AbstractDict) empty(a) @deprecate similar(a::AbstractDict, ::Type{Pair{K,V}}) where {K, V} empty(a, K, V) diff --git a/base/docs/Docs.jl b/base/docs/Docs.jl index 0d6a760a9af29..5e5aa4c33056a 100644 --- a/base/docs/Docs.jl +++ b/base/docs/Docs.jl @@ -236,7 +236,7 @@ function doc!(__module__::Module, b::Binding, str::DocStr, @nospecialize sig = U # We allow for docstrings to be updated, but print a warning since it is possible # that over-writing a docstring *may* have been accidental. The warning # is suppressed for symbols in Main, for interactive use (#23011). - __module__ == Main || warn("replacing docs for '$b :: $sig' in module '$(__module__)'.") + __module__ == Main || @warn "Replacing docs for `$b :: $sig` in module `$(__module__)`" else # The ordering of docstrings for each Binding is defined by the order in which they # are initially added. Replacing a specific docstring does not change it's ordering. diff --git a/base/docs/utils.jl b/base/docs/utils.jl index d4aadefd9430e..0422dae45c404 100644 --- a/base/docs/utils.jl +++ b/base/docs/utils.jl @@ -385,7 +385,7 @@ function docsearch(haystack::Array, needle) false end function docsearch(haystack, needle) - Base.warn_once("unable to search documentation of type $(typeof(haystack))") + @warn "Unable to search documentation of type $(typeof(haystack))" maxlog=1 false end diff --git a/base/error.jl b/base/error.jl index 3ec59e5aa7c23..9446b2c79b4d6 100644 --- a/base/error.jl +++ b/base/error.jl @@ -36,8 +36,6 @@ error(s::AbstractString) = throw(ErrorException(s)) error(msg...) Raise an `ErrorException` with the given message. - -See also [`logging`](@ref). """ function error(s::Vararg{Any,N}) where {N} @_noinline_meta diff --git a/base/exports.jl b/base/exports.jl index 2b3110f4ce225..27a4d5c022efb 100644 --- a/base/exports.jl +++ b/base/exports.jl @@ -769,6 +769,12 @@ export unescape_string, warn, +# logging frontend + @debug, + @info, + @warn, + @error, + # random numbers AbstractRNG, MersenneTwister, diff --git a/base/file.jl b/base/file.jl index bdd4027925c79..7678cabf0d4ef 100644 --- a/base/file.jl +++ b/base/file.jl @@ -565,7 +565,7 @@ function symlink(p::AbstractString, np::AbstractString) err = ccall(:jl_fs_symlink, Int32, (Cstring, Cstring, Cint), p, np, flags) @static if Sys.iswindows() if err < 0 && !isdir(p) - Base.warn_once("Note: on Windows, creating file symlinks requires Administrator privileges.") + @warn "On Windows, creating file symlinks requires Administrator privileges" maxlog=1 _group=:file end end uv_error("symlink",err) diff --git a/base/libgit2/gitcredential.jl b/base/libgit2/gitcredential.jl index 75da9c85f921b..09806ff6dedaf 100644 --- a/base/libgit2/gitcredential.jl +++ b/base/libgit2/gitcredential.jl @@ -237,8 +237,8 @@ function credential_helpers(cfg::GitConfig, cred::GitCredential) # credential helpers avoids potential issues with using the wrong credentials or # writing credentials to the wrong helper. if isempty(value) - Base.warn_once("Resetting the helper list is currently unsupported: " * - "ignoring all git credential helpers.") + @warn """Resetting the helper list is currently unsupported: + ignoring all git credential helpers""" maxlog=1 return GitCredentialHelper[] end diff --git a/base/libgit2/libgit2.jl b/base/libgit2/libgit2.jl index e58c00b226ab3..91ecc806b7e96 100644 --- a/base/libgit2/libgit2.jl +++ b/base/libgit2/libgit2.jl @@ -413,7 +413,7 @@ function branch!(repo::GitRepo, branch_name::AbstractString, set!(cfg, "branch.$branch_name.merge", name(Base.get(branch_ref))) end catch - warn("Please provide remote tracking for branch '$branch_name' in '$(path(repo))'") + @warn "Please provide remote tracking for branch '$branch_name' in '$(path(repo))'" end end diff --git a/base/libgit2/merge.jl b/base/libgit2/merge.jl index f7c5887a3f545..49da78409fdb1 100644 --- a/base/libgit2/merge.jl +++ b/base/libgit2/merge.jl @@ -146,7 +146,7 @@ function merge!(repo::GitRepo, anns::Vector{GitAnnotated}; Ptr{MergeOptions}, Ptr{CheckoutOptions}), repo.ptr, map(x->x.ptr, anns), anns_size, Ref(merge_opts), Ref(checkout_opts)) - info("Review and commit merged changes.") + @info "Review and commit merged changes" return true end @@ -209,7 +209,7 @@ function merge!(repo::GitRepo, anns::Vector{GitAnnotated}, fastforward::Bool; merge_result = if ffpref == Consts.MERGE_PREFERENCE_NONE if isset(ma, Cint(Consts.MERGE_ANALYSIS_FASTFORWARD)) if length(anns) > 1 - warn("Unable to perform Fast-Forward merge with mith multiple merge heads.") + @warn "Unable to perform Fast-Forward merge with mith multiple merge heads" false else ffmerge!(repo, anns[1]) @@ -222,13 +222,13 @@ function merge!(repo::GitRepo, anns::Vector{GitAnnotated}, fastforward::Bool; elseif ffpref == Consts.MERGE_PREFERENCE_FASTFORWARD_ONLY if isset(ma, Cint(Consts.MERGE_ANALYSIS_FASTFORWARD)) if length(anns) > 1 - warn("Unable to perform Fast-Forward merge with mith multiple merge heads.") + @warn "Unable to perform Fast-Forward merge with mith multiple merge heads" false else ffmerge!(repo, anns[1]) end else - warn("Cannot perform fast-forward merge.") + @warn "Cannot perform fast-forward merge" false end elseif ffpref == Consts.MERGE_PREFERENCE_NO_FASTFORWARD @@ -259,7 +259,6 @@ function merge_base(repo::GitRepo, one::AbstractString, two::AbstractString) moid_ptr, repo.ptr, oid1_ptr, oid2_ptr) moid_ptr[] catch e - #warn("Pkg:",path(repo),"=>",e.msg) GitHash() end return moid diff --git a/base/libgit2/types.jl b/base/libgit2/types.jl index 9ba668e0a41e6..a55676b953cc0 100644 --- a/base/libgit2/types.jl +++ b/base/libgit2/types.jl @@ -1086,7 +1086,7 @@ function with_warn(f::Function, ::Type{T}, args...) where T try with(f, obj) catch err - warn("$(string(T)) thrown exception: $err") + @warn "$(string(T)) thrown exception:" exception=err end end diff --git a/base/linalg/blas.jl b/base/linalg/blas.jl index fc797260fb1a2..6aa53b5b65907 100644 --- a/base/linalg/blas.jl +++ b/base/linalg/blas.jl @@ -125,13 +125,15 @@ function check() openblas64 = ismatch(r".*USE64BITINT.*", openblas_config) if Base.USE_BLAS64 != openblas64 if !openblas64 - println("ERROR: OpenBLAS was not built with 64bit integer support.") - println("You're seeing this error because Julia was built with USE_BLAS64=1") - println("Please rebuild Julia with USE_BLAS64=0") + @error """ + OpenBLAS was not built with 64bit integer support. + You're seeing this error because Julia was built with USE_BLAS64=1. + Please rebuild Julia with USE_BLAS64=0""" else - println("ERROR: Julia was not built with support for OpenBLAS with 64bit integer support") - println("You're seeing this error because Julia was built with USE_BLAS64=0") - println("Please rebuild Julia with USE_BLAS64=1") + @error """ + Julia was not built with support for OpenBLAS with 64bit integer support. + You're seeing this error because Julia was built with USE_BLAS64=0. + Please rebuild Julia with USE_BLAS64=1""" end println("Quitting.") quit() diff --git a/base/linalg/lapack.jl b/base/linalg/lapack.jl index 54a705caf18b6..d7874681bae5d 100644 --- a/base/linalg/lapack.jl +++ b/base/linalg/lapack.jl @@ -1059,7 +1059,7 @@ for (gesvx, elty) in ldb, X, n, rcond, ferr, berr, work, iwork, info) chklapackerror(info[]) if info[] == n + 1 - warn("matrix is singular to working precision") + @warn "Matrix is singular to working precision" else chknonsingular(info[]) end @@ -1128,7 +1128,7 @@ for (gesvx, elty, relty) in ldb, X, n, rcond, ferr, berr, work, rwork, info) chklapackerror(info[]) if info[] == n + 1 - warn("matrix is singular to working precision") + @warn "Matrix is singular to working precision" else chknonsingular(info[]) end @@ -5273,7 +5273,7 @@ for (bdsdc, elty) in if compq == 'N' lwork = 6*n elseif compq == 'P' - warn("COMPQ='P' is not tested") + @warn "COMPQ='P' is not tested" #TODO turn this into an actual LAPACK call #smlsiz=ilaenv(9, $elty==:Float64 ? 'dbdsqr' : 'sbdsqr', string(uplo, compq), n,n,n,n) smlsiz=100 #For now, completely overkill diff --git a/base/loading.jl b/base/loading.jl index f22cf952d4916..b1a4fa6732692 100644 --- a/base/loading.jl +++ b/base/loading.jl @@ -153,10 +153,10 @@ function _require_search_from_serialized(mod::Symbol, sourcepath::String) if isa(restored, ErrorException) && endswith(restored.msg, " uuid did not match cache file.") # can't use this cache due to a module uuid mismatch, # defer reporting error until after trying all of the possible matches - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Failed to load $path_to_try because $(restored.msg)") + @debug "Failed to load $path_to_try because $(restored.msg)" continue end - warn("Deserialization checks failed while attempting to load cache from $path_to_try.") + @warn "Deserialization checks failed while attempting to load cache from $path_to_try" throw(restored) else return restored @@ -165,11 +165,6 @@ function _require_search_from_serialized(mod::Symbol, sourcepath::String) return !isempty(paths) end -# this value is set by `require` based on whether JULIA_DEBUG_LOADING -# is presently defined as an environment variable -# and makes the logic in this file noisier about what it is doing and why -const DEBUG_LOADING = Ref(false) - # to synchronize multiple tasks trying to import/using something const package_locks = Dict{Symbol,Condition}() @@ -324,7 +319,7 @@ function register_root_module(key, m::Module) oldm = loaded_modules[key] if oldm !== m name = module_name(oldm) - warn("replacing module $name.") + @warn "Replacing module `$name`" end end loaded_modules[key] = m @@ -376,7 +371,6 @@ function _require(mod::Symbol) # and is not applied recursively to imported modules: old_track_dependencies = _track_dependencies[] _track_dependencies[] = false - DEBUG_LOADING[] = haskey(ENV, "JULIA_DEBUG_LOADING") # handle recursive calls to require loading = get(package_locks, mod, false) @@ -411,8 +405,8 @@ function _require(mod::Symbol) # but it was not handled by the precompile loader, complain for (concrete_mod, concrete_uuid) in _concrete_dependencies if mod === concrete_mod - warn("""Module $mod with uuid $concrete_uuid is missing from the cache. - This may mean module $mod does not support precompilation but is imported by a module that does.""") + @warn """Module $mod with uuid $concrete_uuid is missing from the cache. + This may mean module $mod does not support precompilation but is imported by a module that does.""" if JLOptions().incremental != 0 # during incremental precompilation, this should be fail-fast throw(PrecompilableError(false)) @@ -426,8 +420,7 @@ function _require(mod::Symbol) cachefile = compilecache(mod) m = _require_from_serialized(mod, cachefile) if isa(m, Exception) - warn("The call to compilecache failed to create a usable precompiled cache file for module $name. Got:") - warn(m, prefix="WARNING: ") + @warn "The call to compilecache failed to create a usable precompiled cache file for module $name" exception=m # fall-through, TODO: disable __precompile__(true) error so that the normal include will succeed else register_all(m) @@ -448,7 +441,8 @@ function _require(mod::Symbol) cachefile = compilecache(mod) m = _require_from_serialized(mod, cachefile) if isa(m, Exception) - warn(m, prefix="WARNING: ") + @warn """Module `$mod` declares `__precompile__(true)` but `require` failed + to create a usable precompiled cache file""" exception=m # TODO: disable __precompile__(true) error and do normal include instead of error error("Module $mod declares __precompile__(true) but require failed to create a usable precompiled cache file.") end @@ -621,12 +615,11 @@ function compilecache(name::String) end end # run the expression and cache the result - if isinteractive() || DEBUG_LOADING[] - if isfile(cachefile) - info("Recompiling stale cache file $cachefile for module $name.") - else - info("Precompiling module $name.") - end + verbosity = isinteractive() ? CoreLogging.Info : CoreLogging.Debug + if isfile(cachefile) + @logmsg verbosity "Recompiling stale cache file $cachefile for module $name" + else + @logmsg verbosity "Precompiling module $name" end if success(create_expr_cache(path, cachefile, concrete_deps)) # append checksum to the end of the .ji file: @@ -740,7 +733,7 @@ function stale_cachefile(modpath::String, cachefile::String) io = open(cachefile, "r") try if !isvalid_cache_header(io) - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile due to it containing an invalid cache header.") + @debug "Rejecting cache file $cachefile due to it containing an invalid cache header" return true # invalid cache file end modules, files, required_modules = parse_cache_header(io) @@ -756,7 +749,7 @@ function stale_cachefile(modpath::String, cachefile::String) name = string(mod) path = find_package(name) if path === nothing - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because dependency $name not found.") + @debug "Rejecting cache file $cachefile because dependency $name not found." return true # Won't be able to fullfill dependency end end @@ -770,14 +763,14 @@ function stale_cachefile(modpath::String, cachefile::String) if uuid === uuid_req return false # this is the file we want end - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because it provides the wrong uuid (got $uuid) for $mod (want $uuid_req).") + @debug "Rejecting cache file $cachefile because it provides the wrong uuid (got $uuid) for $mod (want $uuid_req)" return true # cachefile doesn't provide the required version of the dependency end end # now check if this file is fresh relative to its source files if !samefile(files[1][2], modpath) - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because it is for file $(files[1][2])) not file $modpath.") + @debug "Rejecting cache file $cachefile because it is for file $(files[1][2])) not file $modpath" return true # cache file was compiled from a different path end for (_, f, ftime_req) in files @@ -785,7 +778,7 @@ function stale_cachefile(modpath::String, cachefile::String) # Issue #20837: compensate for GlusterFS truncating mtimes to microseconds ftime = mtime(f) if ftime != ftime_req && ftime != floor(ftime_req) && ftime != trunc(ftime_req, 6) - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting stale cache file $cachefile (mtime $ftime_req) because file $f (mtime $ftime) has changed.") + @debug "Rejecting stale cache file $cachefile (mtime $ftime_req) because file $f (mtime $ftime) has changed" return true end end @@ -793,7 +786,7 @@ function stale_cachefile(modpath::String, cachefile::String) # finally, verify that the cache file has a valid checksum crc = _crc32c(seekstart(io), filesize(io)-4) if crc != ntoh(read(io, UInt32)) - DEBUG_LOADING[] && info("JL_DEBUG_LOADING: Rejecting cache file $cachefile because it has an invalid checksum.") + @debug "Rejecting cache file $cachefile because it has an invalid checksum" return true end diff --git a/base/logging.jl b/base/logging.jl new file mode 100644 index 0000000000000..eae786f5b76a2 --- /dev/null +++ b/base/logging.jl @@ -0,0 +1,503 @@ +module CoreLogging + +import Base: isless, +, -, convert, show + +export + AbstractLogger, + LogLevel, + NullLogger, + @debug, + @info, + @warn, + @error, + @logmsg, + with_logger, + current_logger, + global_logger, + disable_logging, + SimpleLogger + +#------------------------------------------------------------------------------- +# The AbstractLogger interface +""" +A logger controls how log records are filtered and dispatched. When a log +record is generated, the logger is the first piece of user configurable code +which gets to inspect the record and decide what to do with it. +""" +abstract type AbstractLogger ; end + +""" + handle_message(logger, level, message, _module, group, id, file, line; key1=val1, ...) + +Log a message to `logger` at `level`. The logical location at which the +message was generated is given by module `_module` and `group`; the source +location by `file` and `line`. `id` is an arbitrary unique `Symbol` to be used +as a key to identify the log statement when filtering. +""" +function handle_message end + +""" + shouldlog(logger, level, _module, group, id) + +Return true when `logger` accepts a message at `level`, generated for +`_module`, `group` and with unique log identifier `id`. +""" +shouldlog(logger, level, _module, group, id) = true + +""" + min_enabled_level(logger) + +Return the maximum disabled level for `logger` for early filtering. That is, +the log level below or equal to which all messages are filtered. +""" +min_enabled_level(logger) = Info + +""" + catch_exceptions(logger) + +Return true if the logger should catch exceptions which happen during log +record construction. By default, messages are caught + +By default all exceptions are caught to prevent log message generation from +crashing the program. This lets users confidently toggle little-used +functionality - such as debug logging - in a production system. + +If you want to use logging as an audit trail you should disable this for your +logger type. +""" +catch_exceptions(logger) = true + + +# The logger equivalent of /dev/null, for when a placeholder is needed +""" + NullLogger() + +Logger which disables all messages and produces no output - the logger +equivalent of /dev/null. +""" +struct NullLogger <: AbstractLogger; end + +min_enabled_level(::NullLogger) = AboveMaxLevel +shouldlog(::NullLogger, args...) = false +handle_message(::NullLogger, args...; kwargs...) = + error("Null logger handle_message() should not be called") + + +#------------------------------------------------------------------------------- +# Standard log levels +""" + LogLevel(level) + +Severity/verbosity of a log record. + +The log level provides a key against which potential log records may be +filtered, before any other work is done to construct the log record data +structure itself. +""" +struct LogLevel + level::Int32 +end + +LogLevel(level::LogLevel) = level + +isless(a::LogLevel, b::LogLevel) = isless(a.level, b.level) ++(level::LogLevel, inc) = LogLevel(level.level+inc) +-(level::LogLevel, inc) = LogLevel(level.level-inc) +convert(::Type{LogLevel}, level::Integer) = LogLevel(level) + +const BelowMinLevel = LogLevel(-1000001) +const Debug = LogLevel( -1000) +const Info = LogLevel( 0) +const Warn = LogLevel( 1000) +const Error = LogLevel( 2000) +const AboveMaxLevel = LogLevel( 1000001) + +function show(io::IO, level::LogLevel) + if level == BelowMinLevel print(io, "BelowMinLevel") + elseif level == Debug print(io, "Debug") + elseif level == Info print(io, "Info") + elseif level == Warn print(io, "Warn") + elseif level == Error print(io, "Error") + elseif level == AboveMaxLevel print(io, "AboveMaxLevel") + else print(io, "LogLevel($(level.level))") + end +end + + +#------------------------------------------------------------------------------- +# Logging macros + +_logmsg_docs = """ + @debug message [key=value | value ...] + @info message [key=value | value ...] + @warn message [key=value | value ...] + @error message [key=value | value ...] + + @logmsg level message [key=value | value ...] + +Create a log record with an informational `message`. For convenience, four +logging macros `@debug`, `@info`, `@warn` and `@error` are defined which log at +the standard severity levels `Debug`, `Info`, `Warn` and `Error`. `@logmsg` +allows `level` to be set programmatically to any `LogLevel` or custom log level +types. + +`message` should be an expression which evaluates to a string which is a human +readable description of the log event. By convention, this string will be +formatted as markdown when presented. + +The optional list of `key=value` pairs supports arbitrary user defined +metadata which will be passed through to the logging backend as part of the +log record. If only a `value` expression is supplied, a key representing the +expression will be generated using `Symbol`. For example, `x` becomes `x=x`, +and `foo(10)` becomes `Symbol("foo(10)")=foo(10)`. For splatting a list of +key value pairs, use the normal splatting syntax, `@info "blah" kws...`. + +There are some keys which allow automatically generated log data to be +overridden: + + * `_module=mod` can be used to specify a different originating module from + the source location of the message. + * `_group=symbol` can be used to override the message group (this is + normally derived from the base name of the source file). + * `_id=symbol` can be used to override the automatically generated unique + message identifier. This is useful if you need to very closely associate + messages generated on different source lines. + * `_file=string` and `_line=integer` can be used to override the apparent + source location of a log message. + +There's also some key value pairs which have conventional meaning: + + * `progress=fraction` should be used to indicate progress through an + algorithmic step named by `message`, it should be a value in the interval + [0,1], and would generally be used to drive a progress bar or meter. + * `maxlog=integer` should be used as a hint to the backend that the message + should be displayed no more than `maxlog` times. + * `exception=ex` should be used to transport an exception with a log message, + often used with `@error`. `AbstractLoggers` should assume that the + associated backtrace can be obtained from `catch_backtrace()`. If the log + message is emitted outside the catch block which generated `ex`, an + associated backtrace `bt` may be attached explicitly using + `exception=(ex,bt)`. + +# Examples + +``` +@debug "Verbose debugging information. Invisible by default" +@info "An informational message" +@warn "Something was odd. You should pay attention" +@error "A non fatal error occurred" + +x = 10 +@info "Some variables attached to the message" x a=42.0 + +@debug begin + sA = sum(A) + "sum(A) = \$sA is an expensive operation, evaluated only when `shouldlog` returns true" +end + +for i=1:10000 + @info "With the default backend, you will only see (i = \$i) ten times" maxlog=10 + @debug "Algorithm1" i progress=i/10000 +end +``` +""" + +# Get (module,filepath,line) for the location of the caller of a macro. +# Designed to be used from within the body of a macro. +macro _sourceinfo() + esc(quote + (__module__, + __source__.file == nothing ? "?" : String(__source__.file), + __source__.line) + end) +end + +macro logmsg(level, message, exs...) logmsg_code((@_sourceinfo)..., esc(level), message, exs...) end +macro debug(message, exs...) logmsg_code((@_sourceinfo)..., :Debug, message, exs...) end +macro info(message, exs...) logmsg_code((@_sourceinfo)..., :Info, message, exs...) end +macro warn(message, exs...) logmsg_code((@_sourceinfo)..., :Warn, message, exs...) end +macro error(message, exs...) logmsg_code((@_sourceinfo)..., :Error, message, exs...) end + +# Logging macros share documentation +@eval @doc $_logmsg_docs :(@logmsg) +@eval @doc $_logmsg_docs :(@debug) +@eval @doc $_logmsg_docs :(@info) +@eval @doc $_logmsg_docs :(@warn) +@eval @doc $_logmsg_docs :(@error) + +_log_record_ids = Set{Symbol}() +# Generate a unique, stable, short, human readable identifier for a logging +# statement. The idea here is to have a key against which log records can be +# filtered and otherwise manipulated. The key should uniquely identify the +# source location in the originating module, but should be stable across +# versions of the originating module, provided the log generating statement +# itself doesn't change. +function log_record_id(_module, level, message_ex) + modname = join(fullname(_module), "_") + # Use (1<<31) to fit well within an (arbitriraly chosen) eight hex digits, + # as we increment h to resolve any collisions. + h = hash(string(modname, level, message_ex)) % (1<<31) + while true + id = Symbol(modname, '_', hex(h, 8)) + # _log_record_ids is a registry of log record ids for use during + # compilation, to ensure uniqueness of ids. Note that this state will + # only persist during module compilation so it will be empty when a + # precompiled module is loaded. + if !(id in _log_record_ids) + push!(_log_record_ids, id) + return id + end + h += 1 + end +end + +# Generate code for logging macros +function logmsg_code(_module, file, line, level, message, exs...) + id = nothing + group = nothing + kwargs = Any[] + for ex in exs + if ex isa Expr && ex.head === :(=) && ex.args[1] isa Symbol + k,v = ex.args + if !(k isa Symbol) + throw(ArgumentError("Expected symbol for key in key value pair `$ex`")) + end + k = ex.args[1] + # Recognize several special keyword arguments + if k == :_id + # id may be overridden if you really want several log + # statements to share the same id (eg, several pertaining to + # the same progress step). + # + # TODO: Refine this - doing it as is, is probably a bad idea + # for consistency, and is hard to make unique between modules. + id = esc(v) + elseif k == :_module + _module = esc(v) + elseif k == :_line + line = esc(v) + elseif k == :_file + file = esc(v) + elseif k == :_group + group = esc(v) + else + # Copy across key value pairs for structured log records + push!(kwargs, Expr(:kw, k, esc(v))) + end + elseif ex isa Expr && ex.head === :... + # Keyword splatting + push!(kwargs, esc(ex)) + else + # Positional arguments - will be converted to key value pairs + # automatically. + push!(kwargs, Expr(:kw, Symbol(ex), esc(ex))) + end + end + # Note that it may be necessary to set `id` and `group` manually during bootstrap + id !== nothing || (id = Expr(:quote, log_record_id(_module, level, exs))) + group !== nothing || (group = Expr(:quote, Symbol(splitext(basename(file))[1]))) + quote + level = $level + std_level = convert(LogLevel, level) + if std_level >= _min_enabled_level[] + logstate = current_logstate() + if std_level >= logstate.min_enabled_level + logger = logstate.logger + _module = $_module + id = $id + group = $group + # Second chance at an early bail-out, based on arbitrary + # logger-specific logic. + if shouldlog(logger, level, _module, group, id) + # Bind log record generation into a closure, allowing us to + # defer creation of the records until after filtering. + create_msg = function cm(logger, level, _module, group, id, file, line) + msg = $(esc(message)) + handle_message(logger, level, msg, _module, group, id, file, line; $(kwargs...)) + end + file = $file + line = $line + dispatch_message(logger, level, _module, group, id, file, line, create_msg) + end + end + end + nothing + end +end + +# Call the log message creation function, and dispatch the result to `logger`. +# TODO: Consider some @nospecialize annotations here +# TODO: The `logger` is loaded from global state and inherently non-inferrable, +# so it might be nice to sever all back edges from `dispatch_message` to +# functions which call it. This function should always return `nothing`. +@noinline function dispatch_message(logger, level, _module, group, id, + filepath, line, create_msg) + try + create_msg(logger, level, _module, group, id, filepath, line) + catch err + if !catch_exceptions(logger) + rethrow(err) + end + # Try really hard to get the message to the logger, with + # progressively less information. + try + msg = "Exception while generating log record in module $_module at $filepath:$line" + handle_message(logger, Error, msg, _module, group, id, filepath, line; exception=err) + catch err2 + try + # Give up and write to STDERR, in three independent calls to + # increase the odds of it getting through. + print(STDERR, "Exception handling log message: ") + println(STDERR, err) + println(STDERR, " module=$_module file=$filepath line=$line") + println(STDERR, " Second exception: ", err2) + catch + end + end + end + nothing +end + +# Global log limiting mechanism for super fast but inflexible global log +# limiting. +const _min_enabled_level = Ref(Debug) + +# LogState - a concretely typed cache of data extracted from the logger, plus +# the logger itself. +struct LogState + min_enabled_level::LogLevel + logger::AbstractLogger +end + +LogState(logger) = LogState(LogLevel(min_enabled_level(logger)), logger) + +_global_logstate = LogState(NullLogger()) # See __init__ + +function current_logstate() + logstate = current_task().logstate + (logstate != nothing ? logstate : _global_logstate)::LogState +end + +function with_logstate(f::Function, logstate) + t = current_task() + old = t.logstate + try + t.logstate = logstate + f() + finally + t.logstate = old + end +end + + +#------------------------------------------------------------------------------- +# Control of the current logger and early log filtering + +""" + disable_logging(level) + +Disable all log messages at log levels equal to or less than `level`. This is +a *global* setting, intended to make debug logging extremely cheap when +disabled. +""" +function disable_logging(level::LogLevel) + _min_enabled_level[] = level + 1 +end + + +""" + global_logger() + +Return the global logger, used to receive messages when no specific logger +exists for the current task. + + global_logger(logger) + +Set the global logger to `logger`. +""" +global_logger() = _global_logstate.logger + +function global_logger(logger::AbstractLogger) + global _global_logstate = LogState(logger) + logger +end + +""" + with_logger(function, logger) + +Execute `function`, directing all log messages to `logger`. + +# Example + +```julia +function test(x) + @info "x = \$x" +end + +with_logger(logger) do + test(1) + test([1,2]) +end +``` +""" +with_logger(f::Function, logger::AbstractLogger) = with_logstate(f, LogState(logger)) + +""" + current_logger() + +Return the logger for the current task, or the global logger if none is +is attached to the task. +""" +current_logger() = current_logstate().logger + + +#------------------------------------------------------------------------------- +# SimpleLogger +""" + SimpleLogger(stream=STDERR, min_level=Info) + +Simplistic logger for logging all messages with level greater than or equal to +`min_level` to `stream`. +""" +struct SimpleLogger <: AbstractLogger + stream::IO + min_level::LogLevel + message_limits::Dict{Any,Int} +end +SimpleLogger(stream::IO=STDERR, level=Info) = SimpleLogger(stream, level, Dict{Any,Int}()) + +shouldlog(logger::SimpleLogger, level, _module, group, id) = + get(logger.message_limits, id, 1) > 0 + +min_enabled_level(logger::SimpleLogger) = logger.min_level + +function handle_message(logger::SimpleLogger, level, message, _module, group, id, + filepath, line; maxlog=nothing, kwargs...) + # TODO: Factor out more complex things here into a separate logger in + # stdlib: in particular maxlog support + colorization. + if maxlog != nothing && maxlog isa Integer + remaining = get!(logger.message_limits, id, maxlog) + logger.message_limits[id] = remaining - 1 + remaining > 0 || return + end + levelstr = string(level) + color = level < Info ? :blue : + level < Warn ? :cyan : + level < Error ? :yellow : :red + buf = IOBuffer() + print_with_color(color, buf, first(levelstr), "- ", bold=true) + msglines = split(string(message), '\n') + for i in 1:length(msglines)-1 + println(buf, msglines[i]) + print_with_color(color, buf, "| ", bold=true) + end + println(buf, msglines[end], " -", levelstr, ":", _module, ":", basename(filepath), ":", line) + for (key,val) in pairs(kwargs) + print_with_color(color, buf, "| ", bold=true) + println(buf, key, " = ", val) + end + write(logger.stream, take!(buf)) + nothing +end + +end # CoreLogging diff --git a/base/pkg/cache.jl b/base/pkg/cache.jl index 61127cf281bdf..2a398952503d7 100644 --- a/base/pkg/cache.jl +++ b/base/pkg/cache.jl @@ -40,7 +40,7 @@ function prefetch(pkg::AbstractString, url::AbstractString, sha1s::Vector) repo = if isdir(cache) LibGit2.GitRepo(cache) # open repo, free it at the end else - info("Cloning cache of $pkg from $normalized_url") + @info "Cloning cache of $pkg from $normalized_url" try # clone repo, free it at the end LibGit2.clone(normalized_url, cache, isbare = true, remote_cb = LibGit2.mirror_cb()) @@ -60,7 +60,7 @@ function prefetch(pkg::AbstractString, url::AbstractString, sha1s::Vector) LibGit2.set_remote_url(repo, "origin", normalized_url) in_cache = BitVector(map(sha1->LibGit2.iscommit(sha1, repo), sha1s)) if !all(in_cache) - info("Updating cache of $pkg...") + @info "Updating cache of $pkg..." LibGit2.fetch(repo) in_cache = BitVector(map(sha1->LibGit2.iscommit(sha1, repo), sha1s)) end diff --git a/base/pkg/dir.jl b/base/pkg/dir.jl index 4bcd8fcef7836..98835bcda340e 100644 --- a/base/pkg/dir.jl +++ b/base/pkg/dir.jl @@ -39,10 +39,10 @@ end function init(meta::AbstractString=DEFAULT_META, branch::AbstractString=META_BRANCH) dir = path() - info("Initializing package repository $dir") + @info "Initializing package repository $dir" metadata_dir = joinpath(dir, "METADATA") if isdir(metadata_dir) - info("Package directory $dir is already initialized.") + @info "Package directory $dir is already initialized" LibGit2.set_remote_url(metadata_dir, "origin", meta) return end @@ -51,7 +51,7 @@ function init(meta::AbstractString=DEFAULT_META, branch::AbstractString=META_BRA mkpath(dir) temp_dir = mktempdir(dir) Base.cd(temp_dir) do - info("Cloning METADATA from $meta") + @info "Cloning METADATA from $meta" with(LibGit2.clone(meta, "METADATA", branch = branch)) do metadata_repo LibGit2.set_remote_url(metadata_repo, "origin", meta) end diff --git a/base/pkg/entry.jl b/base/pkg/entry.jl index 6f6f5482e2752..c4dbfc7a616ad 100644 --- a/base/pkg/entry.jl +++ b/base/pkg/entry.jl @@ -28,7 +28,7 @@ function edit(f::Function, pkg::AbstractString, args...) reqsʹ = Reqs.parse(rʹ) reqsʹ != reqs && resolve(reqsʹ,avail) Reqs.write("REQUIRE",rʹ) - info("Package database updated") + @info "Package database updated" return true end @@ -40,8 +40,8 @@ function edit() reqs = Reqs.parse("REQUIRE") run(`$editor REQUIRE`) reqsʹ = Reqs.parse("REQUIRE") - reqs == reqsʹ && return info("Nothing to be done") - info("Computing changes...") + reqs == reqsʹ && return @info "Nothing to be done" + @info "Computing changes..." resolve(reqsʹ) end @@ -50,7 +50,7 @@ function add(pkg::AbstractString, vers::VersionSet) @sync begin @async if !edit(Reqs.add,pkg,vers) ispath(pkg) || throw(PkgError("unknown package $pkg")) - info("Package $pkg is already installed") + @info "Package $pkg is already installed" end branch = Dir.getmetabranch() outdated = with(GitRepo, "METADATA") do repo @@ -70,16 +70,18 @@ function add(pkg::AbstractString, vers::VersionSet) end if outdated != :no is = outdated == :yes ? "is" : "might be" - info("METADATA $is out-of-date — you may not have the latest version of $pkg") - info("Use `Pkg.update()` to get the latest versions of your packages") + @info """ + METADATA $is out-of-date — you may not have the latest version of $pkg + Use `Pkg.update()` to get the latest versions of your packages + """ end end add(pkg::AbstractString, vers::VersionNumber...) = add(pkg,VersionSet(vers...)) function rm(pkg::AbstractString) edit(Reqs.rm,pkg) && return - ispath(pkg) || return info("Package $pkg is not installed") - info("Removing $pkg (unregistered)") + ispath(pkg) || return @info "Package $pkg is not installed" + @info "Removing $pkg (unregistered)" Write.remove(pkg) end @@ -188,7 +190,7 @@ function status(io::IO, pkg::AbstractString, msg::AbstractString) end function clone(url::AbstractString, pkg::AbstractString) - info("Cloning $pkg from $url") + @info "Cloning $pkg from $url" ispath(pkg) && throw(PkgError("$pkg already exists")) try LibGit2.with(LibGit2.clone(url, pkg)) do repo @@ -198,7 +200,7 @@ function clone(url::AbstractString, pkg::AbstractString) isdir(pkg) && Base.rm(pkg, recursive=true) rethrow(err) end - info("Computing changes...") + @info "Computing changes..." if !edit(Reqs.add, pkg) isempty(Reqs.parse("$pkg/REQUIRE")) && return resolve() @@ -221,14 +223,14 @@ clone(url_or_pkg::AbstractString) = clone(url_and_pkg(url_or_pkg)...) function checkout(pkg::AbstractString, branch::AbstractString, do_merge::Bool, do_pull::Bool) ispath(pkg,".git") || throw(PkgError("$pkg is not a git repo")) - info("Checking out $pkg $branch...") + @info "Checking out $pkg $branch..." with(GitRepo, pkg) do r LibGit2.transact(r) do repo LibGit2.isdirty(repo) && throw(PkgError("$pkg is dirty, bailing")) LibGit2.branch!(repo, branch, track=LibGit2.Consts.REMOTE_ORIGIN) do_merge && LibGit2.merge!(repo, fastforward=true) # merge changes if do_pull - info("Pulling $pkg latest $branch...") + @info "Pulling $pkg latest $branch..." LibGit2.fetch(repo) LibGit2.merge!(repo, fastforward=true) end @@ -244,7 +246,7 @@ function free(pkg::AbstractString) isempty(avail) && throw(PkgError("$pkg cannot be freed – not a registered package")) with(GitRepo, pkg) do repo LibGit2.isdirty(repo) && throw(PkgError("$pkg cannot be freed – repo is dirty")) - info("Freeing $pkg") + @info "Freeing $pkg" vers = sort!(collect(keys(avail)), rev=true) while true for ver in vers @@ -271,7 +273,7 @@ function free(pkgs) isempty(avail) && throw(PkgError("$pkg cannot be freed – not a registered package")) with(GitRepo, pkg) do repo LibGit2.isdirty(repo) && throw(PkgError("$pkg cannot be freed – repo is dirty")) - info("Freeing $pkg") + @info "Freeing $pkg" vers = sort!(collect(keys(avail)), rev=true) for ver in vers sha1 = avail[ver].sha1 @@ -304,7 +306,7 @@ function pin(pkg::AbstractString, head::AbstractString) # note: changing the following naming scheme requires a corresponding change in Read.ispinned() branch = "pinned.$(string(id)[1:8]).tmp" if LibGit2.isattached(repo) && LibGit2.branch(repo) == branch - info("Package $pkg is already pinned" * (isempty(head) ? "" : " to the selected commit")) + @info "Package $pkg is already pinned" * (isempty(head) ? "" : " to the selected commit") should_resolve = false return end @@ -315,9 +317,9 @@ function pin(pkg::AbstractString, head::AbstractString) throw(PkgError("Package $pkg: existing branch $branch has " * "been edited and doesn't correspond to its original commit")) end - info("Package $pkg: checking out existing branch $branch") + @info "Package $pkg: checking out existing branch $branch" else - info("Creating $pkg branch $branch") + @info "Creating $pkg branch $branch" ref = Nullable(LibGit2.create_branch(repo, branch, commit)) end @@ -349,7 +351,7 @@ function pin(pkg::AbstractString, ver::VersionNumber) end function update(branch::AbstractString, upkgs::Set{String}) - info("Updating METADATA...") + @info "Updating METADATA..." with(GitRepo, "METADATA") do repo try with(LibGit2.head(repo)) do h @@ -418,9 +420,9 @@ function update(branch::AbstractString, upkgs::Set{String}) with(GitRepo, pkg) do repo if LibGit2.isattached(repo) if LibGit2.isdirty(repo) - warn("Package $pkg: skipping update (dirty)...") + @warn "Package $pkg: skipping update (dirty)..." elseif Read.ispinned(repo) - info("Package $pkg: skipping update (pinned)...") + @info "Package $pkg: skipping update (pinned)..." else prev_sha = string(LibGit2.head_oid(repo)) success = true @@ -436,8 +438,8 @@ function update(branch::AbstractString, upkgs::Set{String}) if success post_sha = string(LibGit2.head_oid(repo)) branch = LibGit2.branch(repo) - info("Updating $pkg $branch...", - prev_sha != post_sha ? " $(prev_sha[1:8]) → $(post_sha[1:8])" : "") + @info "Updating $pkg $branch..." * (prev_sha != post_sha ? + " $(prev_sha[1:8]) → $(post_sha[1:8])" : "") end end end @@ -455,7 +457,7 @@ function update(branch::AbstractString, upkgs::Set{String}) finally Base.securezero!(creds) end - info("Computing changes...") + @info "Computing changes..." resolve(reqs, avail, instd, fixed, free, upkgs) # Don't use instd here since it may have changed updatehook(sort!(collect(keys(installed())))) @@ -505,7 +507,7 @@ function resolve( # compare what is installed with what should be changes = Query.diff(have, want, avail, fixed) - isempty(changes) && return info("No packages to install, update or remove") + isempty(changes) && return @info "No packages to install, update or remove" # prefetch phase isolates network activity, nothing to roll back missing = [] @@ -531,14 +533,14 @@ function resolve( try for (pkg,(ver1,ver2)) in changes if ver1 === nothing - info("Installing $pkg v$ver2") + @info "Installing $pkg v$ver2" Write.install(pkg, Read.sha1(pkg,ver2)) elseif ver2 === nothing - info("Removing $pkg v$ver1") + @info "Removing $pkg v$ver1" Write.remove(pkg) else up = ver1 <= ver2 ? "Up" : "Down" - info("$(up)grading $pkg: v$ver1 => v$ver2") + @info "$(up)grading $pkg: v$ver1 => v$ver2" Write.update(pkg, Read.sha1(pkg,ver2)) pkgsym = Symbol(pkg) if Base.root_module_exists(pkgsym) @@ -550,36 +552,26 @@ function resolve( catch err for (pkg,(ver1,ver2)) in reverse!(changed) if ver1 === nothing - info("Rolling back install of $pkg") + @info "Rolling back install of $pkg" @recover Write.remove(pkg) elseif ver2 === nothing - info("Rolling back deleted $pkg to v$ver1") + @info "Rolling back deleted $pkg to v$ver1" @recover Write.install(pkg, Read.sha1(pkg,ver1)) else - info("Rolling back $pkg from v$ver2 to v$ver1") + @info "Rolling back $pkg from v$ver2 to v$ver1" @recover Write.update(pkg, Read.sha1(pkg,ver1)) end end rethrow(err) end if !isempty(imported) - warn(join(["The following packages have been updated but were already imported:", - imported..., "Restart Julia to use the updated versions."], "\n")) + @warn join(["The following packages have been updated but were already imported:", + imported..., "Restart Julia to use the updated versions."], "\n") end # re/build all updated/installed packages build(map(x->x[1], filter(x -> x[2][2] !== nothing, changes))) end -function warnbanner(msg...; label="[ WARNING ]", prefix="") - cols = Base.displaysize(STDERR)[2] - str = rpad(lpad(label, div(cols+Base.Unicode.textwidth(label), 2), "="), cols, "=") - warn(prefix="", str) - println(STDERR) - warn(prefix=prefix, msg...) - println(STDERR) - warn(prefix="", "="^cols) -end - function build(pkg::AbstractString, build_file::AbstractString, errfile::AbstractString) # To isolate the build from the running Julia process, we execute each build.jl file in # a separate process. Errors are serialized to errfile for later reporting. @@ -595,12 +587,15 @@ function build(pkg::AbstractString, build_file::AbstractString, errfile::Abstrac open("$(escape_string(errfile))", "a") do f pkg, build_file = "$pkg", "$(escape_string(build_file))" try - info("Building \$pkg") + @info "Building \$pkg" cd(dirname(build_file)) do evalfile(build_file) end catch err - Base.Pkg.Entry.warnbanner(err, label="[ ERROR: \$pkg ]") + @error \""" + ------------------------------------------------------------ + # Build failed for \$pkg + \""" exception=err serialize(f, pkg) serialize(f, err) end @@ -651,14 +646,16 @@ function build(pkgs::Vector) errs = Dict() build!(pkgs,errs) isempty(errs) && return - println(STDERR) - warnbanner(label="[ BUILD ERRORS ]", """ - WARNING: $(join(keys(errs),", "," and ")) had build errors. + @warn """ + ------------------------------------------------------------ + # Build error summary - - packages with build errors remain installed in $(pwd()) - - build the package(s) and all dependencies with `Pkg.build("$(join(keys(errs),"\", \""))")` - - build a single package by running its `deps/build.jl` script - """) + $(join(keys(errs),", "," and ")) had build errors. + + - packages with build errors remain installed in $(pwd()) + - build the package(s) and all dependencies with `Pkg.build("$(join(keys(errs),"\", \""))")` + - build a single package by running its `deps/build.jl` script + """ end build() = build(sort!(collect(keys(installed())))) @@ -668,11 +665,14 @@ function updatehook!(pkgs::Vector, errs::Dict, seen::Set=Set()) updatehook!(Read.requires_list(pkg),errs,push!(seen,pkg)) path = abspath(pkg,"deps","update.jl") isfile(path) || continue - info("Running update script for $pkg") + @info "Running update script for $pkg" cd(dirname(path)) do try evalfile(path) catch err - warnbanner(err, label="[ ERROR: $pkg ]") + @error """ + ------------------------------------------------------------ + # Update hook failed for $pkg + """ exception=err errs[pkg] = err end end @@ -684,12 +684,15 @@ function updatehook(pkgs::Vector) updatehook!(pkgs,errs) isempty(errs) && return println(STDERR) - warnbanner(label="[ UPDATE ERRORS ]", """ - WARNING: $(join(keys(errs),", "," and ")) had update errors. + @warn """ + ------------------------------------------------------------ + # Update hook summary - - Unrelated packages are unaffected - - To retry, run Pkg.update() again - """) + $(join(keys(errs),", "," and ")) had update errors. + + - Unrelated packages are unaffected + - To retry, run Pkg.update() again + """ end function test!(pkg::AbstractString, @@ -700,7 +703,7 @@ function test!(pkg::AbstractString, if isfile(reqs_path) tests_require = Reqs.parse(reqs_path) if (!isempty(tests_require)) - info("Computing test dependencies for $pkg...") + @info "Computing test dependencies for $pkg..." resolve(merge(Reqs.parse("REQUIRE"), tests_require)) end end @@ -710,7 +713,7 @@ function test!(pkg::AbstractString, elseif !isfile(test_path) push!(notests, pkg) else - info("Testing $pkg") + @info "Testing $pkg" cd(dirname(test_path)) do try cmd = ``` @@ -724,9 +727,12 @@ function test!(pkg::AbstractString, $test_path ``` run(cmd) - info("$pkg tests passed") + @info "$pkg tests passed" catch err - warnbanner(err, label="[ ERROR: $pkg ]") + @error """ + ------------------------------------------------------------ + # Testing failed for $pkg + """ exception=err push!(errs,pkg) end end diff --git a/base/pkg/query.jl b/base/pkg/query.jl index 95568c817a376..efc0e5dc6a559 100644 --- a/base/pkg/query.jl +++ b/base/pkg/query.jl @@ -23,10 +23,10 @@ function check_fixed(reqs::Requires, fix::Dict{String,Fixed}, avail::Dict) haskey(avail, p2) || haskey(fix, p2) || throw(PkgError("unknown package $p2 required by $p1")) end satisfies(p1, f1.version, reqs) || - warn("$p1 is fixed at $(f1.version) conflicting with top-level requirement: $(reqs[p1])") + @warn "$p1 is fixed at $(f1.version) conflicting with top-level requirement: $(reqs[p1])" for (p2,f2) in fix satisfies(p1, f1.version, f2.requires) || - warn("$p1 is fixed at $(f1.version) conflicting with requirement for $p2: $(f2.requires[p1])") + @warn "$p1 is fixed at $(f1.version) conflicting with requirement for $p2: $(f2.requires[p1])" end end end @@ -164,14 +164,14 @@ function check_partial_updates(reqs::Requires, for p in upkgs if !haskey(want, p) if !haskey(fixed, p) - warn("Something went wrong with the update of package $p, please submit a bug report") + @warn "Something went wrong with the update of package $p, please submit a bug report" continue end v = fixed[p].version else v = want[p] if haskey(fixed, p) && v != fixed[p].version - warn("Something went wrong with the update of package $p, please submit a bug report") + @warn "Something went wrong with the update of package $p, please submit a bug report" continue end end @@ -200,17 +200,18 @@ function check_partial_updates(reqs::Requires, # Determine if the update of `p` is prevented by it being fixed (e.g. it's dirty, or pinned...) isfixed = haskey(fixed, p) - msg = "Package $p was set to version $v, but a higher version $(vers[end]) exists.\n" - if isfixed - msg *= " The package is fixed. You can try using `Pkg.free(\"$p\")` to update it." - elseif blocking_reqs - msg *= " The update is prevented by explicit requirements constraints. Edit your REQUIRE file to change this." - elseif !isempty(blocking_parents) - msg *= string(" To install the latest version, you could try updating these packages as well: ", join(blocking_parents, ", ", " and "), ".") - else - msg *= " To install the latest version, you could try doing a full update with `Pkg.update()`." + @info begin + "Package $p was set to version $v, but a higher version $(vers[end]) exists.\n" * + if isfixed + "The package is fixed. You can try using `Pkg.free(\"$p\")` to update it." + elseif blocking_reqs + "The update is prevented by explicit requirements constraints. Edit your REQUIRE file to change this." + elseif !isempty(blocking_parents) + string("To install the latest version, you could try updating these packages as well: ", join(blocking_parents, ", ", " and "), ".") + else + "To install the latest version, you could try doing a full update with `Pkg.update()`." + end end - info(msg) end end diff --git a/base/pkg/read.jl b/base/pkg/read.jl index 23945d4330210..804e1d4c4f346 100644 --- a/base/pkg/read.jl +++ b/base/pkg/read.jl @@ -93,7 +93,8 @@ function isfixed(pkg::AbstractString, prepo::LibGit2.GitRepo, avail::Dict=availa break end else - Base.warn_once("unknown $pkg commit $(info.sha1[1:8]), metadata may be ahead of package cache") + @warn """Unknown $pkg commit $(info.sha1[1:8]), metadata may be + ahead of package cache""" maxlog=1 end end finally @@ -154,7 +155,8 @@ function installed_version(pkg::AbstractString, prepo::LibGit2.GitRepo, avail::D elseif LibGit2.iscommit(sha1, prepo) LibGit2.merge_base(prepo, head, sha1) else - Base.warn_once("unknown $pkg commit $(sha1[1:8]), metadata may be ahead of package cache") + @warn """Unknown $pkg commit $(sha1[1:8]), metadata may be ahead + of package cache""" maxlog=1 continue end string(base) == sha1 && push!(ancestors,ver) @@ -164,7 +166,7 @@ function installed_version(pkg::AbstractString, prepo::LibGit2.GitRepo, avail::D cache_has_head && LibGit2.close(crepo) end both = sort!(intersect(ancestors,descendants)) - isempty(both) || warn("$pkg: some versions are both ancestors and descendants of head: $both") + isempty(both) || @warn "$pkg: some versions are both ancestors and descendants of head: $both" if !isempty(descendants) v = minimum(descendants) return VersionNumber(v.major, v.minor, v.patch, ("",), ()) diff --git a/base/pkg/resolve.jl b/base/pkg/resolve.jl index a0743da593a9e..f6c9e9e691a91 100644 --- a/base/pkg/resolve.jl +++ b/base/pkg/resolve.jl @@ -44,7 +44,7 @@ function resolve(reqs::Requires, deps::Dict{String,Dict{VersionNumber,Available} environment variable) """ end - ## info("ERROR MESSAGE:\n" * msg) + ## @info "ERROR MESSAGE:\n" * msg throw(PkgError(msg)) end @@ -114,7 +114,7 @@ function sanity_check(deps::Dict{String,Dict{VersionNumber,Available}}, sub_deps = Query.prune_dependencies(sub_reqs, sub_deps, bktrc) catch err isa(err, PkgError) || rethrow(err) - ## info("ERROR MESSAGE:\n" * err.msg) + ## @info "ERROR MESSAGE:\n" * err.msg for vneq in eq_classes[p][vn] push!(problematic, (p, vneq, "")) end diff --git a/base/pkg/resolve/interface.jl b/base/pkg/resolve/interface.jl index f0cb293b2d838..25cf8f2774858 100644 --- a/base/pkg/resolve/interface.jl +++ b/base/pkg/resolve/interface.jl @@ -321,7 +321,7 @@ function enforce_optimality!(sol::Vector{Int}, interface::Interface) end viol && continue # So the solution is non-optimal: we bump it manually - #warn("nonoptimal solution for package $(interface.pkgs[p0]): sol=$s0") + #@debug "Nonoptimal solution for package `$(interface.pkgs[p0])`: sol=$s0" sol[p0] += 1 restart = true end diff --git a/base/process.jl b/base/process.jl index fc0b499f11ae4..acf983d8075cf 100644 --- a/base/process.jl +++ b/base/process.jl @@ -139,7 +139,7 @@ struct FileRedirect append::Bool function FileRedirect(filename, append) if Unicode.lowercase(filename) == (@static Sys.iswindows() ? "nul" : "/dev/null") - warn_once("for portability use DevNull instead of a file redirect") + @warn "For portability use DevNull instead of a file redirect" maxlog=1 end new(filename, append) end diff --git a/base/repl/LineEdit.jl b/base/repl/LineEdit.jl index deda700e72e80..c3eb56788e312 100644 --- a/base/repl/LineEdit.jl +++ b/base/repl/LineEdit.jl @@ -2321,8 +2321,7 @@ function prompt!(term::TextTerminal, prompt::ModalInterface, s::MIState = init_s try status = fcn(s, kdata) catch e - bt = catch_backtrace() - warn(e, bt = bt, prefix = "ERROR (in the keymap): ") + @error "Error in the keymap" exception=e # try to cleanup and get `s` back to its original state before returning transition(s, :reset) transition(s, old_state) diff --git a/base/repl/REPL.jl b/base/repl/REPL.jl index c22010c168503..b72ae82ba1f99 100644 --- a/base/repl/REPL.jl +++ b/base/repl/REPL.jl @@ -843,7 +843,7 @@ function setup_interface( catch e print_response(repl, e, catch_backtrace(), true, Base.have_color) println(outstream(repl)) - info("Disabling history file for this session.") + @info "Disabling history file for this session" repl.history_file = false end end diff --git a/base/replutil.jl b/base/replutil.jl index afaef1312c5df..cf8490ed3ef72 100644 --- a/base/replutil.jl +++ b/base/replutil.jl @@ -413,8 +413,8 @@ function showerror(io::IO, ex::MethodError) end try show_method_candidates(io, ex, kwargs) - catch - warn(io, "Error showing method candidates, aborted") + catch ex + @error "Error showing method candidates, aborted" exception=ex end end diff --git a/base/sysimg.jl b/base/sysimg.jl index de2e4f2de9342..fe9676f4f41f9 100644 --- a/base/sysimg.jl +++ b/base/sysimg.jl @@ -231,6 +231,10 @@ include("regex.jl") include("show.jl") include("arrayshow.jl") +# Logging +include("logging.jl") +using .CoreLogging + # multidimensional arrays include("cartesian.jl") using .Cartesian @@ -454,6 +458,7 @@ isdefined(Core, :Inference) && Docs.loaddocs(Core.Inference.CoreDocs.DOCS) function __init__() # Base library init reinit_stdio() + global_logger(SimpleLogger(STDERR)) Multimedia.reinit_displays() # since Multimedia.displays uses STDOUT as fallback early_init() init_load_path() @@ -476,6 +481,7 @@ Base.require(:Dates) Base.require(:DelimitedFiles) Base.require(:FileWatching) Base.require(:IterativeEigenSolvers) +Base.require(:Logging) Base.require(:Mmap) Base.require(:Profile) Base.require(:SharedArrays) diff --git a/base/util.jl b/base/util.jl index 35e89b9ae2645..9a600fb6506c7 100644 --- a/base/util.jl +++ b/base/util.jl @@ -347,188 +347,6 @@ println_with_color(color::Union{Int, Symbol}, io::IO, msg...; bold::Bool = false println_with_color(color::Union{Int, Symbol}, msg...; bold::Bool = false) = println_with_color(color, STDOUT, msg...; bold = bold) -## warnings and messages ## - -const log_info_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() -const log_warn_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() -const log_error_to = Dict{Tuple{Union{Module,Void},Union{Symbol,Void}},IO}() - -function _redirect(io::IO, log_to::Dict, sf::StackTraces.StackFrame) - (sf.linfo isa Core.MethodInstance) || return io - mod = sf.linfo.def - isa(mod, Method) && (mod = mod.module) - fun = sf.func - if haskey(log_to, (mod,fun)) - return log_to[(mod,fun)] - elseif haskey(log_to, (mod,nothing)) - return log_to[(mod,nothing)] - elseif haskey(log_to, (nothing,nothing)) - return log_to[(nothing,nothing)] - else - return io - end -end - -function _redirect(io::IO, log_to::Dict, fun::Symbol) - clos = string("#",fun,"#") - kw = string("kw##",fun) - local sf - break_next_frame = false - for trace in backtrace() - stack::Vector{StackFrame} = StackTraces.lookup(trace) - filter!(frame -> !frame.from_c, stack) - for frame in stack - (frame.linfo isa Core.MethodInstance) || continue - sf = frame - break_next_frame && (@goto skip) - mod = frame.linfo.def - isa(mod, Method) && (mod = mod.module) - mod === Base || continue - sff = string(frame.func) - if frame.func == fun || startswith(sff, clos) || startswith(sff, kw) - break_next_frame = true - end - end - end - @label skip - _redirect(io, log_to, sf) -end - -@inline function redirect(io::IO, log_to::Dict, arg::Union{Symbol,StackTraces.StackFrame}) - if isempty(log_to) - return io - else - if length(log_to)==1 && haskey(log_to,(nothing,nothing)) - return log_to[(nothing,nothing)] - else - return _redirect(io, log_to, arg) - end - end -end - -""" - logging(io [, m [, f]][; kind=:all]) - logging([; kind=:all]) - -Stream output of informational, warning, and/or error messages to `io`, -overriding what was otherwise specified. Optionally, divert stream only for -module `m`, or specifically function `f` within `m`. `kind` can be `:all` (the -default), `:info`, `:warn`, or `:error`. See `Base.log_{info,warn,error}_to` -for the current set of redirections. Call `logging` with no arguments (or just -the `kind`) to reset everything. -""" -function logging(io::IO, m::Union{Module,Void}=nothing, f::Union{Symbol,Void}=nothing; - kind::Symbol=:all) - (kind==:all || kind==:info) && (log_info_to[(m,f)] = io) - (kind==:all || kind==:warn) && (log_warn_to[(m,f)] = io) - (kind==:all || kind==:error) && (log_error_to[(m,f)] = io) - nothing -end - -function logging(; kind::Symbol=:all) - (kind==:all || kind==:info) && empty!(log_info_to) - (kind==:all || kind==:warn) && empty!(log_warn_to) - (kind==:all || kind==:error) && empty!(log_error_to) - nothing -end - -""" - info([io, ] msg..., [prefix="INFO: "]) - -Display an informational message. -Argument `msg` is a string describing the information to be displayed. -The `prefix` keyword argument can be used to override the default -prepending of `msg`. - -# Examples -```jldoctest -julia> info("hello world") -INFO: hello world - -julia> info("hello world"; prefix="MY INFO: ") -MY INFO: hello world -``` - -See also [`logging`](@ref). -""" -function info(io::IO, msg...; prefix="INFO: ") - buf = IOBuffer() - iob = redirect(IOContext(buf, io), log_info_to, :info) - print_with_color(info_color(), iob, prefix; bold = true) - println_with_color(info_color(), iob, chomp(string(msg...))) - print(io, String(take!(buf))) - return -end -info(msg...; prefix="INFO: ") = info(STDERR, msg..., prefix=prefix) - -# print a warning only once - -const have_warned = Set() - -warn_once(io::IO, msg...) = warn(io, msg..., once=true) -warn_once(msg...) = warn(STDERR, msg..., once=true) - -""" - warn([io, ] msg..., [prefix="WARNING: ", once=false, key=nothing, bt=nothing, filename=nothing, lineno::Int=0]) - -Display a warning. Argument `msg` is a string describing the warning to be -displayed. Set `once` to true and specify a `key` to only display `msg` the -first time `warn` is called. If `bt` is not `nothing` a backtrace is displayed. -If `filename` is not `nothing` both it and `lineno` are displayed. - -See also [`logging`](@ref). -""" -function warn(io::IO, msg...; - prefix="WARNING: ", once=false, key=nothing, bt=nothing, - filename=nothing, lineno::Int=0) - str = chomp(string(msg...)) - if once - if key === nothing - key = str - end - (key in have_warned) && return - push!(have_warned, key) - end - buf = IOBuffer() - iob = redirect(IOContext(buf, io), log_warn_to, :warn) - print_with_color(warn_color(), iob, prefix; bold = true) - print_with_color(warn_color(), iob, str) - if bt !== nothing - show_backtrace(iob, bt) - end - if filename !== nothing - print(iob, "\nin expression starting at $filename:$lineno") - end - println(iob) - print(io, String(take!(buf))) - return -end - -""" - warn(msg) - -Display a warning. Argument `msg` is a string describing the warning to be displayed. - -# Examples -```jldoctest -julia> warn("Beep Beep") -WARNING: Beep Beep -``` -""" -warn(msg...; kw...) = warn(STDERR, msg...; kw...) - -warn(io::IO, err::Exception; prefix="ERROR: ", kw...) = - warn(io, sprint(showerror, err), prefix=prefix; kw...) - -warn(err::Exception; prefix="ERROR: ", kw...) = - warn(STDERR, err, prefix=prefix; kw...) - -info(io::IO, err::Exception; prefix="ERROR: ", kw...) = - info(io, sprint(showerror, err), prefix=prefix; kw...) - -info(err::Exception; prefix="ERROR: ", kw...) = - info(STDERR, err, prefix=prefix; kw...) - function julia_cmd(julia=joinpath(JULIA_HOME, julia_exename())) opts = JLOptions() cpu_target = unsafe_string(opts.cpu_target) @@ -846,3 +664,19 @@ kwdef_val(::Type{Cwstring}) = Cwstring(C_NULL) kwdef_val(::Type{T}) where {T<:Integer} = zero(T) kwdef_val(::Type{T}) where {T} = T() + + +function _check_bitarray_consistency(B::BitArray{N}) where N + n = length(B) + if N ≠ 1 + all(d ≥ 0 for d in B.dims) || (@warn("Negative d in dims: $(B.dims)"); return false) + prod(B.dims) ≠ n && (@warn("Inconsistent dims/len: prod(dims)=$(prod(B.dims)) len=$n"); return false) + end + Bc = B.chunks + nc = length(Bc) + nc == num_bit_chunks(n) || (@warn("Incorrect chunks length for length $n: expected=$(num_bit_chunks(n)) actual=$nc"); return false) + n == 0 && return true + Bc[end] & _msk_end(n) == Bc[end] || (@warn("Nonzero bits in chunk after `BitArray` end"); return false) + return true +end + diff --git a/doc/src/manual/control-flow.md b/doc/src/manual/control-flow.md index db73443979f96..ccfe0ed66072f 100644 --- a/doc/src/manual/control-flow.md +++ b/doc/src/manual/control-flow.md @@ -691,26 +691,6 @@ Stacktrace: [2] verbose_fussy_sqrt(::Int64) at ./none:3 ``` -### Warnings and informational messages - -Julia also provides other functions that write messages to the standard error I/O, but do not -throw any `Exception`s and hence do not interrupt execution: - -```jldoctest -julia> info("Hi"); 1+1 -INFO: Hi -2 - -julia> warn("Hi"); 1+1 -WARNING: Hi -2 - -julia> error("Hi"); 1+1 -ERROR: Hi -Stacktrace: - [1] error(::String) at ./error.jl:33 -``` - ### The `try/catch` statement The `try/catch` statement allows for `Exception`s to be tested for. For example, a customized diff --git a/doc/src/stdlib/io-network.md b/doc/src/stdlib/io-network.md index 50e90e2aee0dd..0dd5e37f7ae18 100644 --- a/doc/src/stdlib/io-network.md +++ b/doc/src/stdlib/io-network.md @@ -63,9 +63,6 @@ Base.summary Base.print Base.println Base.print_with_color -Base.info -Base.warn -Base.logging Base.Printf.@printf Base.Printf.@sprintf Base.sprint diff --git a/src/julia.h b/src/julia.h index 241bd5b465c5d..9f6d1e0a46826 100644 --- a/src/julia.h +++ b/src/julia.h @@ -1518,6 +1518,7 @@ typedef struct _jl_task_t { jl_value_t *result; jl_value_t *exception; jl_value_t *backtrace; + jl_value_t *logstate; jl_function_t *start; jl_jmp_buf ctx; size_t bufsz; diff --git a/src/task.c b/src/task.c index 16a1ec9c3be3c..7643ae3919130 100644 --- a/src/task.c +++ b/src/task.c @@ -611,6 +611,8 @@ JL_DLLEXPORT jl_task_t *jl_new_task(jl_function_t *start, size_t ssize) t->donenotify = jl_nothing; t->exception = jl_nothing; t->backtrace = jl_nothing; + // Inherit logger state from parent task + t->logstate = ptls->current_task->logstate; // there is no active exception handler available on this stack yet t->eh = NULL; t->gcstack = NULL; @@ -674,7 +676,7 @@ void jl_init_tasks(void) NULL, jl_any_type, jl_emptysvec, - jl_perm_symsvec(9, + jl_perm_symsvec(10, "parent", "storage", "state", @@ -683,8 +685,9 @@ void jl_init_tasks(void) "result", "exception", "backtrace", + "logstate", "code"), - jl_svec(9, + jl_svec(10, jl_any_type, jl_any_type, jl_sym_type, @@ -693,8 +696,9 @@ void jl_init_tasks(void) jl_any_type, jl_any_type, jl_any_type, + jl_any_type, jl_any_type), - 0, 1, 8); + 0, 1, 9); jl_svecset(jl_task_type->types, 0, (jl_value_t*)jl_task_type); done_sym = jl_symbol("done"); @@ -731,6 +735,7 @@ void jl_init_root_task(void *stack, size_t ssize) ptls->current_task->donenotify = jl_nothing; ptls->current_task->exception = jl_nothing; ptls->current_task->backtrace = jl_nothing; + ptls->current_task->logstate = jl_nothing; ptls->current_task->eh = NULL; ptls->current_task->gcstack = NULL; ptls->current_task->tid = ptls->tid; diff --git a/stdlib/Distributed/src/Distributed.jl b/stdlib/Distributed/src/Distributed.jl index a3bfa6c40ab67..7a243bfb94f45 100644 --- a/stdlib/Distributed/src/Distributed.jl +++ b/stdlib/Distributed/src/Distributed.jl @@ -15,7 +15,7 @@ import Base: getindex, wait, put!, take!, fetch, isready, push!, length, using Base: Process, Semaphore, JLOptions, AnyDict, buffer_writes, wait_connected, VERSION_STRING, sync_begin, sync_add, sync_end, async_run_thunk, binding_module, notify_error, atexit, julia_exename, julia_cmd, - AsyncGenerator, display_error, acquire, release, invokelatest, warn_once, + AsyncGenerator, acquire, release, invokelatest, shell_escape_posixly, uv_error using Base.Unicode: isascii, isdigit, isnumeric diff --git a/stdlib/Distributed/src/cluster.jl b/stdlib/Distributed/src/cluster.jl index 82336695584fe..e658d639664c1 100644 --- a/stdlib/Distributed/src/cluster.jl +++ b/stdlib/Distributed/src/cluster.jl @@ -868,7 +868,7 @@ function _rmprocs(pids, waitfor) rmprocset = [] for p in vcat(pids...) if p == 1 - warn("rmprocs: process 1 not removed") + @warn "rmprocs: process 1 not removed" else if haskey(map_pid_wrkr, p) w = map_pid_wrkr[p] @@ -1048,7 +1048,7 @@ function disable_nagle(sock) @static if Sys.islinux() # tcp_quickack is a linux only option if ccall(:jl_tcp_quickack, Cint, (Ptr{Void}, Cint), sock.handle, 1) < 0 - warn_once("Networking unoptimized ( Error enabling TCP_QUICKACK : ", Libc.strerror(Libc.errno()), " )") + @warn "Networking unoptimized ( Error enabling TCP_QUICKACK : $(Libc.strerror(Libc.errno())) )" maxlog=1 end end end @@ -1076,13 +1076,13 @@ function terminate_all_workers() try rmprocs(workers(); waitfor=5.0) catch _ex - warn("Forcibly interrupting busy workers") + @warn "Forcibly interrupting busy workers" exception=_ex # Might be computation bound, interrupt them and try again interrupt(workers()) try rmprocs(workers(); waitfor=5.0) catch _ex2 - warn("Unable to terminate all workers") + @error "Unable to terminate all workers" exception=_ex2 end end end diff --git a/stdlib/Distributed/src/managers.jl b/stdlib/Distributed/src/managers.jl index 389307fa03514..9889a3c13fa08 100644 --- a/stdlib/Distributed/src/managers.jl +++ b/stdlib/Distributed/src/managers.jl @@ -232,11 +232,11 @@ function manage(manager::SSHManager, id::Integer, config::WorkerConfig, op::Symb host = get(config.host) sshflags = get(config.sshflags) if !success(`ssh -T -a -x -o ClearAllForwardings=yes -n $sshflags $host "kill -2 $ospid"`) - warn(STDERR,"error sending a Ctrl-C to julia worker $id on $host") + @error "Error sending a Ctrl-C to julia worker $id on $host" end else # This state can happen immediately after an addprocs - warn(STDERR,"worker $id cannot be presently interrupted.") + @error "Worker $id cannot be presently interrupted." end end end @@ -472,7 +472,7 @@ function socket_reuse_port() rc = ccall(:jl_tcp_reuseport, Int32, (Ptr{Void},), s.handle) if rc < 0 # This is an issue only on systems with lots of client connections, hence delay the warning - nworkers() > 128 && warn_once("Error trying to reuse client port number, falling back to regular socket.") + nworkers() > 128 && @warn "Error trying to reuse client port number, falling back to regular socket" maxlog=1 # provide a clean new socket return TCPSocket() diff --git a/stdlib/Distributed/src/process_messages.jl b/stdlib/Distributed/src/process_messages.jl index e663d3a0b504b..fdbcc544629f8 100644 --- a/stdlib/Distributed/src/process_messages.jl +++ b/stdlib/Distributed/src/process_messages.jl @@ -89,8 +89,7 @@ function deliver_result(sock::IO, msg, oid, value) catch e # terminate connection in case of serialization error # otherwise the reading end would hang - print(STDERR, "fatal error on ", myid(), ": ") - display_error(e, catch_backtrace()) + @error "Fatal error on process $(myid())" exception=e wid = worker_id_from_socket(sock) close(sock) if myid()==1 @@ -211,8 +210,7 @@ function message_handler_loop(r_stream::IO, w_stream::IO, incoming::Bool) # If unhandleable error occurred talking to pid 1, exit if wpid == 1 if isopen(w_stream) - print(STDERR, "fatal error on ", myid(), ": ") - display_error(e, catch_backtrace()) + @error "Fatal error on process $(myid())" exception=e end exit(1) end @@ -343,8 +341,7 @@ function connect_to_peer(manager::ClusterManager, rpid::Int, wconfig::WorkerConf send_connection_hdr(w, true) send_msg_now(w, MsgHeader(), IdentifySocketMsg(myid())) catch e - display_error(e, catch_backtrace()) - println(STDERR, "Error [$e] on $(myid()) while connecting to peer $rpid. Exiting.") + @error "Error on $(myid()) while connecting to peer $rpid, exiting" exception=e exit(1) end end diff --git a/stdlib/Distributed/test/distributed_exec.jl b/stdlib/Distributed/test/distributed_exec.jl index b01528f00b5c7..80112777bb264 100644 --- a/stdlib/Distributed/test/distributed_exec.jl +++ b/stdlib/Distributed/test/distributed_exec.jl @@ -951,7 +951,7 @@ end function test_add_procs_threaded_blas() if get_num_threads() === nothing - warn("Skipping blas num threads tests due to unsupported blas version") + @warn "Skipping blas num threads tests due to unsupported blas version" return end master_blas_thread_count = get_num_threads() @@ -1472,7 +1472,7 @@ function reuseport_tests() @assert (length(ports_lower) + length(ports_higher)) == nworkers() for portset in [ports_lower, ports_higher] if (length(portset) > 0) && (length(unique(portset)) != 1) - warn("SO_REUSEPORT TESTS FAILED. UNSUPPORTED/OLDER UNIX VERSION?") + @warn "SO_REUSEPORT TESTS FAILED. UNSUPPORTED/OLDER UNIX VERSION?" return 0 end end @@ -1491,7 +1491,7 @@ if ccall(:jl_has_so_reuseport, Int32, ()) == 1 addprocs_with_testenv(4; lazy=false) reuseport_tests() else - info("SO_REUSEPORT is unsupported, skipping reuseport tests.") + @info "SO_REUSEPORT is unsupported, skipping reuseport tests" end # Run topology tests last after removing all workers, since a given diff --git a/stdlib/IterativeEigenSolvers/src/IterativeEigenSolvers.jl b/stdlib/IterativeEigenSolvers/src/IterativeEigenSolvers.jl index 23c8f2511bc1c..f27dcb40369ef 100644 --- a/stdlib/IterativeEigenSolvers/src/IterativeEigenSolvers.jl +++ b/stdlib/IterativeEigenSolvers/src/IterativeEigenSolvers.jl @@ -78,7 +78,7 @@ function _eigs(A, B; throw(ArgumentError("input matrix A is too small. Use eigfact instead.")) end if nev > nevmax - warn("Adjusting nev from $nev to $nevmax") + @warn "Adjusting nev from $nev to $nevmax" nev = nevmax end if nev <= 0 @@ -86,7 +86,7 @@ function _eigs(A, B; end ncvmin = nev + (sym ? 1 : 2) if ncv < ncvmin - warn("Adjusting ncv from $ncv to $ncvmin") + @warn "Adjusting ncv from $ncv to $ncvmin" ncv = ncvmin end ncv = BlasInt(min(ncv, n)) @@ -94,7 +94,7 @@ function _eigs(A, B; isshift = sigma !== nothing if isa(which,AbstractString) - warn("Use symbols instead of strings for specifying which eigenvalues to compute") + @warn "Use symbols instead of strings for specifying which eigenvalues to compute" which=Symbol(which) end if (which != :LM && which != :SM && which != :LR && which != :SR && @@ -104,7 +104,7 @@ function _eigs(A, B; if which == :BE && !sym throw(ArgumentError("which=:BE only possible for real symmetric problem")) end - isshift && which == :SM && warn("use of :SM in shift-and-invert mode is not recommended, use :LM to find eigenvalues closest to sigma") + isshift && which == :SM && @warn "Use of :SM in shift-and-invert mode is not recommended, use :LM to find eigenvalues closest to sigma" if which==:SM && !isshift # transform into shift-and-invert method with sigma = 0 isshift=true @@ -187,7 +187,7 @@ function _eigs(A, B; # Issue 10495, 10701: Check that all eigenvalues are converged nev = length(output[1]) nconv = output[ritzvec ? 3 : 2] - nev ≤ nconv || warn("not all wanted Ritz pairs converged. Requested: $nev, converged: $nconv") + nev ≤ nconv || @warn "Not all wanted Ritz pairs converged. Requested: $nev, converged: $nconv" return output end diff --git a/stdlib/IterativeEigenSolvers/test/runtests.jl b/stdlib/IterativeEigenSolvers/test/runtests.jl index d98dab458d87a..833d1d5124079 100644 --- a/stdlib/IterativeEigenSolvers/test/runtests.jl +++ b/stdlib/IterativeEigenSolvers/test/runtests.jl @@ -36,9 +36,9 @@ using Test (d,v) = eigs(a, I, nev=3) # test eigs(A, B; kwargs...) @test a*v[:,2] ≈ d[2]*v[:,2] @test norm(v) > testtol # eigenvectors cannot be null vectors - @test_warn "Use symbols instead of strings for specifying which eigenvalues to compute" eigs(a, which="LM") - @test_warn "Adjusting ncv from 1 to 4" eigs(a, ncv=1, nev=2) - @test_warn "Adjusting nev from $n to $(n-2)" eigs(a, nev=n) + @test_logs (:warn,"Use symbols instead of strings for specifying which eigenvalues to compute") eigs(a, which="LM") + @test_logs (:warn,"Adjusting ncv from 1 to 4") eigs(a, ncv=1, nev=2) + @test_logs (:warn,"Adjusting nev from $n to $(n-2)") eigs(a, nev=n) # (d,v) = eigs(a, b, nev=3, tol=1e-8) # not handled yet # @test a*v[:,2] ≈ d[2]*b*v[:,2] atol=testtol # @test norm(v) > testtol # eigenvectors cannot be null vectors diff --git a/stdlib/Logging/docs/src/index.md b/stdlib/Logging/docs/src/index.md new file mode 100644 index 0000000000000..091eef4035b11 --- /dev/null +++ b/stdlib/Logging/docs/src/index.md @@ -0,0 +1,2 @@ +# Logging + diff --git a/stdlib/Logging/src/Logging.jl b/stdlib/Logging/src/Logging.jl new file mode 100644 index 0000000000000..d3cf5ce167a0e --- /dev/null +++ b/stdlib/Logging/src/Logging.jl @@ -0,0 +1,48 @@ +module Logging + +# For now, simply import most names from Base - we don't want to fully +# stabilize this API for 1.0 so it should officially live here in a stdlib +# package. +# +# See #24490 + +import Base.CoreLogging: + LogLevel, BelowMinLevel, Debug, Info, Warn, Error, AboveMaxLevel, + AbstractLogger, + NullLogger, + handle_message, shouldlog, min_enabled_level, catch_exceptions, + @debug, + @info, + @warn, + @error, + @logmsg, + with_logger, + current_logger, + global_logger, + disable_logging, + SimpleLogger + +export + AbstractLogger, + LogLevel, + NullLogger, + @debug, + @info, + @warn, + @error, + @logmsg, + with_logger, + current_logger, + global_logger, + disable_logging, + SimpleLogger + +# The following are also part of the public API, but not exported: +# +# 1. Log levels: +# BelowMinLevel, Debug, Info, Warn, Error, AboveMaxLevel, +# +# 2. AbstractLogger message related functions: +# handle_message, shouldlog, min_enabled_level, catch_exceptions, + +end diff --git a/stdlib/Logging/test/runtests.jl b/stdlib/Logging/test/runtests.jl new file mode 100644 index 0000000000000..1cf40077a1476 --- /dev/null +++ b/stdlib/Logging/test/runtests.jl @@ -0,0 +1 @@ +# TODO: Move SimpleLogger in here diff --git a/stdlib/Profile/src/Profile.jl b/stdlib/Profile/src/Profile.jl index 299439b1c1d76..a948f09896c37 100644 --- a/stdlib/Profile/src/Profile.jl +++ b/stdlib/Profile/src/Profile.jl @@ -307,9 +307,9 @@ function fetch() len = len_data() maxlen = maxlen_data() if (len == maxlen) - warn("""The profile data buffer is full; profiling probably terminated - before your program finished. To profile for longer runs, call Profile.init - with a larger buffer and/or larger delay.""") + @warn """The profile data buffer is full; profiling probably terminated + before your program finished. To profile for longer runs, call + `Profile.init()` with a larger buffer and/or larger delay.""" end return unsafe_wrap(Array, get_data_pointer(), (len,)) end @@ -673,10 +673,10 @@ function liperm(lilist::Vector{StackFrame}) return sortperm(comb) end -warning_empty() = warn(""" +warning_empty() = @warn """ There were no samples collected. Run your program longer (perhaps by running it multiple times), or adjust the delay between samples with - Profile.init().""") + `Profile.init()`.""" function purgeC(data::Vector{UInt64}, lidict::LineInfoFlatDict) keep = Bool[d == 0 || lidict[d].from_c == false for d in data] diff --git a/stdlib/SuiteSparse/src/cholmod.jl b/stdlib/SuiteSparse/src/cholmod.jl index 20257c927dea5..e7be599a3c7ec 100644 --- a/stdlib/SuiteSparse/src/cholmod.jl +++ b/stdlib/SuiteSparse/src/cholmod.jl @@ -86,8 +86,7 @@ function __init__() if current_version < CHOLMOD_MIN_VERSION - warn(""" - + @warn """ CHOLMOD version incompatibility Julia was compiled with CHOLMOD version $build_version. It is @@ -100,10 +99,9 @@ function __init__() of CHOLMOD, or download the generic binaries from www.julialang.org, which ship with the correct versions of all dependencies. - """) + """ elseif build_version_array[1] != current_version_array[1] - warn(""" - + @warn """ CHOLMOD version incompatibility Julia was compiled with CHOLMOD version $build_version. It is @@ -116,13 +114,12 @@ function __init__() version of CHOLMOD as the one used during the build, or download the generic binaries from www.julialang.org, which ship with the correct versions of all dependencies. - """) + """ end intsize = Int(ccall((:jl_cholmod_sizeof_long,:libsuitesparse_wrapper),Csize_t,())) if intsize != 4length(IndexTypes) - warn(""" - + @error """ CHOLMOD integer size incompatibility Julia was compiled with a version of CHOLMOD that @@ -136,7 +133,7 @@ function __init__() configuration or by downloading the OS X or generic Linux binary from www.julialang.org, which include the correct versions of all dependencies. - """) + """ end ### Initiate CHOLMOD @@ -166,8 +163,7 @@ function __init__() end catch ex - Base.showerror_nostdio(ex, - "WARNING: Error during initialization of module CHOLMOD") + @error "Error during initialization of module CHOLMOD" exception=ex end end diff --git a/stdlib/Test/docs/src/index.md b/stdlib/Test/docs/src/index.md index 52f3c9c024cd9..317fb39eeceb1 100644 --- a/stdlib/Test/docs/src/index.md +++ b/stdlib/Test/docs/src/index.md @@ -181,6 +181,8 @@ ERROR: There was an error during testing ```@docs Test.@inferred +Test.@test_logs +Test.@test_deprecated Test.@test_warn Test.@test_nowarn ``` diff --git a/stdlib/Test/src/Test.jl b/stdlib/Test/src/Test.jl index ad7917b335e5d..a66bd2d2ce15f 100644 --- a/stdlib/Test/src/Test.jl +++ b/stdlib/Test/src/Test.jl @@ -15,7 +15,9 @@ and summarize them at the end of the test set with `@testset`. """ module Test -export @test, @test_throws, @test_broken, @test_skip, @test_warn, @test_nowarn +export @test, @test_throws, @test_broken, @test_skip, + @test_warn, @test_nowarn, + @test_logs, @test_deprecated export @testset # Legacy approximate testing functions, yet to be included export @inferred @@ -503,7 +505,9 @@ function do_test_throws(result::ExecutionResult, @nospecialize(orig_expr), @nosp end #----------------------------------------------------------------------- -# Test for warning messages +# Test for log messages + +# Test for warning messages (deprecated) ismatch_warn(s::AbstractString, output) = contains(output, s) ismatch_warn(s::Regex, output) = ismatch(s, output) @@ -1547,4 +1551,6 @@ begin export @test_approx_eq end +include("logging.jl") + end # module diff --git a/stdlib/Test/src/logging.jl b/stdlib/Test/src/logging.jl new file mode 100644 index 0000000000000..232232fbb9a0d --- /dev/null +++ b/stdlib/Test/src/logging.jl @@ -0,0 +1,256 @@ +using Logging +import Logging: Info, + shouldlog, handle_message, min_enabled_level, catch_exceptions +import Base: ismatch + +#------------------------------------------------------------------------------- +# Log records +struct LogRecord + level + message + _module + group + id + file + line + kwargs +end +LogRecord(args...; kwargs...) = LogRecord(args..., kwargs) + +struct Ignored ; end + +#------------------------------------------------------------------------------- +# Logger with extra test-related state +mutable struct TestLogger <: AbstractLogger + logs::Vector{LogRecord} + min_level::LogLevel + catch_exceptions::Bool + shouldlog_args +end + +TestLogger(; min_level=Info, catch_exceptions=false) = TestLogger(LogRecord[], min_level, catch_exceptions, nothing) +min_enabled_level(logger::TestLogger) = logger.min_level + +function shouldlog(logger::TestLogger, level, _module, group, id) + logger.shouldlog_args = (level, _module, group, id) + true +end + +function handle_message(logger::TestLogger, level, msg, _module, + group, id, file, line; kwargs...) + push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs)) +end + +# Catch exceptions for the test logger only if specified +catch_exceptions(logger::TestLogger) = logger.catch_exceptions + +function collect_test_logs(f; kwargs...) + logger = TestLogger(; kwargs...) + value = with_logger(f, logger) + logger.logs, value +end + + +#------------------------------------------------------------------------------- +# Log testing tools + +# Failure result type for log testing +mutable struct LogTestFailure <: Result + orig_expr + source::Union{Void,LineNumberNode} + patterns + logs +end +function Base.show(io::IO, t::LogTestFailure) + print_with_color(Base.error_color(), io, "Log Test Failed"; bold = true) + print(io, " at ") + print_with_color(:default, io, t.source.file, ":", t.source.line, "\n"; bold = true) + println(io, " Expression: ", t.orig_expr) + println(io, " Log Pattern: ", join(t.patterns, " ")) + println(io, " Captured Logs: ") + for l in t.logs + println(io, " ", l) + end +end + +# Patch support for LogTestFailure into Base.Test test set types +# TODO: Would be better if `Test` itself allowed us to handle this more neatly. +function record(::FallbackTestSet, t::LogTestFailure) + println(t) + throw(FallbackTestSetException("There was an error during testing")) +end + +function record(ts::DefaultTestSet, t::LogTestFailure) + if myid() == 1 + print_with_color(:white, ts.description, ": ") + print(t) + Base.show_backtrace(STDOUT, scrub_backtrace(backtrace())) + println() + end + # Hack: convert to `Fail` so that test summarization works correctly + push!(ts.results, Fail(:test, t.orig_expr, t.logs, nothing, t.source)) + t +end + +""" + @test_logs [log_patterns...] [keywords] expression + +Collect a list of log records generated by `expression` using +`collect_test_logs`, check that they match the sequence `log_patterns`, and +return the value of `expression`. The `keywords` provide some simple filtering +of log records: the `min_level` keyword controls the minimum log level which +will be collected for the test, the `match_mode` keyword defines how matching +will be performed (the default `:all` checks that all logs and patterns match +pairwise; use `:any` to check that the pattern matches at least once somewhere +in the sequence.) + +The most useful log pattern is a simple tuple of the form `(level,message)`. +A different number of tuple elements may be used to match other log metadata, +corresponding to the arguments to passed to `AbstractLogger` via the +`handle_message` function: `(level,message,module,group,id,file,line)`. +Elements which are present will be matched pairwise with the log record fields +using `==` by default, with the special cases that `Symbol`s may be used for +the standard log levels, and `Regex`s in the pattern will match string or +Symbol fields using `ismatch`. + +# Examples + +Consider a function which logs a warning, and several debug messages: + + function foo(n) + @info "Doing foo with n=\$n" + for i=1:n + @debug "Iteration \$i" + end + 42 + end + +We can test the info message using + + @test_logs (:info,"Doing foo with n=2") foo(2) + +If we also wanted to test the debug messages, these need to be enabled with the +`min_level` keyword: + + @test_logs (:info,"Doing foo with n=2") (:debug,"Iteration 1") (:debug,"Iteration 2") min_level=Debug foo(2) + +The macro may be chained with `@test` to also test the returned value: + + @test (@test_logs (:info,"Doing foo with n=2") foo(2)) == 42 + +""" +macro test_logs(exs...) + length(exs) >= 1 || throw(ArgumentError("""`@test_logs` needs at least one arguments. + Usage: `@test_logs [msgs...] expr_to_run`""")) + patterns = Any[] + kwargs = Any[] + for e in exs[1:end-1] + if e isa Expr && e.head == :(=) + push!(kwargs, esc(Expr(:kw, e.args...))) + else + push!(patterns, esc(e)) + end + end + expression = exs[end] + orig_expr = QuoteNode(expression) + sourceloc = QuoteNode(__source__) + Base.remove_linenums!(quote + let testres=nothing, value=nothing + try + didmatch,logs,value = match_logs($(patterns...); $(kwargs...)) do + $(esc(expression)) + end + if didmatch + testres = Pass(:test, nothing, nothing, value) + else + testres = LogTestFailure($orig_expr, $sourceloc, + $(QuoteNode(exs[1:end-1])), logs) + end + catch e + testres = Error(:test_error, $orig_expr, e, catch_backtrace(), $sourceloc) + end + Test.record(Test.get_testset(), testres) + value + end + end) +end + +function match_logs(f, patterns...; match_mode::Symbol=:all, kwargs...) + logs,value = collect_test_logs(f; kwargs...) + if match_mode == :all + didmatch = length(logs) == length(patterns) && + all(ismatch(p,l) for (p,l) in zip(patterns, logs)) + elseif match_mode == :any + didmatch = all(any(ismatch(p,l) for l in logs) for p in patterns) + end + didmatch,logs,value +end + +# TODO: Use a version of parse_level from stdlib/Logging, when it exists. +function parse_level(level::Symbol) + if level == :belowminlevel return Logging.BelowMinLevel + elseif level == :debug return Logging.Debug + elseif level == :info return Logging.Info + elseif level == :warn return Logging.Warn + elseif level == :error return Logging.Error + elseif level == :abovemaxlevel return Logging.AboveMaxLevel + else + throw(ArgumentError("Unknown log level $level")) + end +end + +logfield_ismatch(a, b) = a == b +logfield_ismatch(r::Regex, b) = ismatch(r, b) +logfield_ismatch(r::Regex, b::Symbol) = ismatch(r, String(b)) +logfield_ismatch(a::Symbol, b::LogLevel) = parse_level(a) == b +logfield_ismatch(a::Ignored, b) = true + +function ismatch(pattern::Tuple, r::LogRecord) + stdfields = (r.level, r.message, r._module, r.group, r.id, r.file, r.line) + all(logfield_ismatch(p,f) for (p,f) in zip(pattern, stdfields[1:length(pattern)])) +end + +""" + @test_deprecated [pattern] expression + +When `--depwarn=yes`, test that `expression` emits a deprecation warning and +return the value of `expression`. The log message string will be matched +against `pattern` which defaults to `r"deprecated"i`. + +When `--depwarn=no`, simply return the result of executing `expression`. When +`--depwarn=error`, check that an ErrorException is thrown. + +# Examples + +``` +# Deprecated in julia 0.7 +@test_deprecated num2hex(1) + +# The returned value can be tested by chaining with @test: +@test (@test_deprecated num2hex(1)) == "0000000000000001" +``` +""" +macro test_deprecated(exs...) + 1 <= length(exs) <= 2 || throw(ArgumentError("""`@test_deprecated` expects one or two arguments. + Usage: `@test_deprecated [pattern] expr_to_run`""")) + pattern = length(exs) == 1 ? r"deprecated"i : esc(exs[1]) + expression = esc(exs[end]) + res = quote + dw = Base.JLOptions().depwarn + if dw == 2 + # TODO: Remove --depwarn=error if possible and replace with a more + # flexible mechanism so we don't have to do this. + @test_throws ErrorException $expression + elseif dw == 1 + @test_logs (:warn, $pattern, Ignored(), :depwarn) match_mode=:any $expression + else + $expression + end + end + # Propagate source code location of @test_logs to @test macro + # FIXME: Use rewrite_sourceloc!() for this - see #22623 + res.args[4].args[2].args[2].args[2] = __source__ + res.args[4].args[3].args[2].args[2].args[2] = __source__ + res +end + diff --git a/stdlib/Test/test/runtests.jl b/stdlib/Test/test/runtests.jl index a40de9b449585..8b745114e9e21 100644 --- a/stdlib/Test/test/runtests.jl +++ b/stdlib/Test/test/runtests.jl @@ -2,6 +2,8 @@ using Test, Distributed +import Logging: Debug, Info, Warn + @testset "@test" begin @test true @test 1 == 1 @@ -51,7 +53,7 @@ end end @testset "@test_warn" begin @test 1234 === @test_nowarn(1234) - @test 5678 === @test_warn("WARNING: foo", begin warn("foo"); 5678; end) + @test 5678 === @test_warn("WARNING: foo", begin println(STDERR, "WARNING: foo"); 5678; end) let a @test_throws UndefVarError(:a) a @test_nowarn a = 1 @@ -651,7 +653,7 @@ end @test contains(msg, "at " * f * ":" * "5") rm(f; force=true) - end +end # issue #24919 @testset "≈ with atol" begin @@ -672,3 +674,68 @@ end """) @test contains(msg, "Evaluated: 0.9 ≈ 0.1 (nans=true, atol=0.01)") end + +@testset "@test_logs" begin + function foo(n) + @info "Doing foo with n=$n" + for i=1:n + @debug "Iteration $i" + end + end + + @test_logs (Info,"Doing foo with n=2") foo(2) + + # Log pattern matching + # Regex + @test_logs (Info,r"^Doing foo with n=[0-9]+$") foo(10) + @test_logs (Info,r"^Doing foo with n=[0-9]+$") foo(1) + # Level symbols + @test_logs (:debug,) min_level=Debug @debug "foo" + @test_logs (:info,) @info "foo" + @test_logs (:warn,) @warn "foo" + @test_logs (:error,) @error "foo" + + # Pass through so the value of the expression can also be tested + @test (@test_logs (Info,"blah") (@info "blah"; 42)) == 42 + + # Debug level log collection + @test_logs (Info,"Doing foo with n=2") (Debug,"Iteration 1") (Debug,"Iteration 2") min_level=Debug foo(2) + + @test_logs (Debug,"Iteration 5") min_level=Debug match_mode=:any foo(10) + + # Test failures + fails = @testset NoThrowTestSet "check that @test_logs detects bad input" begin + @test_logs (Warn,) foo(1) + @test_logs (Warn,) match_mode=:any @info "foo" + @test_logs (Debug,) @debug "foo" + end + @test length(fails) == 3 + @test fails[1] isa Test.LogTestFailure + @test fails[2] isa Test.LogTestFailure + @test fails[3] isa Test.LogTestFailure +end + +function newfunc() + 42 +end +@deprecate oldfunc newfunc + +@testset "@test_deprecated" begin + @test_deprecated oldfunc() + + # Expression passthrough + if Base.JLOptions().depwarn != 2 + @test (@test_deprecated oldfunc()) == 42 + + fails = @testset NoThrowTestSet "check that @test_deprecated detects bad input" begin + @test_deprecated newfunc() + @test_deprecated r"Not found in message" oldfunc() + end + @test length(fails) == 2 + @test fails[1] isa Test.LogTestFailure + @test fails[2] isa Test.LogTestFailure + else + @warn """Omitting `@test_deprecated` tests which can't yet + be tested in --depwarn=error mode""" + end +end diff --git a/test/arrayops.jl b/test/arrayops.jl index a4390866a9649..aff680d9a9f6e 100644 --- a/test/arrayops.jl +++ b/test/arrayops.jl @@ -312,16 +312,12 @@ end # TODO: will throw MethodError after 0.6 deprecations are deleted dw = Base.JLOptions().depwarn if dw == 2 + # FIXME: Remove this special case after deperror cleanup @test_throws ErrorException Matrix{Int}() @test_throws ErrorException Matrix() - elseif dw == 1 - @test_warn "deprecated" Matrix{Int}() - @test_warn "deprecated" Matrix() - elseif dw == 0 - @test size(Matrix{Int}()) == (0,0) - @test size(Matrix()) == (0,0) else - error("unexpected depwarn value") + @test size(@test_deprecated Matrix{Int}()) == (0,0) + @test size(@test_deprecated Matrix()) == (0,0) end @test_throws MethodError Array{Int,3}() end diff --git a/test/ccall.jl b/test/ccall.jl index b750b42e4416a..770f6c0763ba8 100644 --- a/test/ccall.jl +++ b/test/ccall.jl @@ -1130,7 +1130,7 @@ elseif Sys.ARCH === :powerpc64le || Sys.ARCH === :ppc64le (1024, 1023, 1022, 1021), (1025, 1024, 1023, 1022), (1026, 1025, 1024, 1023), (1027, 1026, 1025, 1024), (10028, 10027, 10026, 10025)) elseif Sys.ARCH !== :i686 && Sys.ARCH !== :arm # TODO -warn("ccall: no VecReg tests run for this platform") +@warn "ccall: no VecReg tests run for this platform" end diff --git a/test/channels.jl b/test/channels.jl index 7f7b7a24b396b..e70fe0b679189 100644 --- a/test/channels.jl +++ b/test/channels.jl @@ -221,7 +221,7 @@ using Dates @assert (et >= 1.0) && (et <= 1.5) @assert !isready(rr3) catch - warn("timedwait tests delayed. et=$et, isready(rr3)=$(isready(rr3))") + @warn "`timedwait` tests delayed. et=$et, isready(rr3)=$(isready(rr3))" end @test isready(rr1) end diff --git a/test/choosetests.jl b/test/choosetests.jl index 658c3c1a8ca91..aa8e1ceb31800 100644 --- a/test/choosetests.jl +++ b/test/choosetests.jl @@ -52,7 +52,7 @@ function choosetests(choices = []) "checked", "bitset", "floatfuncs", "compile", "inline", "boundscheck", "error", "ambiguous", "cartesian", "asmvariant", "osutils", "channels", "iostream", "specificity", "codegen", "codevalidation", - "reinterpretarray", "syntax", "missing", "asyncmap" + "reinterpretarray", "syntax", "logging", "missing", "asyncmap" ] if isdir(joinpath(JULIA_HOME, Base.DOCDIR, "examples")) @@ -149,12 +149,12 @@ function choosetests(choices = []) try ipa = getipaddr() catch - warn("Networking unavailable: Skipping tests [" * join(net_required_for, ", ") * "]") + @warn "Networking unavailable: Skipping tests [" * join(net_required_for, ", ") * "]" net_on = false end if ccall(:jl_running_on_valgrind,Cint,()) != 0 && "rounding" in tests - warn("Running under valgrind: Skipping rounding tests") + @warn "Running under valgrind: Skipping rounding tests" filter!(x -> x != "rounding", tests) end @@ -172,7 +172,7 @@ function choosetests(choices = []) if startswith(string(Sys.ARCH), "arm") # Remove profile from default tests on ARM since it currently segfaults # Allow explicitly adding it for testing - warn("Skipping Profile tests") + @warn "Skipping Profile tests" filter!(x -> (x != "Profile"), tests) end diff --git a/test/compile.jl b/test/compile.jl index 59df5baf6bf56..daafb6091e8c6 100644 --- a/test/compile.jl +++ b/test/compile.jl @@ -14,8 +14,8 @@ FooBase_module = :FooBase4b3a94a1a081a8cb end using .ConflictingBindings -# this environment variable would affect some error messages being tested below -# so we disable it for the tests below +# FIXME: withenv() is a leftover from previous tests. Oddly, one test below +# fails without it, in a mysterious way. withenv( "JULIA_DEBUG_LOADING" => nothing ) do dir = mktempdir() @@ -174,7 +174,7 @@ try cachefile = joinpath(dir, "$Foo_module.ji") # use _require_from_serialized to ensure that the test fails if # the module doesn't reload from the image: - @test_warn "WARNING: replacing module $Foo_module." begin + @test_logs (:warn,"Replacing module `$Foo_module`") begin ms = Base._require_from_serialized(Foo_module, cachefile) @test isa(ms, Array{Any,1}) Base.register_all(ms) @@ -219,7 +219,7 @@ try # plus modules included in the system image Dict(s => Base.module_uuid(Base.root_module(s)) for s in [:Base64, :CRC32c, :Dates, :DelimitedFiles, :FileWatching, - :IterativeEigenSolvers, :Mmap, :Profile, :SharedArrays, + :IterativeEigenSolvers, :Logging, :Mmap, :Profile, :SharedArrays, :SuiteSparse, :Test, :Unicode, :Distributed])) @test discard_module.(deps) == deps1 @@ -477,7 +477,7 @@ let dir = mktempdir() let fname = tempname() try @test readchomp(pipeline(`$exename -E $(testcode)`, stderr=fname)) == "nothing" - @test Test.ismatch_warn("WARNING: replacing module $Test_module.\n", read(fname, String)) + @test ismatch(Regex("Replacing module `$Test_module`"), read(fname, String)) finally rm(fname, force=true) end @@ -623,4 +623,4 @@ let end end -end # !withenv +end diff --git a/test/deprecation_exec.jl b/test/deprecation_exec.jl index 6a19f717336d5..f5bdc352b6ba6 100644 --- a/test/deprecation_exec.jl +++ b/test/deprecation_exec.jl @@ -70,8 +70,7 @@ end @noinline function f21972() T21972() end - @test_warn "deprecated" f21972() - @test_nowarn f21972() + @test_deprecated "something" f21972() end f24658() = depwarn24658() @@ -80,5 +79,5 @@ depwarn24658() = Base.firstcaller(backtrace(), :_func_not_found_) @testset "firstcaller" begin # issue #24658 - @test eval(:(if true; f24658(); end)) == StackTraces.UNKNOWN + @test eval(:(if true; f24658(); end)) == (Ptr{Void}(0),StackTraces.UNKNOWN) end diff --git a/test/libgit2.jl b/test/libgit2.jl index ba8669eebe563..b008bd3ed1480 100644 --- a/test/libgit2.jl +++ b/test/libgit2.jl @@ -1112,9 +1112,9 @@ mktempdir() do dir head_ann = LibGit2.GitAnnotated(repo, "master") # (fail to) merge them because we can't fastforward - @test_warn "WARNING: Cannot perform fast-forward merge." !LibGit2.merge!(repo, [upst_ann], true) + @test_logs (:warn,"Cannot perform fast-forward merge") !LibGit2.merge!(repo, [upst_ann], true) # merge them now that we allow non-ff - @test_warn "INFO: Review and commit merged changes." LibGit2.merge!(repo, [upst_ann], false) + @test_logs (:info,"Review and commit merged changes") LibGit2.merge!(repo, [upst_ann], false) @test LibGit2.is_ancestor_of(string(oldhead), string(LibGit2.head_oid(repo)), repo) # go back to merge_a and rename a file @@ -1127,7 +1127,7 @@ mktempdir() do dir rename_flag = 0 rename_flag = LibGit2.toggle(rename_flag, 0) # turns on the find renames opt mos = LibGit2.MergeOptions(flags=rename_flag) - @test_warn "INFO: Review and commit merged changes." LibGit2.merge!(repo, [upst_ann], merge_opts=mos) + @test_logs (:info,"Review and commit merged changes") LibGit2.merge!(repo, [upst_ann], merge_opts=mos) end end @@ -1458,7 +1458,7 @@ mktempdir() do dir LibGit2.branch!(repo, "master") a_head_ann = LibGit2.GitAnnotated(repo, "branch/merge_a") # merge returns true if successful - @test_warn "INFO: Review and commit merged changes." LibGit2.merge!(repo, [a_head_ann]) + @test_logs (:info,"Review and commit merged changes") LibGit2.merge!(repo, [a_head_ann]) end end @@ -2544,8 +2544,8 @@ mktempdir() do dir try # OpenSSL needs to be on the path openssl_installed = !isempty(read(`openssl version`, String)) - catch - warn("Skipping hostname verification tests. Is `openssl` on the path?") + catch ex + @warn "Skipping hostname verification tests. Is `openssl` on the path?" exception=ex end # Find a hostname that maps to the loopback address @@ -2574,7 +2574,7 @@ mktempdir() do dir end if isempty(common_name) - warn("Skipping hostname verification tests. Unable to determine a hostname which maps to the loopback address") + @warn "Skipping hostname verification tests. Unable to determine a hostname which maps to the loopback address" end end if openssl_installed && !isempty(common_name) diff --git a/test/linalg/dense.jl b/test/linalg/dense.jl index d5a2101321fc3..e7c7d6d31e01d 100644 --- a/test/linalg/dense.jl +++ b/test/linalg/dense.jl @@ -722,7 +722,7 @@ end @testset "Tests for $elty" for elty in (Int128, Int16, Int32, Int64, Int8, UInt128, UInt16, UInt32, UInt64, UInt8, BigInt) - info("Testing $elty") + #@info "Testing $elty" @test elty[1 1;1 0]^-1 == [0 1; 1 -1] @test elty[1 1;1 0]^-2 == [1 -1; -1 2] @test (@inferred elty[1 1;1 0]^2) == elty[2 1;1 1] diff --git a/test/llvmcall.jl b/test/llvmcall.jl index 70e5f7bbedb6e..0bb4f710b8652 100644 --- a/test/llvmcall.jl +++ b/test/llvmcall.jl @@ -190,7 +190,7 @@ if Base.libllvm_version >= v"3.6" # llvm 3.6 changed the syntax for a gep, so ju end code_llvm(DevNull, foo, ()) else - println("INFO: skipping gep parentage test on llvm < 3.6") + @info "Skipping gep parentage test on llvm < 3.6" end module CcallableRetTypeTest diff --git a/test/logging.jl b/test/logging.jl new file mode 100644 index 0000000000000..d7aa294dceb2d --- /dev/null +++ b/test/logging.jl @@ -0,0 +1,270 @@ +using Base.CoreLogging +import Base.CoreLogging: BelowMinLevel, Debug, Info, Warn, Error, + handle_message, shouldlog, min_enabled_level + +import Test: collect_test_logs, TestLogger + +#------------------------------------------------------------------------------- +@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 = ones(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 ismatch(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 ismatch((Info,"test2"), record2) + kwargs = record2.kwargs + @test kwargs[:value_in_msg_block] === 1000.0 + + # Splatting of keywords + record3 = logs[3] + @test ismatch((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,) 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 filtering, global logger" begin + old_logger = global_logger() + logs = let + logger = TestLogger(min_level=Warn) + global_logger(logger) + @info "b" + @warn "c" + logger.logs + end + global_logger(old_logger) + + @test length(logs) == 1 + @test ismatch((Warn , "c"), logs[1]) + 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 +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 + + +#------------------------------------------------------------------------------- + +# 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 + + # 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...) + s = String(take!(io)) + # Remove the small amount of color, as `Base.print_with_color` can't be + # simply controlled. + s = replace(s, r"^\e\[1m\e\[..m(.*)\e\[39m\e\[22m"m, s"\1") + # println(s) + s + end + + # Simple + @test genmsg(Info, "msg", Main, "some/path.jl", 101) == + """ + I- msg -Info:Main:path.jl:101 + """ + + # Multiline message + @test genmsg(Warn, "line1\nline2", Main, "some/path.jl", 101) == + """ + W- line1 + | line2 -Warn:Main:path.jl:101 + """ + + # Keywords + @test genmsg(Error, "msg", Base, "other.jl", 101, a=1, b="asdf") == + """ + E- msg -Error:Base:other.jl:101 + | a = 1 + | b = asdf + """ +end + +end diff --git a/test/misc.jl b/test/misc.jl index e70a5e8274f2c..8ee89c78102ee 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -2,6 +2,10 @@ # Tests that do not really go anywhere else +# The following tests for deprecated functionality are disabled when --depwarn=error. +# TODO: Clean this up by reimplementing depwarn=error with a logger. +if Base.JLOptions().depwarn != 2 + # Test info @test contains(sprint(info, "test"), "INFO:") @test contains(sprint(info, "test"), "INFO: test") @@ -29,7 +33,7 @@ let bt = backtrace() end # PR #16213 -module Logging +@eval module LogTest function bar(io) info(io,"barinfo") warn(io,"barwarn") @@ -47,94 +51,96 @@ function foo(io) Base.display_error(io,"fooerror",backtrace()) end -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging, :bar; kind=:info) -@test all(contains.(sprint(Logging.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest, :bar; kind=:info) +@test all(contains.(sprint(LogTest.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging; kind=:info) -@test all(contains.(sprint(Logging.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["WARNING: poohwarn", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest; kind=:info) +@test all(contains.(sprint(LogTest.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) logging(DevNull; kind=:info) -@test all(contains.(sprint(Logging.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["WARNING: foowarn", "ERROR: \"fooerror\""])) logging(kind=:info) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging, :bar; kind=:warn) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest, :bar; kind=:warn) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging; kind=:warn) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest; kind=:warn) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) logging(DevNull; kind=:warn) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "ERROR: \"fooerror\""])) logging(kind=:warn) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging, :bar; kind=:error) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn"])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest, :bar; kind=:error) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn"])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging; kind=:error) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn"])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn"])) +logging(DevNull, LogTest; kind=:error) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn"])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn"])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) logging(DevNull; kind=:error) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn"])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn"])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn"])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn"])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn"])) logging(kind=:error) -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging, :bar) -@test sprint(Logging.bar) == "" -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +logging(DevNull, LogTest, :bar) +@test sprint(LogTest.bar) == "" +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) -logging(DevNull, Logging) -@test sprint(Logging.bar) == "" -@test sprint(Logging.pooh) == "" +logging(DevNull, LogTest) +@test sprint(LogTest.bar) == "" +@test sprint(LogTest.pooh) == "" @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) logging(DevNull) -@test sprint(Logging.bar) == "" -@test sprint(Logging.pooh) == "" +@test sprint(LogTest.bar) == "" +@test sprint(LogTest.pooh) == "" @test sprint(foo) == "" logging() -@test all(contains.(sprint(Logging.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) -@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) +@test all(contains.(sprint(LogTest.bar), ["INFO: barinfo", "WARNING: barwarn", "ERROR: \"barerror\""])) +@test all(contains.(sprint(LogTest.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""])) @test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""])) +end + # test assert() method @test_throws AssertionError assert(false) let res = assert(true) diff --git a/test/pkg.jl b/test/pkg.jl index 4d2548f253d87..624ed28f62d47 100644 --- a/test/pkg.jl +++ b/test/pkg.jl @@ -267,45 +267,52 @@ temp_pkg_dir() do # Various pin/free/re-pin/change-pin patterns (issue #17176) @test "" == capture_stdout() do - @test_warn "INFO: Freeing Example" Pkg.free("Example") + nothingtodomsg = (:info,"No packages to install, update or remove") - @test_warn r"^INFO: Creating Example branch pinned\.[0-9a-f]{8}\.tmp$" Pkg.pin("Example") + @test_logs((:info,"Freeing Example"), + nothingtodomsg, + Pkg.free("Example")) + + @test_logs (:info,r"^Creating Example branch pinned\.[0-9a-f]{8}\.tmp$") Pkg.pin("Example") vers = Pkg.installed("Example") branch = LibGit2.with(LibGit2.GitRepo, Pkg.dir("Example")) do repo LibGit2.branch(repo) end - @test_warn "INFO: Freeing Example" Pkg.free("Example") + @test_logs((:info,"Freeing Example"), + nothingtodomsg, + Pkg.free("Example")) - @test_warn ("INFO: Creating Example branch pinned.b1990792.tmp", - "INFO: No packages to install, update or remove") Pkg.pin("Example", v"0.4.0") + @test_logs((:info,"Creating Example branch pinned.b1990792.tmp"), + nothingtodomsg, Pkg.pin("Example", v"0.4.0")) @test Pkg.installed("Example") == v"0.4.0" - @test_warn r"^INFO: Package Example is already pinned to the selected commit$" Pkg.pin("Example", v"0.4.0") + @test_logs (:info,r"^Package Example is already pinned to the selected commit$") Pkg.pin("Example", v"0.4.0") @test Pkg.installed("Example") == v"0.4.0" - @test_warn r"^INFO: Package Example is already pinned$" Pkg.pin("Example") + @test_logs (:info,r"^Package Example is already pinned$") Pkg.pin("Example") @test Pkg.installed("Example") == v"0.4.0" - @test_warn "INFO: Package Example: skipping update (pinned)..." Pkg.update() + @test_logs (:info,"Package Example: skipping update (pinned)...") match_mode=:any Pkg.update() @test Pkg.installed("Example") == v"0.4.0" - @test_warn ("INFO: Creating Example branch pinned.d1ef7b00.tmp", - "INFO: No packages to install, update or remove") Pkg.pin("Example", v"0.3.1") + @test_logs((:info,"Creating Example branch pinned.d1ef7b00.tmp"), + nothingtodomsg, Pkg.pin("Example", v"0.3.1")) @test Pkg.installed("Example") == v"0.3.1" - @test_warn ("INFO: Package Example: checking out existing branch pinned.b1990792.tmp", - "INFO: No packages to install, update or remove") Pkg.pin("Example", v"0.4.0") + @test_logs((:info,"Package Example: checking out existing branch pinned.b1990792.tmp"), + nothingtodomsg, Pkg.pin("Example", v"0.4.0")) @test Pkg.installed("Example") == v"0.4.0" - @test_warn ("INFO: Freeing Example", - "INFO: No packages to install, update or remove") Pkg.free("Example") + @test_logs((:info,"Freeing Example"), + nothingtodomsg, Pkg.free("Example")) @test Pkg.installed("Example") == vers - @test_warn Regex("^INFO: Package Example: checking out existing branch $branch\$") Pkg.pin("Example") + @test_logs (:info,Regex("^Package Example: checking out existing branch $branch\$")) Pkg.pin("Example") @test Pkg.installed("Example") == vers - @test_warn "INFO: Freeing Example" Pkg.free("Example") + @test_logs((:info,"Freeing Example"), + nothingtodomsg, Pkg.free("Example")) @test Pkg.installed("Example") == vers end @@ -400,15 +407,15 @@ temp_pkg_dir() do touch(depsbuild) # Pkg.build works without the src directory now # but it's probably fine to require it. - msg = read(`$(Base.julia_cmd()) --startup-file=no -e 'redirect_stderr(STDOUT); Pkg.build("BuildFail")'`, String) + msg = read(`$(Base.julia_cmd()) --startup-file=no -e 'redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); Pkg.build("BuildFail")'`, String) @test contains(msg, "Building BuildFail") - @test !contains(msg, "ERROR") + @test !contains(msg, "Build failed for BuildFail") open(depsbuild, "w") do fd println(fd, "error(\"Throw build error\")") end - msg = read(`$(Base.julia_cmd()) --startup-file=no -e 'redirect_stderr(STDOUT); Pkg.build("BuildFail")'`, String) + msg = read(`$(Base.julia_cmd()) --startup-file=no -e 'redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); Pkg.build("BuildFail")'`, String) @test contains(msg, "Building BuildFail") - @test contains(msg, "ERROR") + @test contains(msg, "Build failed for BuildFail") @test contains(msg, "Pkg.build(\"BuildFail\")") @test contains(msg, "Throw build error") end @@ -417,7 +424,7 @@ temp_pkg_dir() do let package = "Example" Pkg.rm(package) # Remove package if installed @test Pkg.installed(package) === nothing # Registered with METADATA but not installed - msg = read(ignorestatus(`$(Base.julia_cmd()) --startup-file=no -e "redirect_stderr(STDOUT); Pkg.build(\"$package\")"`), String) + msg = read(ignorestatus(`$(Base.julia_cmd()) --startup-file=no -e "redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); Pkg.build(\"$package\")"`), String) @test contains(msg, "$package is not an installed package") @test !contains(msg, "signal (15)") end @@ -442,34 +449,35 @@ temp_pkg_dir() do # partial Pkg.update @test "" == capture_stdout() do - nothingtodomsg = "INFO: No packages to install, update or remove" + nothingtodomsg = (:info,"No packages to install, update or remove") - @test_warn "INFO: Installing Example v" begin + @test_logs (:info,r"Installing Example v") match_mode=:any begin Pkg.rm("Example") Pkg.add("Example") end - @test_warn nothingtodomsg Pkg.update("Example") + @test_logs nothingtodomsg match_mode=:any Pkg.update("Example") - @test_warn "INFO: Installing Example v0.4.0" begin + @test_logs (:info,"Installing Example v0.4.0") match_mode=:any begin Pkg.rm("Example") Pkg.add("Example", v"0", v"0.4.1-") # force version to be < 0.4.1 end - @test_warn (r"INFO: Package Example was set to version 0\.4\.0, but a higher version \d+\.\d+\.\d+\S* exists.", - "The update is prevented by explicit requirements constraints. Edit your REQUIRE file to change this.", - nothingtodomsg) Pkg.update("Example") - @test_warn "INFO: Installing Example" begin + @test_logs((:info,r"""Package Example was set to version 0\.4\.0, but a higher version \d+\.\d+\.\d+\S* exists. + The update is prevented by explicit requirements constraints. Edit your REQUIRE file to change this."""), + nothingtodomsg, match_mode=:any, Pkg.update("Example")) + + @test_logs (:info,r"Installing Example") match_mode=:any begin Pkg.rm("Example") Pkg.add("Example") Pkg.pin("Example", v"0.4.0") end - @test_warn ("INFO: Package Example: skipping update (pinned)...", - r"INFO: Package Example was set to version 0\.4\.0, but a higher version \d+\.\d+\.\d+\S* exists.", - "The package is fixed. You can try using `Pkg.free(\"Example\")` to update it.", - nothingtodomsg) Pkg.update("Example") + @test_logs((:info,"Package Example: skipping update (pinned)..."), + (:info,r"""Package Example was set to version 0\.4\.0, but a higher version \d+\.\d+\.\d+\S* exists. + The package is fixed. You can try using `Pkg.free\("Example"\)` to update it."""), + nothingtodomsg, match_mode=:any, Pkg.update("Example")) metadata_dir = Pkg.dir("METADATA") old_commit = "313bfaafa301e82d40574a778720e893c559a7e2" @@ -487,28 +495,33 @@ temp_pkg_dir() do @test isempty(Pkg.dependents("Example")) @test isempty(Pkg.dependents("Example.jl")) - @test_warn s -> !contains(s, "updated but were already imported") begin + logs,_ = Test.collect_test_logs() do Pkg.add("Iterators") Pkg.update("Iterators") end + @test all(!contains(l.message,"updated but were already imported") for l in logs) # Do it again, because the above Iterators test will update things prematurely LibGit2.with(LibGit2.GitRepo, metadata_dir) do repo LibGit2.reset!(repo, LibGit2.GitHash(old_commit), LibGit2.Consts.RESET_HARD) end - @test_warn ("INFO: Installing Colors v0.6.4", - "INFO: Installing ColorTypes v0.2.2", - "INFO: Installing FixedPointNumbers v0.1.3", - "INFO: Installing Compat v0.7.18", - "INFO: Installing Reexport v0.0.3") Pkg.add("Colors") + @test_logs((:info,"Installing Colors v0.6.4"), + (:info,"Installing ColorTypes v0.2.2"), + (:info,"Installing FixedPointNumbers v0.1.3"), + (:info,"Installing Compat v0.7.18"), + (:info,"Installing Reexport v0.0.3"), match_mode=:any, Pkg.add("Colors")) + + logs,_ = Test.collect_test_logs() do + Pkg.update("ColorTypes") + end + @test any(ismatch((:info,r"Upgrading ColorTypes: v0\.2\.2 => v\d+\.\d+\.\d+"), l) for l in logs) + @test any(ismatch((:info,r"Upgrading Compat: v0\.7\.18 => v\d+\.\d+\.\d+"), l) for l in logs) + @test !any(ismatch((:info,r"Upgrading Colors"),l) for l in logs) - @test_warn (r"INFO: Upgrading ColorTypes: v0\.2\.2 => v\d+\.\d+\.\d+", - r"INFO: Upgrading Compat: v0\.7\.18 => v\d+\.\d+\.\d+", - s -> !contains(s, "INFO: Upgrading Colors: ")) Pkg.update("ColorTypes") @test Pkg.installed("Colors") == v"0.6.4" - @test_warn nothingtodomsg Pkg.update("FixedPointNumbers") + @test_logs nothingtodomsg match_mode=:any Pkg.update("FixedPointNumbers") end # issue #18239 @@ -526,15 +539,15 @@ temp_pkg_dir() do Pkg.add(package) msg = read(ignorestatus(`$(Base.julia_cmd()) --startup-file=no -e - "redirect_stderr(STDOUT); using Example; Pkg.update(\"$package\")"`), String) - @test contains(msg, "- $package\nRestart Julia to use the updated versions.") + "redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); using Example; Pkg.update(\"$package\")"`), String) + @test ismatch(Regex("- $package.*Restart Julia to use the updated versions","s"), msg) end # Verify that the --startup-file flag is respected by Pkg.build / Pkg.test let package = "StartupFile" content = """ - info("JULIA_RC_LOADED defined \$(isdefined(@__MODULE__, :JULIA_RC_LOADED))") - info("Main.JULIA_RC_LOADED defined \$(isdefined(Main, :JULIA_RC_LOADED))") + @info "JULIA_RC_LOADED defined \$(isdefined(@__MODULE__, :JULIA_RC_LOADED))" + @info "Main.JULIA_RC_LOADED defined \$(isdefined(Main, :JULIA_RC_LOADED))" """ write_build(package, content) @@ -549,27 +562,27 @@ temp_pkg_dir() do write(joinpath(home, ".juliarc.jl"), "const JULIA_RC_LOADED = true") withenv((Sys.iswindows() ? "USERPROFILE" : "HOME") => home) do - code = "redirect_stderr(STDOUT); Pkg.build(\"$package\")" + code = "redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); Pkg.build(\"$package\")" msg = read(`$(Base.julia_cmd()) --startup-file=no -e $code`, String) - @test contains(msg, "INFO: JULIA_RC_LOADED defined false") - @test contains(msg, "INFO: Main.JULIA_RC_LOADED defined false") + @test contains(msg, "JULIA_RC_LOADED defined false") + @test contains(msg, "Main.JULIA_RC_LOADED defined false") msg = read(`$(Base.julia_cmd()) --startup-file=yes -e $code`, String) - @test contains(msg, "INFO: JULIA_RC_LOADED defined false") - @test contains(msg, "INFO: Main.JULIA_RC_LOADED defined true") + @test contains(msg, "JULIA_RC_LOADED defined false") + @test contains(msg, "Main.JULIA_RC_LOADED defined true") - code = "redirect_stderr(STDOUT); Pkg.test(\"$package\")" + code = "redirect_stderr(STDOUT); using Logging; global_logger(SimpleLogger(STDOUT)); Pkg.test(\"$package\")" msg = read(`$(Base.julia_cmd()) --startup-file=no -e $code`, String) - @test contains(msg, "INFO: JULIA_RC_LOADED defined false") - @test contains(msg, "INFO: Main.JULIA_RC_LOADED defined false") + @test contains(msg, "JULIA_RC_LOADED defined false") + @test contains(msg, "Main.JULIA_RC_LOADED defined false") # Note: Since both the startup-file and "runtests.jl" are run in the Main # module any global variables created in the .juliarc.jl can be referenced. msg = read(`$(Base.julia_cmd()) --startup-file=yes -e $code`, String) - @test contains(msg, "INFO: JULIA_RC_LOADED defined true") - @test contains(msg, "INFO: Main.JULIA_RC_LOADED defined true") + @test contains(msg, "JULIA_RC_LOADED defined true") + @test contains(msg, "Main.JULIA_RC_LOADED defined true") end end @@ -660,18 +673,19 @@ temp_pkg_dir(initialize=false) do cd(Pkg.dir()) do errors = Dict() + # Log forwarding TODO - port these to @test_logs empty!(errors) - @test_warn ("INFO: Building Error", - "INFO: Building Normal") Pkg.Entry.build!(["Error", "Normal"], errors) + @test_warn ("Building Error", + "Building Normal") Pkg.Entry.build!(["Error", "Normal"], errors) empty!(errors) - @test_warn ("INFO: Building Exit", - "INFO: Building Normal") Pkg.Entry.build!(["Exit", "Normal"], errors) + @test_warn ("Building Exit", + "Building Normal") Pkg.Entry.build!(["Exit", "Normal"], errors) empty!(errors) - @test_warn ("INFO: Building Exit", - "INFO: Building Normal", - "INFO: Building Exit", - "INFO: Building Normal") Pkg.Entry.build!(["Exit", "Normal", "Exit", "Normal"], errors) + @test_warn ("Building Exit", + "Building Normal", + "Building Exit", + "Building Normal") Pkg.Entry.build!(["Exit", "Normal", "Exit", "Normal"], errors) end end diff --git a/test/read.jl b/test/read.jl index fc7f5954da0c1..c72ac33deb9b4 100644 --- a/test/read.jl +++ b/test/read.jl @@ -452,7 +452,7 @@ if !Sys.iswindows() && get(ENV, "USER", "") != "root" && get(ENV, "HOME", "") != @test_throws SystemError open(f) @test_throws Base.UVError Base.Filesystem.open(f, Base.Filesystem.JL_O_RDONLY) else - Sys.iswindows() || warn("file permissions tests skipped due to running tests as root (not recommended)") + Sys.iswindows() || @warn "File permissions tests skipped due to running tests as root (not recommended)" close(open(f)) end chmod(f, 0o400) @@ -500,7 +500,7 @@ if get(ENV, "USER", "") != "root" && get(ENV, "HOME", "") != "/root" @test_throws SystemError open(f, "r+") @test_throws Base.UVError Base.Filesystem.open(f, Base.Filesystem.JL_O_RDWR) else - warn("file permissions tests skipped due to running tests as root (not recommended)") + @warn "File permissions tests skipped due to running tests as root (not recommended)" end chmod(f, 0o600) f1 = open(f, "r+") diff --git a/test/reflection.jl b/test/reflection.jl index 882063917a63c..d471f005db531 100644 --- a/test/reflection.jl +++ b/test/reflection.jl @@ -602,8 +602,8 @@ has_backslashes(x) = Nullable{Method}() h16850 = has_backslashes(Base) if Sys.iswindows() if isnull(h16850) - warn("No methods found in Base with backslashes in file name, ", - "skipping test for Base.url") + @warn """No methods found in Base with backslashes in file name, + skipping test for `Base.url`""" else @test !('\\' in Base.url(get(h16850))) end diff --git a/test/show.jl b/test/show.jl index 00434d2d085ab..ea1b6df260a2d 100644 --- a/test/show.jl +++ b/test/show.jl @@ -469,7 +469,7 @@ let filename = tempname() @test chomp(read(filename, String)) == "hello" ret = open(filename, "w") do f redirect_stderr(f) do - warn("hello") + println(STDERR, "WARNING: hello") [2] end end diff --git a/test/socket.jl b/test/socket.jl index 0b7a62bc7e2e9..99a6ebcffcc3a 100644 --- a/test/socket.jl +++ b/test/socket.jl @@ -333,7 +333,7 @@ end end catch e if isa(e, Base.UVError) && Base.uverrorname(e) == "EPERM" - warn("UDP broadcast test skipped (permission denied upon send, restrictive firewall?)") + @warn "UDP broadcast test skipped (permission denied upon send, restrictive firewall?)" else rethrow() end diff --git a/test/spawn.jl b/test/spawn.jl index ff5004f6d4fe7..93703cef90c44 100644 --- a/test/spawn.jl +++ b/test/spawn.jl @@ -459,7 +459,7 @@ if Sys.isunix() push!(ps, p) end if isnull(ulimit_n) - warn("`ulimit -n` is set to unlimited, fd exhaustion cannot be tested") + @warn "`ulimit -n` is set to unlimited, fd exhaustion cannot be tested" @test_broken false else @test false