Change logs to use current_exceptions_to_string() instead of exception= pattern (#1092)

* Change logs to use `current_exceptions_to_string()` instead of `exception=`

* cleanup unused variable `catch e`

* Update Exceptions.jl for older julia

* Rename err => msg; fix missing import

* Make "Don't retry on internal exceptions" less flakey

---------

Co-authored-by: Nick Robinson <[email protected]>
Co-authored-by: Tomáš Drvoštěp <[email protected]>

Author: 3 people

src/Connections.jl

@@ -478,9 +478,9 @@ function keepalive!(tcp)
     Base.iolock_begin()
     try
         Base.check_open(tcp)
-        err = ccall(:uv_tcp_keepalive, Cint, (Ptr{Nothing}, Cint, Cuint),
+        msg = ccall(:uv_tcp_keepalive, Cint, (Ptr{Nothing}, Cint, Cuint),
                                             tcp.handle, 1, 1)
-        Base.uv_error("failed to set keepalive on tcp socket", err)
+        Base.uv_error("failed to set keepalive on tcp socket", msg)
     finally
         Base.iolock_end()
     end

src/Exceptions.jl

@@ -100,8 +100,13 @@ function current_exceptions_to_string()
     buf = IOBuffer()
     println(buf)
     println(buf, "\n===========================\nHTTP Error message:\n")
-    Base.display_error(buf, Base.catch_stack())
+    exc = @static if VERSION >= v"1.8.0-"
+        Base.current_exceptions()
+    else
+        Base.catch_stack()
+    end
+    Base.display_error(buf, exc)
     return String(take!(buf))
 end
 
-end # module Exceptions
+end # module Exceptions

src/Servers.jl

@@ -192,8 +192,9 @@ shutdown(::Nothing) = nothing
 function shutdown(fn::Function)
     try
         fn()
-    catch e
-        @error "shutdown function $fn failed" exception=(e, catch_backtrace())
+    catch
+        msg = current_exceptions_to_string()
+        @error "shutdown function $fn failed. $msg"
     end
 end
 
@@ -392,7 +393,8 @@ 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
-                @errorv 2 "Server on $(listener.hostname):$(listener.hostport) errored" exception=(e, catch_backtrace())
+                msg = current_exceptions_to_string()
+                @errorv 2 "Server on $(listener.hostname):$(listener.hostport) errored. $msg"
                 # 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)
@@ -431,7 +433,8 @@ 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
-                @debugv 1 "handle_connection startread error" exception=(e, catch_backtrace())
+                msg = current_exceptions_to_string()
+                @debugv 1 "handle_connection startread error. $msg"
                 break
             end
 
@@ -458,7 +461,8 @@ 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
-                @logmsgv 1 level "handle_connection handler error" exception=(e, stacktrace(catch_backtrace()))
+                msg = current_exceptions_to_string()
+                @logmsgv 1 level "handle_connection handler error. $msg"
 
                 if isopen(http) && !iswritable(http)
                     request.response.status = 500
@@ -473,9 +477,10 @@ function handle_connection(f, c::Connection, listener, readtimeout, access_log)
                 end
             end
         end
-    catch e
+    catch
         # we should be catching everything inside the while loop, but just in case
-        @errorv 1 "error while handling connection" exception=(e, catch_backtrace())
+        msg = current_exceptions_to_string()
+        @errorv 1 "error while handling connection. $msg"
     finally
         if readtimeout > 0
             wait_for_timeout[] = false

src/Streams.jl

@@ -326,7 +326,7 @@ function IOExtras.readuntil(http::Stream, f::Function)::ByteView
         bytes = IOExtras.readuntil(http.stream, f)
         update_ntoread(http, length(bytes))
         return bytes
-    catch e
+    catch
         # if we error, it means we didn't find what we were looking for
         return UInt8[]
     end

src/WebSockets.jl

@@ -3,6 +3,7 @@ module WebSockets
 using Base64, LoggingExtras, UUIDs, Sockets, Random
 using MbedTLS: digest, MD_SHA1, SSLContext
 using ..IOExtras, ..Streams, ..Connections, ..Messages, ..Conditions, ..Servers
+using ..Exceptions: current_exceptions_to_string
 import ..open
 import ..HTTP # for doc references
 
@@ -439,7 +440,8 @@ function upgrade(f::Function, http::Streams.Stream; suppress_close_error::Bool=f
         f(ws)
     catch e
         if !isok(e)
-            suppress_close_error || @error "$(ws.id): Unexpected websocket server error" exception=(e, catch_backtrace())
+            msg = current_exceptions_to_string()
+            suppress_close_error || @error "$(ws.id): Unexpected websocket server error. $msg"
         end
         if !isclosed(ws)
             if e isa WebSocketError && e.message isa CloseFrameBody

src/clientlayers/ConnectionRequest.jl

@@ -80,8 +80,8 @@ function connectionlayer(handler)
             io = newconnection(IOType, url.host, url.port; readtimeout=readtimeout, connect_timeout=connect_timeout, kw...)
         catch e
             if logerrors
-                err = current_exceptions_to_string()
-                @error err type=Symbol("HTTP.ConnectError") method=req.method url=req.url context=req.context logtag=logtag
+                msg = current_exceptions_to_string()
+                @error msg 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 +127,12 @@ 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
-                err = current_exceptions_to_string()
-                @error err type=Symbol("HTTP.StatusError") method=req.method url=req.url context=req.context logtag=logtag
+                msg = current_exceptions_to_string()
+                @error msg type=Symbol("HTTP.StatusError") method=req.method url=req.url context=req.context logtag=logtag
             end
             if logerrors && !ExceptionUnwrapping.has_wrapped_exception(e, HTTPError)
-                err = current_exceptions_to_string(e)
-                @error err type=Symbol("HTTP.ConnectionRequest") method=req.method url=req.url context=req.context logtag=logtag
+                msg = current_exceptions_to_string()
+                @error msg 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

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

src/clientlayers/TimeoutRequest.jl

@@ -2,6 +2,7 @@ module TimeoutRequest
 
 using ..Connections, ..Streams, ..Exceptions, ..Messages
 using LoggingExtras, ConcurrentUtilities
+using ..Exceptions: current_exceptions_to_string
 
 export timeoutlayer
 
@@ -25,8 +26,8 @@ function timeoutlayer(handler)
                 req = stream.message.request
                 req.context[:timeout_errors] = get(req.context, :timeout_errors, 0) + 1
                 if logerrors
-                    err = current_exceptions_to_string()
-                    @error err type=Symbol("HTTP.TimeoutError") method=req.method url=req.url context=req.context timeout=readtimeout logtag=logtag
+                    msg = current_exceptions_to_string()
+                    @error msg type=Symbol("HTTP.TimeoutError") method=req.method url=req.url context=req.context timeout=readtimeout logtag=logtag
                 end
                 e = Exceptions.TimeoutError(readtimeout)
             end

test/client.jl

@@ -646,8 +646,8 @@ end
 end
 
 @testset "Don't retry on internal exceptions" begin
-    kws = (retry_delays = [1, 2, 3], retries=3) # ~ 6 secs
-    max_wait = 3
+    kws = (retry_delays = [10, 20, 30], retries=3) # ~ 60 secs
+    max_wait = 30
 
     function test_finish_within(f, secs)
         timedout = Ref(false)

test/server.jl

@@ -191,17 +191,17 @@ const echostreamhandler = HTTP.streamhandler(echohandler)
             HTTP.startwrite(http)
             write(http, "response body\n")
         end
-    
+
         port = HTTP.port(server)
-    
+
         sock = connect(host, port)
         close(sock)
-    
+
         r = HTTP.get("https://$(host):$(port)/"; readtimeout=30, require_ssl_verification = false)
         @test r.status == 200
 
         close(server)
-    end    
+    end
 end # @testset
 
 @testset "on_shutdown" begin
@@ -222,7 +222,7 @@ end # @testset
     # First shutdown function errors, second adds 1
     shutdown_throw() = throw(ErrorException("Broken"))
     server = HTTP.listen!(x -> nothing; listenany=true, on_shutdown=[shutdown_throw, shutdown_add])
-    @test_logs (:error, r"shutdown function .* failed") close(server)
+    @test_logs (:error, r"shutdown function .* failed.*ERROR: Broken.*"s) close(server)
     @test TEST_COUNT[] == 4
 end # @testset