Riak-S2 javascript aws-sdk failing on multi-part uploads

John Fanjoy jfanjoy at inetu.net
Thu Jan 14 10:29:16 EST 2016


Shino and Luke,

Thank you for helping me work through this. The tcplog mode in haproxy actually doesn’t provide enough information because it doesn’t bother with paths or query strings or anything http like. I am using the httplog mode as a result, and the odd thing is that the error logged indicated the browser is actually responsible for closing the connections. Usually these errors would be generated when a user clicks stop or navigates away from a page. Per the haproxy docs:

CH   The client aborted while waiting for the server to start responding.
          It might be the server taking too long to respond or the client
          clicking the 'Stop' button too fast.


Here is the log data for a request made using the aws-sdk-js library.

```
Jan 14 09:46:59 localhost haproxy-gen1[400]: 10.100.88.52:62880 [14/Jan/2016:09:46:58.970] www-https~ www-backend/www-1 37/0/0/12/49 200 382 - - ---- 1/1/0/0/0 0/0 "POST /three2016com-devopsdevel/Archive.zip?uploads HTTP/1.1"
Jan 14 09:46:59 localhost haproxy-gen1[400]: 10.100.88.52:62885 [14/Jan/2016:09:46:59.918] www-https~ cors_opts/<NOSRV> 48/-1/-1/-1/48 503 399 - - SC-- 3/3/0/0/0 0/0 "OPTIONS /three2016com-devopsdevel/Archive.zip?partNumber=2&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:00 localhost haproxy-gen1[400]: 10.100.88.52:62886 [14/Jan/2016:09:46:59.945] www-https~ cors_opts/<NOSRV> 57/-1/-1/-1/57 503 399 - - SC-- 2/2/0/0/0 0/0 "OPTIONS /three2016com-devopsdevel/Archive.zip?partNumber=3&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:00 localhost haproxy-gen1[400]: 10.100.88.52:62887 [14/Jan/2016:09:46:59.960] www-https~ cors_opts/<NOSRV> 45/-1/-1/-1/45 503 399 - - SC-- 1/1/0/0/0 0/0 "OPTIONS /three2016com-devopsdevel/Archive.zip?partNumber=4&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:12 localhost haproxy-gen1[400]: 10.100.88.52:62892 [14/Jan/2016:09:47:01.369] www-https~ www-backend/www-1 28/0/0/11442/11470 200 165 - - ---- 4/4/3/3/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?partNumber=2&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1”

Jan 14 09:47:12 localhost haproxy-gen1[400]: 10.100.88.52:62892 [14/Jan/2016:09:47:12.840] www-https~ cors_opts/<NOSRV> 70/-1/-1/-1/70 503 399 - - SC-- 3/3/0/0/0 0/0 "OPTIONS /three2016com-devopsdevel/Archive.zip?uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1”
Jan 14 09:47:13 localhost haproxy-gen1[400]: 10.100.88.52:62888 [14/Jan/2016:09:46:59.965] www-https~ www-backend/www-1 41/0/0/-1/13182 -1 0 - - CH-- 2/2/2/2/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?partNumber=1&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:13 localhost haproxy-gen1[400]: 10.100.88.52:62894 [14/Jan/2016:09:47:03.601] www-https~ www-backend/www-1 63/0/0/-1/9581 -1 0 - - CH-- 1/1/1/1/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?partNumber=3&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:13 localhost haproxy-gen1[400]: 10.100.88.52:62897 [14/Jan/2016:09:47:04.981] www-https~ www-backend/www-1 118/0/0/-1/8268 -1 0 - - CH-- 1/1/0/0/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?partNumber=4&uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1"
Jan 14 09:47:13 localhost haproxy-gen1[400]: 10.100.88.52:62899 [14/Jan/2016:09:47:13.429] www-https~ www-backend/www-1 40/0/0/22/62 204 126 - - ---- 1/1/0/0/0 0/0 "DELETE /three2016com-devopsdevel/Archive.zip?uploadId=xlC0aPjOQ96Mkn8asY62cw%3D%3D HTTP/1.1”

```

The SC errors are expected on the OPTIONS requests as I have a separate backend without any servers handling the preflights which I don’t think riak-cs will do (if it will please enlighten me and I will update my config). The client is actually receiving a 200 response with the CORS headers for OPTIONS requests. There also appear to be a number of BADREQ errors in the log, but these appear to be connections that that the browser initiated and then never used. No HTTP requests are actually being made in those requests and I don’t appear to be missing anything above (OPTIONS + PUT). As mentioned, the first PUT request is successful, but subsequent requests appear to fail, or more accurately appear to be closed by the client. When I use cyberduck for the same file I see the following log entries:

