Project

General

Profile

Bug #19627

Several related(?) failures calling the s3 interface, when using Amazon libraries

Added by David Collier-Brown almost 7 years ago. Updated almost 7 years ago.

Status:
New
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
Yes
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

This is a collection of issues seen when working through the s3 interface from the Go language, using the Amazon AWS SDK for Go. The problems were initially noticed by a colleague using .net, and confirmed by my trying a set of interfaces described in http://docs.aws.amazon.com/sdk-for-go/v1/developer-guide/aws-sdk-go-dg.pdf

Configuration

The machine was Fedora 25, _Linux miles 4.10.8-200.fc25.x86_64 #1 SMP Fri Mar 31 13:20:22 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

The ceph release was kraken, and was tested with two different ceph servers, one in our lab and another in a docker virtual machine, each installed by a different engineer.

The Go version was go1.7.5 linux/amd64

Golang was used because my load-test program is in Go, but I expect other Amazon-provided libraries will fail in related ways. Certainly .net fails! If you have some which work, a comparison might provide valuable information.

I somewhat suspect Amazon of carelessly throwing sabots in the wheels of ceph: in particular I reported bug #19582 which is a result of how Amazon chose to do v4 authentication.

Test Program

The program used is attached,

Test Setup
The order used here is the order in which we tested: it is not significant in any way.

The bucket is test-bucket, the file to upload is test.jpg and to download is test_file

S3cmd works normally:

$ s3cmd ls
2017-04-05 18:24 s3://kbimages-test
2017-04-06 16:51 s3://load-test
2017-04-05 18:07 s3://my-new-bucket
2017-04-05 19:03 s3://my-new-bucket-dotnet
2017-04-07 21:27 s3://regression-test

$ s3cmd la
2017-04-10 19:28 7059 s3://kbimages-test/21b22198-6194-4be1-aac8-9cac07ae2ac4-140-215-60-False-the-shadow-land.jpg
2017-04-05 20:07 5092 s3://kbimages-test/4eb5b4d3-c615-440a-afa6-0d2cc222dfcb-140-215-60-False-it-happens-all-the-time-2.jpg
2017-04-05 18:50 759083 s3://kbimages-test/CephBestPractices.pdf

2017-04-08 13:13 10 s3://load-test/test_file

1) uploading a file with s3manager.NewUploader
With both the lab and docker machine, the error is
Unable to upload "test.jpg" to "load-test", MissingRegion: could not find region configuration

The test program logged:
---
GOROOT=/usr/lib/golang
GOPATH=/home/davecb/go
/usr/lib/golang/bin/go build -i -o "/tmp/Build main.go and run1go" /home/davecb/go/src/s3v4Errors/main.go
"/tmp/Build main.go and run1go"
cfg=&{<nil> 0xc42001c780 0xc42014e050 <nil> 0xc42014e060 0xc42014e040 <nil> 0xc42000dfb8 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}
2017/04/13 15:16:44 Unable to upload "test.jpg" to "load-test", MissingRegion: could not find region configuration
sess=&{0xc42013e240 {{[{core.ValidateEndpointHandler 0x6218e0} {core.ValidateParametersHandler 0x621a40}] 0x5be050} {[{core.SDKVersionUserAgentHandler 0x5c5300}] 0x5be050} {[{core.BuildContentLengthHandler 0x61ffd0}] <nil>} {[{core.ValidateReqSigHandler 0x6203c0} {core.SendHandler 0x6205b0}] <nil>} {[{core.ValidateResponseHandler 0x6212a0}] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[{core.AfterRetryHandler 0x621450}] <nil>} {[] <nil>}}}
svc=&{0xc4200c0580}
uploader=&{5242880 5 false 10000 0xc42002e0d8 []}

Process finished with exit code 0
----
All runs will have an exit code of 0, as I do not set it.

The server log, ceph-client.rgw.ceph-on-centos1.log, shows NO upload-related activity:
2017-04-13 15:16:43.518665 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:17:05.518800 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:17:27.518964 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
...

2) create a bucket, "fraggle"

the client logged
---
GOROOT=/usr/lib/golang
GOPATH=/home/davecb/go
/usr/lib/golang/bin/go build i -o "/tmp/Build main.go and rungo" /home/davecb/go/src/s3v4Errors/main.go
"/tmp/Build main.go and rungo"
cfg=&{<nil> 0xc42001c780 0xc42014e070 <nil> 0xc42014e080 0xc42014e060 <nil> 0xc42000dfd8 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}
sess=&{0xc42013e240 {{[{core.ValidateEndpointHandler 0x5c7140} {core.ValidateParametersHandler 0x5c72a0}] 0x564790} {[{core.SDKVersionUserAgentHandler 0x56ac90}] 0x564790} {[{core.BuildContentLengthHandler 0x5c5830}] <nil>} {[{core.ValidateReqSigHandler 0x5c5c20} {core.SendHandler 0x5c5e10}] <nil>} {[{core.ValidateResponseHandler 0x5c6b00}] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[{core.AfterRetryHandler 0x5c6cb0}] <nil>} {[] <nil>}}}
svc=&{0xc4200c0580}
Waiting for bucket "fraggle" to be created...
Error occurred while waiting for bucket to be created, ResourceNotReady: exceeded wait attempts
Process finished with exit code 0
--

The server logged
---
2017-04-13 15:22:57.522080 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:23:19.522223 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:23:41.522402 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:24:03.522530 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:24:25.522667 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:24:47.522793 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:25:03.446747 7f9c78446700 0 -- 192.168.0.21:0/6404061 >> 192.168.0.21:6804/2028 conn(0x7f9c96d7f800 :-1 s=STATE_OPEN pgs=424043 cs=93 l=0).fault initiating reconnect
2017-04-13 15:25:09.522925 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:25:31.523058 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:25:53.523318 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start

3) list buckets, which worked (phew!)

the client logged
---
GOROOT=/usr/lib/golang
GOPATH=/home/davecb/go
/usr/lib/golang/bin/go build i -o "/tmp/Build main.go and rungo" /home/davecb/go/src/s3v4Errors/main.go
"/tmp/Build main.go and rungo"
cfg=&{<nil> 0xc420070720 0xc420075eb0 <nil> 0xc420075ec0 0xc420075ea0 <nil> 0xc420075e18 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}
sess=&{0xc420160240 {{[{core.ValidateEndpointHandler 0x5c4630} {core.ValidateParametersHandler 0x5c4790}] 0x563b30} {[{core.SDKVersionUserAgentHandler 0x5687c0}] 0x563b30} {[{core.BuildContentLengthHandler 0x5c2d20}] <nil>} {[{core.ValidateReqSigHandler 0x5c3110} {core.SendHandler 0x5c3300}] <nil>} {[{core.ValidateResponseHandler 0x5c3ff0}] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[{core.AfterRetryHandler 0x5c41a0}] <nil>} {[] <nil>}}}
svc=&{0xc4200e0580}
bucket 0 = {
CreationDate: 2017-04-05 18:24:44.694 +0000 UTC,
Name: "kbimages-test"
}
bucket 1 = {
CreationDate: 2017-04-06 16:51:04.304 +0000 UTC,
Name: "load-test"
}
bucket 2 = {
CreationDate: 2017-04-05 18:07:12.421 +0000 UTC,
Name: "my-new-bucket"
}
bucket 3 = {
CreationDate: 2017-04-05 19:03:51.224 +0000 UTC,
Name: "my-new-bucket-dotnet"
}
bucket 4 = {
CreationDate: 2017-04-07 21:27:26.09 +0000 UTC,
Name: "regression-test"
}
--

