Improve Mocking debugging

Project.toml

@@ -19,7 +19,8 @@ julia = "1"
 [extras]
 Aqua = "4c88cf16-eb10-579e-8560-4a9242c79595"
 Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
 
 [targets]
-test = ["Aqua", "Dates", "Test"]
+test = ["Aqua", "Dates", "Logging", "Test"]

docs/src/faq.md

@@ -23,6 +23,10 @@ When your patch isn't being applied you should remember to check for the followi
 - Call sites you want to patch are using [`@mock`](@ref).
 - The patch's argument types are supertypes the values passed in at the call site.
 
+You can also start Julia with `JULIA_DEBUG=Mocking` to show details about what methods are
+being dispatched to from `@mock`ed call sites. These interception messages are only
+displayed if `Mocking.activate` has been called.
+
 ## Where should I add `Mocking.activate()`?
 
 We recommend putting the call to [`Mocking.activate`](@ref activate) in your package's

src/Mocking.jl

@@ -14,6 +14,7 @@ export @patch, @mock, Patch, apply
 
 include("expr.jl")
 include("dispatch.jl")
+include("debug.jl")
 include("patch.jl")
 include("mock.jl")
 include("deprecated.jl")

src/debug.jl

@@ -0,0 +1,48 @@
+function _intercepted_msg(
+    call_site::AbstractString, method::Union{Method,Nothing}, reason::AbstractString
+)
+    return """
+        Mocking intercepted:
+        call site:  $call_site
+        dispatched: $(method === nothing ? "(no matching method)" : method)
+        reason:     $reason
+        """
+end
+
+function _call_site(target, args, location)
+    call = "$target($(join(map(arg -> "::$(Core.Typeof(arg))", args), ", ")))"
+    return "$call $location"
+end
+
+# Mirroring the print format used when showing a method. Based upon the function
+# `Base.print_module_path_file` which was introduced in Julia 1.10.
+if VERSION >= v"1.9"
+    function _print_module_path_file(io::IO, modul, file::AbstractString, line::Integer)
+        print(io, "@")
+
+        # module
+        modul !== nothing && print(io, " ", modul)
+
+        # filename, separator, line
+        file = contractuser(file)
+        print(io, " ", file, ":", line)
+
+        return nothing
+    end
+else
+    function _print_module_path_file(io::IO, modul, file::AbstractString, line::Integer)
+        print(io, "in")
+
+        # module
+        modul !== nothing && print(io, " ", modul, " at")
+
+        # filename, separator, line
+        print(io, " ", file, ":", line)
+
+        return nothing
+    end
+end
+
+function _print_module_path_file(io::IO, modul, source::LineNumberNode)
+    return _print_module_path_file(io, modul, string(source.file), source.line)
+end

src/mock.jl

@@ -33,14 +33,16 @@ macro mock(expr)
     args = filter(!iskwarg, expr.args[2:end])
     kwargs = extract_kwargs(expr)
 
+    call_loc = sprint(_print_module_path_file, __module__, __source__)
+
     # Due to how world-age works (see Julia issue #265 and PR #17057) when
     # `Mocking.activated` is overwritten then all dependent functions will be recompiled.
     # When `Mocking.activated() == false` then Julia will optimize the
     # code below to have zero-overhead by only executing the original expression.
     result = quote
         if $activated()
             args_var = tuple($(args...))
-            alternate_var = $get_alternate($target, args_var...)
+            alternate_var = $get_alternate($target, args_var...; call_loc=$call_loc)
             if alternate_var !== nothing
                 Base.invokelatest(alternate_var, args_var...; $(kwargs...))
             else
@@ -54,32 +56,32 @@ macro mock(expr)
     return esc(result)
 end
 
-function get_alternate(pe::PatchEnv, target, args...)
+function get_alternate(pe::PatchEnv, target, args...; call_loc)
     if haskey(pe.mapping, target)
         m, f = dispatch(pe.mapping[target], args...)
 
-        if pe.debug
+        @debug begin
+            call_site = _call_site(target, args, call_loc)
             if m !== nothing
-                @info _debug_msg(m, target, args)
+                _intercepted_msg(call_site, m, "Patch called")
             else
                 target_m, _ = dispatch([target], args...)
-                @info _debug_msg(target_m, target, args)
+                _intercepted_msg(call_site, target_m, "No patch handles provided arguments")
             end
-        end
+        end _file = nothing _line = nothing
 
         return f
     else
+        @debug begin
+            call_site = _call_site(target, args, call_loc)
+            target_m, _ = dispatch([target], args...)
+            _intercepted_msg(call_site, target_m, "No patch defined for target function")
+        end _file = nothing _line = nothing
+
         return nothing
     end
 end
 
-get_alternate(target, args...) = get_alternate(PATCH_ENV[], target, args...)
-
-function _debug_msg(method::Union{Method,Nothing}, target, args)
-    call = "$target($(join(map(arg -> "::$(Core.Typeof(arg))", args), ", ")))"
-    return """
-        Mocking intercepted:
-        call:       $call
-        dispatched: $(method === nothing ? "(no matching method)" : method)
-        """
+function get_alternate(target, args...; kwargs...)
+    return get_alternate(PATCH_ENV[], target, args...; kwargs...)
 end

src/patch.jl

@@ -42,19 +42,19 @@ end
 
 struct PatchEnv
     mapping::Dict{Any,Vector{Function}}
-    debug::Bool
+    PatchEnv(mapping::AbstractDict) = new(mapping)
 end
 