```
Jan 14 10:01:36 localhost haproxy-gen1[400]: 10.100.88.52:63105 [14/Jan/2016:10:01:36.063] www-https~ www-backend/www-1 59/0/0/14/73 200 382 - - ---- 1/1/0/0/0 0/0 "POST /three2016com-devopsdevel/Archive.zip?uploads HTTP/1.1"
Jan 14 10:02:48 localhost haproxy-gen1[400]: 10.100.88.52:63105 [14/Jan/2016:10:01:36.136] www-https~ www-backend/www-1 70/0/1/72138/72209 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=3 HTTP/1.1"
Jan 14 10:02:53 localhost haproxy-gen1[400]: 10.100.88.52:63119 [14/Jan/2016:10:01:36.266] www-https~ www-backend/www-1 136/0/1/76606/76743 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=1 HTTP/1.1"
Jan 14 10:02:56 localhost haproxy-gen1[400]: 10.100.88.52:63117 [14/Jan/2016:10:01:36.266] www-https~ www-backend/www-1 90/0/1/79916/80007 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=10 HTTP/1.1"
Jan 14 10:02:57 localhost haproxy-gen1[400]: 10.100.88.52:63116 [14/Jan/2016:10:01:36.265] www-https~ www-backend/www-1 100/0/1/81618/81719 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=9 HTTP/1.1"
Jan 14 10:03:23 localhost haproxy-gen1[400]: 10.100.88.52:63118 [14/Jan/2016:10:01:36.266] www-https~ www-backend/www-1 130/0/0/107459/107589 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=2 HTTP/1.1"
Jan 14 10:03:28 localhost haproxy-gen1[400]: 10.100.88.52:63115 [14/Jan/2016:10:01:36.265] www-https~ www-backend/www-1 137/0/0/111934/112071 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=8 HTTP/1.1"
Jan 14 10:03:52 localhost haproxy-gen1[400]: 10.100.88.52:63113 [14/Jan/2016:10:01:36.245] www-https~ www-backend/www-1 112/0/0/136606/136718 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=5 HTTP/1.1"
Jan 14 10:04:05 localhost haproxy-gen1[400]: 10.100.88.52:63105 [14/Jan/2016:10:02:48.346] www-https~ www-backend/www-1 121/0/1/76853/76975 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=11 HTTP/1.1"
Jan 14 10:04:05 localhost haproxy-gen1[400]: 10.100.88.52:63120 [14/Jan/2016:10:01:36.266] www-https~ www-backend/www-1 99/0/1/149217/149317 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=4 HTTP/1.1"
Jan 14 10:04:08 localhost haproxy-gen1[400]: 10.100.88.52:63112 [14/Jan/2016:10:01:36.245] www-https~ www-backend/www-1 112/0/0/152150/152262 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=6 HTTP/1.1"
Jan 14 10:04:19 localhost haproxy-gen1[400]: 10.100.88.52:63114 [14/Jan/2016:10:01:36.261] www-https~ www-backend/www-1 104/0/1/160670/160775 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=7 HTTP/1.1"
Jan 14 10:04:34 localhost haproxy-gen1[400]: 10.100.88.52:63119 [14/Jan/2016:10:02:53.008] www-https~ www-backend/www-1 100/0/0/99129/99229 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=12 HTTP/1.1"
Jan 14 10:04:39 localhost haproxy-gen1[400]: 10.100.88.52:63116 [14/Jan/2016:10:02:57.985] www-https~ www-backend/www-1 181/0/0/99530/99711 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=14 HTTP/1.1"
Jan 14 10:04:41 localhost haproxy-gen1[400]: 10.100.88.52:63117 [14/Jan/2016:10:02:56.274] www-https~ www-backend/www-1 312/0/0/102647/102959 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=13 HTTP/1.1"
Jan 14 10:04:52 localhost haproxy-gen1[400]: 10.100.88.52:63113 [14/Jan/2016:10:03:52.963] www-https~ www-backend/www-1 203/0/0/57611/57814 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=17 HTTP/1.1"
Jan 14 10:05:11 localhost haproxy-gen1[400]: 10.100.88.52:63118 [14/Jan/2016:10:03:23.856] www-https~ www-backend/www-1 109/0/0/105391/105500 200 190 - - ---- 10/10/9/9/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=15 HTTP/1.1"
Jan 14 10:05:28 localhost haproxy-gen1[400]: 10.100.88.52:63105 [14/Jan/2016:10:04:05.320] www-https~ www-backend/www-1 231/0/0/80927/81158 200 190 - - ---- 9/9/8/8/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=18 HTTP/1.1"
Jan 14 10:05:45 localhost haproxy-gen1[400]: 10.100.88.52:63114 [14/Jan/2016:10:04:19.199] www-https~ www-backend/www-1 89/0/0/86180/86269 200 190 - - ---- 8/8/7/7/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=21 HTTP/1.1"
Jan 14 10:05:46 localhost haproxy-gen1[400]: 10.100.88.52:63113 [14/Jan/2016:10:04:52.940] www-https~ www-backend/www-1 172/0/1/53672/53845 200 190 - - ---- 8/8/6/6/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=25 HTTP/1.1"
Jan 14 10:05:58 localhost haproxy-gen1[400]: 10.100.88.52:63120 [14/Jan/2016:10:04:05.583] www-https~ www-backend/www-1 233/0/1/110598/110832 200 190 - - ---- 6/6/5/5/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=19 HTTP/1.1"
Jan 14 10:05:59 localhost haproxy-gen1[400]: 10.100.88.52:63117 [14/Jan/2016:10:04:41.396] www-https~ www-backend/www-1 248/0/0/77581/77829 200 190 - - ---- 6/6/4/4/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=24 HTTP/1.1"
Jan 14 10:06:00 localhost haproxy-gen1[400]: 10.100.88.52:63119 [14/Jan/2016:10:04:34.402] www-https~ www-backend/www-1 197/0/0/85485/85682 200 190 - - ---- 6/6/3/3/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=22 HTTP/1.1"
Jan 14 10:06:00 localhost haproxy-gen1[400]: 10.100.88.52:63116 [14/Jan/2016:10:04:39.859] www-https~ www-backend/www-1 178/0/0/80650/80828 200 190 - - ---- 6/6/2/2/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=23 HTTP/1.1"
Jan 14 10:06:01 localhost haproxy-gen1[400]: 10.100.88.52:63115 [14/Jan/2016:10:03:28.336] www-https~ www-backend/www-1 75/0/0/150705/150780 200 190 - - ---- 6/6/1/1/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=16 HTTP/1.1"
Jan 14 10:06:06 localhost haproxy-gen1[400]: 10.100.88.52:63112 [14/Jan/2016:10:04:08.508] www-https~ www-backend/www-1 126/0/0/116172/116298 200 190 - - ---- 6/6/0/0/0 0/0 "PUT /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D&partNumber=20 HTTP/1.1"
Jan 14 10:06:07 localhost haproxy-gen1[400]: 10.100.88.52:63112 [14/Jan/2016:10:06:06.970] www-https~ www-backend/www-1 86/0/0/21/107 200 468 - - ---- 6/6/0/0/0 0/0 "POST /three2016com-devopsdevel/Archive.zip?uploadId=Ui6QDuCuSBqpbGGdf8SHig%3D%3D HTTP/1.1"
```