the server logged
---
2017-04-13 15:26:43.730970 7f9c58c07700 20 RGWEnv::set(): HTTP_HOST: s4.rakops.com
2017-04-13 15:26:43.731004 7f9c58c07700 20 RGWEnv::set(): HTTP_USER_AGENT: aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:26:43.731011 7f9c58c07700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731017 7f9c58c07700 20 RGWEnv::set(): HTTP_X_AMZ_CONTENT_SHA256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:26:43.731020 7f9c58c07700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: 20170413T192643Z
2017-04-13 15:26:43.731023 7f9c58c07700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: gzip
2017-04-13 15:26:43.731029 7f9c58c07700 20 RGWEnv::set(): REQUEST_METHOD: GET
2017-04-13 15:26:43.731031 7f9c58c07700 20 RGWEnv::set(): REQUEST_URI: /
2017-04-13 15:26:43.731033 7f9c58c07700 20 RGWEnv::set(): SCRIPT_URI: /
2017-04-13 15:26:43.731274 7f9c58c07700 20 RGWEnv::set(): SERVER_PORT: 80
2017-04-13 15:26:43.731305 7f9c58c07700 20 HTTP_ACCEPT_ENCODING=gzip
2017-04-13 15:26:43.731310 7f9c58c07700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731314 7f9c58c07700 20 HTTP_HOST=s4.rakops.com
2017-04-13 15:26:43.731318 7f9c58c07700 20 HTTP_USER_AGENT=aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:26:43.731320 7f9c58c07700 20 HTTP_X_AMZ_CONTENT_SHA256=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:26:43.731322 7f9c58c07700 20 HTTP_X_AMZ_DATE=20170413T192643Z
2017-04-13 15:26:43.731326 7f9c58c07700 20 REQUEST_METHOD=GET
2017-04-13 15:26:43.731328 7f9c58c07700 20 REQUEST_URI=/
2017-04-13 15:26:43.731330 7f9c58c07700 20 SCRIPT_URI=/
2017-04-13 15:26:43.731331 7f9c58c07700 20 SERVER_PORT=80
2017-04-13 15:26:43.731334 7f9c58c07700 1 ====== starting new request req=0x7f9c58c01340 =====
2017-04-13 15:26:43.731360 7f9c58c07700 2 req 30:0.000026::GET /::initializing for trans_id = tx00000000000000000001e-0058efd0f3-5e36-default
2017-04-13 15:26:43.731373 7f9c58c07700 10 rgw api priority: s3=5 s3website=4
2017-04-13 15:26:43.731376 7f9c58c07700 10 host=s4.rakops.com
2017-04-13 15:26:43.731386 7f9c58c07700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2017-04-13 15:26:43.731389 7f9c58c07700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/
2017-04-13 15:26:43.731399 7f9c58c07700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2017-04-13 15:26:43.731404 7f9c58c07700 10 meta>> HTTP_X_AMZ_DATE
2017-04-13 15:26:43.731409 7f9c58c07700 10 x>> x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:26:43.731411 7f9c58c07700 10 x>> x-amz-date:20170413T192643Z
2017-04-13 15:26:43.731424 7f9c58c07700 20 get_handler handler=26RGWHandler_REST_Service_S3
2017-04-13 15:26:43.731429 7f9c58c07700 10 handler=26RGWHandler_REST_Service_S3
2017-04-13 15:26:43.731432 7f9c58c07700 2 req 30:0.000098:s3:GET /::getting op 0
2017-04-13 15:26:43.731437 7f9c58c07700 10 op=26RGWListBuckets_ObjStore_S3
2017-04-13 15:26:43.731440 7f9c58c07700 2 req 30:0.000106:s3:GET /:list_buckets:authorizing
2017-04-13 15:26:43.731461 7f9c58c07700 10 v4 signature format = 193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731468 7f9c58c07700 10 v4 credential format = WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request
2017-04-13 15:26:43.731471 7f9c58c07700 10 access key id = WHF0J757LOLM09WMNIJT
2017-04-13 15:26:43.731473 7f9c58c07700 10 credential scope = 20170413/us-east-1/s3/aws4_request
2017-04-13 15:26:43.731496 7f9c58c07700 10 canonical headers format = host:s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T192643Z

2017-04-13 15:26:43.731540 7f9c58c07700 10 payload request hash = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:26:43.731560 7f9c58c07700 10 canonical request = GET
/

host:s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T192643Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:26:43.731562 7f9c58c07700 10 canonical request hash = 8852553f300bdaea249c269d4df0d6b8915621c389dcd0300aab940f4088f3c6
2017-04-13 15:26:43.731565 7f9c58c07700 10 string to sign = AWS4-HMAC-SHA256
20170413T192643Z
20170413/us-east-1/s3/aws4_request
8852553f300bdaea249c269d4df0d6b8915621c389dcd0300aab940f4088f3c6
2017-04-13 15:26:43.731616 7f9c58c07700 10 date_k = fe9b4bb4c8eaf30d9cec8875f194a016ea6b87c43477433cc18b9c83b672805c
2017-04-13 15:26:43.731644 7f9c58c07700 10 region_k = c40871584b9787b1b2b3a5458f8ef3d63127fd41256b30ccea58ed33dc5b7ff3
2017-04-13 15:26:43.731670 7f9c58c07700 10 service_k = 3bd399b5c03aa0e02ee1559c0ff477cf47a36dcb2ccca08b8dae9cef8c5d6a47
2017-04-13 15:26:43.731697 7f9c58c07700 10 signing_k = a9d71a6faa67b630b80724cc8b66434f5864cfb851d7489ef6cf2c06640c2920
2017-04-13 15:26:43.731725 7f9c58c07700 10 signature_k = 193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731728 7f9c58c07700 10 new signature = 193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731730 7f9c58c07700 10 ----------------------------- Verifying signatures
2017-04-13 15:26:43.731731 7f9c58c07700 10 Signature = 193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731732 7f9c58c07700 10 New Signature = 193244f10a60a521fd31c6e849da6f5a7d6c210f27ac7a6a169b035808c13c34
2017-04-13 15:26:43.731734 7f9c58c07700 10 -----------------------------
2017-04-13 15:26:43.731736 7f9c58c07700 10 v4 auth ok
2017-04-13 15:26:43.731741 7f9c58c07700 2 req 30:0.000407:s3:GET /:list_buckets:normalizing buckets and tenants
2017-04-13 15:26:43.731764 7f9c58c07700 10 s->object=<NULL> s->bucket=
2017-04-13 15:26:43.731768 7f9c58c07700 2 req 30:0.000434:s3:GET /:list_buckets:init permissions
2017-04-13 15:26:43.731773 7f9c58c07700 2 req 30:0.000440:s3:GET /:list_buckets:recalculating target
2017-04-13 15:26:43.731776 7f9c58c07700 2 req 30:0.000443:s3:GET /:list_buckets:reading permissions
2017-04-13 15:26:43.731779 7f9c58c07700 2 req 30:0.000446:s3:GET /:list_buckets:init op
2017-04-13 15:26:43.731782 7f9c58c07700 2 req 30:0.000448:s3:GET /:list_buckets:verifying op mask
2017-04-13 15:26:43.731784 7f9c58c07700 20 required_mask= 1 user.op_mask=7
2017-04-13 15:26:43.731789 7f9c58c07700 2 req 30:0.000453:s3:GET /:list_buckets:verifying op permissions
2017-04-13 15:26:43.731792 7f9c58c07700 2 req 30:0.000458:s3:GET /:list_buckets:verifying op params
2017-04-13 15:26:43.731794 7f9c58c07700 2 req 30:0.000461:s3:GET /:list_buckets:pre-executing
2017-04-13 15:26:43.731797 7f9c58c07700 2 req 30:0.000463:s3:GET /:list_buckets:executing
2017-04-13 15:26:43.733829 7f9c58c07700 2 req 30:0.002494:s3:GET /:list_buckets:completing
2017-04-13 15:26:43.733886 7f9c58c07700 2 req 30:0.002552:s3:GET /:list_buckets:op status=0
2017-04-13 15:26:43.733891 7f9c58c07700 2 req 30:0.002557:s3:GET /:list_buckets:http status=200
2017-04-13 15:26:43.733895 7f9c58c07700 1 ====== req done req=0x7f9c58c01340 op status=0 http_status=200 ======
2017-04-13 15:26:43.733961 7f9c58c07700 1 civetweb: 0x7f9c948d9000: 172.20.1.50 - - [13/Apr/2017:15:26:43 -0400] "GET / HTTP/1.1" 1 0 - aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:26:59.524067 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:27:21.524241 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start

