Initial work to overhaul debug logging

Project.toml

@@ -8,6 +8,7 @@ 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"

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
 
 # hasdotsuffix reports whether s ends in "."+suffix.
@@ -69,7 +69,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
@@ -106,7 +106,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
@@ -117,7 +117,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
 
 const default_cookiejar = Dict{String, Set{Cookie}}[]
 
@@ -67,10 +68,10 @@ function getcookies(cookies, url)
                               url.host, url.path)
             t = cookie.expires
             if t != Dates.DateTime(1) && t < Dates.now(Dates.UTC)
-                @debug 1 "Deleting expired Cookie: $cookie.name"
+                @debugv 1 "Deleting expired Cookie: $cookie.name"
                 push!(expired, cookie)
             else
-                @debug 1 "Sending Cookie: $cookie.name to $url.host"
+                @debugv 1 "Sending Cookie: $cookie.name to $url.host"
                 push!(tosend, cookie)
             end
         end
@@ -82,7 +83,7 @@ end
 function setcookies(cookies, host, headers)
     for (k, v) in headers
         ascii_lc_isequal(k, "set-cookie") || continue
-        @debug 1 "Set-Cookie: $v (from $host)"
+        @debugv 1 "Set-Cookie: $v (from $host)"
         push!(cookies, Cookies.readsetcookie(host, v))
     end
 end

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.with(level=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()
@@ -330,7 +331,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)
@@ -348,8 +349,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

@@ -1,9 +1,9 @@
 module Handlers
 
-export serve, Router, register!
+export serve, Router, register!, getparams, getcookies
 
 using URIs
-using ..Messages, ..Streams, ..IOExtras, ..Servers, ..Sockets
+using ..Messages, ..Streams, ..IOExtras, ..Servers, ..Sockets, ..Cookies
 
 """
     streamhandler(request_handler) -> stream handler
@@ -291,4 +291,17 @@ function (r::Router)(req)
     end
 end
 
+getparams(req) = get(req.context, :params, nothing)
+
+function cookie_middleware(handler)
+    function (req)
+        if !haskey(req.context, :cookies)
+            req.context[:cookies] = Cookies.cookies(req)
+        end
+        return handler(req)
+    end
+end
+
+getcookies(req) = get(() => Cookie[], req.context, :cookies)
+
 end # module