HTTPS GET requests to S3 hang forever when doing a lot of them

[quatrix]

The following code never finishes:

using HTTP

function main()
    get(i) = begin
        try
            data = HTTP.get("https://public-test-bucket-quatrix.s3.amazonaws.com/signals/10737/1574792548712.wav")

            @info "got" i=i data=size(data.body)
        catch e
            @error "error" exception=e
        end
    end

    asyncmap(get, 1:6000, ntasks=20)
end

main()

while running the following exception pop up

IOError: write: broken pipe (EPIPE)

and sometimes also

ArgumentError: `unsafe_write` requires `iswritable(::SSLContext)`

1. It usually finishes when running one time, second run hangs forever. so you may want to run it multiple times to reproduce.
2. Payload size is 150k, it also hangs when downloading a 11 bytes payload, a bit less often, you can by replacing the URL to: https://public-test-bucket-quatrix.s3.amazonaws.com/hey.txt
3. Runs that don't hang may still have the ArgumentError exception, but not the broken pipe exception.
4. Changing https to http seems to make it always not hang - with http also tried doubling the iterations and increasing payload to 400k, all finishes many times.
5. Setting readtimeout=5 doesn't seem to have an effect, it just hangs forever regardless
6. Changing ntasks to 2, also hangs, but takes more time

I'm testing this from an Azure machine downloading objects from AWS.

this is the output when hitting ctrl+c

┌ Info: got
│   i = 5982
└   data = (155990,)
┌ Info: got
│   i = 5991
└   data = (155990,)



^C
signal (2): Interrupt
in expression starting at /data/repos/research_infra/scripts/reproduce.jl:26
epoll_pwait at /build/glibc-OTsEL5/glibc-2.27/misc/../sysdeps/unix/sysv/linux/epoll_pwait.c:42
uv__io_poll at /workspace/srcdir/libuv/src/unix/linux-core.c:270
uv_run at /workspace/srcdir/libuv/src/unix/core.c:359
jl_task_get_next at /buildworker/worker/package_linux64/build/src/partr.c:448
poptaskref at ./task.jl:660
wait at ./task.jl:667
task_done_hook at ./task.jl:401
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2135 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2305
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1631 [inlined]
jl_finish_task at /buildworker/worker/package_linux64/build/src/task.c:181
start_task at /buildworker/worker/package_linux64/build/src/task.c:669
unknown function (ip: 0xffffffffffffffff)
unknown function (ip: 0xffffffffffffffff)
Allocations: 36707340 (Pool: 36687998; Big: 19342); GC: 80

Julia 1.3.1
HTTP.jl 0.8.12
MbedTLS.jl 0.7.0

[quinnj]

I can't seem to reproduce this locally; I ran the script 4-5 times and saw 0 errors; so it might be network connection related? The broken pipe error indeed shows up when there's some kind of network interruption. It might be worth some other people trying to see if they can reproduce this on various kinds of networks.

[quatrix]

Hi,

Thanks for trying to reproduce!

I just ran it multiple times on my local machine, and it indeed finished, then I tried running on Azure machine and AWS machine, and both hang as described.

