added logging() for redirection of info/warn/error messages

Author: bjarthur

NEWS.md

@@ -132,6 +132,9 @@ Library improvements
     implemented; the semantics are as if the `Nullable` were a container with
     zero or one elements ([#16961]).
 
+  * `logging` can be used to redirect `info`, `warn`, and `error` messages
+    either universally or on a per-module/function basis ([#16213]).
+
 Compiler/Runtime improvements
 -----------------------------
 

base/REPL.jl

@@ -110,16 +110,6 @@ function ip_matches_func(ip, func::Symbol)
     return false
 end
 
-function display_error(io::IO, er, bt)
-    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)
-    if eval_ind != 0
-        bt = bt[1:eval_ind-1]
-    end
-    showerror(IOContext(io, :limit => true), er, bt)
-end
-
 immutable REPLDisplay{R<:AbstractREPL} <: Display
     repl::R
 end
@@ -144,8 +134,7 @@ function print_response(errio::IO, val::ANY, bt, show_value::Bool, have_color::B
         try
             Base.sigatomic_end()
             if bt !== nothing
-                display_error(errio, val, bt)
-                println(errio)
+                Base.display_error(errio, val, bt)
                 iserr, lasterr = false, ()
             else
                 if val !== nothing && show_value

base/client.jl

@@ -125,14 +125,26 @@ function repl_cmd(cmd, out)
     nothing
 end
 
-display_error(er) = display_error(er, [])
-function display_error(er, bt)
-    print_with_color(Base.error_color(), STDERR, "ERROR: "; bold = true)
-    with_output_color(Base.error_color(), STDERR) do io
-        showerror(io, er, bt)
+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)
+    if eval_ind != 0
+        bt = bt[1:eval_ind-1]
+    end
+    with_output_color(Base.error_color(), io) do io
+        showerror(IOContext(io, :limit => true), er, bt)
         println(io)
     end
 end
+display_error(er, bt) = display_error(STDERR, er, bt)
+display_error(er) = display_error(er, [])
 
 function eval_user_input(ast::ANY, show_value)
     errcount, lasterr, bt = 0, (), nothing

base/error.jl

@@ -19,6 +19,14 @@
 ## native julia error handling ##
 
 error(s::AbstractString) = throw(ErrorException(s))
+
+"""
+    error(msg...)
+
+Raise an `ErrorException` with the given message.
+
+See also [`logging`](@ref).
+"""
 error(s...) = throw(ErrorException(Main.Base.string(s...)))
 
 rethrow() = ccall(:jl_rethrow, Bottom, ())

base/exports.jl

@@ -810,6 +810,7 @@ export
     isxdigit,
     join,
     lcfirst,
+    logging,
     lowercase,
     lpad,
     lstrip,

base/stacktraces.jl

@@ -153,6 +153,13 @@ function stacktrace(trace::Vector{Ptr{Void}}, c_funcs::Bool=false)
 
     # Remove frame for this function (and any functions called by this function).
     remove_frames!(stack, :stacktrace)
+
+    # is there a better way?  the func symbol has a number suffix which changes.
+    # it's possible that no test is needed and we could just shift! all the time.
+    # this line was added to PR #16213 because otherwise stacktrace() != stacktrace(false).
+    # not sure why.  possibly b/c of re-ordering of base/sysimg.jl
+    !isempty(stack) && startswith(string(stack[1].func),"jlcall_stacktrace") && shift!(stack)
+    stack
 end
 
 stacktrace(c_funcs::Bool=false) = stacktrace(backtrace(), c_funcs)

base/sysimg.jl

@@ -311,6 +311,10 @@ include("REPLCompletions.jl")
 include("REPL.jl")
 include("client.jl")
 
+# Stack frames and traces
+include("stacktraces.jl")
+importall .StackTraces
+
 # misc useful functions & macros
 include("util.jl")
 
@@ -342,10 +346,6 @@ include("libgit2/libgit2.jl")
 # package manager
 include("pkg/pkg.jl")
 
-# Stack frames and traces
-include("stacktraces.jl")
-importall .StackTraces
-
 # profiler
 include("profile.jl")
 importall .Profile

base/util.jl

@@ -335,9 +335,88 @@ println_with_color(color::Union{Int, Symbol}, msg::AbstractString...; bold::Bool
 
 ## 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)
+    isnull(sf.linfo) && return io
+    mod = get(sf.linfo).def.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
+            isnull(frame.linfo) && continue
+            sf = frame
+            break_next_frame && (@goto skip)
+            get(frame.linfo).def.module == 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 && in((nothing,nothing),keys(log_to))
+            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 also be
+`: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(msg...; prefix="INFO: ")
+    info([io, ] msg..., [prefix="INFO: "])
 
 Display an informational message.
 Argument `msg` is a string describing the information to be displayed.
@@ -351,10 +430,14 @@ 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: ")
+    io = redirect(io, log_info_to, :info)
     print_with_color(info_color(), io, prefix; bold = true)
     println_with_color(info_color(), io, chomp(string(msg...)))
+    return
 end
 info(msg...; prefix="INFO: ") = info(STDERR, msg..., prefix=prefix)
 
@@ -365,6 +448,16 @@ 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)
@@ -376,6 +469,7 @@ function warn(io::IO, msg...;
         (key in have_warned) && return
         push!(have_warned, key)
     end
+    io = redirect(io, log_warn_to, :warn)
     print_with_color(warn_color(), io, prefix; bold = true)
     print_with_color(warn_color(), io, str)
     if bt !== nothing

doc/src/stdlib/io-network.md

@@ -66,6 +66,7 @@ Base.println
 Base.print_with_color
 Base.info
 Base.warn
+Base.logging
 Base.Printf.@printf
 Base.Printf.@sprintf
 Base.sprint

test/misc.jl

@@ -28,6 +28,113 @@ let bt = backtrace()
     end
 end
 
+# PR #16213
+module Logging
+    function bar(io)
+        info(io,"barinfo")
+        warn(io,"barwarn")
+        Base.display_error(io,"barerror",backtrace())
+    end
+    function pooh(io)
+        info(io,"poohinfo")
+        warn(io,"poohwarn")
+        Base.display_error(io,"pooherror",backtrace())
+    end
+end
+function foo(io)
+    info(io,"fooinfo")
+    warn(io,"foowarn")
+    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(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+
+logging(DevNull, TestMain_misc.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\""]))
+@test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+logging(DevNull, TestMain_misc.Logging;  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(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(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(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+
+logging(DevNull, TestMain_misc.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\""]))
+@test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+logging(DevNull, TestMain_misc.Logging;  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(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(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(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+
+logging(DevNull, TestMain_misc.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\""]))
+@test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+logging(DevNull, TestMain_misc.Logging;  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(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(foo), ["INFO: fooinfo", "WARNING: foowarn"]))
+
+logging(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(foo), ["INFO: fooinfo", "WARNING: foowarn"]))
+
+
+logging(DevNull, TestMain_misc.Logging, :bar)
+@test sprint(Logging.bar) == ""
+@test all(contains.(sprint(Logging.pooh), ["INFO: poohinfo", "WARNING: poohwarn", "ERROR: \"pooherror\""]))
+@test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+logging(DevNull, TestMain_misc.Logging)
+@test sprint(Logging.bar) == ""
+@test sprint(Logging.pooh) == ""
+@test all(contains.(sprint(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
+logging(DevNull)
+@test sprint(Logging.bar) == ""
+@test sprint(Logging.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(foo), ["INFO: fooinfo", "WARNING: foowarn", "ERROR: \"fooerror\""]))
+
 # test assert() method
 @test_throws AssertionError assert(false)
 let res = assert(true)