4) list objects found no objects,

client logged
---
GOROOT=/usr/lib/golang
GOPATH=/home/davecb/go
/usr/lib/golang/bin/go build -i -o "/tmp/Build main.go and rungo" /home/davecb/go/src/s3v4Errors/main.go
"/tmp/Build main.go and rungo"
cfg=&{<nil> 0xc420074720 0xc420079eb0 <nil> 0xc420079ec0 0xc420079ea0 <nil> 0xc420079e18 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}
sess=&{0xc420162240 {{[{core.ValidateEndpointHandler 0x5c7f70} {core.ValidateParametersHandler 0x5c80d0}] 0x566a60} {[{core.SDKVersionUserAgentHandler 0x56c100}] 0x566a60} {[{core.BuildContentLengthHandler 0x5c6660}] <nil>} {[{core.ValidateReqSigHandler 0x5c6a50} {core.SendHandler 0x5c6c40}] <nil>} {[{core.ValidateResponseHandler 0x5c7930}] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[{core.AfterRetryHandler 0x5c7ae0}] <nil>} {[] <nil>}}}
svc=&{0xc4200e2580}
Page, 0

Process finished with exit code 0
---

server logged
---
2017-04-13 15:28:49.524942 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:28:51.514577 7f9c57c05700 20 RGWEnv::set(): HTTP_HOST: load-test.s4.rakops.com
2017-04-13 15:28:51.514602 7f9c57c05700 20 RGWEnv::set(): HTTP_USER_AGENT: aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:28:51.514606 7f9c57c05700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.514611 7f9c57c05700 20 RGWEnv::set(): HTTP_X_AMZ_CONTENT_SHA256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:28:51.514615 7f9c57c05700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: 20170413T192851Z
2017-04-13 15:28:51.514618 7f9c57c05700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: gzip
2017-04-13 15:28:51.514620 7f9c57c05700 20 RGWEnv::set(): REQUEST_METHOD: GET
2017-04-13 15:28:51.514624 7f9c57c05700 20 RGWEnv::set(): REQUEST_URI: /
2017-04-13 15:28:51.514626 7f9c57c05700 20 RGWEnv::set(): SCRIPT_URI: /
2017-04-13 15:28:51.514631 7f9c57c05700 20 RGWEnv::set(): SERVER_PORT: 80
2017-04-13 15:28:51.514633 7f9c57c05700 20 HTTP_ACCEPT_ENCODING=gzip
2017-04-13 15:28:51.514635 7f9c57c05700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.514637 7f9c57c05700 20 HTTP_HOST=load-test.s4.rakops.com
2017-04-13 15:28:51.514638 7f9c57c05700 20 HTTP_USER_AGENT=aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:28:51.514639 7f9c57c05700 20 HTTP_X_AMZ_CONTENT_SHA256=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:28:51.514642 7f9c57c05700 20 HTTP_X_AMZ_DATE=20170413T192851Z
2017-04-13 15:28:51.514643 7f9c57c05700 20 REQUEST_METHOD=GET
2017-04-13 15:28:51.514644 7f9c57c05700 20 REQUEST_URI=/
2017-04-13 15:28:51.514646 7f9c57c05700 20 SCRIPT_URI=/
2017-04-13 15:28:51.514647 7f9c57c05700 20 SERVER_PORT=80
2017-04-13 15:28:51.514650 7f9c57c05700 1 ====== starting new request req=0x7f9c57bff340 =====
2017-04-13 15:28:51.514670 7f9c57c05700 2 req 31:0.000019::GET /::initializing for trans_id = tx00000000000000000001f-0058efd173-5e36-default
2017-04-13 15:28:51.514712 7f9c57c05700 10 rgw api priority: s3=5 s3website=4
2017-04-13 15:28:51.514716 7f9c57c05700 10 host=load-test.s4.rakops.com
2017-04-13 15:28:51.514719 7f9c57c05700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2017-04-13 15:28:51.514722 7f9c57c05700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/
2017-04-13 15:28:51.514731 7f9c57c05700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2017-04-13 15:28:51.514737 7f9c57c05700 10 meta>> HTTP_X_AMZ_DATE
2017-04-13 15:28:51.514742 7f9c57c05700 10 x>> x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:28:51.514744 7f9c57c05700 10 x>> x-amz-date:20170413T192851Z
2017-04-13 15:28:51.514759 7f9c57c05700 20 get_handler handler=26RGWHandler_REST_Service_S3
2017-04-13 15:28:51.514764 7f9c57c05700 10 handler=26RGWHandler_REST_Service_S3
2017-04-13 15:28:51.514767 7f9c57c05700 2 req 31:0.000117:s3:GET /::getting op 0
2017-04-13 15:28:51.514771 7f9c57c05700 10 op=26RGWListBuckets_ObjStore_S3
2017-04-13 15:28:51.514774 7f9c57c05700 2 req 31:0.000124:s3:GET /:list_buckets:authorizing
2017-04-13 15:28:51.514794 7f9c57c05700 10 v4 signature format = cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.514803 7f9c57c05700 10 v4 credential format = WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request
2017-04-13 15:28:51.514815 7f9c57c05700 10 access key id = WHF0J757LOLM09WMNIJT
2017-04-13 15:28:51.514817 7f9c57c05700 10 credential scope = 20170413/us-east-1/s3/aws4_request
2017-04-13 15:28:51.514839 7f9c57c05700 10 canonical headers format = host:load-test.s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T192851Z

