From 737e5735b8e88ba293e5712b571ca61a5685756c Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 16 Jul 2024 10:42:07 -0500
Subject: [PATCH 1/6] Use debug logging for Mocking intercept messages

---
 src/mock.jl   | 40 ++++++++++++++++++++++++++++++----------
 src/patch.jl  | 20 +++++++++-----------
 test/merge.jl |  8 --------
 3 files changed, 39 insertions(+), 29 deletions(-)

diff --git a/src/mock.jl b/src/mock.jl
index a8ca487..510012a 100644
--- a/src/mock.jl
+++ b/src/mock.jl
@@ -33,6 +33,10 @@ macro mock(expr)
     args = filter(!iskwarg, expr.args[2:end])
     kwargs = extract_kwargs(expr)
 
+    call_loc = sprint(
+        Base.print_module_path_file, __module__, string(__source__.file), __source__.line
+    )
+
     # 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
@@ -40,7 +44,7 @@ macro mock(expr)
     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 +58,48 @@ 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(get_active_env(), target, args...)
+function get_alternate(target, args...; kwargs...)
+    return get_alternate(get_active_env(), target, args...; kwargs...)
+end
 
-function _debug_msg(method::Union{Method,Nothing}, target, args)
-    call = "$target($(join(map(arg -> "::$(Core.Typeof(arg))", args), ", ")))"
+function _intercepted_msg(
+    call_site::AbstractString, method::Union{Method,Nothing}, reason::AbstractString
+)
     return """
         Mocking intercepted:
-        call:       $call
+        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
diff --git a/src/patch.jl b/src/patch.jl
index 7eedd2c..d995950 100644
--- a/src/patch.jl
+++ b/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
@@ -206,8 +204,8 @@ function apply(body::Function, pe::PatchEnv)
     end
 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
 
 const PATCH_ENV = Ref{PatchEnv}(PatchEnv())
diff --git a/test/merge.jl b/test/merge.jl
index 4e5559a..6236bf1 100644
--- a/test/merge.jl
+++ b/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

From 03d26640ad2e6b07dba9822833deba85ca31e923 Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 16 Jul 2024 10:55:54 -0500
Subject: [PATCH 2/6] Document enabling Mocking debug messages

---
 docs/src/faq.md | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/docs/src/faq.md b/docs/src/faq.md
index 1129023..5cffd9f 100644
--- a/docs/src/faq.md
+++ b/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

From a25a2a250082bad1722f6dba2acfde90745db626 Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 16 Jul 2024 11:51:31 -0500
Subject: [PATCH 3/6] Support call site location on older Julia versions

---
 src/Mocking.jl   |  1 +
 src/debug.jl     | 44 ++++++++++++++++++++++++++++++++++++++++++++
 src/mock.jl      | 33 ++++++++++++++++++++++++++++++---
 test/debug.jl    | 38 ++++++++++++++++++++++++++++++++++++++
 test/runtests.jl |  1 +
 5 files changed, 114 insertions(+), 3 deletions(-)
 create mode 100644 src/debug.jl
 create mode 100644 test/debug.jl

diff --git a/src/Mocking.jl b/src/Mocking.jl
index 67049b9..0560615 100644
--- a/src/Mocking.jl
+++ b/src/Mocking.jl
@@ -7,6 +7,7 @@ export @patch, @mock, Patch, apply
 
 include("expr.jl")
 include("dispatch.jl")
+include("debug.jl")
 include("patch.jl")
 include("mock.jl")
 include("deprecated.jl")
diff --git a/src/debug.jl b/src/debug.jl
new file mode 100644
index 0000000..0347449
--- /dev/null
+++ b/src/debug.jl
@@ -0,0 +1,44 @@
+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)
+    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)
+    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
diff --git a/src/mock.jl b/src/mock.jl
index 510012a..fc728b9 100644
--- a/src/mock.jl
+++ b/src/mock.jl
@@ -33,9 +33,7 @@ macro mock(expr)
     args = filter(!iskwarg, expr.args[2:end])
     kwargs = extract_kwargs(expr)
 
-    call_loc = sprint(
-        Base.print_module_path_file, __module__, string(__source__.file), __source__.line
-    )
+    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.
@@ -103,3 +101,32 @@ 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)
+    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)
+    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
diff --git a/test/debug.jl b/test/debug.jl
new file mode 100644
index 0000000..1a3a558
--- /dev/null
+++ b/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
diff --git a/test/runtests.jl b/test/runtests.jl
index c827a3c..d8ffc25 100644
--- a/test/runtests.jl
+++ b/test/runtests.jl
@@ -16,6 +16,7 @@ Mocking.activate()
     include("dispatch.jl")
     include("mock.jl")
     include("patch.jl")
+    include("debug.jl")
 
     include("concept.jl")
     include("targets.jl")

From 23fae393b8313e124db1d3e1bb4cd7817e299cbf Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 16 Jul 2024 11:54:24 -0500
Subject: [PATCH 4/6] fixup! Support call site location on older Julia versions

---
 src/debug.jl |  4 ++++
 src/mock.jl  | 45 ---------------------------------------------
 2 files changed, 4 insertions(+), 45 deletions(-)

diff --git a/src/debug.jl b/src/debug.jl
index 0347449..4d9d971 100644
--- a/src/debug.jl
+++ b/src/debug.jl
@@ -26,6 +26,8 @@ if VERSION >= v"1.9"
         # 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)
@@ -36,6 +38,8 @@ else
 
         # filename, separator, line
         print(io, " ", file, ":", line)
+
+        return nothing
     end
 end
 
diff --git a/src/mock.jl b/src/mock.jl
index fc728b9..92af1f2 100644
--- a/src/mock.jl
+++ b/src/mock.jl
@@ -85,48 +85,3 @@ end
 function get_alternate(target, args...; kwargs...)
     return get_alternate(get_active_env(), target, args...; kwargs...)
 end
-
-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)
-    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)
-    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

From e27d669ad0e84440cf9f5836998c89f05991ec70 Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 23 Jul 2024 09:50:01 -0500
Subject: [PATCH 5/6] Test debug logging

---
 Project.toml     |  3 ++-
 test/runtests.jl |  3 ++-
 test/targets.jl  | 24 ++++++++++++++++++++++++
 3 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/Project.toml b/Project.toml
index 9306367..2226080 100644
--- a/Project.toml
+++ b/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"]
diff --git a/test/runtests.jl b/test/runtests.jl
index 577dbaa..f90d909 100644
--- a/test/runtests.jl
+++ b/test/runtests.jl
@@ -3,6 +3,7 @@ using Test
 
 using Aqua: Aqua
 using Dates: Dates, Hour
+using Logging: Debug
 using Mocking: anon_morespecific, anonymous_signature, apply, dispatch, type_morespecific
 
 Mocking.activate()
@@ -10,7 +11,7 @@ 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
 
diff --git a/test/targets.jl b/test/targets.jl
index ad40ef6..2ff0fa4 100644
--- a/test/targets.jl
+++ b/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

From 599af55085789d764d8614ae0e8f0a5d76874f51 Mon Sep 17 00:00:00 2001
From: Curtis Vogt <curtis.vogt@gmail.com>
Date: Tue, 23 Jul 2024 09:54:11 -0500
Subject: [PATCH 6/6] Formatting

Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>
---
 test/targets.jl | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/test/targets.jl b/test/targets.jl
index 2ff0fa4..708fa38 100644
--- a/test/targets.jl
+++ b/test/targets.jl
@@ -107,19 +107,19 @@ end
     patch = @patch f(::Int) = "patched"
     apply(patch) do
         # Call patched function
-        @test_logs min_level=Debug (:debug, r"Patch called") begin
+        @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_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_logs min_level = Debug (:debug, r"No patch defined for target function") begin
             @test (@mock f(1)) == "original"
         end
     end