I observed that the local run is a lot slower (6 mbps) than Azure ( 93 mbps) /AWS ( 364 mbps) (by the time they reach a hanging state, the local run isn't even halfway done)

I'm guessing that when doing this high rate download maybe S3 starts to throttle / close the socket, which doesn't happen when running via a slower connection.

Would it be possible for you trying to reproduce on AWS/Azure machine?

[Keno]

I can reproduce this on a local machine that has high bandwidth to AWS. I was hoping #528 might aid in debugging.

[Keno]

So first things first - let's look at what's up with all these EPIPE errors. Here's the packet capture for this

No.	Time	Source	Destination	Protocol	Length	Info
79928	78.367814	2001:550:2:2c::46:13	2600:1fa0:8064:9a91:34d8:68ed::	TCP	74	57420 → 443 [ACK] Seq=32497 Ack=15712435 Win=1821568 Len=0
79934	78.380922	2001:550:2:2c::46:13	2600:1fa0:8064:9a91:34d8:68ed::	TLSv1.2	150	[TLS segment of a reassembled PDU]
79938	78.394487	2600:1fa0:8064:9a91:34d8:68ed::	2001:550:2:2c::46:13	TCP	74	443 → 57420 [FIN, ACK] Seq=15712435 Ack=32573 Win=74752 Len=0
79994	78.421669	2001:550:2:2c::46:13	2600:1fa0:8064:9a91:34d8:68ed::	TLSv1.2	174	[TLS segment of a reassembled PDU]
79998	78.434266	2600:1fa0:8064:9a91:34d8:68ed::	2001:550:2:2c::46:13	TCP	74	443 → 57420 [RST] Seq=15712436 Win=0 Len=0

So we're acking the server reponse, and then we send the next request as two packets, the first being

GET /signals/10737/1574792548712.wav HTTP/1.1

the second

Host: public-test-bucket-quatrix.s3.dualstack.us-east-1.amazonaws.com

And we get a TCP FIN/ACK in the middle. So the server really did shut down the connection there. That's mostly fine, we should just retry with a new connection and not even be verbose about it.

[Keno]

That said, it's a bit odd that we're splitting the HTTP header over two TCP packets. I wouldn't be surprised if the server would have still served that request if it arrived as one packet.

[Keno]

I applied this patch, which helped cut the number of EPIPE errors quite a bit:

diff --git a/src/Streams.jl b/src/Streams.jl
index 51a053a..c6dd094 100644
--- a/src/Streams.jl
+++ b/src/Streams.jl
@@ -82,7 +82,9 @@ function IOExtras.startwrite(http::Stream)
     else
         http.writechunked = ischunked(m)
     end
-    writeheaders(http.stream, m)
+    buf = IOBuffer()
+    writeheaders(buf, m)
+    write(http.stream, take!(buf))
 end

 function Base.unsafe_write(http::Stream, p::Ptr{UInt8}, n::UInt)

I did still see it here:

No.	Time	Source	Destination	Protocol	Length	Info
45635	90.024816	2600:1fa0:80a4:ad48:34d8:cd55::	2001:550:2:2c::46:13	TLSv1.2	813	Application Data
45636	90.024820	2600:1fa0:80a4:ad48:34d8:cd55::	2001:550:2:2c::46:13	TLSv1.2	105	Encrypted Alert
45641	90.065833	2001:550:2:2c::46:13	2600:1fa0:80a4:ad48:34d8:cd55::	TCP	74	59850 → 443 [ACK] Seq=20897 Ack=15712290 Win=3025920 Len=0
45685	90.088367	2001:550:2:2c::46:13	2600:1fa0:80a4:ad48:34d8:cd55::	HTTP	277	GET /signals/10737/1574792548712.wav HTTP/1.1 
45686	90.101662	2600:1fa0:80a4:ad48:34d8:cd55::	2001:550:2:2c::46:13	TCP	74	443 → 59850 [FIN, ACK] Seq=15712290 Ack=21100 Win=130816 Len=0

So we got a TLS level connection abort, but apparently ignored it and sent another request. I assume what happened here is that we just didn't look for any more pending data on the SSL socket, so we didn't pick up the close message.

[Keno]

With this patch to MBedTLS (in addition to the patch above), I don't see any errors logged at all:

diff --git a/src/ssl.jl b/src/ssl.jl
index d01352c..cd576ed 100644
--- a/src/ssl.jl
+++ b/src/ssl.jl
@@ -143,7 +143,15 @@ True unless:
  - the peer closed the connection (and the TLS buffer is empty), or
  - an un-handled exception occurred while reading.
 """
-Base.isreadable(ctx::SSLContext) = ctx.isreadable
+function Base.isreadable(ctx::SSLContext)
+    ctx.isreadable || return false
+    # It's possible we received the shutdown, but didn't process it yet - if so
,
+    # do that now.
+    if bytesavailable(ctx.bio) > 0 || ssl_check_pending(ctx)
+        ssl_unsafe_read(ctx, Ptr{UInt8}(C_NULL), UInt(0))
+    end
+    return ctx.isreadable
+end

 """
 True unless:

[quatrix]

@Keno thanks a lot! I updated all relevant packages.

Now i don't see any errors but unfortunately I'm still able to reproduce the original problem, running the above example on an aws machine usually reproduces on the second run.

It just hangs forever. :(

(I though maybe it's some threading thing and I tried on Julia 1.4 and 1.5, same results)

[c42f]

We (the JuliaHub team) have just hit something rather similar-looking to this in production. Our application wasn't doing a massive pile of S3 requests, but at some point it appeared as if all requests to S3 started hanging (seeming indefinitely). I've also observed something similar for PUTs when uploading a smaller number of large files.

I can confirm that a minor variation of the original script hangs for me, though even more easily - I only need N=1000 jobs with ntasks=20 in order to get ~10 hung tasks. I tried with a S3 presigned URL rather than a public S3 bucket as that was easier for me to set up. I used an EC2 instance in the same region as the bucket.

using HTTP                                                                    

# 25 byte file (for no particular reason)
# aws s3 presign s3://some-bucket/blah --expires-in 604800
const _url = "..."

function get_data(done_list, i)
    try
        data = HTTP.get(_url, require_ssl_verification=false)
        @info "got" i=i data=size(data.body)
        done_list[i] = true
    catch e
        @error "error" exception=e
    end
end     
    
done_list = nothing
    
function main(N=1000)
    global done_list = falses(N)
    asyncmap(i->get_data(done_list, i), 1:N, ntasks=20)
end 
    
main()

julia> main()
[lots of logs, then hangs]
^C

julia> sum(done_list)
985

(@v1.6) pkg> status HTTP MbedTLS
      Status `~/.julia/environments/v1.6/Project.toml`
  [cd3eb016] HTTP v0.9.12
  [739be429] MbedTLS v1.0.3

I had a go at reproducing this with a local nginx server to handle the https traffic rather than S3, but it seems to work fine in that case. (I managed to get SSL working with the require_ssl_verification=false hack above but in general I don't really know what I'm doing with nginx yet.)

[c42f]

I was wondering whether this could be related to the connection pool. Setting reuse_limit=0 we get IOError exceptions downloading from S3 rather than tasks hanging. Example script:

using HTTP

# Dummy data
const _url = "https://datasets-jl-test.s3.amazonaws.com/foo.txt?AWSAccessKeyId=ASIAZK43HGP34BZT5BTD&Signature=EYFYnxfvnV%2F2yrk8MBfqTtgbPfs%3D&x-amz-security-token=FwoGZXIvYXdzECwaDITnkSRSAAnM6zSHSiKGAfY4EPAezrGovUqdVuBloHpxfc9x2Onm4Y1v2mO8Hop%2FPVVCTcNinYfLIzfjrfzEo2QKXACH%2B4hrAsYp%2FqK9%2FmeGwI0OthUjerZbr8mIbNjYx3qsKYqWz44%2BL%2BalIi%2B17eA9kaGBcsNQO6opsQe1FvFH9eZrwkooF%2FRBEmouQdv9MCX9Ag%2FRKJj3uocGMijhHdYdt5vWmAy4yFF4f1vcowW7GslhSnoJ9290DDNRN0vr5VSnzE7Y&Expires=1626863359"

function main2(; N=1000, ntasks=20)
    M = N÷ntasks
    tasks = []
    for i=1:ntasks
        let ti = i
            t = @async for j=1:M
                try
                    data = HTTP.get(_url, require_ssl_verification=false, reuse_limit=0)
                    @info "got" i=ti j data=sizeof(data.body)
                catch
                    @error "task $ti failed"
                    rethrow()
                end
            end
            push!(tasks, t)
        end
    end
    tasks
end

After running tasks = main2() and watching for a bit, many of the tasks fail. I don't need to run on EC2 to reproduce this. All failures have the same stacktrace:

IOError(EOFError() during request(https://datasets-jl-test.s3.amazonaws.com/foo.txt?AWSAccessKeyId=ASIAZK43HGP34BZT5BTD&Signature=EYFYnxfvnV%2F2yrk8MBfqTtgbPfs%3D&x-amz-security-token=FwoGZXIvYXdzECwaDITnkSRSAAnM6zSHSiKGAfY4EPAezrGovUqdVuBloHpxfc9x2Onm4Y1v2mO8Hop%2FPVVCTcNinYfLIzfjrfzEo2QKXACH%2B4hrAsYp%2FqK9%2FmeGwI0OthUjerZbr8mIbNjYx3qsKYqWz44%2BL%2BalIi%2B17eA9kaGBcsNQO6opsQe1FvFH9eZrwkooF%2FRBEmouQdv9MCX9Ag%2FRKJj3uocGMijhHdYdt5vWmAy4yFF4f1vcowW7GslhSnoJ9290DDNRN0vr5VSnzE7Y&Expires=1626863359))

Stacktrace:
  [1] read_to_buffer(t::HTTP.ConnectionPool.Transaction{MbedTLS.SSLContext}, sizehint::Int64)
    @ HTTP.ConnectionPool ~/.julia/packages/HTTP/dCYNB/src/ConnectionPool.jl:273
  [2] readuntil(t::HTTP.ConnectionPool.Transaction{MbedTLS.SSLContext}, f::Function, sizehint::Int64)
    @ HTTP.ConnectionPool ~/.julia/packages/HTTP/dCYNB/src/ConnectionPool.jl:292
  [3] readuntil
    @ ~/.julia/packages/HTTP/dCYNB/src/ConnectionPool.jl:290 [inlined]
  [4] readheaders
    @ ~/.julia/packages/HTTP/dCYNB/src/Messages.jl:537 [inlined]
  [5] startread(http::HTTP.Streams.Stream{HTTP.Messages.Response, HTTP.ConnectionPool.Transaction{MbedTLS.SSLContext}})
    @ HTTP.Streams ~/.julia/packages/HTTP/dCYNB/src/Streams.jl:164
  [6] macro expansion
    @ ~/.julia/packages/HTTP/dCYNB/src/StreamRequest.jl:67 [inlined]
  [7] macro expansion
    @ ./task.jl:382 [inlined]
  [8] request(::Type{StreamLayer{Union{}}}, io::HTTP.ConnectionPool.Transaction{MbedTLS.SSLContext}, req::HTTP.Messages.Request, body::Vector{UInt8}; reached_redirect_limit::Bool, response_stream::Nothing, iofunction::Nothing, verbose::Int64, kw::Base.Iterators.Pairs{Symbol, Bool, Tuple{Symbol}, NamedTuple{(:require_ssl_verification,), Tuple{Bool}}})
    @ HTTP.StreamRequest ~/.julia/packages/HTTP/dCYNB/src/StreamRequest.jl:57
  [9] request(::Type{ConnectionPoolLayer{StreamLayer{Union{}}}}, url::URIs.URI, req::HTTP.Messages.Request, body::Vector{UInt8}; proxy::Nothing, socket_type::Type, reuse_limit::Int64, kw::Base.Iterators.Pairs{Symbol, Union{Nothing, Bool}, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:iofunction, :reached_redirect_limit, :require_ssl_verification), Tuple{Nothing, Bool, Bool}}})
    @ HTTP.ConnectionRequest ~/.julia/packages/HTTP/dCYNB/src/ConnectionRequest.jl:108
 [10] request(::Type{ExceptionLayer{ConnectionPoolLayer{StreamLayer{Union{}}}}}, ::URIs.URI, ::Vararg{Any, N} where N; kw::Base.Iterators.Pairs{Symbol, Union{Nothing, Integer}, NTuple{4, Symbol}, NamedTuple{(:iofunction, :reached_redirect_limit, :require_ssl_verification, :reuse_limit), Tuple{Nothing, Bool, Bool, Int64}}})
    @ HTTP.ExceptionRequest ~/.julia/packages/HTTP/dCYNB/src/ExceptionRequest.jl:19
 [11] (::Base.var"#70#72"{Base.var"#70#71#73"{ExponentialBackOff, HTTP.RetryRequest.var"#2#3"{Bool, HTTP.Messages.Request}, typeof(HTTP.request)}})(::Type, ::Vararg{Any, N} where N; kwargs::Base.Iterators.Pairs{Symbol, Union{Nothing, Integer}, NTuple{4, Symbol}, NamedTuple{(:iofunction, :reached_redirect_limit, :require_ssl_verification, :reuse_limit), Tuple{Nothing, Bool, Bool, Int64}}})
    @ Base ./error.jl:301
 [12] #request#1
    @ ~/.julia/packages/HTTP/dCYNB/src/RetryRequest.jl:44 [inlined]
 [13] request(::Type{MessageLayer{RetryLayer{ExceptionLayer{ConnectionPoolLayer{StreamLayer{Union{}}}}}}}, method::String, url::URIs.URI, headers::Vector{Pair{SubString{String}, SubString{String}}}, body::Vector{UInt8}; http_version::VersionNumber, target::String, parent::Nothing, iofunction::Nothing, kw::Base.Iterators.Pairs{Symbol, Integer, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:reached_redirect_limit, :require_ssl_verification, :reuse_limit), Tuple{Bool, Bool, Int64}}})
    @ HTTP.MessageRequest ~/.julia/packages/HTTP/dCYNB/src/MessageRequest.jl:66
 [14] request(::Type{BasicAuthLayer{MessageLayer{RetryLayer{ExceptionLayer{ConnectionPoolLayer{StreamLayer{Union{}}}}}}}}, method::String, url::URIs.URI, headers::Vector{Pair{SubString{String}, SubString{String}}}, body::Vector{UInt8}; kw::Base.Iterators.Pairs{Symbol, Integer, Tuple{Symbol, Symbol, Symbol}, NamedTuple{(:reached_redirect_limit, :require_ssl_verification, :reuse_limit), Tuple{Bool, Bool, Int64}}})
    @ HTTP.BasicAuthRequest ~/.julia/packages/HTTP/dCYNB/src/BasicAuthRequest.jl:28
 [15] request(::Type{RedirectLayer{BasicAuthLayer{MessageLayer{RetryLayer{ExceptionLayer{ConnectionPoolLayer{StreamLayer{Union{}}}}}}}}}, method::String, url::URIs.URI, headers::Vector{Pair{SubString{String}, SubString{String}}}, body::Vector{UInt8}; redirect_limit::Int64, forwardheaders::Bool, kw::Base.Iterators.Pairs{Symbol, Integer, Tuple{Symbol, Symbol}, NamedTuple{(:require_ssl_verification, :reuse_limit), Tuple{Bool, Int64}}})
    @ HTTP.RedirectRequest ~/.julia/packages/HTTP/dCYNB/src/RedirectRequest.jl:24
 [16] request(method::String, url::String, h::Vector{Pair{SubString{String}, SubString{String}}}, b::Vector{UInt8}; headers::Vector{Pair{SubString{String}, SubString{String}}}, body::Vector{UInt8}, query::Nothing, kw::Base.Iterators.Pairs{Symbol, Integer, Tuple{Symbol, Symbol}, NamedTuple{(:require_ssl_verification, :reuse_limit), Tuple{Bool, Int64}}})
    @ HTTP ~/.julia/packages/HTTP/dCYNB/src/HTTP.jl:315
 [17] #get#13
    @ ~/.julia/packages/HTTP/dCYNB/src/HTTP.jl:392 [inlined]
 [18] macro expansion
    @ ~/tmp/http_hang.jl:35 [inlined]
 [19] (::var"#12#13"{Int64, Int64})()
    @ Main ./task.jl:406

[c42f]

Looks like there's something messed up with the connection pool.

When setting reuse_limit == 0 I nevertheless see Transactions with sequence numbers up to 4 in testing (and it seems that it's these transactions which are failing).

I'm trying to figure out what's actually going on now. The connection pooling code is fairly subtle.

[c42f]

Reading through the ConnectionPool code I've noticed a few weird-seeming things.

• It seems both closeread(::Transaction) and closewrite(::Transaction) call release(::Connection) which returns the connection to the pool. So the connection will be returned to the pool multiple times per request-response. In addition, closewrite ends up being called twice as part of request(::Type{StreamLayer{<:}}) - both in the body of that function and also in writebody(). So a given connection will be returned to the pool's channel up to three times. This seems weird to me and potentially broken.

• reuse_limit is not respected because it checks readcount() rather than the sequence number. But readcount isn't incremented immediately on assigning a transaction to a connection, but only later when closeread is called.

• It seems that isvalid() is happy to close connection streams based on various conditions (timeout and reuse counts) when the stream isn't currently reading/writing. But depending on the details of locking, a connection could already have had pending transactions assigned to it which have not yet started reading or writing. It seems easy for race conditions to creep in here.

[c42f]

Possibly ConnectionPool requires a bit of a rewrite. I'm reading up on https://datatracker.ietf.org/doc/html/rfc7230#section-6 and looking at Go's HTTP/1.1 implementation in their net/http stdlib for inspiration.