2017-04-13 15:28:51.514915 7f9c57c05700 10 payload request hash = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:28:51.514937 7f9c57c05700 10 canonical request = GET
/

host:load-test.s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T192851Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:28:51.514939 7f9c57c05700 10 canonical request hash = e32c341fe90df34a77f35986161908306806f1e928b55fccf0fe14ee59662256
2017-04-13 15:28:51.514942 7f9c57c05700 10 string to sign = AWS4-HMAC-SHA256
20170413T192851Z
20170413/us-east-1/s3/aws4_request
e32c341fe90df34a77f35986161908306806f1e928b55fccf0fe14ee59662256
2017-04-13 15:28:51.514990 7f9c57c05700 10 date_k = fe9b4bb4c8eaf30d9cec8875f194a016ea6b87c43477433cc18b9c83b672805c
2017-04-13 15:28:51.515019 7f9c57c05700 10 region_k = c40871584b9787b1b2b3a5458f8ef3d63127fd41256b30ccea58ed33dc5b7ff3
2017-04-13 15:28:51.515046 7f9c57c05700 10 service_k = 3bd399b5c03aa0e02ee1559c0ff477cf47a36dcb2ccca08b8dae9cef8c5d6a47
2017-04-13 15:28:51.515073 7f9c57c05700 10 signing_k = a9d71a6faa67b630b80724cc8b66434f5864cfb851d7489ef6cf2c06640c2920
2017-04-13 15:28:51.515118 7f9c57c05700 10 signature_k = cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.515121 7f9c57c05700 10 new signature = cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.515123 7f9c57c05700 10 ----------------------------- Verifying signatures
2017-04-13 15:28:51.515124 7f9c57c05700 10 Signature = cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.515125 7f9c57c05700 10 New Signature = cf05ff188bc3ddc185433710d95e88946a86a0d35f807ca161a74038db08fca6
2017-04-13 15:28:51.515126 7f9c57c05700 10 -----------------------------
2017-04-13 15:28:51.515129 7f9c57c05700 10 v4 auth ok
2017-04-13 15:28:51.515134 7f9c57c05700 2 req 31:0.000484:s3:GET /:list_buckets:normalizing buckets and tenants
2017-04-13 15:28:51.515138 7f9c57c05700 10 s->object=<NULL> s->bucket=
2017-04-13 15:28:51.515142 7f9c57c05700 2 req 31:0.000491:s3:GET /:list_buckets:init permissions
2017-04-13 15:28:51.515147 7f9c57c05700 2 req 31:0.000497:s3:GET /:list_buckets:recalculating target
2017-04-13 15:28:51.515151 7f9c57c05700 2 req 31:0.000501:s3:GET /:list_buckets:reading permissions
2017-04-13 15:28:51.515154 7f9c57c05700 2 req 31:0.000504:s3:GET /:list_buckets:init op
2017-04-13 15:28:51.515157 7f9c57c05700 2 req 31:0.000507:s3:GET /:list_buckets:verifying op mask
2017-04-13 15:28:51.515159 7f9c57c05700 20 required_mask= 1 user.op_mask=7
2017-04-13 15:28:51.515162 7f9c57c05700 2 req 31:0.000512:s3:GET /:list_buckets:verifying op permissions
2017-04-13 15:28:51.515164 7f9c57c05700 2 req 31:0.000515:s3:GET /:list_buckets:verifying op params
2017-04-13 15:28:51.515167 7f9c57c05700 2 req 31:0.000517:s3:GET /:list_buckets:pre-executing
2017-04-13 15:28:51.515170 7f9c57c05700 2 req 31:0.000520:s3:GET /:list_buckets:executing
2017-04-13 15:28:51.516264 7f9c57c05700 2 req 31:0.001613:s3:GET /:list_buckets:completing
2017-04-13 15:28:51.516304 7f9c57c05700 2 req 31:0.001653:s3:GET /:list_buckets:op status=0
2017-04-13 15:28:51.516308 7f9c57c05700 2 req 31:0.001658:s3:GET /:list_buckets:http status=200
2017-04-13 15:28:51.516312 7f9c57c05700 1 ====== req done req=0x7f9c57bff340 op status=0 http_status=200 ======
2017-04-13 15:28:51.516419 7f9c57c05700 1 civetweb: 0x7f9c948e2000: 172.20.1.50 - - [13/Apr/2017:15:28:51 0400] "GET / HTTP/1.1" 1 0 - aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:29:11.525081 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:29:33.525326 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:29:55.525508 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
--

s3cmd found one file
---
$ s3cmd ls s3://load-test
2017-04-08 13:13 10 s3://load-test/test_file
---

when s3cmd ran, the server logged
---
2017-04-13 15:31:01.526147 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:31:03.474955 7f9c56402700 20 RGWEnv::set(): HTTP_HOST: s4.rakops.com
2017-04-13 15:31:03.474976 7f9c56402700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: identity
2017-04-13 15:31:03.474980 7f9c56402700 20 RGWEnv::set(): CONTENT_LENGTH: 0
2017-04-13 15:31:03.474983 7f9c56402700 20 RGWEnv::set(): HTTP_X_AMZ_CONTENT_SHA256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:31:03.474988 7f9c56402700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/US/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.474993 7f9c56402700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: 20170413T193103Z
2017-04-13 15:31:03.474996 7f9c56402700 20 RGWEnv::set(): REQUEST_METHOD: GET
2017-04-13 15:31:03.474998 7f9c56402700 20 RGWEnv::set(): REQUEST_URI: /load-test/
2017-04-13 15:31:03.475000 7f9c56402700 20 RGWEnv::set(): SCRIPT_URI: /load-test/
2017-04-13 15:31:03.475002 7f9c56402700 20 RGWEnv::set(): QUERY_STRING: delimiter=/
2017-04-13 15:31:03.475008 7f9c56402700 20 RGWEnv::set(): SERVER_PORT: 80
2017-04-13 15:31:03.475011 7f9c56402700 20 CONTENT_LENGTH=0
2017-04-13 15:31:03.475015 7f9c56402700 20 HTTP_ACCEPT_ENCODING=identity
2017-04-13 15:31:03.475016 7f9c56402700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/US/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date,Signature=503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475018 7f9c56402700 20 HTTP_HOST=s4.rakops.com
2017-04-13 15:31:03.475020 7f9c56402700 20 HTTP_X_AMZ_CONTENT_SHA256=e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:31:03.475021 7f9c56402700 20 HTTP_X_AMZ_DATE=20170413T193103Z
2017-04-13 15:31:03.475022 7f9c56402700 20 QUERY_STRING=delimiter=/
2017-04-13 15:31:03.475023 7f9c56402700 20 REQUEST_METHOD=GET
2017-04-13 15:31:03.475025 7f9c56402700 20 REQUEST_URI=/load-test/
2017-04-13 15:31:03.475026 7f9c56402700 20 SCRIPT_URI=/load-test/
2017-04-13 15:31:03.475027 7f9c56402700 20 SERVER_PORT=80
2017-04-13 15:31:03.475029 7f9c56402700 1 ====== starting new request req=0x7f9c563fc340 =====
2017-04-13 15:31:03.475055 7f9c56402700 2 req 33:0.000026::GET /load-test/::initializing for trans_id = tx000000000000000000021-0058efd1f7-5e36-default
2017-04-13 15:31:03.475067 7f9c56402700 10 rgw api priority: s3=5 s3website=4
2017-04-13 15:31:03.475071 7f9c56402700 10 host=s4.rakops.com
2017-04-13 15:31:03.475073 7f9c56402700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2017-04-13 15:31:03.475076 7f9c56402700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/load-test/
2017-04-13 15:31:03.475087 7f9c56402700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2017-04-13 15:31:03.475093 7f9c56402700 10 meta>> HTTP_X_AMZ_DATE
2017-04-13 15:31:03.475098 7f9c56402700 10 x>> x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:31:03.475100 7f9c56402700 10 x>> x-amz-date:20170413T193103Z
2017-04-13 15:31:03.475138 7f9c56402700 20 get_handler handler=25RGWHandler_REST_Bucket_S3
2017-04-13 15:31:03.475144 7f9c56402700 10 handler=25RGWHandler_REST_Bucket_S3
2017-04-13 15:31:03.475150 7f9c56402700 2 req 33:0.000120:s3:GET /load-test/::getting op 0
2017-04-13 15:31:03.475156 7f9c56402700 10 op=25RGWListBucket_ObjStore_S3
2017-04-13 15:31:03.475159 7f9c56402700 2 req 33:0.000130:s3:GET /load-test/:list_bucket:authorizing
2017-04-13 15:31:03.475177 7f9c56402700 10 v4 signature format = 503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475184 7f9c56402700 10 v4 credential format = WHF0J757LOLM09WMNIJT/20170413/US/s3/aws4_request
2017-04-13 15:31:03.475187 7f9c56402700 10 access key id = WHF0J757LOLM09WMNIJT
2017-04-13 15:31:03.475189 7f9c56402700 10 credential scope = 20170413/US/s3/aws4_request
2017-04-13 15:31:03.475221 7f9c56402700 10 canonical headers format = host:s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T193103Z

