Initial work to overhaul debug logging

Project.toml

@@ -8,12 +8,14 @@ Base64 = "2a0f44e3-6c83-55bd-87e4-b1978d98bd5f"
 Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
 IniFile = "83e8ac13-25f8-5344-8a64-a9f2b223428f"
 Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
+LoggingExtras = "e6f89c97-d47a-5376-807f-9c37f3926c36"
 MbedTLS = "739be429-bea8-5141-9913-cc70e7f3736d"
 NetworkOptions = "ca575930-c2e3-43a9-ace4-1e988b2c1908"
 Sockets = "6462fe0b-24de-5631-8697-dd941f90decc"
 URIs = "5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4"
 
 [compat]
+LoggingExtras = "0.5"
 IniFile = "0.5"
 MbedTLS = "0.6.8, 0.7, 1"
 URIs = "1.3"

src/BasicAuthRequest.jl

@@ -3,7 +3,7 @@ module BasicAuthRequest
 using ..Base64
 using URIs
 import ..Messages: setheader, hasheader
-import ..@debug, ..DEBUG_LEVEL
+using LoggingExtras
 
 export basicauthlayer
 """
@@ -16,7 +16,7 @@ function basicauthlayer(handler)
         if basicauth
             userinfo = unescapeuri(req.url.userinfo)
             if !isempty(userinfo) && !hasheader(req.headers, "Authorization")
-                @debug 1 "Adding Authorization: Basic header."
+                @debugv 1 "Adding Authorization: Basic header."
                 setheader(req.headers, "Authorization" => "Basic $(base64encode(userinfo))")
             end
         end

src/ConnectionPool.jl

@@ -22,8 +22,9 @@ module ConnectionPool
 export Connection, newconnection, getrawstream, inactiveseconds
 
 using ..IOExtras, ..Sockets
+using LoggingExtras
 
-import ..@debug, ..DEBUG_LEVEL, ..taskid
+import ..DEBUG_LEVEL, ..taskid
 import ..@require, ..precondition_error, ..@ensure, ..postcondition_error
 using MbedTLS: SSLConfig, SSLContext, setup!, associate!, hostname!, handshake!
 import NetworkOptions
@@ -221,7 +222,7 @@ end
 function IOExtras.startwrite(c::Connection)
     @require !iswritable(c)
     c.writable = true
-    @debug 2 "👁  Start write:$c"
+    @debugv 2 "👁  Start write:$c"
     return
 end
 
@@ -233,7 +234,7 @@ Signal that an entire Request Message has been written to the `Connection`.
 function IOExtras.closewrite(c::Connection)
     @require iswritable(c)
     c.writable = false
-    @debug 2 "🗣  Write done: $c"
+    @debugv 2 "🗣  Write done: $c"
     flush(c)
     return
 end
@@ -245,7 +246,7 @@ function IOExtras.startread(c::Connection)
     @require !isreadable(c)
     c.timestamp = time()
     c.readable = true
-    @debug 2 "👁  Start read: $c"
+    @debugv 2 "👁  Start read: $c"
     return
 end
 
@@ -254,7 +255,7 @@ Wait for `c` to receive data or reach EOF.
 Close `c` on EOF or if response data arrives when no request was sent.
 """
 function monitor_idle_connection(c::Connection)
-    if eof(c.io)                                  ;@debug 2 "💀  Closed:     $c"
+    if eof(c.io)                                  ;@debugv 2 "💀  Closed:     $c"
         close(c.io)
     end
 end
@@ -267,7 +268,7 @@ Signal that an entire Response Message has been read from the `Connection`.
 function IOExtras.closeread(c::Connection)
     @require isreadable(c)
     c.readable = false
-    @debug 2 "✉️  Read done:  $c"
+    @debugv 2 "✉️  Read done:  $c"
     if c.clientconnection
         release(POOL, connectionkey(c), c)
         # Ignore SSLContext as it already monitors idle connections for TLS close_notify messages
