From 9f7cba08ba1b3a21f0cefff75f79888322f45e6e Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 17 Aug 2023 16:15:38 -0600 Subject: [PATCH 1/7] Change logs to use `current_exceptions_to_string()` instead of `exception=` --- src/Exceptions.jl | 4 ++-- src/Servers.jl | 17 +++++++++++------ src/WebSockets.jl | 3 ++- test/server.jl | 10 +++++----- 4 files changed, 20 insertions(+), 14 deletions(-) diff --git a/src/Exceptions.jl b/src/Exceptions.jl index 914aff317..c283fb91f 100644 --- a/src/Exceptions.jl +++ b/src/Exceptions.jl @@ -100,8 +100,8 @@ function current_exceptions_to_string() buf = IOBuffer() println(buf) println(buf, "\n===========================\nHTTP Error message:\n") - Base.display_error(buf, Base.catch_stack()) + Base.display_error(buf, Base.current_exceptions()) 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..e9fe6716b 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 + err = current_exceptions_to_string() + @error "shutdown function $fn failed. $err" 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()) + err = current_exceptions_to_string() + @errorv 2 "Server on $(listener.hostname):$(listener.hostport) errored. $err" # 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()) + err = current_exceptions_to_string() + @debugv 1 "handle_connection startread error. $err" 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())) + err = current_exceptions_to_string() + @logmsgv 1 level "handle_connection handler error. $err" if isopen(http) && !iswritable(http) request.response.status = 500 @@ -475,7 +479,8 @@ function handle_connection(f, c::Connection, listener, readtimeout, access_log) end catch e # we should be catching everything inside the while loop, but just in case - @errorv 1 "error while handling connection" exception=(e, catch_backtrace()) + err = current_exceptions_to_string() + @errorv 1 "error while handling connection. $err" finally if readtimeout > 0 wait_for_timeout[] = false diff --git a/src/WebSockets.jl b/src/WebSockets.jl index 56b6933a9..81b2621d3 100644 --- a/src/WebSockets.jl +++ b/src/WebSockets.jl @@ -439,7 +439,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()) + err = current_exceptions_to_string() + suppress_close_error || @error "$(ws.id): Unexpected websocket server error. $err" end if !isclosed(ws) if e isa WebSocketError && e.message isa CloseFrameBody diff --git a/test/server.jl b/test/server.jl index 7b35396f9..4ea3edbdc 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 .*ErrorException.*Broken.*") close(server) @test TEST_COUNT[] == 4 end # @testset From 459621950d59bffb20c1b463546dfffedd7f1d3d Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 17 Aug 2023 16:18:53 -0600 Subject: [PATCH 2/7] cleanup unused variable `catch e` --- src/Servers.jl | 2 +- src/Streams.jl | 2 +- src/clientlayers/StreamRequest.jl | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Servers.jl b/src/Servers.jl index e9fe6716b..583ab494c 100644 --- a/src/Servers.jl +++ b/src/Servers.jl @@ -477,7 +477,7 @@ 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 err = current_exceptions_to_string() @errorv 1 "error while handling connection. $err" 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/clientlayers/StreamRequest.jl b/src/clientlayers/StreamRequest.jl index 3ba642702..873e16481 100644 --- a/src/clientlayers/StreamRequest.jl +++ b/src/clientlayers/StreamRequest.jl @@ -68,7 +68,7 @@ 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 From 08f400e0e57228da07bc69f45f28b4d9d7c4883c Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 17 Aug 2023 21:36:04 -0600 Subject: [PATCH 3/7] Update Exceptions.jl for older julia --- src/Exceptions.jl | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/Exceptions.jl b/src/Exceptions.jl index c283fb91f..ba7a30df0 100644 --- a/src/Exceptions.jl +++ b/src/Exceptions.jl @@ -100,7 +100,12 @@ function current_exceptions_to_string() buf = IOBuffer() println(buf) println(buf, "\n===========================\nHTTP Error message:\n") - Base.display_error(buf, Base.current_exceptions()) + 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 From 8b8e0b0cbe538d794a72eb4430082c9dce142f52 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Wed, 23 Aug 2023 12:14:38 -0600 Subject: [PATCH 4/7] Update test/server.jl Co-authored-by: Nick Robinson --- test/server.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/server.jl b/test/server.jl index 4ea3edbdc..a84ac2b4a 100644 --- a/test/server.jl +++ b/test/server.jl @@ -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 .*ErrorException.*Broken.*") close(server) + @test_logs (:error, r"shutdown function .* failed .*ERROR: Broken.*") close(server) @test TEST_COUNT[] == 4 end # @testset From 45b6d92edd73ab5cc9885d6c5ca611fb9233aceb Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Tue, 5 Sep 2023 22:11:09 -0400 Subject: [PATCH 5/7] Update test/server.jl --- test/server.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/server.jl b/test/server.jl index a84ac2b4a..af1a98741 100644 --- a/test/server.jl +++ b/test/server.jl @@ -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 .*ERROR: Broken.*") close(server) + @test_logs (:error, r"shutdown function .* failed.*ERROR: Broken.*"s) close(server) @test TEST_COUNT[] == 4 end # @testset From c1b4230b14d91937165b70a21893fa275dc96953 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Mon, 18 Sep 2023 08:38:14 -0600 Subject: [PATCH 6/7] Rename err => msg; fix missing import --- src/Connections.jl | 4 ++-- src/Servers.jl | 20 ++++++++++---------- src/WebSockets.jl | 5 +++-- src/clientlayers/ConnectionRequest.jl | 12 ++++++------ src/clientlayers/StreamRequest.jl | 4 ++-- src/clientlayers/TimeoutRequest.jl | 5 +++-- 6 files changed, 26 insertions(+), 24 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/Servers.jl b/src/Servers.jl index 583ab494c..4a8f37194 100644 --- a/src/Servers.jl +++ b/src/Servers.jl @@ -193,8 +193,8 @@ function shutdown(fn::Function) try fn() catch - err = current_exceptions_to_string() - @error "shutdown function $fn failed. $err" + msg = current_exceptions_to_string() + @error "shutdown function $fn failed. $msg" end end @@ -393,8 +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 - err = current_exceptions_to_string() - @errorv 2 "Server on $(listener.hostname):$(listener.hostport) errored. $err" + 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) @@ -433,8 +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 - err = current_exceptions_to_string() - @debugv 1 "handle_connection startread error. $err" + msg = current_exceptions_to_string() + @debugv 1 "handle_connection startread error. $msg" break end @@ -461,8 +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 - err = current_exceptions_to_string() - @logmsgv 1 level "handle_connection handler error. $err" + msg = current_exceptions_to_string() + @logmsgv 1 level "handle_connection handler error. $msg" if isopen(http) && !iswritable(http) request.response.status = 500 @@ -479,8 +479,8 @@ 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 - err = current_exceptions_to_string() - @errorv 1 "error while handling connection. $err" + msg = current_exceptions_to_string() + @errorv 1 "error while handling connection. $msg" finally if readtimeout > 0 wait_for_timeout[] = false diff --git a/src/WebSockets.jl b/src/WebSockets.jl index 81b2621d3..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,8 +440,8 @@ function upgrade(f::Function, http::Streams.Stream; suppress_close_error::Bool=f f(ws) catch e if !isok(e) - err = current_exceptions_to_string() - suppress_close_error || @error "$(ws.id): Unexpected websocket server error. $err" + 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 873e16481..4442574b6 100644 --- a/src/clientlayers/StreamRequest.jl +++ b/src/clientlayers/StreamRequest.jl @@ -72,8 +72,8 @@ 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 - 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 From bab328a5862e690c2db9f2d078a198000ddf7241 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1=C5=A1=20Drvo=C5=A1t=C4=9Bp?= Date: Mon, 18 Sep 2023 17:50:25 +0200 Subject: [PATCH 7/7] Make "Don't retry on internal exceptions" less flakey --- test/client.jl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/client.jl b/test/client.jl index e9c60e7c3..868ac8ded 100644 --- a/test/client.jl +++ b/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)