2017-04-13 15:31:03.475266 7f9c56402700 10 payload request hash = e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:31:03.475339 7f9c56402700 10 canonical request = GET
/load-test/
delimiter=%2F
host:s4.rakops.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20170413T193103Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2017-04-13 15:31:03.475342 7f9c56402700 10 canonical request hash = 207fad664117bfc8fde836153e60aebbdf6a99f9454b3002607a7af066899e2e
2017-04-13 15:31:03.475345 7f9c56402700 10 string to sign = AWS4-HMAC-SHA256
20170413T193103Z
20170413/US/s3/aws4_request
207fad664117bfc8fde836153e60aebbdf6a99f9454b3002607a7af066899e2e
2017-04-13 15:31:03.475402 7f9c56402700 10 date_k = fe9b4bb4c8eaf30d9cec8875f194a016ea6b87c43477433cc18b9c83b672805c
2017-04-13 15:31:03.475431 7f9c56402700 10 region_k = 7261aec90ec71250cadf3d50cdf9ea91c3c86463834147c0bbd9df74d5731b96
2017-04-13 15:31:03.475458 7f9c56402700 10 service_k = f5b55212852f924e51b0eb8231b2c015fc03015760e55f4b03ba0848816e0c7c
2017-04-13 15:31:03.475484 7f9c56402700 10 signing_k = 5da245104d98786c9e2c4ab2e192b18e3893389bdd2995f8c3d8903627518584
2017-04-13 15:31:03.475512 7f9c56402700 10 signature_k = 503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475515 7f9c56402700 10 new signature = 503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475516 7f9c56402700 10 ----------------------------- Verifying signatures
2017-04-13 15:31:03.475517 7f9c56402700 10 Signature = 503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475519 7f9c56402700 10 New Signature = 503363e593d12cd1a003f5854b05e58fac60647598b0da925bb1610ac5aed011
2017-04-13 15:31:03.475520 7f9c56402700 10 -----------------------------
2017-04-13 15:31:03.475522 7f9c56402700 10 v4 auth ok
2017-04-13 15:31:03.475527 7f9c56402700 2 req 33:0.000497:s3:GET /load-test/:list_bucket:normalizing buckets and tenants
2017-04-13 15:31:03.475531 7f9c56402700 10 s->object=<NULL> s->bucket=load-test
2017-04-13 15:31:03.475535 7f9c56402700 2 req 33:0.000506:s3:GET /load-test/:list_bucket:init permissions
2017-04-13 15:31:03.475564 7f9c56402700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Owner><ID>testuser</ID><DisplayName>Test User</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="CanonicalUser"><ID>testuser</ID><DisplayName>Test User</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2017-04-13 15:31:03.475578 7f9c56402700 2 req 33:0.000548:s3:GET /load-test/:list_bucket:recalculating target
2017-04-13 15:31:03.475581 7f9c56402700 2 req 33:0.000551:s3:GET /load-test/:list_bucket:reading permissions
2017-04-13 15:31:03.475584 7f9c56402700 2 req 33:0.000554:s3:GET /load-test/:list_bucket:init op
2017-04-13 15:31:03.475587 7f9c56402700 2 req 33:0.000558:s3:GET /load-test/:list_bucket:verifying op mask
2017-04-13 15:31:03.475589 7f9c56402700 20 required_mask= 1 user.op_mask=7
2017-04-13 15:31:03.475591 7f9c56402700 2 req 33:0.000562:s3:GET /load-test/:list_bucket:verifying op permissions
2017-04-13 15:31:03.475599 7f9c56402700 5 Searching permissions for identity=RGWDummyIdentityApplier(auth_id=testuser, perm_mask=15, is_admin=0) mask=49
2017-04-13 15:31:03.475607 7f9c56402700 5 Searching permissions for uid=testuser
2017-04-13 15:31:03.475609 7f9c56402700 5 Found permission: 15
2017-04-13 15:31:03.475611 7f9c56402700 5 Searching permissions for group=1 mask=49
2017-04-13 15:31:03.475612 7f9c56402700 5 Permissions for group not found
2017-04-13 15:31:03.475614 7f9c56402700 5 Searching permissions for group=2 mask=49
2017-04-13 15:31:03.475616 7f9c56402700 5 Permissions for group not found
2017-04-13 15:31:03.475617 7f9c56402700 5 Getting permissions identity=RGWDummyIdentityApplier(auth_id=testuser, perm_mask=15, is_admin=0) owner=testuser perm=1
2017-04-13 15:31:03.475620 7f9c56402700 10 identity=RGWDummyIdentityApplier(auth_id=testuser, perm_mask=15, is_admin=0) requested perm (type)=1, policy perm=1, user_perm_mask=1, acl perm=1
2017-04-13 15:31:03.475623 7f9c56402700 2 req 33:0.000593:s3:GET /load-test/:list_bucket:verifying op params
2017-04-13 15:31:03.475626 7f9c56402700 2 req 33:0.000596:s3:GET /load-test/:list_bucket:pre-executing
2017-04-13 15:31:03.475628 7f9c56402700 2 req 33:0.000599:s3:GET /load-test/:list_bucket:executing
2017-04-13 15:31:03.475638 7f9c56402700 10 cls_bucket_list load-test(@{i=default.rgw.buckets.index,e=default.rgw.buckets.non-ec}default.rgw.buckets.data[0cd32163-34cc-497e-92f8-b16176bf5626.24098.2]) start [] num_entries 1001
2017-04-13 15:31:03.475658 7f9c56402700 20 reading from default.rgw.data.root:.bucket.meta.load-test:0cd32163-34cc-497e-92f8-b16176bf5626.24098.2
2017-04-13 15:31:03.475667 7f9c56402700 20 get_system_obj_state: rctx=0x7f9c563fa980 obj=default.rgw.data.root:.bucket.meta.load-test:0cd32163-34cc-497e-92f8-b16176bf5626.24098.2 state=0x7f9c95e4fe98 s->prefetch_data=0
2017-04-13 15:31:03.475675 7f9c56402700 10 cache get: name=default.rgw.data.root+.bucket.meta.load-test:0cd32163-34cc-497e-92f8-b16176bf5626.24098.2 : hit (requested=0x16, cached=0x17)
2017-04-13 15:31:03.475681 7f9c56402700 20 get_system_obj_state: s->obj_tag was set empty
2017-04-13 15:31:03.475686 7f9c56402700 10 cache get: name=default.rgw.data.root+.bucket.meta.load-test:0cd32163-34cc-497e-92f8-b16176bf5626.24098.2 : hit (requested=0x11, cached=0x17)
2017-04-13 15:31:03.477163 7f9c56402700 10 RGWRados::cls_bucket_list: got test_file[]
2017-04-13 15:31:03.477197 7f9c56402700 2 req 33:0.002167:s3:GET /load-test/:list_bucket:completing
2017-04-13 15:31:03.477318 7f9c56402700 2 req 33:0.002287:s3:GET /load-test/:list_bucket:op status=0
2017-04-13 15:31:03.477326 7f9c56402700 2 req 33:0.002297:s3:GET /load-test/:list_bucket:http status=200
2017-04-13 15:31:03.477333 7f9c56402700 1 ====== req done req=0x7f9c563fc340 op status=0 http_status=200 ======
2017-04-13 15:31:03.477469 7f9c56402700 1 civetweb: 0x7f9c948e7000: 172.20.1.50 - - [13/Apr/2017:15:31:03 0400] "GET /load-test/?delimiter=/ HTTP/1.1" 1 0 - -
--

