Create our own custom logger

docs/src/debugging.md

@@ -16,23 +16,33 @@ Currently, the best way to turn on logging is within a running Julia session:
 
 ```jldoctest; setup=(using Revise)
 julia> rlogger = Revise.debug_logger()
-Test.TestLogger(Test.LogRecord[], Debug, false, nothing)
+Revise.ReviseLogger(Revise.LogRecord[], Debug)
 ```
-Hold on to `rlogger`; you're going to use it at the end to retrieve the logs.
-
-!!! note
-
-    This replaces the global logger; in rare circumstances this may have consequences for other code.
+You'll use `rlogger` at the end to retrieve the logs.
 
 Now carry out the series of julia commands and code edits that reproduces the problem.
 
 ## Capturing the logs and submitting them with your bug report
 
 Once all the revisions have been triggered and the mistake has been reproduced,
-it's time to capture the logs:
+it's time to capture the logs.
+To capture all the logs, use
+
+```julia
+julia> logs = filter(r->r.level==Debug, rlogger.logs);
+```
+
+You can capture just the log events that recorded a difference between two
+versions of the same file with
 
 ```julia
-julia> logs = filter(r->r.level==Debug && r._module==Revise, rlogger.logs);
+julia> log = Revise.diffs(rlogger)
+```
+
+or just the changes that Revise made to running code with
+
+```julia
+julia> logs = Revise.actions(rlogger)
 ```
 
 You can either let these print to the console and copy/paste the text output into the
@@ -61,15 +71,15 @@ flavors:
   `(sigt, newlineno, oldoffset=>newoffset)`.
 
 If you're debugging mistakes in method creation/deletion, the `"LineOffset"` events
-may be distracting; you can remove them by additionally filtering on
-`r.message ∈ ("Eval", "DeleteMethod")`.
+may be distracting; by default [`Revise.actions`](@ref) excludes these events.
 
 Note that Revise records the time of each revision, which can sometimes be useful in
 determining which revisions occur in conjunction with which user actions.
 If you want to make use of this, it can be handy to capture the start time with `tstart = time()`
 before commencing on a session.
 
 See [`Revise.debug_logger`](@ref) for information on groups besides "Action."
+One part
 
 ## A complete debugging demo
 
@@ -91,34 +101,35 @@ julia> ReviseTest.cube(3)
 27
 
 julia> rlogger.logs
