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

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

* Bump version

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