@@ -357,7 +358,7 @@ function newconnection(::Type{T},
 end
 
 function keepalive!(tcp)
-    @debug 2 "setting keepalive on tcp socket"
+    @debugv 2 "setting keepalive on tcp socket"
     err = ccall(:uv_tcp_keepalive, Cint, (Ptr{Nothing}, Cint, Cuint),
                                           tcp.handle, 1, 1)
     err != 0 && error("error setting keepalive on socket")
@@ -379,7 +380,7 @@ function getconnection(::Type{TCPSocket},
 
     p::UInt = isempty(port) ? UInt(80) : parse(UInt, port)
 
-    @debug 2 "TCP connect: $host:$p..."
+    @debugv 2 "TCP connect: $host:$p..."
 
     addrs = Sockets.getalladdrinfo(host)
 
@@ -449,7 +450,7 @@ function getconnection(::Type{SSLContext},
                        kw...)::SSLContext
 
     port = isempty(port) ? "443" : port
-    @debug 2 "SSL connect: $host:$port..."
+    @debugv 2 "SSL connect: $host:$port..."
     tcp = getconnection(TCPSocket, host, port; kw...)
     return sslconnection(tcp, host; kw...)
 end

src/ConnectionRequest.jl

@@ -6,7 +6,7 @@ using ..IOExtras
 using ..ConnectionPool
 using MbedTLS: SSLContext, SSLConfig
 using Base64: base64encode
-import ..@debug, ..DEBUG_LEVEL
+using LoggingExtras
 import ..Streams: Stream
 
 islocalhost(host) = host == "localhost" || host == "127.0.0.1" || host == "127.0.0.1"
@@ -71,7 +71,7 @@ function connectionlayer(handler)
 
             userinfo = unescapeuri(url.userinfo)
             if !isempty(userinfo) && !hasheader(req.headers, "Proxy-Authorization")
-                @debug 1 "Adding Proxy-Authorization: Basic header."
+                @debugv 1 "Adding Proxy-Authorization: Basic header."
                 setheader(req.headers, "Proxy-Authorization" => "Basic $(base64encode(userinfo))")
             end
         else
@@ -114,7 +114,7 @@ function connectionlayer(handler)
 
             return resp
         catch e
-            @debug 1 "❗️  ConnectionLayer $e. Closing: $io"
+            @debugv 1 "❗️  ConnectionLayer $e. Closing: $io"
             try; close(io); catch; end
             rethrow(isioerror(e) ? IOError(e, "during request($url)") : e)
         end
@@ -125,7 +125,7 @@ sockettype(url::URI, default) = url.scheme in ("wss", "https") ? SSLContext : de
 
 function connect_tunnel(io, target_url, req)
     target = "$(URIs.hoststring(target_url.host)):$(target_url.port)"
-    @debug 1 "📡  CONNECT HTTPS tunnel to $target"
+    @debugv 1 "📡  CONNECT HTTPS tunnel to $target"
     headers = Dict("Host" => target)
     if (auth = header(req, "Proxy-Authorization"); !isempty(auth))
         headers["Proxy-Authorization"] = auth

src/ContentTypeRequest.jl

@@ -5,7 +5,7 @@ import ..sniff
 import ..Form
 using ..Messages
 import ..IOExtras
-import ..@debug, ..DEBUG_LEVEL
+using LoggingExtras
 
 export contenttypedetectionlayer
 
@@ -17,7 +17,7 @@ function contenttypedetectionlayer(handler)
 
             sn = sniff(bytes(req.body))
             setheader(req.headers, "Content-Type" => sn)
-            @debug 1 "setting Content-Type header to: $sn"
+            @debugv 1 "setting Content-Type header to: $sn"
         end
         return handler(req; kw...)
     end

src/CookieRequest.jl

@@ -1,10 +1,11 @@
 module CookieRequest
 
 import ..Dates
+using LoggingExtras
 using URIs
 using ..Cookies
 using ..Messages: Request, ascii_lc_isequal, header, setheader
-import ..@debug, ..DEBUG_LEVEL, ..access_threaded
+import ..access_threaded
 
 # default global cookie jar
 const COOKIEJAR = CookieJar()

src/DebugRequest.jl

@@ -1,25 +1,26 @@
 module DebugRequest
 
+using Logging, LoggingExtras
 import ..DEBUG_LEVEL
-using ..IOExtras
-import ..Streams: Stream
-
-include("IODebug.jl")
 
 export debuglayer
 
 """
     debuglayer(stream::Stream) -> HTTP.Response
 
-Wrap the `IO` stream in an `IODebug` stream and print Message data.
+If `verbose` keyword arg is > 0, or the HTTP.jl global `DEBUG_LEVEL[]` is > 0,
+then enabled debug logging with verbosity `verbose` for the lifetime of the request.
 """
 function debuglayer(handler)
-    return function(stream::Stream; verbose::Int=0, kw...)
-        # if debugging, wrap stream.stream in IODebug
-        if verbose >= 3 || DEBUG_LEVEL[] >= 3
-            stream = Stream(stream.message, IODebug(stream.stream))
+    return function(request; verbose::Int=0, kw...)
+        # if debugging, enable by wrapping request in custom logger logic
+        if verbose >= 0 || DEBUG_LEVEL[] >= 0
+            LoggingExtras.withlevel(Debug; verbosity=verbose) do
+                handler(request; verbose=verbose, kw...)
+            end
+        else
+            return handler(request; verbose=verbose, kw...)
         end
-        return handler(stream; verbose=verbose, kw...)
     end
 end
 

src/HTTP.jl

@@ -9,6 +9,7 @@ Base.@deprecate escape escapeuri
 
 using Base64, Sockets, Dates
 using URIs
+using LoggingExtras
 
 function access_threaded(f, v::Vector)
     tid = Threads.threadid()
@@ -337,7 +338,7 @@ function request(method, url, h=Header[], b=nobody;
     return request(HTTP.stack(), method, url, headers, body, query; kw...)
 end
 
-const STREAM_LAYERS = [timeoutlayer, exceptionlayer, debuglayer]
+const STREAM_LAYERS = [timeoutlayer, exceptionlayer]
 const REQUEST_LAYERS = [redirectlayer, defaultheaderslayer, basicauthlayer, contenttypedetectionlayer, cookielayer, retrylayer, canonicalizelayer]
 
 pushlayer!(layer; request::Bool=true) = push!(request ? REQUEST_LAYERS : STREAM_LAYERS, layer)
@@ -355,8 +356,9 @@ function stack(
     layers2 = foldr((x, y) -> x(y), STREAM_LAYERS, init=layers)
     # request layers
     # messagelayer must be the 1st/outermost layer to convert initial args to Request
+    # we also want debuglayer to be early to ensure any debug logging is handled correctly in other layers
     layers3 = foldr((x, y) -> x(y), requestlayers; init=connectionlayer(layers2))
-    return messagelayer(foldr((x, y) -> x(y), REQUEST_LAYERS; init=layers3))
+    return messagelayer(debuglayer(foldr((x, y) -> x(y), REQUEST_LAYERS; init=layers3)))
 end
 
 function request(stack::Base.Callable, method, url, h=Header[], b=nobody, q=nothing;

src/Handlers.jl

@@ -304,4 +304,4 @@ end
 
 getcookies(req) = get(() => Cookie[], req.context, :cookies)
 
-end # module
+end # module

src/RedirectRequest.jl

@@ -4,7 +4,7 @@ using URIs
 using ..Messages
 using ..Pairs: setkv
 import ..Header
-import ..@debug, ..DEBUG_LEVEL
+using LoggingExtras
 
 export redirectlayer, nredirects
 
@@ -55,7 +55,7 @@ function redirectlayer(handler)
             else
                 req.headers = Header[]
             end
-            @debug 1 "➡️  Redirect: $url"
+            @debugv 1 "➡️  Redirect: $url"
             count += 1
         end
         @assert false "Unreachable!"

src/RetryRequest.jl

@@ -5,7 +5,8 @@ using ..Sockets
 using ..IOExtras
 using ..MessageRequest
 using ..Messages
-import ..@debug, ..DEBUG_LEVEL, ..sprintcompact
+import ..sprintcompact
+using LoggingExtras
 
 export retrylayer
 
@@ -33,10 +34,10 @@ function retrylayer(handler)
             check=(s, ex)->begin
                 retry = isrecoverable(ex, req, retry_non_idempotent, get(req.context, :retrycount, 0))
                 if retry
-                    @debug 1 "🔄  Retry $ex: $(sprintcompact(req))"
+                    @debugv 1 "🔄  Retry $ex: $(sprintcompact(req))"
                     reset!(req.response)
                 else
-                    @debug 1 "🚷  No Retry: $(no_retry_reason(ex, req))"
+                    @debugv 1 "🚷  No Retry: $(no_retry_reason(ex, req))"
                 end
                 return s, retry
             end)