-8-element Array{Test.LogRecord,1}:
- Test.LogRecord(Debug, "Diff", Revise, "Parsing", :Revise_1dfe9141, "/home/tim/.julia/dev/Revise/src/Revise.jl", 212, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:activemodule, :newexprs, :oldexprs),Tuple{Tuple{Symbol},Set{Revise.RelocatableExpr},Set{Revise.RelocatableExpr}}}}(:activemodule=>(:Main,),:newexprs=>Set(Revise.RelocatableExpr[]),:oldexprs=>Set(Revise.RelocatableExpr[])))
- Test.LogRecord(Debug, "Diff", Revise, "Parsing", :Revise_1dfe9142, "/home/tim/.julia/dev/Revise/src/Revise.jl", 212, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:activemodule, :newexprs, :oldexprs),Tuple{Tuple{Symbol,Symbol},Set{Revise.RelocatableExpr},Set{Revise.RelocatableExpr}}}}(:activemodule=>(:Main, :ReviseTest),:newexprs=>Set(Revise.RelocatableExpr[:(fourth(x) = begin
+8-element Array{Revise.LogRecord,1}:
+ Revise.LogRecord(Debug, Diff, Parsing, Revise_1dfe9141, "/home/tim/.julia/dev/Revise/src/Revise.jl", 214, (activemodule=(:Main,), newexprs=Set(Revise.RelocatableExpr[]), oldexprs=Set(Revise.RelocatableExpr[])))
+ Revise.LogRecord(Debug, Diff, Parsing, Revise_1dfe9142, "/home/tim/.julia/dev/Revise/src/Revise.jl", 214, (activemodule=(:Main, :ReviseTest), newexprs=Set(Revise.RelocatableExpr[:(fourth(x) = begin
           x ^ 4
       end), :(cube(x) = begin
           x ^ 3
-      end)]),:oldexprs=>Set(Revise.RelocatableExpr[:(cube(x) = begin
+      end)]), oldexprs=Set(Revise.RelocatableExpr[:(cube(x) = begin
           x ^ 4
       end)])))
- Test.LogRecord(Debug, "Eval", Revise, "Action", :Revise_443cc0b6, "/home/tim/.julia/dev/Revise/src/Revise.jl", 267, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol},NamedTuple{(:time, :deltainfo),Tuple{Float64,Tuple{Module,Revise.RelocatableExpr}}}}(:time=>1.53487e9,:deltainfo=>(Main.ReviseTest, :(cube(x) = begin
+ Revise.LogRecord(Debug, Eval, Action, Revise_443cc0b6, "/home/tim/.julia/dev/Revise/src/Revise.jl", 270, (time=1.535105837129072e9, deltainfo=(Main.ReviseTest, :(cube(x) = begin
           x ^ 3
       end))))
- Test.LogRecord(Debug, "Eval", Revise, "Action", :Revise_443cc0b7, "/home/tim/.julia/dev/Revise/src/Revise.jl", 267, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol},NamedTuple{(:time, :deltainfo),Tuple{Float64,Tuple{Module,Revise.RelocatableExpr}}}}(:time=>1.53487e9,:deltainfo=>(Main.ReviseTest, :(fourth(x) = begin
+ Revise.LogRecord(Debug, Eval, Action, Revise_443cc0b7, "/home/tim/.julia/dev/Revise/src/Revise.jl", 270, (time=1.535105837152789e9, deltainfo=(Main.ReviseTest, :(fourth(x) = begin
           x ^ 4
       end))))
- Test.LogRecord(Debug, "Diff", Revise, "Parsing", :Revise_1dfe9143, "/home/tim/.julia/dev/Revise/src/Revise.jl", 212, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:activemodule, :newexprs, :oldexprs),Tuple{Tuple{Symbol,Symbol,Symbol},Set{Revise.RelocatableExpr},Set{Revise.RelocatableExpr}}}}(:activemodule=>(:Main, :ReviseTest, :Internal),:newexprs=>Set(Revise.RelocatableExpr[:(mult3(x) = begin
+ Revise.LogRecord(Debug, Diff, Parsing, Revise_1dfe9143, "/home/tim/.julia/dev/Revise/src/Revise.jl", 214, (activemodule=(:Main, :ReviseTest, :Internal), newexprs=Set(Revise.RelocatableExpr[:(mult3(x) = begin
           3x
-      end)]),:oldexprs=>Set(Revise.RelocatableExpr[:(mult4(x) = begin
+      end)]), oldexprs=Set(Revise.RelocatableExpr[:(mult4(x) = begin
           -x
       end), :(mult3(x) = begin
           4x
       end)])))
- Test.LogRecord(Debug, "LineOffset", Revise, "Action", :Revise_3e9f6659, "/home/tim/.julia/dev/Revise/src/Revise.jl", 227, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol},NamedTuple{(:time, :deltainfo),Tuple{Float64,Tuple{Array{Any,1},Int64,Pair{Int64,Int64}}}}}(:time=>1.53487e9,:deltainfo=>(Any[Tuple{typeof(mult2),Any}], 13, 0=>2)))
- Test.LogRecord(Debug, "Eval", Revise, "Action", :Revise_443cc0b8, "/home/tim/.julia/dev/Revise/src/Revise.jl", 267, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol},NamedTuple{(:time, :deltainfo),Tuple{Float64,Tuple{Module,Revise.RelocatableExpr}}}}(:time=>1.53487e9,:deltainfo=>(Main.ReviseTest.Internal, :(mult3(x) = begin
+ Revise.LogRecord(Debug, LineOffset, Action, Revise_3e9f6659, "/home/tim/.julia/dev/Revise/src/Revise.jl", 229, (time=1.535105837187501e9, deltainfo=(Any[Tuple{typeof(mult2),Any}], 13, 0 => 2)))
+ Revise.LogRecord(Debug, Eval, Action, Revise_443cc0b8, "/home/tim/.julia/dev/Revise/src/Revise.jl", 270, (time=1.535105837214e9, deltainfo=(Main.ReviseTest.Internal, :(mult3(x) = begin
           3x
       end))))
- Test.LogRecord(Debug, "DeleteMethod", Revise, "Action", :Revise_04f4de6f, "/home/tim/.julia/dev/Revise/src/Revise.jl", 249, Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol},NamedTuple{(:time, :deltainfo),Tuple{Float64,Tuple{DataType,MethodSummary}}}}(:time=>1.53487e9,:deltainfo=>(Tuple{typeof(mult4),Any}, MethodSummary(:mult4, :Internal, Symbol("/tmp/revisetest.jl"), 13, Tuple{typeof(mult4),Any}))))
+ Revise.LogRecord(Debug, DeleteMethod, Action, Revise_04f4de6f, "/home/tim/.julia/dev/Revise/src/Revise.jl", 251, (time=1.535105837214255e9, deltainfo=(Tuple{typeof(Main.ReviseTest.Internal.mult4),Any}, MethodSummary(:mult4, :Internal, Symbol("/tmp/revisetest.jl"), 13, Tuple{typeof(Main.ReviseTest.Internal.mult4),Any}))))
 ```
+
 In addition to the "Action" items, you can see other entries that record the "Diff"s encountered
 by Revise during revision.
 

docs/src/user_reference.md

@@ -9,7 +9,19 @@ prevent it from watching specific packages.
 revise
 Revise.track
 includet
+```
+
+### Revise logs (debugging Revise)
+
+```@docs
 Revise.debug_logger
+Revise.actions
+Revise.diffs
+```
+
+### Prevent Revise from watching specific packages
+
+```@docs
 Revise.dont_watch_pkgs
 Revise.silence
 ```

src/Revise.jl

@@ -1,6 +1,6 @@
 module Revise
 
-using FileWatching, REPL, Base.CoreLogging, Distributed, UUIDs
+using FileWatching, REPL, Distributed, UUIDs
 import LibGit2
 using Base: PkgId
 
@@ -61,6 +61,7 @@ include("exprutils.jl")
 include("pkgs.jl")
 include("git.jl")
 include("recipes.jl")
+include("logging.jl")
 
 ### Globals to keep track of state
 
@@ -209,44 +210,46 @@ end
 function eval_revised!(fmmrep::FMMaps, mod::Module,
                        fmmnew::FMMaps, fmmref::FMMaps)
     # Update to the state of fmmnew, preventing any unnecessary evaluation
-    @debug "Diff" _group="Parsing" activemodule=fullname(mod) newexprs=setdiff(keys(fmmnew.defmap), keys(fmmref.defmap)) oldexprs=setdiff(keys(fmmref.defmap), keys(fmmnew.defmap))
-    for (def,val) in fmmnew.defmap
-        @assert def != nothing
-        defref = getkey(fmmref.defmap, def, nothing)
-        if defref != nothing
-            # The same expression is found in both, only update the lineoffset
-            if val !== nothing
-                sigtref, oldoffset = fmmref.defmap[defref]
-                lnref = firstlineno(defref)
-                lnnew = firstlineno(def)
-                lineoffset = (isa(lnref, Integer) && isa(lnnew, Integer)) ? lnnew-lnref : 0
-                fmmrep.defmap[defref] = (sigtref, lineoffset)
-                for sigt in sigtref
-                    fmmrep.sigtmap[sigt] = defref
+    with_logger(_debug_logger) do
+        @debug "Diff" _group="Parsing" activemodule=fullname(mod) newexprs=setdiff(keys(fmmnew.defmap), keys(fmmref.defmap)) oldexprs=setdiff(keys(fmmref.defmap), keys(fmmnew.defmap))
+        for (def,val) in fmmnew.defmap
+            @assert def != nothing
+            defref = getkey(fmmref.defmap, def, nothing)
+            if defref != nothing
+                # The same expression is found in both, only update the lineoffset
+                if val !== nothing
+                    sigtref, oldoffset = fmmref.defmap[defref]
+                    lnref = firstlineno(defref)
+                    lnnew = firstlineno(def)
+                    lineoffset = (isa(lnref, Integer) && isa(lnnew, Integer)) ? lnnew-lnref : 0
+                    fmmrep.defmap[defref] = (sigtref, lineoffset)
+                    for sigt in sigtref
+                        fmmrep.sigtmap[sigt] = defref
+                    end
+                    oldoffset != lineoffset && @debug "LineOffset" _group="Action" time=time() deltainfo=(sigtref, lnnew, oldoffset=>lineoffset)
+                else
+                    fmmrep.defmap[defref] = nothing
                 end
-                oldoffset != lineoffset && @debug "LineOffset" _group="Action" time=time() deltainfo=(sigtref, lnnew, oldoffset=>lineoffset)
             else
-                fmmrep.defmap[defref] = nothing
+                eval_and_insert!(fmmrep, mod, def=>val)
             end
-        else
-            eval_and_insert!(fmmrep, mod, def=>val)
         end
-    end
-    # Delete any methods missing in fmmnew
-    for (sigt,_) in fmmref.sigtmap
-        if !haskey(fmmrep.sigtmap, sigt)
-            m = get_method(sigt)
-            if isa(m, Method)
-                Base.delete_method(m)
-            else
-                mths = Base._methods_by_ftype(sigt, -1, typemax(UInt))
-                io = IOBuffer()
-                println(io, "Extracted method table:")
-                println(io, mths)
-                info = String(take!(io))
-                @warn "Revise failed to find any methods for signature $sigt\n  Perhaps it was already deleted.\n$info"
+        # Delete any methods missing in fmmnew
+        for (sigt,_) in fmmref.sigtmap
+            if !haskey(fmmrep.sigtmap, sigt)
+                m = get_method(sigt)
+                if isa(m, Method)
+                    Base.delete_method(m)
+                else
+                    mths = Base._methods_by_ftype(sigt, -1, typemax(UInt))
+                    io = IOBuffer()
+                    println(io, "Extracted method table:")
+                    println(io, mths)
+                    info = String(take!(io))
+                    @warn "Revise failed to find any methods for signature $sigt\n  Perhaps it was already deleted.\n$info"
+                end
+                @debug "DeleteMethod" _group="Action" time=time() deltainfo=(sigt, MethodSummary(m))
             end
-            @debug "DeleteMethod" _group="Action" time=time() deltainfo=(sigt, MethodSummary(m))
         end
     end
     return fmmrep
@@ -798,41 +801,6 @@ function async_steal_repl_backend()
     return nothing
 end
 
-"""
-    logger = Revise.debug_logger()
-
-Turn on [debug logging](https://docs.julialang.org/en/stable/stdlib/Logging/) and return the logger object.
-`logger.logs` contains a list of the logged events. The items in this list are of type `Test.LogRecord`,
-with the following relevant fields:
-
-- `group`: the event category. Revise currently uses the following groups:
-  + "Action": a change was implemented, of type described in the `message` field.
-  + "Parsing": a "significant" event in parsing. For these, examine the `message` field
-    for more information.
-  + "Watching": an indication that Revise determined that a particular file needed to be
-    examined for possible code changes. This is typically done on the basis of `mtime`,
-    the modification time of the file, and does not necessarily indicate that there were
-    any changes.
-- `message`: a string containing more information. Some examples:
-  + For entries in the "Action" group, `message` can be `"Eval"` when modifying
-    old methods or defining new ones, "DeleteMethod" when deleting a method,
-    and "LineOffset" to indicate that the line offset for a method
-    was updated (the last only affects the printing of stacktraces upon error,
-    it does not change how code runs)
-  + Items with group "Parsing" and message "Diff" contain sets `:newexprs` and `:oldexprs`
-    that contain the expression unique to post- or pre-revision, respectively.
-- `kwargs`: a pairs list of any other data. This is usually specific to particular `group`/`message`
-  combinations.
-
-Note that the logs may also contain information from sources other than Revise.
-"""
-function debug_logger()
-    @eval using Test
-    rlogger = Test.TestLogger(min_level=CoreLogging.Debug)
-    CoreLogging.global_logger(rlogger)
-    return rlogger
-end
-
 function __init__()
     # Base.register_root_module(Base.__toplevel__)
     if isfile(silencefile[])

src/logging.jl

@@ -0,0 +1,122 @@
+using Base.CoreLogging
+using Base.CoreLogging: Info, Debug
+
+struct LogRecord
+    level
+    message
+    group
+    id
+    file
+    line
+    kwargs
+end
+LogRecord(args...; kwargs...) = LogRecord(args..., kwargs)
+
+mutable struct ReviseLogger <: AbstractLogger
+    logs::Vector{LogRecord}
+    min_level::LogLevel
+end
+
+ReviseLogger(; min_level=Info) = ReviseLogger(LogRecord[], min_level)
+
+CoreLogging.min_enabled_level(logger::ReviseLogger) = logger.min_level
+
+CoreLogging.shouldlog(logger::ReviseLogger, level, _module, group, id) = _module == Revise
+
+function CoreLogging.handle_message(logger::ReviseLogger, level, msg, _module,
+                                    group, id, file, line; kwargs...)
+    push!(logger.logs, LogRecord(level, msg, group, id, file, line, kwargs))
+end
+
+CoreLogging.catch_exceptions(::ReviseLogger) = false
+
+function Base.show(io::IO, l::LogRecord)
+    print(io, LogRecord)
+    print(io, '(', l.level, ", ", l.message, ", ", l.group, ", ", l.id, ", \"", l.file, "\", ", l.line)
+    if !isempty(l.kwargs)
+        print(io, ", (")
+        prefix = ""
+        for (kw, val) in l.kwargs
+            print(io, prefix, kw, "=", val)
+            prefix = ", "
+        end
+        print(io, ')')
+    end
+    print(io, ')')
+end
+
+const _debug_logger = ReviseLogger()
+
+"""
+    logger = Revise.debug_logger(; min_level=Debug)
+
+Turn on [debug logging](https://docs.julialang.org/en/stable/stdlib/Logging/)
+(if `min_level` is set to `Debug` or better) and return the logger object.
+`logger.logs` contains a list of the logged events. The items in this list are of type `Revise.LogRecord`,
+with the following relevant fields:
+
+- `group`: the event category. Revise currently uses the following groups:
+  + "Action": a change was implemented, of type described in the `message` field.
+  + "Parsing": a "significant" event in parsing. For these, examine the `message` field
+    for more information.
+  + "Watching": an indication that Revise determined that a particular file needed to be
+    examined for possible code changes. This is typically done on the basis of `mtime`,
+    the modification time of the file, and does not necessarily indicate that there were
+    any changes.
+- `message`: a string containing more information. Some examples:
+  + For entries in the "Action" group, `message` can be `"Eval"` when modifying
+    old methods or defining new ones, "DeleteMethod" when deleting a method,
+    and "LineOffset" to indicate that the line offset for a method
+    was updated (the last only affects the printing of stacktraces upon error,
+    it does not change how code runs)
+  + Items with group "Parsing" and message "Diff" contain sets `:newexprs` and `:oldexprs`
+    that contain the expression unique to post- or pre-revision, respectively.
+- `kwargs`: a pairs list of any other data. This is usually specific to particular `group`/`message`
+  combinations.
+
+See also [`Revise.actions`](@ref) and [`Revise.diffs`](@ref).
+"""
+function debug_logger(; min_level=Debug)
+    _debug_logger.min_level = min_level
+    return _debug_logger
+end
+
+"""
+    actions(logger; line=false)
+
+Return a vector of all log events in the "Action" group. "LineOffset" events are returned
+only if `line=true`; by default the returned items are the events that modified
+methods in your session.
+"""
+function actions(logger::ReviseLogger; line=false)
+    filter(logger.logs) do r
+        r.group=="Action" && (line || r.message!="LineOffset")
+    end
+end
+
+"""
+    diffs(logger)
+
+Return a vector of all log events that encode a (non-empty) diff between two versions of a file.
+"""
+function diffs(logger::ReviseLogger)
+    filter(logger.logs) do r
+        r.message=="Diff" && r.group=="Parsing" && (!isempty(r.kwargs[:newexprs]) || !isempty(r.kwargs[:oldexprs]))
+    end
+end
+
+## Make the logs portable
+
+"""
+    MethodSummary(method)
+
+Create a portable summary of a method. In particular, a MethodSummary can be saved to a JLD2 file.
+"""
+struct MethodSummary
+    name::Symbol
+    modulename::Symbol
+    file::Symbol
+    line::Int32
+    sig::Type
+end
+MethodSummary(m::Method) = MethodSummary(m.name, nameof(m.module), m.file, m.line, m.sig)

src/parsing.jl

@@ -166,7 +166,9 @@ module is "parented" by `mod`. Source-code expressions are added to
 function parse_module!(fm::FileModules, ex::Expr, file::Symbol, mod::Module)
     newname = _module_name(ex)
     if mod != Base.__toplevel__ && !isdefined(mod, newname)
-        @debug "parse_module" _group="Parsing" activemodule=fullname(mod) newmodule=fullname(newname)
+        with_logger(_debug_logger) do
+            @debug "parse_module" _group="Parsing" activemodule=fullname(mod) newmodule
+        end
         try
             Core.eval(mod, ex) # support creating new submodules
         catch