Backport logging improvement from pull/1150 to v1.9 release (#1151)

* Don't collect exception stack if it won't be logged

* Bump version

Author: nickrobinson251

Project.toml

@@ -1,7 +1,7 @@
 name = "HTTP"
 uuid = "cd3eb016-35fb-5094-929b-558a96fad6f3"
 authors = ["Jacob Quinn", "contributors: https://github.com/JuliaWeb/HTTP.jl/graphs/contributors"]
-version = "1.9.16"
+version = "1.9.17"
 
 [deps]
 Base64 = "2a0f44e3-6c83-55bd-87e4-b1978d98bd5f"

src/Servers.jl

@@ -193,8 +193,10 @@ function shutdown(fn::Function)
     try
         fn()
     catch
-        msg = current_exceptions_to_string()
-        @error "shutdown function $fn failed. $msg"
+        @error begin
+            msg = current_exceptions_to_string()
+            "shutdown function $fn failed. $msg"
+        end
     end
 end
 
@@ -393,8 +395,10 @@ function listenloop(f, listener, conns, tcpisvalid,
             if e isa Base.IOError && e.code == Base.UV_ECONNABORTED
                 verbose >= 0 && @infov 1 "Server on $(listener.hostname):$(listener.hostport) closing"
             else
-                msg = current_exceptions_to_string()
-                @errorv 2 "Server on $(listener.hostname):$(listener.hostport) errored. $msg"
+                @errorv 2 begin
+                    msg = current_exceptions_to_string()
+                    "Server on $(listener.hostname):$(listener.hostport) errored. $msg"
+                end
                 # quick little sleep in case there's a temporary
                 # local error accepting and this might help avoid quickly re-erroring
                 sleep(0.05 + rand() * 0.05)
@@ -433,8 +437,10 @@ function handle_connection(f, c::Connection, listener, readtimeout, access_log)
                 if e isa ParseError
                     write(c, Response(e.code == :HEADER_SIZE_EXCEEDS_LIMIT ? 431 : 400, string(e.code)))
                 end
-                msg = current_exceptions_to_string()
-                @debugv 1 "handle_connection startread error. $msg"
+                @debugv 1 begin
+                    msg = current_exceptions_to_string()
+                    "handle_connection startread error. $msg"
+                end
                 break
             end
 
@@ -461,8 +467,10 @@ function handle_connection(f, c::Connection, listener, readtimeout, access_log)
                 # The remote can close the stream whenever it wants to, but there's nothing
                 # anyone can do about it on this side. No reason to log an error in that case.
                 level = e isa Base.IOError && !isopen(c) ? Logging.Debug : Logging.Error
-                msg = current_exceptions_to_string()
-                @logmsgv 1 level "handle_connection handler error. $msg"
+                @logmsgv 1 level begin
+                    msg = current_exceptions_to_string()
+                    "handle_connection handler error. $msg"
+                end
 
                 if isopen(http) && !iswritable(http)
                     request.response.status = 500
@@ -479,8 +487,10 @@ function handle_connection(f, c::Connection, listener, readtimeout, access_log)
         end
     catch
         # we should be catching everything inside the while loop, but just in case
-        msg = current_exceptions_to_string()
-        @errorv 1 "error while handling connection. $msg"
+        @errorv 1 begin
+            msg = current_exceptions_to_string()
+            "error while handling connection. $msg"
+        end
     finally
         if readtimeout > 0
             wait_for_timeout[] = false

src/WebSockets.jl

@@ -440,8 +440,10 @@ function upgrade(f::Function, http::Streams.Stream; suppress_close_error::Bool=f
         f(ws)
     catch e
         if !isok(e)
-            msg = current_exceptions_to_string()
-            suppress_close_error || @error "$(ws.id): Unexpected websocket server error. $msg"
+            suppress_close_error || @error begin
+                msg = current_exceptions_to_string()
+                "$(ws.id): Unexpected websocket server error. $msg"
+            end
         end
         if !isclosed(ws)
             if e isa WebSocketError && e.message isa CloseFrameBody

src/clientlayers/ConnectionRequest.jl

@@ -80,8 +80,7 @@ function connectionlayer(handler)
             io = newconnection(IOType, url.host, url.port; readtimeout=readtimeout, connect_timeout=connect_timeout, kw...)
         catch e
             if logerrors
-                msg = current_exceptions_to_string()
-                @error msg type=Symbol("HTTP.ConnectError") method=req.method url=req.url context=req.context logtag=logtag
+                @error current_exceptions_to_string() type=Symbol("HTTP.ConnectError") method=req.method url=req.url context=req.context logtag=logtag
             end
             req.context[:connect_errors] = get(req.context, :connect_errors, 0) + 1
             throw(ConnectError(string(url), e))
@@ -127,12 +126,10 @@ function connectionlayer(handler)
             root_err = ExceptionUnwrapping.unwrap_exception_to_root(e)
             # don't log if it's an HTTPError since we should have already logged it
             if logerrors && root_err isa StatusError
-                msg = current_exceptions_to_string()
-                @error msg type=Symbol("HTTP.StatusError") method=req.method url=req.url context=req.context logtag=logtag
+                @error current_exceptions_to_string() type=Symbol("HTTP.StatusError") method=req.method url=req.url context=req.context logtag=logtag
             end
             if logerrors && !ExceptionUnwrapping.has_wrapped_exception(e, HTTPError)
-                msg = current_exceptions_to_string()
-                @error msg type=Symbol("HTTP.ConnectionRequest") method=req.method url=req.url context=req.context logtag=logtag
+                @error current_exceptions_to_string() type=Symbol("HTTP.ConnectionRequest") method=req.method url=req.url context=req.context logtag=logtag
             end
             @debugv 1 "❗️  ConnectionLayer $root_err. Closing: $io"
             if @isdefined(stream) && stream.nwritten == -1

src/clientlayers/StreamRequest.jl

@@ -72,8 +72,7 @@ function streamlayer(stream::Stream; iofunction=nothing, decompress::Union{Nothi
         if timedout === nothing || !timedout[]
             req.context[:io_errors] = get(req.context, :io_errors, 0) + 1
             if logerrors
-                msg = current_exceptions_to_string()
-                @error msg type=Symbol("HTTP.IOError") method=req.method url=req.url context=req.context logtag=logtag
+                @error current_exceptions_to_string() type=Symbol("HTTP.IOError") method=req.method url=req.url context=req.context logtag=logtag
             end
         end
         rethrow()

src/clientlayers/TimeoutRequest.jl

@@ -26,8 +26,7 @@ function timeoutlayer(handler)
                 req = stream.message.request
                 req.context[:timeout_errors] = get(req.context, :timeout_errors, 0) + 1
                 if logerrors
-                    msg = current_exceptions_to_string()
-                    @error msg type=Symbol("HTTP.TimeoutError") method=req.method url=req.url context=req.context timeout=readtimeout logtag=logtag
+                    @error current_exceptions_to_string() type=Symbol("HTTP.TimeoutError") method=req.method url=req.url context=req.context timeout=readtimeout logtag=logtag
                 end
                 e = Exceptions.TimeoutError(readtimeout)
             end