From 939aef2e4b9208371da7bee13da1a79e421efda9 Mon Sep 17 00:00:00 2001 From: Tim Holy Date: Fri, 24 Aug 2018 05:44:56 -0500 Subject: [PATCH] Create our own custom logger It turns out that using TestLogger interacted with atsign-testset. Consequently, it's better to use something completely independent. The overall design of the logger mimics that of TestLogger. This also adds some convenience utilities and nicer printing. Overall it makes it considerably nicer to collect and inspect logs. --- docs/src/debugging.md | 53 +++++++++------- docs/src/user_reference.md | 12 ++++ src/Revise.jl | 106 +++++++++++--------------------- src/logging.jl | 122 +++++++++++++++++++++++++++++++++++++ src/parsing.jl | 4 +- src/recipes.jl | 4 +- src/types.jl | 14 ----- test/runtests.jl | 23 ++++--- 8 files changed, 223 insertions(+), 115 deletions(-) create mode 100644 src/logging.jl diff --git a/docs/src/debugging.md b/docs/src/debugging.md index eb86f294..96c99f63 100644 --- a/docs/src/debugging.md +++ b/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,8 +71,7 @@ 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. @@ -70,6 +79,7 @@ If you want to make use of this, it can be handy to capture the start time with 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. diff --git a/docs/src/user_reference.md b/docs/src/user_reference.md index 9cf73b4b..3e040921 100644 --- a/docs/src/user_reference.md +++ b/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 ``` diff --git a/src/Revise.jl b/src/Revise.jl index d8ab1ea4..bff8a656 100644 --- a/src/Revise.jl +++ b/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[]) diff --git a/src/logging.jl b/src/logging.jl new file mode 100644 index 00000000..b9c06f4c --- /dev/null +++ b/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) diff --git a/src/parsing.jl b/src/parsing.jl index 03a6e599..7cc15a75 100644 --- a/src/parsing.jl +++ b/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 diff --git a/src/recipes.jl b/src/recipes.jl index d71c58eb..53d53e4c 100644 --- a/src/recipes.jl +++ b/src/recipes.jl @@ -22,7 +22,9 @@ function track(mod::Module) push!(fileinfos, filename=>FileInfo(submod, basesrccache)) push!(files, filename) if mtime(filename) > mtcache - @debug "Recipe for Base" _group="Watching" filename=filename mtime=mtime(filename) mtimeref=mtcache + with_logger(_debug_logger) do + @debug "Recipe for Base" _group="Watching" filename=filename mtime=mtime(filename) mtimeref=mtcache + end push!(revision_queue, filename) end end diff --git a/src/types.jl b/src/types.jl index 6a9f4769..dad976e1 100644 --- a/src/types.jl +++ b/src/types.jl @@ -132,17 +132,3 @@ end function Base.showerror(io::IO, ex::GitRepoException) print(io, "no repository at ", ex.filename, " to track stdlibs you must build Julia from source") end - -""" - 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) diff --git a/test/runtests.jl b/test/runtests.jl index 19474c41..db578741 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -6,8 +6,8 @@ using Test using Pkg, Unicode, Distributed, InteractiveUtils, REPL import LibGit2 using OrderedCollections: OrderedSet -using Test: collect_test_logs, TestLogger -using Base.CoreLogging: Debug, global_logger +using Test: collect_test_logs +using Base.CoreLogging: Debug,Info include("common.jl") @@ -220,18 +220,18 @@ k(x) = 4 end @testset "Comparison and line numbering" begin + # We'll also use these tests to try out the logging system + rlogger = Revise.debug_logger() + fl1 = joinpath(@__DIR__, "revisetest.jl") fl2 = joinpath(@__DIR__, "revisetest_revised.jl") fl3 = joinpath(@__DIR__, "revisetest_errors.jl") - # Also test logging - rlogger = TestLogger(min_level=Debug) - stdlogger = global_logger(rlogger) include(fl1) # So the modules are defined # test the "mistakes" @test ReviseTest.cube(2) == 16 @test ReviseTest.Internal.mult3(2) == 8 @test ReviseTest.Internal.mult4(2) == -2 - # Construct the Diff from the deletion while we still have the method + # One method will be deleted, for log testing we need to grab it while we still have it delmeth = first(methods(ReviseTest.Internal.mult4)) oldmd = Revise.parse_source(fl1, Main) @@ -292,13 +292,16 @@ k(x) = 4 end return nothing end - logs = filter(r->r.level==Debug && r._module==Revise && r.group=="Action", rlogger.logs) + logs = filter(r->r.level==Debug && r.group=="Action", rlogger.logs) @test length(logs) == 5 cmpdiff(logs[1], "Eval"; deltainfo=(ReviseTest, Revise.relocatable!(:(cube(x) = x^3)))) cmpdiff(logs[2], "Eval"; deltainfo=(ReviseTest, Revise.relocatable!(:(fourth(x) = x^4)))) cmpdiff(logs[3], "LineOffset"; deltainfo=(Any[Tuple{typeof(ReviseTest.Internal.mult2),Any}], 13, 0 => 2)) cmpdiff(logs[4], "Eval"; deltainfo=(ReviseTest.Internal, Revise.relocatable!(:(mult3(x) = 3*x)))) cmpdiff(logs[5], "DeleteMethod"; deltainfo=(Tuple{typeof(ReviseTest.Internal.mult4),Any}, MethodSummary(delmeth))) + @test length(Revise.actions(rlogger)) == 4 # by default LineOffset is skipped + @test length(Revise.actions(rlogger; line=true)) == 5 + @test length(Revise.diffs(rlogger)) == 2 empty!(rlogger.logs) # Backtraces @@ -321,11 +324,13 @@ k(x) = 4 @test bt.func == :mult2 && bt.file == Symbol(fl3) && bt.line == 13 end - logs = filter(r->r.level==Debug && r._module==Revise && r.group=="Action", rlogger.logs) + logs = filter(r->r.level==Debug && r.group=="Action", rlogger.logs) @test length(logs) == 2 cmpdiff(logs[1], "Eval"; deltainfo=(ReviseTest, Revise.relocatable!(:(cube(x) = error("cube"))))) cmpdiff(logs[2], "Eval"; deltainfo=(ReviseTest.Internal, Revise.relocatable!(:(mult2(x) = error("mult2"))))) - global_logger(stdlogger) + + # Turn off future logging + Revise.debug_logger(; min_level=Info) # Gensymmed symbols rex1 = Revise.relocatable!(macroexpand(Main, :(t = @elapsed(foo(x)))))