From e6657ccce293a17399a0fbec1f801e56ce1776c8 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Mon, 18 Sep 2023 10:10:56 -0600 Subject: [PATCH] Change logs to use `current_exceptions_to_string()` instead of `exception=` pattern (#1092) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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 Co-authored-by: Tomáš Drvoštěp --- src/Connections.jl | 4 ++-- src/Exceptions.jl | 9 +++++++-- src/Servers.jl | 19 ++++++++++++------- src/Streams.jl | 2 +- src/WebSockets.jl | 4 +++- src/clientlayers/ConnectionRequest.jl | 12 ++++++------ src/clientlayers/StreamRequest.jl | 6 +++--- src/clientlayers/TimeoutRequest.jl | 5 +++-- test/server.jl | 10 +++++----- 9 files changed, 42 insertions(+), 29 deletions(-) diff --git a/src/Connections.jl b/src/Connections.jl index 182bace24..60d6eb9b7 100644 --- a/src/Connections.jl +++ b/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 diff --git a/src/Exceptions.jl b/src/Exceptions.jl index 914aff317..ba7a30df0 100644 --- a/src/Exceptions.jl +++ b/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 \ No newline at end of file +end # module Exceptions diff --git a/src/Servers.jl b/src/Servers.jl index 6afb16590..4a8f37194 100644 --- a/src/Servers.jl +++ b/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 diff --git a/src/Streams.jl b/src/Streams.jl index 116bf2000..220d11c4e 100644 --- a/src/Streams.jl +++ b/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 diff --git a/src/WebSockets.jl b/src/WebSockets.jl index 56b6933a9..ab9e532da 100644 --- a/src/WebSockets.jl +++ b/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 diff --git a/src/clientlayers/ConnectionRequest.jl b/src/clientlayers/ConnectionRequest.jl index f26d7cb02..564a8f088 100644 --- a/src/clientlayers/ConnectionRequest.jl +++ b/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 diff --git a/src/clientlayers/StreamRequest.jl b/src/clientlayers/StreamRequest.jl index 3ba642702..4442574b6 100644 --- a/src/clientlayers/StreamRequest.jl +++ b/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() diff --git a/src/clientlayers/TimeoutRequest.jl b/src/clientlayers/TimeoutRequest.jl index 94e58b587..13486c081 100644 --- a/src/clientlayers/TimeoutRequest.jl +++ b/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 diff --git a/test/server.jl b/test/server.jl index 7b35396f9..af1a98741 100644 --- a/test/server.jl +++ b/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