Change logs to use current_exceptions_to_string() instead of `excep…

…tion=` 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 <npr251@gmail.com>
Co-authored-by: Tomáš Drvoštěp <tomas.drvostep@gmail.com>

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/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