Log the parsed (and pretty-printed) response body at `LogLevel(-1_000…

…`) (#132)

* Log the parsed (and pretty-printed) response body at `LogLevel(-3_000`)

Co-authored-by: DilumAluthge <DilumAluthge@users.noreply.github.com>

* Log at `LogLevel(-1_000)` (#155)

* Add tests for #132 (#156)

Co-authored-by: Dilum Aluthge <dilum@aluthge.com>

---------

Co-authored-by: DilumAluthge <DilumAluthge@users.noreply.github.com>
Co-authored-by: David Widmann <devmotion@users.noreply.github.com>

Project.toml

@@ -8,6 +8,7 @@ Base64 = "2a0f44e3-6c83-55bd-87e4-b1978d98bd5f"
 Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
 HTTP = "cd3eb016-35fb-5094-929b-558a96fad6f3"
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 Mmap = "a63ad114-7e13-5084-954f-fe012c677804"
 SaferIntegers = "88634af6-177f-5301-88b8-7819386cfa38"
 StructTypes = "856f2bd8-1eba-4b0a-8007-ebc267875bd4"
@@ -16,16 +17,18 @@ URIs = "5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4"
 UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4"
 
 [compat]
-Base64 = "1"
-Dates = "1"
+Base64 = "<0.0.1, 1"
+Dates = "<0.0.1, 1"
 HTTP = "0.9.8, 1"
 JSON3 = "1.5.1"
-Mmap = "1"
+Logging = "<0.0.1, 1"
+Mmap = "<0.0.1, 1"
 SaferIntegers = "2.5.1, 3"
 StructTypes = "1.2.3"
+Test = "<0.0.1, 1"
 TimeZones = "1.5.2"
 URIs = "1.3"
-UUIDs = "1"
+UUIDs = "<0.0.1, 1"
 julia = "1.4"
 
 [extras]

src/FHIRClient.jl

@@ -4,11 +4,14 @@ import Base64
 import Dates
 import HTTP
 import JSON3
+import Logging
 import SaferIntegers
 import StructTypes
 import TimeZones
 import URIs
 
+using Logging: @logmsg, LogLevel
+
 include("types.jl")
 
 include("r4.jl")
@@ -18,5 +21,6 @@ include("fhir-to-julia.jl")
 include("headers.jl")
 include("other-fhir-versions.jl")
 include("requests.jl")
+include("tryparse.jl")
 
 end # end module FHIRClient

src/requests.jl

@@ -265,7 +265,7 @@ See also [`request_json`](@ref) and [`request_raw`](@ref).
     kwargs...,
 )::T where {T}
     _new_request_body = _write_struct_request_body(body)
-    response_body::String = request_raw(
+    response_body = request_raw(
         client,
         verb,
         path;
@@ -274,6 +274,17 @@ See also [`request_json`](@ref) and [`request_raw`](@ref).
         query = query,
         require_base_url = require_base_url,
     )::String
-    response_object::T = JSON3.read(response_body, T; kwargs...)::T
+
+    # Recall that the default log levels are:
+    #     Error === LogLevel(2_000)
+    #     Warn === LogLevel(1_000)
+    #     Info === LogLevel(0)
+    #     Debug === LogLevel(-1_000)
+    #
+    # Ref: https://docs.julialang.org/en/v1/stdlib/Logging
+
+    @logmsg LogLevel(-1_000) "FHIRClient.request()" path verb tryparse_json(response_body)
+
+    response_object = JSON3.read(response_body, T; kwargs...)::T
     return response_object
 end

src/tryparse.jl

@@ -0,0 +1,16 @@
+function tryparse_json(response_body::AbstractString)
+    response_json = try
+        JSON3.read(response_body)
+    catch ex
+        # If no exception is thrown, we don't need to log `response_body`.
+        #
+        # However, if an exception is thrown, we need to log the entire raw
+        # `response_body` so that the user can try to figure out why it failed to
+        # parse as valid JSON.
+        bt = catch_backtrace()
+        @logmsg LogLevel(-1_000) "FHIRClient.tryparse_json()" response_body exception =
+            (ex, bt)
+        nothing
+    end
+    return response_json
+end

test/integration/json.jl

@@ -19,9 +19,19 @@
         @test json_response isa JSON3.Object
         @test json_response == JSON3.read(raw_response)
 
-        dict_response = FHIRClient.request(Dict, client, "GET", patient_request)
+        test_logger = Test.TestLogger(; min_level = Logging.Debug, catch_exceptions = false)
+        dict_response = Logging.with_logger(test_logger) do
+            FHIRClient.request(Dict, client, "GET", patient_request)
+        end
         @test dict_response isa Dict
         @test dict_response == JSON3.read(raw_response, Dict)
+        log = only(filter(x -> x._module === FHIRClient, test_logger.logs))
+        @test log.message == "FHIRClient.request()"
+        @test log.level == Logging.LogLevel(-1_000)
+        @test length(log.kwargs) == 3
+        @test log.kwargs[:path] == patient_request
+        @test log.kwargs[:verb] == "GET"
+        @test log.kwargs[Symbol("tryparse_json(response_body)")] == json_response
 
         # Relative paths
         for path in ("Patient/$(patient_id)", "./Patient/$(patient_id)")

test/runtests.jl

@@ -3,9 +3,25 @@ using Test
 
 import Dates
 import JSON3
+import Logging
 import URIs
 
+# This is necessary to work around https://github.com/JuliaLang/julia/issues/52234
+# Also possibly related: https://github.com/JuliaLang/julia/issues/34037
+#
+# Note: this is a GLOBAL setting:
+# Logging.disable_logging(Logging.BelowMinLevel)
+
 @testset "FHIRClient.jl" begin
-    include("unit.jl")
-    include("integration.jl")
+    # When we run the tests, we want to make sure that none of the `@logmsg`
+    # statements throw any errors.
+    test_logger = Test.TestLogger(;
+        # min_level = Logging.BelowMinLevel,
+        min_level = Logging.LogLevel(-5_000),
+        catch_exceptions = false,
+    )
+    Logging.with_logger(test_logger) do
+        include("unit.jl")
+        include("integration.jl")
+    end
 end

test/unit/requests.jl

@@ -52,4 +52,25 @@
             end
         end
     end
+
+    @testset "tryparse_json" begin
+        for json_body in ("42", "{}", "{\"firstName\":\"John\", \"lastName\":\"Doe\"}")
+            @test (@test_logs min_level = Logging.Debug FHIRClient.tryparse_json(
+                json_body,
+            )) == JSON3.read(json_body)
+        end
+        for no_json_body in ("{3}", "[ 4 }", "{\"firstName\":John}")
+            logger = Test.TestLogger(; min_level = Logging.Debug)
+            res = Logging.with_logger(logger) do
+                FHIRClient.tryparse_json(no_json_body)
+            end
+            @test res === nothing
+            log = only(logger.logs)
+            @test log.message == "FHIRClient.tryparse_json()"
+            @test log.level == Logging.LogLevel(-1_000)
+            @test length(log.kwargs) == 2
+            @test log.kwargs[:exception] isa Tuple{<:Exception,<:Any}
+            @test log.kwargs[:response_body] == no_json_body
+        end
+    end
 end