*5) upload using PutObject *
client logs
---GOROOT=/usr/lib/golang
GOPATH=/home/davecb/go
/usr/lib/golang/bin/go build -i -o "/tmp/Build main.go and rungo" /home/davecb/go/src/s3v4Errors/main.go
"/tmp/Build main.go and rungo"
cfg=&{<nil> 0xc42001c780 0xc42014c060 <nil> 0xc42014c070 0xc42014c050 <nil> 0xc42000dfc8 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}
sess=&{0xc42013c240 {{[{core.ValidateEndpointHandler 0x5c5a70} {core.ValidateParametersHandler 0x5c5bd0}] 0x564f70} {[{core.SDKVersionUserAgentHandler 0x569c00}] 0x564f70} {[{core.BuildContentLengthHandler 0x5c4160}] <nil>} {[{core.ValidateReqSigHandler 0x5c4550} {core.SendHandler 0x5c4740}] <nil>} {[{core.ValidateResponseHandler 0x5c5430}] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[] <nil>} {[{core.AfterRetryHandler 0x5c55e0}] <nil>} {[] <nil>}}}
svc=&{0xc4200c0580}
bad response: InvalidArgument:
status code: 400, request id: tx000000000000000000022-0058efd259-5e36-default, host id: response {

}
Process finished with exit code 0
---

server logs
---

2017-04-13 15:32:29.527153 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:32:41.387155 7f9c55c01700 20 RGWEnv::set(): HTTP_HOST: load-test.s4.rakops.com
2017-04-13 15:32:41.387173 7f9c55c01700 20 RGWEnv::set(): HTTP_USER_AGENT: aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:32:41.387182 7f9c55c01700 20 RGWEnv::set(): CONTENT_LENGTH: 92193
2017-04-13 15:32:41.387186 7f9c55c01700 20 RGWEnv::set(): HTTP_AUTHORIZATION: AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=content-length;content-type;host;x-amz-content-sha256;x-amz-date, Signature=7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.387195 7f9c55c01700 20 RGWEnv::set(): CONTENT_TYPE: image/jpeg
2017-04-13 15:32:41.387201 7f9c55c01700 20 RGWEnv::set(): HTTP_X_AMZ_CONTENT_SHA256: 051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
2017-04-13 15:32:41.387204 7f9c55c01700 20 RGWEnv::set(): HTTP_X_AMZ_DATE: 20170413T193241Z
2017-04-13 15:32:41.387207 7f9c55c01700 20 RGWEnv::set(): HTTP_ACCEPT_ENCODING: gzip
2017-04-13 15:32:41.387209 7f9c55c01700 20 RGWEnv::set(): REQUEST_METHOD: PUT
2017-04-13 15:32:41.387210 7f9c55c01700 20 RGWEnv::set(): REQUEST_URI: /test.jpg
2017-04-13 15:32:41.387212 7f9c55c01700 20 RGWEnv::set(): SCRIPT_URI: /test.jpg
2017-04-13 15:32:41.387216 7f9c55c01700 20 RGWEnv::set(): SERVER_PORT: 80
2017-04-13 15:32:41.387219 7f9c55c01700 20 CONTENT_LENGTH=92193
2017-04-13 15:32:41.387221 7f9c55c01700 20 CONTENT_TYPE=image/jpeg
2017-04-13 15:32:41.387222 7f9c55c01700 20 HTTP_ACCEPT_ENCODING=gzip
2017-04-13 15:32:41.387223 7f9c55c01700 20 HTTP_AUTHORIZATION=AWS4-HMAC-SHA256 Credential=WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request, SignedHeaders=content-length;content-type;host;x-amz-content-sha256;x-amz-date, Signature=7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.387225 7f9c55c01700 20 HTTP_HOST=load-test.s4.rakops.com
2017-04-13 15:32:41.387227 7f9c55c01700 20 HTTP_USER_AGENT=aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:32:41.387228 7f9c55c01700 20 HTTP_X_AMZ_CONTENT_SHA256=051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
2017-04-13 15:32:41.387230 7f9c55c01700 20 HTTP_X_AMZ_DATE=20170413T193241Z
2017-04-13 15:32:41.387231 7f9c55c01700 20 REQUEST_METHOD=PUT
2017-04-13 15:32:41.387233 7f9c55c01700 20 REQUEST_URI=/test.jpg
2017-04-13 15:32:41.387234 7f9c55c01700 20 SCRIPT_URI=/test.jpg
2017-04-13 15:32:41.387235 7f9c55c01700 20 SERVER_PORT=80
2017-04-13 15:32:41.387237 7f9c55c01700 1 ====== starting new request req=0x7f9c55bfb340 =====
2017-04-13 15:32:41.387264 7f9c55c01700 2 req 34:0.000026::PUT /test.jpg::initializing for trans_id = tx000000000000000000022-0058efd259-5e36-default
2017-04-13 15:32:41.387282 7f9c55c01700 10 rgw api priority: s3=5 s3website=4
2017-04-13 15:32:41.387285 7f9c55c01700 10 host=load-test.s4.rakops.com
2017-04-13 15:32:41.387289 7f9c55c01700 20 subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2017-04-13 15:32:41.387295 7f9c55c01700 20 final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/test.jpg
2017-04-13 15:32:41.387308 7f9c55c01700 10 meta>> HTTP_X_AMZ_CONTENT_SHA256
2017-04-13 15:32:41.387313 7f9c55c01700 10 meta>> HTTP_X_AMZ_DATE
2017-04-13 15:32:41.387317 7f9c55c01700 10 x>> x-amz-content-sha256:051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
2017-04-13 15:32:41.387320 7f9c55c01700 10 x>> x-amz-date:20170413T193241Z
2017-04-13 15:32:41.387333 7f9c55c01700 20 get_handler handler=25RGWHandler_REST_Bucket_S3
2017-04-13 15:32:41.387340 7f9c55c01700 10 handler=25RGWHandler_REST_Bucket_S3
2017-04-13 15:32:41.387343 7f9c55c01700 2 req 34:0.000105:s3:PUT /test.jpg::getting op 1
2017-04-13 15:32:41.387349 7f9c55c01700 10 op=27RGWCreateBucket_ObjStore_S3
2017-04-13 15:32:41.387351 7f9c55c01700 2 req 34:0.000113:s3:PUT /test.jpg:create_bucket:authorizing
2017-04-13 15:32:41.387370 7f9c55c01700 10 v4 signature format = 7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.387377 7f9c55c01700 10 v4 credential format = WHF0J757LOLM09WMNIJT/20170413/us-east-1/s3/aws4_request
2017-04-13 15:32:41.387380 7f9c55c01700 10 access key id = WHF0J757LOLM09WMNIJT
2017-04-13 15:32:41.387381 7f9c55c01700 10 credential scope = 20170413/us-east-1/s3/aws4_request
2017-04-13 15:32:41.387412 7f9c55c01700 10 canonical headers format = content-length:92193
content-type:image/jpeg
host:load-test.s4.rakops.com
x-amz-content-sha256:051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
x-amz-date:20170413T193241Z

