diff --git a/Project.toml b/Project.toml index bebfc3f51f..0339e617f2 100644 --- a/Project.toml +++ b/Project.toml @@ -37,6 +37,7 @@ XMLDict = "0.3, 0.4" julia = "1.6" [extras] +Logging = "56ddb016-857b-54e1-b83d-db4d58db5568" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" StableRNGs = "860ef19b-820b-49d6-a774-d7a799459cd3" Suppressor = "fd094767-a336-5f1f-9728-57cf17d0bbfb" @@ -44,4 +45,4 @@ Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4" [targets] -test = ["Pkg", "Suppressor", "StableRNGs", "Test", "UUIDs"] +test = ["Pkg", "Logging", "StableRNGs", "Suppressor", "Test", "UUIDs"] diff --git a/src/utilities/downloads_backend.jl b/src/utilities/downloads_backend.jl index bbce7ebf92..ca95cd5a6c 100644 --- a/src/utilities/downloads_backend.jl +++ b/src/utilities/downloads_backend.jl @@ -110,6 +110,19 @@ function _http_request(backend::DownloadsBackend, request::Request, response_str return nothing end + check = (s, e) -> begin + if isa(e, HTTP.StatusError) && AWS._http_status(e) >= 500 + @debug "AWS.jl Downloads inner retry for status >= 500" retry=true reason="status >= 500" status=AWS._http_status(e) exception=e + return true + elseif isa(e, Downloads.RequestError) + @debug "AWS.jl Downloads inner retry for Downloads.RequestError" retry=true reason="Downloads.RequestError" exception=e + return true + else + @debug "AWS.jl Downloads inner retry declined" retry=false reason="Exception passed onwards" exception=e + return false + end + end + try retry(get_response; check=check, delays=delays)() finally diff --git a/src/utilities/request.jl b/src/utilities/request.jl index a214eec436..a0d1e6d118 100644 --- a/src/utilities/request.jl +++ b/src/utilities/request.jl @@ -147,22 +147,29 @@ function submit_request(aws::AbstractAWSConfig, request::Request; return_headers if e isa HTTP.StatusError e = AWSException(e, stream) rethrow(e) + elseif !(e isa AWSException) + @debug "AWS.jl declined to retry non-AWSException" retry=false reason="Non-AWSException" exception=e end rethrow() end end - check = function (s, e) + check = (s, e) -> begin # Pass on non-AWS exceptions. if !(e isa AWSException) + @debug "AWS.jl declined to retry non-AWSException" retry=false reason="Non-AWSException" exception=e return false end - occursin("Signature expired", e.message) && return true + if occursin("Signature expired", e.message) + @debug "AWS.jl retry for signature expired" retry=true reason="Signature expired" exception=e + return true + end # Handle ExpiredToken... # https://github.com/aws/aws-sdk-go/blob/v1.31.5/aws/request/retryer.go#L98 if e isa AWSException && e.code in EXPIRED_ERROR_CODES + @debug "AWS.jl retry for expired credentials" retry=true reason="Credentials expired" exception=e check_credentials(credentials(aws); force_refresh=true) return true end @@ -170,29 +177,41 @@ function submit_request(aws::AbstractAWSConfig, request::Request; return_headers # Throttle handling # https://github.com/boto/botocore/blob/1.16.17/botocore/data/_retry.json # https://docs.aws.amazon.com/general/latest/gr/api-retries.html - if _http_status(e.cause) == TOO_MANY_REQUESTS || e.code in THROTTLING_ERROR_CODES + if _http_status(e.cause) == TOO_MANY_REQUESTS + @debug "AWS.jl retry too many requests" retry=true reason="too many requests" exception=e + return true + elseif e.code in THROTTLING_ERROR_CODES + @debug "AWS.jl retry for throttling" retry=true reason="throttled" exception=e return true end # Handle BadDigest error and CRC32 check sum failure - if _header(e.cause, "crc32body") == "x-amz-crc32" || - e.code in ("BadDigest", "RequestTimeout", "RequestTimeoutException") + if _header(e.cause, "crc32body") == "x-amz-crc32" + @debug "AWS.jl retry for check sum failure" retry=true reason="Check sum failure" exception=e + return true + end + + if e.code in ("BadDigest", "RequestTimeout", "RequestTimeoutException") + @debug "AWS.jl retry for $(e.code)" retry=true reason="$(e.code)" exception=e return true end if occursin("Missing Authentication Token", e.message) && aws.credentials === nothing + @debug "AWS.jl declined to retry request without credentials" retry=false reason="No credentials" exception=e + return throw( NoCredentials( - "You're attempting to perform a request without credentials set." + "You're attempting to perform a request without credentials set.", ), ) end + + @debug "AWS.jl declined to retry uncaught error" retry=false reason="Error unhandled" exception=e return false end delays = AWSExponentialBackoff(; max_attempts=max_attempts(aws)) - retry(upgrade_error(get_response); check=check, delays=delays)() if request.use_response_type @@ -234,14 +253,24 @@ function _http_request(http_backend::HTTPBackend, request::Request, response_str return nothing end - check = function (s, e) - return isa(e, HTTP.ConnectError) || - isa(e, HTTP.RequestError) || - (isa(e, HTTP.StatusError) && _http_status(e) >= 500) - end - delays = AWSExponentialBackoff(; max_attempts=4) + check = (s, e) -> begin + errors = (Sockets.DNSError, HTTP.ParseError, Base.IOError) + for error in errors + if isa(e, error) + @debug "AWS.jl HTTP inner retry for $error" retry=true reason="$error" exception=e + return true + end + end + if (isa(e, HTTP.StatusError) && _http_status(e) >= 500) + @debug "AWS.jl HTTP inner retry for status >= 500" retry=true reason="status >= 500" status=_http_status(e) exception=e + return true + end + @debug "AWS.jl HTTP inner retry declined" retry=false reason="Exception passed onwards" exception=e + return false + end + try retry(get_response; check=check, delays=delays)() finally diff --git a/test/issues.jl b/test/issues.jl index 9c67e7f437..c4d17e2d1e 100644 --- a/test/issues.jl +++ b/test/issues.jl @@ -2,6 +2,14 @@ BUCKET_NAME = "aws-jl-test-issues---" * _now_formatted() +# We try to be insensitive to the existence of other logging messages, so we test +# by counting the number of messages that meet some criteria +function log_is_retry(successful) + return record -> + record.level == Logging.Debug && + get(record.kwargs, :retry, nothing) == successful +end + try S3.create_bucket(BUCKET_NAME) @@ -202,12 +210,24 @@ try config = AWSConfig(; creds=nothing) @testset "Fail 2 attempts then succeed" begin - apply(_incomplete_patch(; data=data, num_attempts_to_fail=2)) do - retrieved = S3.get_object(bucket, key; aws_config=config) + logger = Test.TestLogger(; min_level=Logging.Debug) + with_logger(logger) do + apply(_incomplete_patch(; data=data, num_attempts_to_fail=2)) do + retrieved = S3.get_object(bucket, key; aws_config=config) - @test length(retrieved) == n - @test retrieved == data + @test length(retrieved) == n + @test retrieved == data + end end + logs = logger.logs + + println("Fail two ") + println(logs) + + # Two successful retries + @test count(log_is_retry(true), logs) == 2 + # No unsuccessful ones + @test count(log_is_retry(false), logs) == 0 end @testset "Fail all 4 attempts then throw" begin @@ -218,15 +238,27 @@ try end io = IOBuffer() - apply(_incomplete_patch(; data=data, num_attempts_to_fail=4)) do - params = Dict("response_stream" => io) - @test_throws err_t S3.get_object(bucket, key, params; aws_config=config) + logger = Test.TestLogger(; min_level=Logging.Debug) + with_logger(logger) do + apply(_incomplete_patch(; data=data, num_attempts_to_fail=4)) do + params = Dict("response_stream" => io) + @test_throws err_t S3.get_object(bucket, key, params; aws_config=config) - seekstart(io) - retrieved = read(io) - @test length(retrieved) == n - 1 - @test retrieved == data[1:(n - 1)] + seekstart(io) + retrieved = read(io) + @test length(retrieved) == n - 1 + @test retrieved == data[1:(n - 1)] + end end + logs = logger.logs + + println("Fail 4") + println(logs) + + # Three successful retries - from the inner retry loop + @test count(log_is_retry(true), logs) == 3 + # One unsuccessful one - from the outer loop where we pass it on + @test count(log_is_retry(false), logs) == 1 end end diff --git a/test/runtests.jl b/test/runtests.jl index 3df8afe121..3731e4b8af 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -25,16 +25,17 @@ using GitHub using HTTP using IniFile: Inifile using JSON -using OrderedCollections: LittleDict, OrderedDict +using Logging using MbedTLS: digest, MD_SHA256, MD_MD5 using Mocking +using OrderedCollections: LittleDict, OrderedDict using Pkg using Random +using StableRNGs using Suppressor using Test using UUIDs using XMLDict -using StableRNGs Mocking.activate()