work

Author: quinnj

src/HTTP.jl

@@ -42,6 +42,32 @@ include("StatusCodes.jl")              ;using .StatusCodes
 include("Messages.jl")                 ;using .Messages
 include("cookies.jl")                  ;using .Cookies
 include("Streams.jl")                  ;using .Streams
+
+function observe_layer(f, cntnm, durnm, req, args...; kw...)
+    start_time = time()
+    req.context[cntnm] = Base.get(req.context, cntnm, 0) + 1
+    try
+        return f(args...; kw...)
+    finally
+        req.context[durnm] = Base.get(req.context, durnm, 0) + (time() - start_time) * 1000
+        # @info "observed layer = $f, count = $(req.context[cntnm]), duration = $(req.context[durnm])"
+    end
+end
+
+function observe_request_layer(f)
+    nm = nameof(f)
+    cntnm = Symbol(nm, "_count")
+    durnm = Symbol(nm, "_duration_ms")
+    return (req::Request; kw...) -> observe_layer(f, cntnm, durnm, req, req; kw...)
+end
+
+function observe_stream_layer(f)
+    nm = nameof(f)
+    cntnm = Symbol(nm, "_count")
+    durnm = Symbol(nm, "_duration_ms")
+    return (stream::Stream; kw...) -> observe_layer(f, cntnm, durnm, stream.message.request, stream; kw...)
+end
+
 include("clientlayers/MessageRequest.jl");           using .MessageRequest
 include("clientlayers/RedirectRequest.jl");          using .RedirectRequest
 include("clientlayers/DefaultHeadersRequest.jl");    using .DefaultHeadersRequest
