RFC: Base logging

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

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)

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

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

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,35 +64,45 @@ 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,))
 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)

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.

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
 

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