Add debug logging messages on retry

Project.toml

@@ -37,11 +37,12 @@ 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"
 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"]

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=_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

src/utilities/request.jl

@@ -147,52 +147,73 @@ 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
+                return false
             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
 
         # 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 +255,31 @@ 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
+        # `Base.IOError` is needed because HTTP.jl can often have errors that aren't
+        # caught and wrapped in an `HTTP.IOError`
+        # https://github.com/JuliaWeb/HTTP.jl/issues/382
+        errors = (Sockets.DNSError, HTTP.ParseError, HTTP.IOError, 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 = AWS._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

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,20 @@ 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
+            # 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 +234,23 @@ 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
+            # 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
 

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()