2017-04-13 15:32:41.387415 7f9c55c01700 10 delaying v4 auth
2017-04-13 15:32:41.387422 7f9c55c01700 2 req 34:0.000184:s3:PUT /test.jpg:create_bucket:normalizing buckets and tenants
2017-04-13 15:32:41.387425 7f9c55c01700 10 s->object=<NULL> s->bucket=test.jpg
2017-04-13 15:32:41.387429 7f9c55c01700 2 req 34:0.000192:s3:PUT /test.jpg:create_bucket:init permissions
2017-04-13 15:32:41.387432 7f9c55c01700 2 req 34:0.000195:s3:PUT /test.jpg:create_bucket:recalculating target
2017-04-13 15:32:41.387435 7f9c55c01700 2 req 34:0.000198:s3:PUT /test.jpg:create_bucket:reading permissions
2017-04-13 15:32:41.387438 7f9c55c01700 2 req 34:0.000201:s3:PUT /test.jpg:create_bucket:init op
2017-04-13 15:32:41.387441 7f9c55c01700 2 req 34:0.000204:s3:PUT /test.jpg:create_bucket:verifying op mask
2017-04-13 15:32:41.387444 7f9c55c01700 20 required_mask= 2 user.op_mask=7
2017-04-13 15:32:41.387447 7f9c55c01700 2 req 34:0.000209:s3:PUT /test.jpg:create_bucket:verifying op permissions
2017-04-13 15:32:41.388686 7f9c55c01700 2 req 34:0.001444:s3:PUT /test.jpg:create_bucket:verifying op params
2017-04-13 15:32:41.388730 7f9c55c01700 2 req 34:0.001492:s3:PUT /test.jpg:create_bucket:pre-executing
2017-04-13 15:32:41.388735 7f9c55c01700 2 req 34:0.001497:s3:PUT /test.jpg:create_bucket:executing
2017-04-13 15:32:41.390930 7f9c55c01700 10 payload request hash = 051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
2017-04-13 15:32:41.390973 7f9c55c01700 10 canonical request = PUT
/test.jpg

content-length:92193
content-type:image/jpeg
host:load-test.s4.rakops.com
x-amz-content-sha256:051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
x-amz-date:20170413T193241Z

content-length;content-type;host;x-amz-content-sha256;x-amz-date
051517b6e4fbf5242bbbc7444a9bf7745d0f1f45efae3e9c665f44d5d8099a4f
2017-04-13 15:32:41.390976 7f9c55c01700 10 canonical request hash = 0bb74eebf748f0097aba4cf1d416dfb12915b0248c0b8c7046aa244f48cb376d
2017-04-13 15:32:41.390982 7f9c55c01700 10 string to sign = AWS4-HMAC-SHA256
20170413T193241Z
20170413/us-east-1/s3/aws4_request
0bb74eebf748f0097aba4cf1d416dfb12915b0248c0b8c7046aa244f48cb376d
2017-04-13 15:32:41.391028 7f9c55c01700 10 date_k = fe9b4bb4c8eaf30d9cec8875f194a016ea6b87c43477433cc18b9c83b672805c
2017-04-13 15:32:41.391057 7f9c55c01700 10 region_k = c40871584b9787b1b2b3a5458f8ef3d63127fd41256b30ccea58ed33dc5b7ff3
2017-04-13 15:32:41.391099 7f9c55c01700 10 service_k = 3bd399b5c03aa0e02ee1559c0ff477cf47a36dcb2ccca08b8dae9cef8c5d6a47
2017-04-13 15:32:41.391145 7f9c55c01700 10 signing_k = a9d71a6faa67b630b80724cc8b66434f5864cfb851d7489ef6cf2c06640c2920
2017-04-13 15:32:41.391174 7f9c55c01700 10 signature_k = 7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.391185 7f9c55c01700 10 new signature = 7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.391187 7f9c55c01700 10 ----------------------------- Verifying signatures
2017-04-13 15:32:41.391237 7f9c55c01700 10 Signature = 7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.391246 7f9c55c01700 10 New Signature = 7b59a988bed7528534684e6dafd8ff12aeb03c541b573d8c390493f7b7ed9a1d
2017-04-13 15:32:41.391248 7f9c55c01700 10 -----------------------------
2017-04-13 15:32:41.391251 7f9c55c01700 10 v4 auth ok
2017-04-13 15:32:41.392420 7f9c55c01700 20 create bucket input data=����
2017-04-13 15:32:41.392432 7f9c55c01700 0 failed to parse input: ����
2017-04-13 15:32:41.392890 7f9c55c01700 2 req 34:0.005651:s3:PUT /test.jpg:create_bucket:completing
2017-04-13 15:32:41.392988 7f9c55c01700 2 req 34:0.005751:s3:PUT /test.jpg:create_bucket:op status=-22
2017-04-13 15:32:41.392993 7f9c55c01700 2 req 34:0.005755:s3:PUT /test.jpg:create_bucket:http status=400
2017-04-13 15:32:41.393050 7f9c55c01700 1 ====== req done req=0x7f9c55bfb340 op status=-22 http_status=400 ======
2017-04-13 15:32:41.393066 7f9c55c01700 20 process_request() returned -22
2017-04-13 15:32:41.393124 7f9c55c01700 1 civetweb: 0x7f9c948fa000: 172.20.1.50 - - [13/Apr/2017:15:32:41 -0400] "PUT /test.jpg HTTP/1.1" 1 0 - aws-sdk-go/1.8.11 (go1.7.5; linux; amd64)
2017-04-13 15:32:51.527340 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start
2017-04-13 15:33:13.527517 7f9c7443e700 2 RGWDataChangesLog::ChangesRenewThread: start

