search

soto-project / soto

Swift SDK for AWS that works on Linux, macOS and iOS
https://soto.codes
Apache License 2.0
871 stars 83 forks source link

"stream ended at an unexpected time" error when downloading objects. #637

Closed ghost closed 1 year ago

ghost commented 1 year ago

Describe the bug We're getting "stream ended at an unexpected time" from swift-nio when running getObject. Happens sometimes, and mostly with big files (>80MB).

I've seen this issue in NIO, I assume it is related, but it still happens for me on the latest version. soto - 6.2.0, swift-nio - 2.44.0.

Is there any workaround that we can use to avoid this until it is fixed?

To Reproduce Steps to reproduce the behavior:

  1. try downloading an object using getObject.
  2. doesn't reproduce every time

Expected behavior "stream ended at an unexpected time" doesn't appear.

Setup (please complete the following information):

adam-fowler commented 1 year ago

Regarding the issue you linked to, that is resolved in NIO v2.44. This is an issue in the HTTP parser NIO use. NIO have implemented a workaround because the HTTP parser fix hasn't been implemented.

Are you running a HEAD request before the getObject call? If you are the NIO fix might not cover every instance. Add the AWSLoggingMiddleware() to the AWSClient or S3 object to log every request sent to AWS. 

let s3 = S3(client: awsClient ...).with(middlewares: [AWSLoggingMiddleware()])

You can then verify if any HEAD requests are being sent to AWS.

Does this only occur with large files? If so you could use multipartUpload instead. You can upload the file in 16 separate parts if smaller uploads work. For an 80mb file you should really be using multipartUpload anyway.

ghost commented 1 year ago

Hi @adam-fowler; thank you for the response. Got some logs, but seems like there is no HEAD request. Logs for getObject:

Request:
  GetObject
  GET https://bucket-name.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject
  Headers: [
    user-agent : Soto/6.0
  ]
  Body: empty
stream ended at an unexpected time - stream ended at an unexpected time

Does this only occur with large files?

Not 100% sure; the issue occurs once in 5-10 attempts. And primarily for large files; at least, I didn't catch one with a small size (if not counting the next part).

If so you could use multipartUpload instead.

I assume you mean multipartDownload. Tried to use it instead but got the same error on a 2nd try. Here're the logs:

Multipart download logs: ``` Request: HeadObject HEAD https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip Headers: [ user-agent : Soto/6.0 ] Body: empty Response: Status : 200 Headers: [ x-amz-id-2 : fVSRY6fNXpv8QU6S2mchceUPrkhshg7/GJm3hY7cj6011hl56PJsWo6f5JvAM1xLUpJ1JgV2xvA= x-amz-request-id : QPDY089DNXXHMWXM Date : Wed, 16 Nov 2022 14:40:40 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 95932144 ] Body: empty Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=0-5242879 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : cGW70yyfNXPgPXJnFzE5TksYI9Cnn1O+A26tL2oikPPI0+HksjSeeKvbZD/9CnAvOH2l1r5vNKE= x-amz-request-id : QPDYAGZGQM9KZYX5 Date : Wed, 16 Nov 2022 14:40:40 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 0-5242879/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=5242880-10485759 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : oWkVXFpMOgenqcDBjlcMHJ+VYgEc9kO9gA1YhYr8d9C/IZHTUdC+ti/hBoc9IjaoYLv72/M8m9o= x-amz-request-id : D7JAJCA3CMFBDETW Date : Wed, 16 Nov 2022 14:40:44 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 5242880-10485759/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=10485760-15728639 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : M4mFw4uAXko8LjoM/vMKRf6zIBjGjq7Xqp/+Gwlu30nj3n0ISuJFXZWKJxfoCrjqphYF+yUre2I= x-amz-request-id : NKYK40F0B5F20NXV Date : Wed, 16 Nov 2022 14:40:50 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 10485760-15728639/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=15728640-20971519 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : 9xW00QmBc+fVRK3tfgIBtYulusG9DYMw9ptVgZK/AzaXsJKkL9vTWE6q3oVa7/efhcJBMeBNzZw= x-amz-request-id : DRTVV4R6DR8F4FK8 Date : Wed, 16 Nov 2022 14:40:56 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 15728640-20971519/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=20971520-26214399 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : 6JU+LJ6dJRCcK58QEe1DIlvkQ+V+Eh7BNz0SEXmlnLfTigdk7D6GXZFIpRHvnvo9ngDCOu3+BJU= x-amz-request-id : TA8VWHXVSG8H2P9N Date : Wed, 16 Nov 2022 14:41:04 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 20971520-26214399/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=26214400-31457279 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : M9+Hgi5R7an+Gfs8ANB80bAt7oDEmkPfME8bCtVPZT8qG9ElU/Mr/PnoF5/5+a6pz8FqHMvd/qI= x-amz-request-id : 1M902EJMXVM8QKD7 Date : Wed, 16 Nov 2022 14:41:13 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 26214400-31457279/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=31457280-36700159 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : 85clseKkh+oHsu8Es16w+4zkdm+8zD593HdZHwWsFvg0ZzKCAfo1+r8kTs3yACCB/p3awhrFqUo= x-amz-request-id : WCEQTZXNX2AZ7K9J Date : Wed, 16 Nov 2022 14:41:17 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 31457280-36700159/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=36700160-41943039 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : kV0Jnm3XjNjziMbBFhDPdT5emDv0kSab4QSEW1fZcIyvxC+MR0VfrZCtgFdv9FTm1avUgNeQ7Jo= x-amz-request-id : KC03B9Q82YWG5S8W Date : Wed, 16 Nov 2022 14:41:23 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 36700160-41943039/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=41943040-47185919 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : hoAeDlnIi+b3dGUAIg2Wx3GTCTY2RQ514HWup/nTcNqPcAX+jF9CFn8IoT6KtVr2mnUNoKocTco= x-amz-request-id : 0R44QVMZVRQ7G7TW Date : Wed, 16 Nov 2022 14:41:35 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 41943040-47185919/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=47185920-52428799 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : ruzfOMIqnvKK4BzX4xcdBkEvIrTTRcPonPjXC1ycf1PrEDZxQnwYA+iSaI8m1Zn7xgfvjBkSGaI= x-amz-request-id : G3VRN5HHW1N5TJK7 Date : Wed, 16 Nov 2022 14:41:42 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 47185920-52428799/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=52428800-57671679 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : TJjw84ekp6eNkS1v4i9p6xCYBaQSqHjRtAKm3gRjvsQR5HX/U5S4F/bEPmgS7MlUtv4gpM7czv8= x-amz-request-id : SAE5HGSKCHS38QRN Date : Wed, 16 Nov 2022 14:41:46 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 52428800-57671679/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=57671680-62914559 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : 5zynmyUwevSA8BVOD9/xzSIkuzeXNNgOVXpzYcLP5sCJ01OZOUVftk8A3mRcrSWGqxogGy2yK74= x-amz-request-id : DRCZSVVAQSWPF4EF Date : Wed, 16 Nov 2022 14:41:52 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 57671680-62914559/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=62914560-68157439 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : nFV9u4EySutG6ODXp371Sbl4egA3SH2iEKoFyPgHROTWPMP011xGkqFDQJ4IbAXpRB8m5E3jV2c= x-amz-request-id : JHBHPDS0MVBT4N8Y Date : Wed, 16 Nov 2022 14:41:57 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 62914560-68157439/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=68157440-73400319 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : pPwLBCfA87aO5oAhRaOn6BcwJGHVvWusLl4mdizy/u52oRqRvTU4VOs0/gQANCfSKaf1a3NcSnw= x-amz-request-id : VC1P5FD2F8CY0321 Date : Wed, 16 Nov 2022 14:41:59 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 68157440-73400319/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=73400320-78643199 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : pbUtXXC42OwuBVssprUcP2Qj1P2/vK6H8zQl9O7LGi2Ya/QStNAy+l26oW6QBXINQ5v5nl6oEmk= x-amz-request-id : ZAEQA3PDP24F959G Date : Wed, 16 Nov 2022 14:42:05 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 73400320-78643199/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=78643200-83886079 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : NPSu7odMQOhXAEVBSc1+CwhW0fOfq8AbXsn4VYmgyz9uROBY3KCCDhBjkSQQxYYJ2pyHl7ee3q0= x-amz-request-id : MTW2Y80JRV4HGFQR Date : Wed, 16 Nov 2022 14:42:11 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 78643200-83886079/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=83886080-89128959 user-agent : Soto/6.0 ] Body: empty Response: Status : 206 Headers: [ x-amz-id-2 : BNE/w8DRuB7ksr/UkHMpPtokR2fHMd0YRjpJfR2fqAJL2BgrnxVTCIYw+5ZcDOaqlbozEutOt00= x-amz-request-id : 8YKP8ADPERB777AE Date : Wed, 16 Nov 2022 14:42:14 GMT Last-Modified : Wed, 16 Nov 2022 13:30:35 GMT ETag : "d7488c9e2c622de5dbd09492f2456f88" x-amz-version-id : f6.I_S2b23TLGnqRy9_gwu9jSgZJ4HZJ Accept-Ranges : bytes Content-Range : bytes 83886080-89128959/95932144 Content-Type : application/octet-stream Server : AmazonS3 Content-Length : 5242880 ] Body: raw (5242880 bytes) Request: GetObject GET https://bucket-name.s3.us-east-1.amazonaws.com/path/file.zip?x-id=GetObject Headers: [ Range : bytes=89128960-94371839 user-agent : Soto/6.0 ] Body: empty stream ended at an unexpected time - stream ended at an unexpected time ```
adam-fowler commented 1 year ago

Hi sorry, I haven't got back to you earlier.

I believe this is most likely an issue with either AsyncHTTPClient or SwiftNIO. I can't be sure though. I'm going to ask for more info again though to see if I can narrow it down a little further. Can you do the GetObject call with a Logger that is set to output trace logs eg

var logger = Logger(label: "test")
logger.logLevel = .trace
let request = S3.GetObjectRequest(...)
try s3.getObject(request, logger: logger).wait()

And then post the results here

ghost commented 1 year ago

Hi @adam-fowler, no problem. Sure, I'll try to do it and get back to you, but it might take some time. Also, one note, we've enabled "Transfer Acceleration" in the bucket, and I didn't experience an issue since that. It is probably still here, but I'd assume that it mostly happened at a slow speed.

adam-fowler commented 1 year ago

When you say you've enabled transfer acceleration have you also added the option to the Soto S3 type to use it.

ghost commented 1 year ago

Yes, we did

ghost commented 1 year ago

Hello, tried to reproduce an issue for the last 3 hours with no luck. Same setup as before, with no code changes and no transfer acceleration, but all works as expected now. I'll close an issue; it seems like it has nothing to do with soto.

But feel free to reopen and ping me if I can help by providing anything in addition.

Out of context, thank you for a great library!