@@ -399,10 +425,10 @@ function stack(
         inner_stream_layers = streamlayers
         outer_stream_layers = ()
     end
-    layers = foldr((x, y) -> x(y), inner_stream_layers, init=streamlayer)
-    layers2 = foldr((x, y) -> x(y), STREAM_LAYERS, init=layers)
+    layers = foldr((x, y) -> observe_stream_layer(x(y)), inner_stream_layers, init=observe_stream_layer(streamlayer))
+    layers2 = foldr((x, y) -> observe_stream_layer(x(y)), STREAM_LAYERS, init=layers)
     if !isempty(outer_stream_layers)
-        layers2 = foldr((x, y) -> x(y), outer_stream_layers, init=layers2)
+        layers2 = foldr((x, y) -> observe_stream_layer(x(y)), outer_stream_layers, init=layers2)
     end
     # request layers
     # messagelayer must be the 1st/outermost layer to convert initial args to Request
@@ -414,7 +440,7 @@ function stack(
         inner_request_layers = requestlayers
         outer_request_layers = ()
     end
-    layers3 = foldr((x, y) -> x(y), inner_request_layers; init=connectionlayer(layers2))
+    layers3 = foldr((x, y) -> x(y), inner_request_layers; init=observe_request_layer(connectionlayer(layers2)))
     layers4 = foldr((x, y) -> x(y), REQUEST_LAYERS; init=layers3)
     if !isempty(outer_request_layers)
         layers4 = foldr((x, y) -> x(y), outer_request_layers, init=layers4)

src/clientlayers/BasicAuthRequest.jl

@@ -11,7 +11,7 @@ export basicauthlayer
 Add `Authorization: Basic` header using credentials from url userinfo.
 """
 function basicauthlayer(handler)
-    return function(req; basicauth::Bool=true, kw...)
+    return function basicauths(req; basicauth::Bool=true, kw...)
         if basicauth
             userinfo = unescapeuri(req.url.userinfo)
             if !isempty(userinfo) && !hasheader(req.headers, "Authorization")

src/clientlayers/CanonicalizeRequest.jl

@@ -10,7 +10,7 @@ export canonicalizelayer
 Rewrite request and response headers in Canonical-Camel-Dash-Format.
 """
 function canonicalizelayer(handler)
-    return function(req; canonicalize_headers::Bool=false, kw...)
+    return function canonicalizes(req; canonicalize_headers::Bool=false, kw...)
         if canonicalize_headers
             req.headers = canonicalizeheaders(req.headers)
         end

src/clientlayers/ConnectionRequest.jl

@@ -55,7 +55,7 @@ Close the connection if the request throws an exception.
 Otherwise leave it open so that it can be reused.
 """
 function connectionlayer(handler)
-    return function(req; proxy=getproxy(req.url.scheme, req.url.host), socket_type::Type=TCPSocket, socket_type_tls::Type=SOCKET_TYPE_TLS[], readtimeout::Int=0, logerrors::Bool=false, kw...)
+    return function connections(req; proxy=getproxy(req.url.scheme, req.url.host), socket_type::Type=TCPSocket, socket_type_tls::Type=SOCKET_TYPE_TLS[], readtimeout::Int=0, logerrors::Bool=false, kw...)
         local io, stream
         if proxy !== nothing
             target_url = req.url
@@ -126,7 +126,7 @@ function connectionlayer(handler)
             end
             # if logerrors
             if !(e isa StatusError || e isa TimeoutError)
-                @error sprint(showerror, e, catch_backtrace())
+                @error "HTTP.ConnectionRequest" exception=(e, catch_backtrace()) request=req
             end
             @debugv 1 "❗️  ConnectionLayer $e. Closing: $io"
             shouldreuse = false

src/clientlayers/ContentTypeRequest.jl

@@ -11,7 +11,7 @@ export contenttypedetectionlayer
 Try and detect the content type of the request body and add the "Content-Type" header.
 """
 function contenttypedetectionlayer(handler)
-    return function(req; detect_content_type::Bool=false, kw...)
+    return function contenttypedetections(req; detect_content_type::Bool=false, kw...)
         if detect_content_type && (!hasheader(req.headers, "Content-Type")
             && !isa(req.body, Form)
             && isbytes(req.body))

src/clientlayers/CookieRequest.jl

@@ -16,7 +16,7 @@ from the `cookiejar` keyword argument (by default, a global cookiejar is used).
 Store "Set-Cookie" cookies from the response headers.
 """
 function cookielayer(handler)
-    return function(req::Request; cookies=true, cookiejar::CookieJar=COOKIEJAR, kw...)
+    return function managecookies(req::Request; cookies=true, cookiejar::CookieJar=COOKIEJAR, kw...)
         if cookies === true || (cookies isa AbstractDict && !isempty(cookies))
             url = req.url
             cookiestosend = Cookies.getcookies!(cookiejar, url)

src/clientlayers/DebugRequest.jl

@@ -13,7 +13,7 @@ debug logging with verbosity `verbose` for the lifetime of the request.
 If no `verbose` is specified, it defaults to the *HTTP.jl* global `DEBUG_LEVEL[]`.
 """
 function debuglayer(handler)
-    return function(request; verbose=DEBUG_LEVEL[], kw...)
+    return function debugs(request; verbose=DEBUG_LEVEL[], kw...)
         # if debugging, enable by wrapping request in custom logger logic
         if verbose > 0
             LoggingExtras.withlevel(Logging.Debug; verbosity=verbose) do

src/clientlayers/DefaultHeadersRequest.jl

@@ -10,7 +10,7 @@ using ..Messages, ..Forms, ..IOExtras
 Sets default expected headers.
 """
 function defaultheaderslayer(handler)
-    return function(req; iofunction=nothing, decompress=nothing, kw...)
+    return function defaultheaders(req; iofunction=nothing, decompress=nothing, kw...)
         headers = req.headers
         if isempty(req.url.port) ||
             (req.url.scheme == "http" && req.url.port == "80") ||

src/clientlayers/ExceptionRequest.jl

@@ -10,12 +10,12 @@ using ..IOExtras, ..Messages, ..Exceptions
 Throw a `StatusError` if the request returns an error response status.
 """
 function exceptionlayer(handler)
-    return function(stream; status_exception::Bool=true, kw...)
+    return function exceptions(stream; status_exception::Bool=true, kw...)
         res = handler(stream; kw...)
         if status_exception && iserror(res)
             res.request.context[:status_errors] = get(res.request.context, :status_errors, 0) + 1
             e = StatusError(res.status, res.request.method, res.request.target, res)
-            @error sprint(showerror, e, catch_backtrace())
+            @error "HTTP.StatusError" exception=(e, catch_backtrace()) request=res.request
             throw(e)
         else
             return res

src/clientlayers/MessageRequest.jl

@@ -33,6 +33,8 @@ function messagelayer(handler)
             end
             rethrow(e)
         finally
+            dur = (time() - start_time) * 1000
+            req.context[:total_request_duration_ms] = dur
             if @isdefined(resp) && iserror(resp) && haskey(resp.request.context, :response_body)
                 if isbytes(resp.body)
                     resp.body = resp.request.context[:response_body]
@@ -42,8 +44,8 @@ function messagelayer(handler)
             end
             if @isdefined(resp)
                 end_time = time()
-                rbytes = get(resp.request.context, :nbytes, 0)
-                wbytes = get(resp.request.context, :nbytes_written, 0)
+                rbytes = Base.get(resp.request.context, :nbytes, 0)
+                wbytes = Base.get(resp.request.context, :nbytes_written, 0)
                 rgbits_per_second = rbytes == 0 ? 0 : (((8 * rbytes) / 1e9) / (end_time - start_time))
                 wgbits_per_second = wbytes == 0 ? 0 : (((8 * wbytes) / 1e9) / (end_time - start_time))
                 @debugv 1 "Request complete with bandwidth: $(wgbits_per_second) Gbps write, $(rgbits_per_second) Gbps read"

src/clientlayers/RedirectRequest.jl

@@ -11,7 +11,7 @@ export redirectlayer, nredirects
 Redirects the request in the case of 3xx response status.
 """
 function redirectlayer(handler)
-    return function(req; redirect::Bool=true, redirect_limit::Int=3, redirect_method=nothing, forwardheaders::Bool=true, response_stream=nothing, kw...)
+    return function redirects(req; redirect::Bool=true, redirect_limit::Int=3, redirect_method=nothing, forwardheaders::Bool=true, response_stream=nothing, kw...)
         if !redirect || redirect_limit == 0
             # no redirecting
             return handler(req; kw...)

src/clientlayers/RetryRequest.jl

@@ -2,6 +2,7 @@ module RetryRequest
 
 using Sockets, LoggingExtras, MbedTLS, OpenSSL
 using ..IOExtras, ..Messages, ..Strings, ..ExceptionRequest, ..Exceptions
+import ..observe_request_layer
 
 export retrylayer
 
@@ -27,7 +28,7 @@ retry check _wouldn't_ retry, if `retry_check` returns true, then the request
 will be retried anyway.
 """
 function retrylayer(handler)
-    return function(req::Request; retry::Bool=true, retries::Int=4,
+    return observe_request_layer(function manageretries(req::Request; retry::Bool=true, retries::Int=4,
         retry_delays=ExponentialBackOff(n = retries, factor=3.0), retry_check=FALSE,
         retry_non_idempotent::Bool=false, logerrors::Bool=false, kw...)
         if !retry || retries == 0
@@ -73,7 +74,7 @@ function retrylayer(handler)
             end
         )
         return retry_request(req; kw...)
-    end
+    end)
 end
 
 const EAI_AGAIN = 2

src/clientlayers/TimeoutRequest.jl

@@ -11,7 +11,7 @@ export timeoutlayer
 Close the `HTTP.Stream` if no data has been received for `readtimeout` seconds.
 """
 function timeoutlayer(handler)
-    return function(stream::Stream; readtimeout::Int=0, kw...)
+    return function timeouts(stream::Stream; readtimeout::Int=0, kw...)
         if readtimeout <= 0
             # skip
             return handler(stream; kw...)
@@ -22,7 +22,7 @@ function timeoutlayer(handler)
             end
         catch e
             if e isa TimeoutError
-                @error sprint(showerror, e, catch_backtrace())
+                @error "HTTP.TimeoutError" exception=(e, catch_backtrace()) request=stream.message.request
                 req = stream.message.request
                 req.context[:timeout_errors] = get(req.context, :timeout_errors, 0) + 1
             end

test/client.jl

@@ -586,7 +586,7 @@ end
         seekstart(req_body)
         resp = HTTP.get("http://localhost:8080/retry"; body=req_body, response_stream=res_body, retry=false, status_exception=false)
         @test String(take!(res_body)) == "500 unexpected error"
-        # even if status_exception=true, we should still get the right response body
+        # even if StatusError, we should still get the right response body
         shouldfail[] = true
         seekstart(req_body)
         try