Our workaround is to read objects using the s3 .net library, but to build our own put in open code.

If there are any languages, APIs or libraries you'd care to suggest as a workaround, we'd be interested. I don't entirely trust what I get from Amazon.

main.go (4.37 KB) David Collier-Brown, 04/13/2017 07:35 PM

d1.go (5.44 KB) Marcus Watts, 04/18/2017 04:28 AM

History

#1 Updated by David Collier-Brown almost 7 years ago

If you'd prefer me to use exactly the examples out of https://github.com/awsdocs/aws-doc-sdk-examples/blob/master/go/example_code/s3/s3_download.go just say. For safety (against stupid finger-errors (:-)) I'm going to work through them in any case.

#2 Updated by David Collier-Brown almost 7 years ago

Drilling down, it appears as if
cfg := aws.NewConfig().WithRegion("us-east-1").
WithEndpoint(host).
WithDisableSSL(true).
WithLogLevel(3).
WithCredentials(creds)
does not set the configuration that the Amazon code uses.

Manually changing the code they use to validate the config to print out the old value and then force it to the desired one prints out
```
r.Config.Region was =
r.Config.Endpoint was =
r.Config.Region is now =us-east-1
r.Config.Endpoint is =s4.rakops.com
2017/04/14 17:47:04 Unable to download fileName "test.jpg", RequestError: send request failed
caused by: Get https://load-test.s3..amazonaws.com/test.jpg: dial tcp: lookup load-test.s3..amazonaws.com: invalid domain name
```

which suggests to me that the bucket and filename are fine, but the region was not used (it's blank!) and the endpoint is overridden to be "amazonaws.com".

The code I hacked is github.com/aws/aws-sdk-go/aws/corehandlers/handlers.go line 195 ff,
```
// ValidateEndpointHandler is a request handler to validate a request had the
// appropriate Region and Endpoint set. Will set r.Error if the endpoint or
// region is not valid. FIXME DCB
var ValidateEndpointHandler = request.NamedHandler{Name: "core.ValidateEndpointHandler", Fn: func(r *request.Request) {
var region, endpoint = "us-east-1", "s4.rakops.com"

fmt.Printf("r.Config.Region was =%v\n", aws.StringValue(r.Config.Region))
fmt.Printf("r.Config.Endpoint was =%v\n", aws.StringValue(r.Config.Endpoint))
r.Config.Region = &region
r.Config.Endpoint = &endpoint
fmt.Printf("r.Config.Region is now =%v\n", aws.StringValue(r.Config.Region))
fmt.Printf("r.Config.Endpoint is =%v\n", aws.StringValue(r.Config.Endpoint))
return
if r.ClientInfo.SigningRegion "" && aws.StringValue(r.Config.Region) "" {
r.Error = aws.ErrMissingRegion
} else if r.ClientInfo.Endpoint == "" {
r.Error = aws.ErrMissingEndpoint
}
}}
```

I't a weekend, I'll keep drilling down (;-))

#3 Updated by David Collier-Brown almost 7 years ago

I'm underwhelmed!

The Amazone s3 go interface code is quite broken when using any other than an Amazon server. It is, IMHO, after the addition of v4 authentication, no longer usable with anything other than aws.

I'm going to suggest you close this ticket as "not our bug, will not fix", and file a documentation rfe to
1) say "always use us-east-1" and
2) recommend a different api library such as minio, whom I've also told about this.

Thanks guys! Noy your bug!

--dave

#4 Updated by David Collier-Brown almost 7 years ago

And, in case you haven't guessed, I tend to make spelling misteaques when typing too fast (:-))

#5 Updated by Marcus Watts almost 7 years ago

What are you doing with dns in your test environment? A lot of your tests appear to want
to resolve names of the form "container/endpoint".

#6 Updated by David Collier-Brown almost 7 years ago

I don't understand the question, but both the sucessful and unsucessful cases use the same hostname and IP address, delivered by /etc/hosts without any use of dns.

Running the equivalent operations with the minio ceph library and the same adresses results in proper behavior.

Looking at the code near where the amazon library reports errors shows it is often without a hostname at all, and occasionally has been set to amazonaws.com, depending on which code-path has been followed.

Does that help?

#7 Updated by Marcus Watts almost 7 years ago

If you haven't done anything with dns then some (all?) of your test program should fail. If you don't
have something like " WithS3ForcePathStyle(true). " in your call to aws.NewConfig() then you get to use "host path style", which means the bucket name goes into the DNS name.

In your "case 4", you report the following error:
caused by: Get http://kbimages-test.s4.rakops.WithS3ForcePathStylecom/: dial tcp: lookup kbimages-test.s4.rakops.com on 172.19.1.10:53: no such host
apparently, at the time, you were using the bucket "kbimages-test", and your test program tried to resolve the dns name "kbimages-test.s4.rakops.com" - and failed.

So, you probably want to either use WithS3ForcePathStyle or you want to do something clever with DNS.

#8 Updated by Marcus Watts almost 7 years ago

But, there's another problem. When the go program makes an http request, it puts in "absolute URLs" (and not absolute paths) in its request. For instance,

instead of,
PUT /load-test/test.jpg HTTP/1.1
go does
PUT http://campodus.eng.arb.redhat.com/load-test/test.jpg HTTP/1.1

The civetweb code in radosgw doesn't know what to do with the host name, and winds up doing absolutely nothing, just closing the connection.

For your test case 5, the output would look like this,
bad response: RequestError: send request failed
caused by: Put http://campodus.eng.arb.redhat.com/load-test/test.jpg: write tcp 10.17.148.106:48606->10.17.152.69:80: write: broken pipe

Here's a more trival way to see the same thing;
http_proxy=http://campodus.eng.arb.redhat.com:80 curl -v http://campodus.eng.arb.redhat.com/

#9 Updated by Marcus Watts almost 7 years ago

A workaround for this is to add this option to the radosgw civetweb frontend line:
authentication_domain=campodus.eng.arb.redhat.com
(obviously you would use your hostname, not mine).

#10 Updated by Marcus Watts almost 7 years ago

I'm uploading a slight evolution of your "main.go" file, which lacking any imagination I named "d1.go". It uses environment variables or cmdline options (instead of hard-wired configuration) and is slightly smarter about not continuing after an error. Also, case 1 uses NewUploaderWithClient in place of NewUploader - so it actually gets local configuration.

I was able to get all 5 test cases there to run in my environment.

#11 Updated by Abhishek Lekshmanan almost 7 years ago

For absolute urls there is also https://github.com/ceph/ceph/pull/12861 which bypasses the authentication domain checks in civetweb

Also available in: Atom PDF