-function PatchEnv(patches, debug::Bool=false)
-    pe = PatchEnv(debug)
+function PatchEnv(patches)
+    pe = PatchEnv()
     apply!(pe, patches)
     return pe
 end
 
-PatchEnv(debug::Bool=false) = PatchEnv(Dict{Any,Vector{Function}}(), debug)
+PatchEnv() = PatchEnv(Dict{Any,Vector{Function}}())
 
 function Base.:(==)(pe1::PatchEnv, pe2::PatchEnv)
-    return pe1.mapping == pe2.mapping && pe1.debug == pe2.debug
+    return pe1.mapping == pe2.mapping
 end
 
 """
@@ -75,12 +75,10 @@ pe = PatchEnv(patches)
 
 @assert pe == merge(pe1, pe2)
 ```
-
-The `debug` flag will be set to true if either `pe1` or `pe2` have it set to true.
 """
 function Base.merge(pe1::PatchEnv, pe2::PatchEnv)
     mapping = mergewith(vcat, pe1.mapping, pe2.mapping)
-    return PatchEnv(mapping, pe1.debug || pe2.debug)
+    return PatchEnv(mapping)
 end
 
 function apply!(pe::PatchEnv, p::Patch)
@@ -98,7 +96,7 @@ function apply!(pe::PatchEnv, patches)
 end
 
 """
-    apply(body::Function, patches; debug::Bool=false) -> Any
+    apply(body::Function, patches) -> Any
 
 Applies one or more `patches` during execution of `body`. Specifically ,any [`@mock`](@ref)
 call sites encountered while running `body` will include the provided `patches` when
@@ -201,8 +199,8 @@ function apply(body::Function, pe::PatchEnv)
     return with_active_env(body, merged_pe)
 end
 
-function apply(body::Function, patches; debug::Bool=false)
-    return apply(body, PatchEnv(patches, debug))
+function apply(body::Function, patches)
+    return apply(body, PatchEnv(patches))
 end
 
 # https://github.com/JuliaLang/julia/pull/50958

test/debug.jl

@@ -0,0 +1,38 @@
+@testset "_print_module_path_file" begin
+    using Mocking: _print_module_path_file
+
+    @testset "no module" begin
+        call_site = sprint(_print_module_path_file, nothing, "no-module.jl", 1)
+        if VERSION >= v"1.9"
+            @test call_site == "@ no-module.jl:1"
+        else
+            @test call_site == "in no-module.jl:1"
+        end
+    end
+
+    @testset "no file" begin
+        @test_throws MethodError sprint(_print_module_path_file, Main, nothing, 1)
+    end
+
+    @testset "no line" begin
+        @test_throws MethodError sprint(_print_module_path_file, Main, "file.jl", nothing)
+    end
+
+    @testset "contractuser" begin
+        call_site = sprint(_print_module_path_file, Main, joinpath(homedir(), "user.jl"), 2)
+        if VERSION >= v"1.9"
+            @test call_site == "@ Main $(joinpath("~", "user.jl")):2"
+        else
+            @test call_site == "in Main at $(joinpath(homedir(), "user.jl")):2"
+        end
+    end
+
+    @testset "source" begin
+        call_site = sprint(_print_module_path_file, Main, LineNumberNode(3, "source.jl"))
+        if VERSION >= v"1.9"
+            @test call_site == "@ Main source.jl:3"
+        else
+            @test call_site == "in Main at source.jl:3"
+        end
+    end
+end

test/merge.jl

@@ -17,12 +17,4 @@
 
         @test pe == merge(pe1, pe2)
     end
-
-    @testset "debug flag" begin
-        pe1 = Mocking.PatchEnv(patches[1], true)
-        pe2 = Mocking.PatchEnv(patches[2:3])
-        pe = Mocking.PatchEnv(patches, true)
-
-        @test pe == merge(pe1, pe2)
-    end
 end

test/runtests.jl

@@ -3,20 +3,22 @@ using Test
 
 using Aqua: Aqua
 using Dates: Dates, Hour
+using Logging: Debug
 using Mocking: anon_morespecific, anonymous_signature, apply, dispatch, type_morespecific
 
 Mocking.activate()
 
 @testset "Mocking" begin
     @testset "Code quality (Aqua.jl)" begin
         # Unable to add compat entries for stdlibs while we support Julia 1.0
-        stdlibs = [:Dates, :Test]
+        stdlibs = [:Dates, :Logging, :Test]
         Aqua.test_all(Mocking; deps_compat=(; check_extras=(; ignore=stdlibs)))
     end
 
     include("dispatch.jl")
     include("mock.jl")
     include("patch.jl")
+    include("debug.jl")
 
     include("concept.jl")
     include("targets.jl")

test/targets.jl

@@ -100,3 +100,27 @@ end
     @test !isdefined(@__MODULE__, :f)
     @test_throws UndefVarError (@patch f() = 1)
 end
+
+@testset "debugging" begin
+    f(::Number) = "original"
+
+    patch = @patch f(::Int) = "patched"
+    apply(patch) do
+        # Call patched function
+        @test_logs min_level = Debug (:debug, r"Patch called") begin
+            @test (@mock f(1)) == "patched"
+        end
+
+        # Call original function
+        @test_logs min_level = Debug (:debug, r"No patch handles provided arguments") begin
+            @test (@mock f(1.0)) == "original"
+        end
+    end
+
+    # Call unpatched function
+    apply([]) do
+        @test_logs min_level = Debug (:debug, r"No patch defined for target function") begin
+            @test (@mock f(1)) == "original"
+        end
+    end
+end