Since this is not a browser client there is no preflight (OPTIONS) required. There are no errors being logged at all, and the upload completes without issue. 

So far I have only tested this functionality in Chrome. I am going to try and test Safari and FF now and I will let you know if there is any difference (or not).


Thanks,

John Fanjoy
Systems Engineer
jfanjoy at inetu.net





On 1/14/16, 9:31 AM, "Shunichi Shinohara" <shino at basho.com> wrote:

>Hi John,
>
>I tested Multipart Upload with aws-sdk-js with the patch you
>mentioned, against riak_cs (s2),
>upload finished without errors up to 1GB object. The environment is
>all local on my laptop,
>so latency is small. The script I used is in [1].
>
>As Luke mentioned, HAProxy would be the point to be investigated first.
>Or, if it's possible to get packet capture, by finding some wrong TCP
>packet, like
>RST or premature (from the point of HTTP) FIN, one can identify who
>closes TCP connection
>actively. In this case, packet should be captured on client box,
>HAProxy box and riak cs box.
>
>[1] https://gist.github.com/shino/ac7d56398557fb936899
>
>Thanks,
>Shino
>
>
>2016-01-14 8:51 GMT+09:00 Luke Bakken <lbakken at basho.com>:
>> Hi John,
>>
>> Thanks for the info. I'm very curious to see what's in the haproxy
>> logs with regard to TCP.
>> --
>> Luke Bakken
>> Engineer
>> lbakken at basho.com
>>
>>
>> On Wed, Jan 13, 2016 at 3:50 PM, John Fanjoy <jfanjoy at inetu.net> wrote:
>>> Luke,
>>>
>>> As a test I’ve already increased all timeouts to 5 minutes but the failure occurs within under 1 minute so it doesn’t appear to be timeout related. I change the logs to tcplog tomorrow and let you know if I find anything.
>>>
>>> Thanks
>>>
>>> John Fanjoy
>>> Systems Engineer
>>> jfanjoy at inetu.net
>>>
>>>
>>>
>>>
>>>
>>> On 1/13/16, 6:05 PM, "Luke Bakken" <lbakken at basho.com> wrote:
>>>
>>>>haproxy ships with some "short" default timeouts. If CyberDuck is able
>>>>to upload these files faster than aws-sdk, it may be doing so within
>>>>the default haproxy timeouts.
>>>>
>>>>You can also look at haproxy's log to see if you find any TCP
>>>>connections that it has closed.
>>>>--
>>>>Luke Bakken
>>>>Engineer
>>>>lbakken at basho.com
>>>>
>>>>
>>>>On Wed, Jan 13, 2016 at 3:02 PM, John Fanjoy <jfanjoy at inetu.net> wrote:
>>>>> Luke,
>>>>>
>>>>> I may be able to do that. The only problem is without haproxy I have no way to inject CORS headers which the browser requires, but I may be able to write up small nodejs app to get past that and see if it is somehow related to haproxy. The fact that these errors are not present when using Cyberduck which is also talking to haproxy leads me to believe that’s not the cause, but it’s definitely worth testing.
>>>>>
>>>>> --
>>>>> John Fanjoy
>>>>> Systems Engineer
>>>>> jfanjoy at inetu.net
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> On 1/13/16, 5:55 PM, "Luke Bakken" <lbakken at basho.com> wrote:
>>>>>
>>>>>>John -
>>>>>>
>>>>>>The following error indicates that the connection was unexpectedly
>>>>>>closed by something outside of Riak while the chunk is uploading:
>>>>>>
>>>>>>{badmatch,{error,closed}}
>>>>>>
>>>>>>Is it possible to remove haproxy to test using the the aws-sdk?
>>>>>>
>>>>>>That is my first thought as to the cause of this issue, especially
>>>>>>since writing to S3 works with the same code.
>>>>>>
>>>>>>--
>>>>>>Luke Bakken
>>>>>>Engineer
>>>>>>lbakken at basho.com
>>>>>>
>>>>>>On Wed, Jan 13, 2016 at 2:46 PM, John Fanjoy <jfanjoy at inetu.net> wrote:
>>>>>>> Luke,
>>>>>>>
>>>>>>> Yes on both parts. To confirm cyberduck was using multi-part I actually tailed the console.log while it was uploading the file, and it uploaded the file in approx. 40 parts. Afterwards the parts were reassembled as you would expect. The AWS-SDK for javascript has an object called ManagedUpload which automatically switches to multi-part when the input is larger than the maxpartsize (default 5mb). I have confirmed that it is splitting the files up, but so far I’ve only ever seen one part get successfully uploaded before the others failed at which point it removes the upload (DELETE call) automatically. I also verified that the javascript I have in place does work with an actual AWS S3 bucket to rule out coding issues on my end and the same >400mb file was successfully uploaded to the bucket I created there without issue.
>>>>>>>
>>>>>>> A few things worth mentioning that I missed before. I am running riak-s2 behind haproxy. Haproxy is handling ssl and enabling CORS for browser based requests. I have tested smaller files (~4-5mb) and GET requests using the browser client and everything works with my current haproxy configuration, but the larger files are failing, usually after 1 part is successfully uploaded. I can also list bucket contents and delete existing contents. The only feature that is not working appears to be the multi-part uploads. We are running centOS 7 (kernel version 3.10.0-327.4.4.el7.x86_64). Please let me know if you have any further questions.
>>>>>>>
>>>>>>> --
>>>>>>> John Fanjoy
>>>>>>> Systems Engineer
>>>>>>> jfanjoy at inetu.net
>>
>> _______________________________________________
>> riak-users mailing list
>> riak-users at lists.basho.com
>> http://lists.basho.com/mailman/listinfo/riak-users_lists.basho.com


More information about the riak-users mailing list