Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

S3-sync feature does not synchronize directories properly #483

Closed
jdrowe opened this issue Jun 24, 2016 · 14 comments
Closed

S3-sync feature does not synchronize directories properly #483

jdrowe opened this issue Jun 24, 2016 · 14 comments

Comments

@jdrowe
Copy link

jdrowe commented Jun 24, 2016

When attempting to use "aws s3 sync" or "s3cmd sync" each with the --delete option does not actually delete directories missing from the origin.
When dealing with a flat directory of files it works fine, but when syncing multiple directories it does not seem to.

Thanks!

Expected result as seen in AWS's S3 environment:

Initial Sync:

[centos@testhost test]$ aws --profile ops s3 sync . s3://pardotops-leotest/synctest/
upload: 1/random-file-01.txt to s3://pardotops-leotest/synctest/1/random-file-01.txt
upload: 1/random-file-07.txt to s3://pardotops-leotest/synctest/1/random-file-07.txt
upload: 1/random-file-10.txt to s3://pardotops-leotest/synctest/1/random-file-10.txt
upload: 1/random-file-09.txt to s3://pardotops-leotest/synctest/1/random-file-09.txt
upload: 1/random-file-08.txt to s3://pardotops-leotest/synctest/1/random-file-08.txt
upload: 1/random-file-04.txt to s3://pardotops-leotest/synctest/1/random-file-04.txt
upload: 1/random-file-03.txt to s3://pardotops-leotest/synctest/1/random-file-03.txt
upload: 2/random-file-01.txt to s3://pardotops-leotest/synctest/2/random-file-01.txt
upload: 1/random-file-02.txt to s3://pardotops-leotest/synctest/1/random-file-02.txt
upload: 1/random-file-06.txt to s3://pardotops-leotest/synctest/1/random-file-06.txt
upload: 1/random-file-05.txt to s3://pardotops-leotest/synctest/1/random-file-05.txt
upload: 2/random-file-02.txt to s3://pardotops-leotest/synctest/2/random-file-02.txt
upload: 2/random-file-06.txt to s3://pardotops-leotest/synctest/2/random-file-06.txt
upload: 2/random-file-03.txt to s3://pardotops-leotest/synctest/2/random-file-03.txt
upload: 2/random-file-05.txt to s3://pardotops-leotest/synctest/2/random-file-05.txt
upload: 2/random-file-04.txt to s3://pardotops-leotest/synctest/2/random-file-04.txt
upload: 2/random-file-08.txt to s3://pardotops-leotest/synctest/2/random-file-08.txt
upload: 2/random-file-07.txt to s3://pardotops-leotest/synctest/2/random-file-07.txt
upload: 3/random-file-02.txt to s3://pardotops-leotest/synctest/3/random-file-02.txt
upload: 3/random-file-04.txt to s3://pardotops-leotest/synctest/3/random-file-04.txt
upload: 2/random-file-10.txt to s3://pardotops-leotest/synctest/2/random-file-10.txt
upload: 3/random-file-06.txt to s3://pardotops-leotest/synctest/3/random-file-06.txt
upload: 3/random-file-03.txt to s3://pardotops-leotest/synctest/3/random-file-03.txt
upload: 3/random-file-05.txt to s3://pardotops-leotest/synctest/3/random-file-05.txt
upload: 3/random-file-01.txt to s3://pardotops-leotest/synctest/3/random-file-01.txt
upload: 2/random-file-09.txt to s3://pardotops-leotest/synctest/2/random-file-09.txt
upload: 3/random-file-08.txt to s3://pardotops-leotest/synctest/3/random-file-08.txt
upload: 3/random-file-07.txt to s3://pardotops-leotest/synctest/3/random-file-07.txt
upload: 3/random-file-10.txt to s3://pardotops-leotest/synctest/3/random-file-10.txt
upload: 4/random-file-04.txt to s3://pardotops-leotest/synctest/4/random-file-04.txt
upload: 4/random-file-01.txt to s3://pardotops-leotest/synctest/4/random-file-01.txt
upload: 3/random-file-09.txt to s3://pardotops-leotest/synctest/3/random-file-09.txt
upload: 4/random-file-06.txt to s3://pardotops-leotest/synctest/4/random-file-06.txt
upload: 4/random-file-02.txt to s3://pardotops-leotest/synctest/4/random-file-02.txt
upload: 4/random-file-03.txt to s3://pardotops-leotest/synctest/4/random-file-03.txt
upload: 4/random-file-05.txt to s3://pardotops-leotest/synctest/4/random-file-05.txt
upload: 4/random-file-07.txt to s3://pardotops-leotest/synctest/4/random-file-07.txt
upload: 4/random-file-09.txt to s3://pardotops-leotest/synctest/4/random-file-09.txt
upload: 4/random-file-08.txt to s3://pardotops-leotest/synctest/4/random-file-08.txt
upload: 4/random-file-10.txt to s3://pardotops-leotest/synctest/4/random-file-10.txt
upload: 5/random-file-01.txt to s3://pardotops-leotest/synctest/5/random-file-01.txt
upload: 5/random-file-03.txt to s3://pardotops-leotest/synctest/5/random-file-03.txt
upload: 5/random-file-04.txt to s3://pardotops-leotest/synctest/5/random-file-04.txt
upload: 5/random-file-02.txt to s3://pardotops-leotest/synctest/5/random-file-02.txt
upload: 5/random-file-06.txt to s3://pardotops-leotest/synctest/5/random-file-06.txt
upload: 5/random-file-05.txt to s3://pardotops-leotest/synctest/5/random-file-05.txt
upload: 5/random-file-07.txt to s3://pardotops-leotest/synctest/5/random-file-07.txt
upload: 5/random-file-08.txt to s3://pardotops-leotest/synctest/5/random-file-08.txt
upload: 5/random-file-10.txt to s3://pardotops-leotest/synctest/5/random-file-10.txt
upload: 5/random-file-09.txt to s3://pardotops-leotest/synctest/5/random-file-09.txt

Move directory out of the way

[centos@testhost test]$ mv 3 ../

resync with the --delete option

[centos@testhost test]$ aws --profile ops s3 sync . s3://pardotops-leotest/synctest/ --delete
delete: s3://pardotops-leotest/synctest/3/random-file-01.txt
delete: s3://pardotops-leotest/synctest/3/random-file-06.txt
delete: s3://pardotops-leotest/synctest/3/random-file-08.txt
delete: s3://pardotops-leotest/synctest/3/random-file-04.txt
delete: s3://pardotops-leotest/synctest/3/random-file-03.txt
delete: s3://pardotops-leotest/synctest/3/random-file-05.txt
delete: s3://pardotops-leotest/synctest/3/random-file-07.txt
delete: s3://pardotops-leotest/synctest/3/random-file-02.txt
delete: s3://pardotops-leotest/synctest/3/random-file-09.txt
delete: s3://pardotops-leotest/synctest/3/random-file-10.txt
[centos@testhost test]$

When using LeoFS:

Initial Sync:

[centos@testhost test]$ aws --endpoint-url http://s3-dev.pardot.com/ s3 sync . s3://opstest/synctest/
upload: 1/random-file-03.txt to s3://opstest/synctest/1/random-file-03.txt
upload: 1/random-file-02.txt to s3://opstest/synctest/1/random-file-02.txt
upload: 1/random-file-04.txt to s3://opstest/synctest/1/random-file-04.txt
upload: 1/random-file-07.txt to s3://opstest/synctest/1/random-file-07.txt
upload: 1/random-file-01.txt to s3://opstest/synctest/1/random-file-01.txt
upload: 1/random-file-08.txt to s3://opstest/synctest/1/random-file-08.txt
upload: 1/random-file-09.txt to s3://opstest/synctest/1/random-file-09.txt
upload: 1/random-file-06.txt to s3://opstest/synctest/1/random-file-06.txt
upload: 1/random-file-05.txt to s3://opstest/synctest/1/random-file-05.txt
upload: 1/random-file-10.txt to s3://opstest/synctest/1/random-file-10.txt
upload: 2/random-file-01.txt to s3://opstest/synctest/2/random-file-01.txt
upload: 2/random-file-03.txt to s3://opstest/synctest/2/random-file-03.txt
upload: 2/random-file-02.txt to s3://opstest/synctest/2/random-file-02.txt
upload: 2/random-file-04.txt to s3://opstest/synctest/2/random-file-04.txt
upload: 2/random-file-07.txt to s3://opstest/synctest/2/random-file-07.txt
upload: 2/random-file-05.txt to s3://opstest/synctest/2/random-file-05.txt
upload: 2/random-file-09.txt to s3://opstest/synctest/2/random-file-09.txt
upload: 2/random-file-08.txt to s3://opstest/synctest/2/random-file-08.txt
upload: 2/random-file-06.txt to s3://opstest/synctest/2/random-file-06.txt
upload: 2/random-file-10.txt to s3://opstest/synctest/2/random-file-10.txt
upload: 3/random-file-01.txt to s3://opstest/synctest/3/random-file-01.txt
upload: 3/random-file-02.txt to s3://opstest/synctest/3/random-file-02.txt
upload: 3/random-file-04.txt to s3://opstest/synctest/3/random-file-04.txt
upload: 3/random-file-03.txt to s3://opstest/synctest/3/random-file-03.txt
upload: 3/random-file-07.txt to s3://opstest/synctest/3/random-file-07.txt
upload: 3/random-file-08.txt to s3://opstest/synctest/3/random-file-08.txt
upload: 3/random-file-10.txt to s3://opstest/synctest/3/random-file-10.txt
upload: 4/random-file-01.txt to s3://opstest/synctest/4/random-file-01.txt
upload: 3/random-file-06.txt to s3://opstest/synctest/3/random-file-06.txt
upload: 3/random-file-05.txt to s3://opstest/synctest/3/random-file-05.txt
upload: 3/random-file-09.txt to s3://opstest/synctest/3/random-file-09.txt
upload: 4/random-file-02.txt to s3://opstest/synctest/4/random-file-02.txt
upload: 4/random-file-04.txt to s3://opstest/synctest/4/random-file-04.txt
upload: 4/random-file-03.txt to s3://opstest/synctest/4/random-file-03.txt
upload: 4/random-file-05.txt to s3://opstest/synctest/4/random-file-05.txt
upload: 4/random-file-06.txt to s3://opstest/synctest/4/random-file-06.txt
upload: 4/random-file-07.txt to s3://opstest/synctest/4/random-file-07.txt
upload: 4/random-file-08.txt to s3://opstest/synctest/4/random-file-08.txt
upload: 5/random-file-02.txt to s3://opstest/synctest/5/random-file-02.txt
upload: 4/random-file-09.txt to s3://opstest/synctest/4/random-file-09.txt
upload: 4/random-file-10.txt to s3://opstest/synctest/4/random-file-10.txt
upload: 5/random-file-01.txt to s3://opstest/synctest/5/random-file-01.txt
upload: 5/random-file-03.txt to s3://opstest/synctest/5/random-file-03.txt
upload: 5/random-file-04.txt to s3://opstest/synctest/5/random-file-04.txt
upload: 5/random-file-05.txt to s3://opstest/synctest/5/random-file-05.txt
upload: 5/random-file-06.txt to s3://opstest/synctest/5/random-file-06.txt
upload: 5/random-file-07.txt to s3://opstest/synctest/5/random-file-07.txt
upload: 5/random-file-08.txt to s3://opstest/synctest/5/random-file-08.txt
upload: 5/random-file-09.txt to s3://opstest/synctest/5/random-file-09.txt
upload: 5/random-file-10.txt to s3://opstest/synctest/5/random-file-10.txt

Move file out of the way

[centos@testhost test]$ mv 3 ../

resync with the --delete option

[centos@testhost test]$ aws --endpoint-url http://s3-dev.pardot.com/ s3 sync . s3://opstest/synctest/ --delete
upload: 1/random-file-06.txt to s3://opstest/synctest/1/random-file-06.txt
upload: 1/random-file-02.txt to s3://opstest/synctest/1/random-file-02.txt
upload: 1/random-file-09.txt to s3://opstest/synctest/1/random-file-09.txt
upload: 1/random-file-04.txt to s3://opstest/synctest/1/random-file-04.txt
upload: 1/random-file-05.txt to s3://opstest/synctest/1/random-file-05.txt
upload: 1/random-file-10.txt to s3://opstest/synctest/1/random-file-10.txt
upload: 1/random-file-03.txt to s3://opstest/synctest/1/random-file-03.txt
upload: 1/random-file-07.txt to s3://opstest/synctest/1/random-file-07.txt
upload: 1/random-file-01.txt to s3://opstest/synctest/1/random-file-01.txt
upload: 1/random-file-08.txt to s3://opstest/synctest/1/random-file-08.txt
upload: 2/random-file-01.txt to s3://opstest/synctest/2/random-file-01.txt
upload: 2/random-file-02.txt to s3://opstest/synctest/2/random-file-02.txt
upload: 2/random-file-03.txt to s3://opstest/synctest/2/random-file-03.txt
upload: 2/random-file-04.txt to s3://opstest/synctest/2/random-file-04.txt
upload: 2/random-file-07.txt to s3://opstest/synctest/2/random-file-07.txt
upload: 2/random-file-09.txt to s3://opstest/synctest/2/random-file-09.txt
upload: 2/random-file-06.txt to s3://opstest/synctest/2/random-file-06.txt
upload: 2/random-file-05.txt to s3://opstest/synctest/2/random-file-05.txt
upload: 2/random-file-10.txt to s3://opstest/synctest/2/random-file-10.txt
upload: 2/random-file-08.txt to s3://opstest/synctest/2/random-file-08.txt
upload: 4/random-file-01.txt to s3://opstest/synctest/4/random-file-01.txt
upload: 4/random-file-02.txt to s3://opstest/synctest/4/random-file-02.txt
upload: 4/random-file-04.txt to s3://opstest/synctest/4/random-file-04.txt
upload: 4/random-file-05.txt to s3://opstest/synctest/4/random-file-05.txt
upload: 4/random-file-03.txt to s3://opstest/synctest/4/random-file-03.txt
upload: 4/random-file-07.txt to s3://opstest/synctest/4/random-file-07.txt
upload: 4/random-file-06.txt to s3://opstest/synctest/4/random-file-06.txt
upload: 4/random-file-08.txt to s3://opstest/synctest/4/random-file-08.txt
upload: 4/random-file-09.txt to s3://opstest/synctest/4/random-file-09.txt
upload: 5/random-file-01.txt to s3://opstest/synctest/5/random-file-01.txt
upload: 4/random-file-10.txt to s3://opstest/synctest/4/random-file-10.txt
upload: 5/random-file-02.txt to s3://opstest/synctest/5/random-file-02.txt
upload: 5/random-file-03.txt to s3://opstest/synctest/5/random-file-03.txt
upload: 5/random-file-04.txt to s3://opstest/synctest/5/random-file-04.txt
upload: 5/random-file-05.txt to s3://opstest/synctest/5/random-file-05.txt
upload: 5/random-file-06.txt to s3://opstest/synctest/5/random-file-06.txt
upload: 5/random-file-07.txt to s3://opstest/synctest/5/random-file-07.txt
upload: 5/random-file-08.txt to s3://opstest/synctest/5/random-file-08.txt
upload: 5/random-file-10.txt to s3://opstest/synctest/5/random-file-10.txt
upload: 5/random-file-09.txt to s3://opstest/synctest/5/random-file-09.txt
@yosukehara
Copy link
Member

@jdrowe Thank you for filing this issue. We'll test s3cmd sync --delete option, then start fixing it.

@mocchira
Copy link
Member

mocchira commented Jul 1, 2016

s3cmd output with --debug

vagrant@vagrant-ubuntu-trusty-64:~/dev/s3cmd$ s3cmd --debug --delete-removed sync test2 s3://bbb
DEBUG: s3cmd version 1.6.1
DEBUG: ConfigParser: Reading file '/home/vagrant/.s3cfg'
DEBUG: ConfigParser: access_key->05...2_chars...6
DEBUG: ConfigParser: access_token->
DEBUG: ConfigParser: add_encoding_exts->
DEBUG: ConfigParser: add_headers->
DEBUG: ConfigParser: bucket_location->US
DEBUG: ConfigParser: ca_certs_file->
DEBUG: ConfigParser: cache_file->
DEBUG: ConfigParser: check_ssl_certificate->True
DEBUG: ConfigParser: check_ssl_hostname->True
DEBUG: ConfigParser: cloudfront_host->cloudfront.amazonaws.com
DEBUG: ConfigParser: default_mime_type->binary/octet-stream
DEBUG: ConfigParser: delay_updates->False
DEBUG: ConfigParser: delete_after->False
DEBUG: ConfigParser: delete_after_fetch->False
DEBUG: ConfigParser: delete_removed->False
DEBUG: ConfigParser: dry_run->False
DEBUG: ConfigParser: enable_multipart->True
DEBUG: ConfigParser: encoding->UTF-8
DEBUG: ConfigParser: encrypt->False
DEBUG: ConfigParser: expiry_date->
DEBUG: ConfigParser: expiry_days->
DEBUG: ConfigParser: expiry_prefix->
DEBUG: ConfigParser: follow_symlinks->False
DEBUG: ConfigParser: force->False
DEBUG: ConfigParser: get_continue->False
DEBUG: ConfigParser: gpg_command->/usr/bin/gpg
DEBUG: ConfigParser: gpg_decrypt->%(gpg_command)s -d --verbose --no-use-agent --batch --yes --passphrase-fd %(passphrase_fd)s -o %(output_file)s %(input_file)s
DEBUG: ConfigParser: gpg_encrypt->%(gpg_command)s -c --verbose --no-use-agent --batch --yes --passphrase-fd %(passphrase_fd)s -o %(output_file)s %(input_file)s
DEBUG: ConfigParser: gpg_passphrase->...-3_chars...
DEBUG: ConfigParser: guess_mime_type->True
DEBUG: ConfigParser: host_base->s3.amazonaws.com
DEBUG: ConfigParser: host_bucket->%(bucket)s.s3.amazonaws.com
DEBUG: ConfigParser: human_readable_sizes->False
DEBUG: ConfigParser: invalidate_default_index_on_cf->False
DEBUG: ConfigParser: invalidate_default_index_root_on_cf->True
DEBUG: ConfigParser: invalidate_on_cf->False
DEBUG: ConfigParser: kms_key->
DEBUG: ConfigParser: limitrate->0
DEBUG: ConfigParser: list_md5->False
DEBUG: ConfigParser: log_target_prefix->
DEBUG: ConfigParser: long_listing->False
DEBUG: ConfigParser: max_delete->-1
DEBUG: ConfigParser: mime_type->
DEBUG: ConfigParser: multipart_chunk_size_mb->15
DEBUG: ConfigParser: multipart_max_chunks->10000
DEBUG: ConfigParser: preserve_attrs->True
DEBUG: ConfigParser: progress_meter->True
DEBUG: ConfigParser: proxy_host->localhost
DEBUG: ConfigParser: proxy_port->8080
DEBUG: ConfigParser: put_continue->False
DEBUG: ConfigParser: recursive->False
DEBUG: ConfigParser: recv_chunk->65536
DEBUG: ConfigParser: reduced_redundancy->False
DEBUG: ConfigParser: requester_pays->False
DEBUG: ConfigParser: restore_days->1
DEBUG: ConfigParser: secret_key->80...6_chars...5
DEBUG: ConfigParser: send_chunk->65536
DEBUG: ConfigParser: server_side_encryption->False
DEBUG: ConfigParser: signature_v2->True
DEBUG: ConfigParser: simpledb_host->sdb.amazonaws.com
DEBUG: ConfigParser: skip_existing->False
DEBUG: ConfigParser: socket_timeout->300
DEBUG: ConfigParser: stats->False
DEBUG: ConfigParser: stop_on_error->False
DEBUG: ConfigParser: storage_class->
DEBUG: ConfigParser: urlencoding_mode->normal
DEBUG: ConfigParser: use_https->False
DEBUG: ConfigParser: use_mime_magic->True
DEBUG: ConfigParser: verbosity->WARNING
DEBUG: ConfigParser: website_endpoint->http://%(bucket)s.s3-website-%(location)s.amazonaws.com/
DEBUG: ConfigParser: website_error->
DEBUG: ConfigParser: website_index->index.html
DEBUG: Updating Config.Config cache_file ->
DEBUG: Updating Config.Config delete_removed -> True
DEBUG: Updating Config.Config follow_symlinks -> False
DEBUG: Updating Config.Config verbosity -> 10
DEBUG: Unicodising 'sync' using UTF-8
DEBUG: Unicodising 'test2' using UTF-8
DEBUG: Unicodising 's3://bbb' using UTF-8
DEBUG: Command: sync
DEBUG: DeUnicodising u'test2' using UTF-8
DEBUG: DeUnicodising u'test2' using UTF-8
INFO: Compiling list of local files...
DEBUG: DeUnicodising u'test2' using UTF-8
DEBUG: DeUnicodising u'test2' using UTF-8
DEBUG: Unicodising '4' using UTF-8
DEBUG: DeUnicodising u'test2/4' using UTF-8
DEBUG: CHECK: u'test2/4/'
DEBUG: PASS: u'test2/4/'
DEBUG: Unicodising '2' using UTF-8
DEBUG: DeUnicodising u'test2/2' using UTF-8
DEBUG: CHECK: u'test2/2/'
DEBUG: PASS: u'test2/2/'
DEBUG: Unicodising '1' using UTF-8
DEBUG: DeUnicodising u'test2/1' using UTF-8
DEBUG: CHECK: u'test2/1/'
DEBUG: PASS: u'test2/1/'
DEBUG: DeUnicodising u'test2/4' using UTF-8
DEBUG: DeUnicodising u'test2/4' using UTF-8
DEBUG: Unicodising '02' using UTF-8
DEBUG: DeUnicodising u'test2/4/02' using UTF-8
DEBUG: Unicodising '04' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: Unicodising '03' using UTF-8
DEBUG: DeUnicodising u'test2/4/03' using UTF-8
DEBUG: DeUnicodising u'test2/4/02' using UTF-8
DEBUG: DeUnicodising u'test2/4/02' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: DeUnicodising u'test2/4/03' using UTF-8
DEBUG: DeUnicodising u'test2/4/03' using UTF-8
DEBUG: DeUnicodising u'test2/2' using UTF-8
DEBUG: DeUnicodising u'test2/2' using UTF-8
DEBUG: Unicodising '02' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: Unicodising '04' using UTF-8
DEBUG: DeUnicodising u'test2/2/04' using UTF-8
DEBUG: Unicodising '03' using UTF-8
DEBUG: DeUnicodising u'test2/2/03' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: DeUnicodising u'test2/2/04' using UTF-8
DEBUG: DeUnicodising u'test2/2/04' using UTF-8
DEBUG: DeUnicodising u'test2/2/03' using UTF-8
DEBUG: DeUnicodising u'test2/2/03' using UTF-8
DEBUG: DeUnicodising u'test2/1' using UTF-8
DEBUG: DeUnicodising u'test2/1' using UTF-8
DEBUG: Unicodising '02' using UTF-8
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: Unicodising '04' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: Unicodising '03' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: Applying --exclude/--include
DEBUG: CHECK: test2/1/02
DEBUG: PASS: u'test2/1/02'
DEBUG: CHECK: test2/1/03
DEBUG: PASS: u'test2/1/03'
DEBUG: CHECK: test2/1/04
DEBUG: PASS: u'test2/1/04'
DEBUG: CHECK: test2/2/02
DEBUG: PASS: u'test2/2/02'
DEBUG: CHECK: test2/2/03
DEBUG: PASS: u'test2/2/03'
DEBUG: CHECK: test2/2/04
DEBUG: PASS: u'test2/2/04'
DEBUG: CHECK: test2/4/02
DEBUG: PASS: u'test2/4/02'
DEBUG: CHECK: test2/4/03
DEBUG: PASS: u'test2/4/03'
DEBUG: CHECK: test2/4/04
DEBUG: PASS: u'test2/4/04'
INFO: Running stat() and reading/calculating MD5 values on 9 files, this may take some time...
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: doing file I/O to read md5 of test2/1/02
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: doing file I/O to read md5 of test2/1/03
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: doing file I/O to read md5 of test2/1/04
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: doing file I/O to read md5 of test2/2/02
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: DeUnicodising u'test2/2/03' using UTF-8
DEBUG: doing file I/O to read md5 of test2/2/03
DEBUG: DeUnicodising u'test2/2/03' using UTF-8
DEBUG: DeUnicodising u'test2/2/04' using UTF-8
DEBUG: doing file I/O to read md5 of test2/2/04
DEBUG: DeUnicodising u'test2/2/04' using UTF-8
DEBUG: DeUnicodising u'test2/4/02' using UTF-8
DEBUG: doing file I/O to read md5 of test2/4/02
DEBUG: DeUnicodising u'test2/4/02' using UTF-8
DEBUG: DeUnicodising u'test2/4/03' using UTF-8
DEBUG: doing file I/O to read md5 of test2/4/03
DEBUG: DeUnicodising u'test2/4/03' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: doing file I/O to read md5 of test2/4/04
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
INFO: Retrieving list of remote files for s3://bbb/test2 ...
DEBUG: String 'test2' encoded to 'test2'
DEBUG: CreateRequest: resource[uri]=/
DEBUG: Using signature v2
DEBUG: SignHeaders: 'GET\n\n\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\n/bbb/'
DEBUG: Processing request, please wait...
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/?prefix=test2
DEBUG: Sending request method_string='GET', uri='http://bbb.s3.amazonaws.com/?prefix=test2', headers={'Authorization': 'AWS 05236:95DD7SQHMJ5WAVVnjJsUO9mA1Rs=', 'x-amz-date': 'Fri, 01 Jul 2016 06:44:35 +0000'},
body=(0 bytes)
DEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response:
{'data': '<?xml version="1.0" encoding="UTF-8"?><ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>standalone</Name><Prefix>test2</Prefix><Marker></Marker><NextMarker>bbb/test2/4/</NextMarke
r><MaxKeys>1000</MaxKeys><Delimiter>/</Delimiter><IsTruncated>false</IsTruncated><CommonPrefixes><Prefix>test2/1/</Prefix></CommonPrefixes><CommonPrefixes><Prefix>test2/2/</Prefix></CommonPrefixes><CommonPrefixe
s><Prefix>test2/3/</Prefix></CommonPrefixes><CommonPrefixes><Prefix>test2/4/</Prefix></CommonPrefixes></ListBucketResult>',
 'headers': {'connection': 'keep-alive',
             'content-length': '533',
             'content-type': 'application/xml',
             'date': 'Fri, 01 Jul 2016 06:44:35 GMT',
             'server': 'LeoFS'},
 'reason': 'OK',
 'status': 200}
DEBUG: Applying --exclude/--include
INFO: Found 9 local files, 0 remote files
INFO: Verifying attributes...
DEBUG: Comparing filelists (direction: local -> remote)
DEBUG: CHECK: test2/1/02
DEBUG: CHECK: test2/1/03
DEBUG: DST COPY dst: test2/1/02 -> test2/1/03
DEBUG: CHECK: test2/1/04
DEBUG: DST COPY dst: test2/1/02 -> test2/1/04
DEBUG: CHECK: test2/2/02
DEBUG: DST COPY dst: test2/1/02 -> test2/2/02
DEBUG: CHECK: test2/2/03
DEBUG: DST COPY dst: test2/1/02 -> test2/2/03
DEBUG: CHECK: test2/2/04
DEBUG: DST COPY dst: test2/1/02 -> test2/2/04
DEBUG: CHECK: test2/4/02
DEBUG: DST COPY dst: test2/1/02 -> test2/4/02
DEBUG: CHECK: test2/4/03
DEBUG: DST COPY dst: test2/1/02 -> test2/4/03
DEBUG: CHECK: test2/4/04
DEBUG: DST COPY dst: test2/1/02 -> test2/4/04
INFO: Summary: 1 local files to upload, 8 files to remote copy, 0 remote files to delete
DEBUG: attr_header: {'x-amz-meta-s3cmd-attrs': 'uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902ac237024bdd0c176cb93063dc4/ctime:1467354663'}
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: String 'test2/1/02' encoded to 'test2/1/02'
DEBUG: CreateRequest: resource[uri]=/test2/1/02
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/02'
DEBUG: Unicodising 'test2/1/02' using UTF-8
upload: 'test2/1/02' -> 's3://bbb/test2/1/02'  [1 of 1]
DEBUG: DeUnicodising u'test2/1/02' using UTF-8
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/02'
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/1/02
 12 of 12   100% in    0s     5.66 kB/sDEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response: {'status': 200, 'headers': {'date': 'Fri, 01 Jul 2016 06:44:35 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-length': '0', 'server': 'LeoFS'}, 'reason'
: 'OK', 'data': '', 'size': 12L}
 12 of 12   100% in    0s  1343.33 B/s  done
DEBUG: MD5 sums: computed=6f5902ac237024bdd0c176cb93063dc4, received="6f5902ac237024bdd0c176cb93063dc4"
DEBUG: Remote Copying from test2/1/02 to test2/1/03
DEBUG: String 'test2/1/02' encoded to 'test2/1/02'
DEBUG: CreateRequest: resource[uri]=/test2/1/02?acl
DEBUG: Using signature v2
DEBUG: SignHeaders: 'GET\n\n\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\n/bbb/test2/1/02?acl'
DEBUG: Processing request, please wait...
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/1/02?acl
DEBUG: Sending request method_string='GET', uri='http://bbb.s3.amazonaws.com/test2/1/02?acl', headers={'Authorization': 'AWS 05236:FLX87zrycCcW7wvbuGTKpJ4hXic=', 'x-amz-date': 'Fri, 01 Jul 2016 06:44:35 +0000'},
 body=(0 bytes)
DEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response:
{'data': 'hello world\n',
 'headers': {'connection': 'keep-alive',
             'content-length': '12',
             'content-type': 'application/octet-stream',
             'date': 'Fri, 01 Jul 2016 06:44:35 GMT',
             'etag': '"6f5902ac237024bdd0c176cb93063dc4"',
             'last-modified': 'Fri, 01 Jul 2016 06:44:35 GMT',
             'server': 'LeoFS',
             'x-from-cache': 'True/via memory'},
 'reason': 'OK',
 'status': 200}
ERROR: Error parsing xml: syntax error: line 1, column 0
ERROR: hello world

WARNING: Unable to remote copy files 's3://bbb/test2/1/02' -> 's3://bbb/test2/1/03'
DEBUG: Remote Copying from test2/1/02 to test2/1/04
DEBUG: String 'test2/1/02' encoded to 'test2/1/02'
DEBUG: CreateRequest: resource[uri]=/test2/1/02?acl
DEBUG: Using signature v2
DEBUG: SignHeaders: 'GET\n\n\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\n/bbb/test2/1/02?acl'
DEBUG: Processing request, please wait...
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/1/02?acl
DEBUG: Sending request method_string='GET', uri='http://bbb.s3.amazonaws.com/test2/1/02?acl', headers={'Authorization': 'AWS 05236:FLX87zrycCcW7wvbuGTKpJ4hXic=', 'x-amz-date': 'Fri, 01 Jul 2016 06:44:35 +0000'},
 body=(0 bytes)
DEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response:
{'data': 'hello world\n',
 'headers': {'connection': 'keep-alive',
             'content-length': '12',
             'content-type': 'application/octet-stream',
             'date': 'Fri, 01 Jul 2016 06:44:35 GMT',
             'etag': '"6f5902ac237024bdd0c176cb93063dc4"',
             'last-modified': 'Fri, 01 Jul 2016 06:44:35 GMT',
             'server': 'LeoFS',
             'x-from-cache': 'True/via memory'},
 'reason': 'OK',
 'status': 200}
ERROR: Error parsing xml: syntax error: line 1, column 0
ERROR: hello world

WARNING: Unable to remote copy files 's3://bbb/test2/1/02' -> 's3://bbb/test2/1/04'

~~ snip ~

DEBUG: Process files that was not remote copied
DEBUG: attr_header: {'x-amz-meta-s3cmd-attrs': 'uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902ac237024bdd0c176cb93063dc4/ctime:1467354663'}
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: String 'test2/1/03' encoded to 'test2/1/03'
DEBUG: CreateRequest: resource[uri]=/test2/1/03
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/03'
DEBUG: Unicodising 'test2/1/03' using UTF-8
upload: 'test2/1/03' -> 's3://bbb/test2/1/03'  [2 of 9]
DEBUG: DeUnicodising u'test2/1/03' using UTF-8
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/03'
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/1/03
 12 of 12   100% in    0s    12.04 kB/sDEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response: {'status': 200, 'headers': {'date': 'Fri, 01 Jul 2016 06:44:35 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-length': '0', 'server': 'LeoFS'}, 'reason'
: 'OK', 'data': '', 'size': 12L}
 12 of 12   100% in    0s  1589.61 B/s  done
DEBUG: MD5 sums: computed=6f5902ac237024bdd0c176cb93063dc4, received="6f5902ac237024bdd0c176cb93063dc4"
DEBUG: attr_header: {'x-amz-meta-s3cmd-attrs': 'uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902ac237024bdd0c176cb93063dc4/ctime:1467354663'}
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: String 'test2/1/04' encoded to 'test2/1/04'
DEBUG: CreateRequest: resource[uri]=/test2/1/04
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/04'
DEBUG: Unicodising 'test2/1/04' using UTF-8
upload: 'test2/1/04' -> 's3://bbb/test2/1/04'  [3 of 9]
DEBUG: DeUnicodising u'test2/1/04' using UTF-8
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354663/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354663\nx-amz-storage-class:STANDARD\n/bbb/test2/1/04'
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/1/04
 12 of 12   100% in    0s     4.58 kB/sDEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response: {'status': 200, 'headers': {'date': 'Fri, 01 Jul 2016 06:44:35 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-length': '0', 'server': 'LeoFS'}, 'reason'
: 'OK', 'data': '', 'size': 12L}
 12 of 12   100% in    0s  1802.34 B/s  done
DEBUG: MD5 sums: computed=6f5902ac237024bdd0c176cb93063dc4, received="6f5902ac237024bdd0c176cb93063dc4"
DEBUG: attr_header: {'x-amz-meta-s3cmd-attrs': 'uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354665/atime:1467354690/md5:6f5902ac237024bdd0c176cb93063dc4/ctime:1467354665'}
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: DeUnicodising u'test2/2/02' using UTF-8
DEBUG: String 'test2/2/02' encoded to 'test2/2/02'

~~ snip ~~

DEBUG: attr_header: {'x-amz-meta-s3cmd-attrs': 'uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354667/atime:1467354690/md5:6f5902ac237024bdd0c176cb93063dc4/ctime:1467354667'}
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: String 'test2/4/04' encoded to 'test2/4/04'
DEBUG: CreateRequest: resource[uri]=/test2/4/04
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354667/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354667\nx-amz-storage-class:STANDARD\n/bbb/test2/4/04'
DEBUG: Unicodising 'test2/4/04' using UTF-8
upload: 'test2/4/04' -> 's3://bbb/test2/4/04'  [9 of 9]
DEBUG: DeUnicodising u'test2/4/04' using UTF-8
DEBUG: Using signature v2
DEBUG: SignHeaders: 'PUT\n\ntext/plain\n\nx-amz-date:Fri, 01 Jul 2016 06:44:35 +0000\nx-amz-meta-s3cmd-attrs:uid:1000/gname:vagrant/uname:vagrant/gid:1000/mode:33204/mtime:1467354667/atime:1467354690/md5:6f5902a
c237024bdd0c176cb93063dc4/ctime:1467354667\nx-amz-storage-class:STANDARD\n/bbb/test2/4/04'
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: ConnMan.get(): creating new connection: proxy://localhost:8080
DEBUG: proxied HTTPConnection(localhost, 8080)
DEBUG: get_hostname(bbb): bbb.s3.amazonaws.com
DEBUG: format_uri(): http://bbb.s3.amazonaws.com/test2/4/04
 12 of 12   100% in    0s     8.65 kB/sDEBUG: ConnMan.put(): closing proxy connection (keep-alive not yet supported)
DEBUG: Response: {'status': 200, 'headers': {'date': 'Fri, 01 Jul 2016 06:44:35 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-length': '0', 'server': 'LeoFS'}, 'reason'
: 'OK', 'data': '', 'size': 12L}
 12 of 12   100% in    0s  1708.19 B/s  done
DEBUG: MD5 sums: computed=6f5902ac237024bdd0c176cb93063dc4, received="6f5902ac237024bdd0c176cb93063dc4"
Done. Uploaded 108 bytes in 1.0 seconds, 108.00 B/s.

@mocchira
Copy link
Member

mocchira commented Jul 1, 2016

Turned out some facts with the output pasted above.

  1. Fix [s3] LeoFS does not comply with S3 Spec of GET Bucket (List Object) #431 ( handle the delimiter parameter properly when listing objects )

    LeoFS should respond all objects even if those are stored under nested directories when delimiter is not specified

  2. Handle COPY requests properly
    As s3cmd use the COPY request if it's possible to avoid copying from local files to remote files

  3. Handle Get Object ACL properly
    As s3cmd use the Get Object ACL before sending the copy request

@windkit
Copy link
Contributor

windkit commented Jul 4, 2016

@mocchira for the sync, I have recalled that we fix if with #367
which is a special case for #431, (for a path like like structure, only "/" is used as delimiter)
Do you think that would be enough? we can back port it from 1.4

@mocchira
Copy link
Member

mocchira commented Jul 5, 2016

@windkit thanks for reminding me that ( I completely forgot it ) .
We are now considering whether that fix should be included within 1.3.

@mocchira
Copy link
Member

mocchira commented Jul 5, 2016

aws output with --debug

vagrant@vagrant-ubuntu-trusty-64:~/dev/s3cmd$ aws --debug --endpoint-url http://localhost:8080 s3 sync te
st2 s3://bbb --delete
2016-07-05 03:29:32,349 - MainThread - awscli.clidriver - DEBUG - CLI version: aws-cli/1.10.44 Python/2.7.6 Linux/3.13.0-91-generic botocore/1.4.34
2016-07-05 03:29:32,349 - MainThread - awscli.clidriver - DEBUG - Arguments entered to CLI: ['--debug', '--endpoint-url', 'http://localhost:8080', 's3', 'sync', 'test2', 's3://bbb', '--delete']
2016-07-05 03:29:32,349 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function add_scalar_parsers at 0x7f174c7e0500>
2016-07-05 03:29:32,350 - MainThread - botocore.hooks - DEBUG - Event session-initialized: calling handler <function inject_assume_role_provider_cache at 0x7f174cbbc0c8>
2016-07-05 03:29:32,350 - MainThread - botocore.credentials - DEBUG - Skipping environment variable credential check because profile name was explicitly set.
2016-07-05 03:29:32,350 - MainThread - botocore.hooks - DEBUG - Event building-command-table.s3: calling handler <function add_waiters at 0x7f174c7e79b0>
2016-07-05 03:29:32,351 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.s3.anonymous: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,351 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sync: calling handler <function register_sync_strategies at 0x7f174c85ad70>
2016-07-05 03:29:32,351 - MainThread - botocore.hooks - DEBUG - Event building-command-table.sync: calling handler <function add_waiters at 0x7f174c7e79b0>
2016-07-05 03:29:32,352 - MainThread - botocore.hooks - DEBUG - Event building-arg-table.sync: calling handler <bound method SizeOnlySync.add_sync_argument of <awscli.customizations.s3.syncstrategy.sizeonly.Size
OnlySync object at 0x7f174c4de6d0>>
2016-07-05 03:29:32,352 - MainThread - botocore.hooks - DEBUG - Event building-arg-table.sync: calling handler <bound method ExactTimestampsSync.add_sync_argument of <awscli.customizations.s3.syncstrategy.exactt
imestamps.ExactTimestampsSync object at 0x7f174c4de190>>
2016-07-05 03:29:32,352 - MainThread - botocore.hooks - DEBUG - Event building-arg-table.sync: calling handler <bound method DeleteSync.add_sync_argument of <awscli.customizations.s3.syncstrategy.delete.DeleteSy
nc object at 0x7f174c4de410>>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse-c-key: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.grants: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.content-language: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.page-size: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.anonymous: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse-c-copy-source-key: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.exact-timestamps: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,355 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.paths: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.anonymous: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.size-only: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.source-region: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.content-encoding: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.content-disposition: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.cache-control: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.metadata: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.dryrun: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,356 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse-c: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.expires: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse-c-copy-source: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.ignore-glacier-warnings: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.content-type: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,357 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.metadata-directive: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.only-show-errors: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.force-glacier-transfer: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.quiet: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,358 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.acl: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.storage-class: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.sse-kms-key-id: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.website-redirect: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.follow-symlinks: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event load-cli-arg.custom.sync.delete: calling handler <function uri_param at 0x7f174cc629b0>
2016-07-05 03:29:32,359 - MainThread - botocore.hooks - DEBUG - Event process-cli-arg.custom.sync: calling handler <awscli.argprocess.ParamShorthandParser object at 0x7f174c7e4dd0>
2016-07-05 03:29:32,359 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: env
2016-07-05 03:29:32,359 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: assume-role
2016-07-05 03:29:32,359 - MainThread - botocore.credentials - DEBUG - Looking for credentials via: shared-credentials-file
2016-07-05 03:29:32,360 - MainThread - botocore.credentials - INFO - Found credentials in shared credentials file: ~/.aws/credentials
2016-07-05 03:29:32,360 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/lib/python2.7/dist-packages/botocore/data/endpoints.json
2016-07-05 03:29:32,368 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/lib/python2.7/dist-packages/botocore/data/s3/2006-03-01/service-2.json
2016-07-05 03:29:32,396 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: s3
2016-07-05 03:29:32,398 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7f174d06b8c0>
2016-07-05 03:29:32,398 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7f174d06b050>
2016-07-05 03:29:32,401 - MainThread - botocore.client - DEBUG - The s3 config key is not a dictionary type, ignoring its value of: None
2016-07-05 03:29:32,402 - MainThread - botocore.endpoint - DEBUG - Setting s3 timeout as (60, 60)
2016-07-05 03:29:32,410 - MainThread - botocore.client - DEBUG - Registering retry handlers for service: s3
2016-07-05 03:29:32,416 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7f174d06b8c0>
2016-07-05 03:29:32,416 - MainThread - botocore.hooks - DEBUG - Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7f174d06b050>
2016-07-05 03:29:32,419 - MainThread - botocore.client - DEBUG - The s3 config key is not a dictionary type, ignoring its value of: None
2016-07-05 03:29:32,420 - MainThread - botocore.endpoint - DEBUG - Setting s3 timeout as (60, 60)
2016-07-05 03:29:32,421 - MainThread - awscli.customizations.s3.s3handler - DEBUG - Using a multipart threshold of 8388608 and a part size of 8388608
2016-07-05 03:29:32,421 - MainThread - awscli.customizations.s3.executor - DEBUG - Using max queue size for s3 tasks of: 1000
2016-07-05 03:29:32,421 - MainThread - awscli.customizations.s3.s3handler - DEBUG - Using a multipart threshold of 8388608 and a part size of 8388608
2016-07-05 03:29:32,421 - MainThread - awscli.customizations.s3.executor - DEBUG - Using max queue size for s3 tasks of: 2
2016-07-05 03:29:32,421 - MainThread - botocore.hooks - DEBUG - Event choosing-s3-sync-strategy: calling handler <bound method SizeOnlySync.use_sync_strategy of <awscli.customizations.s3.syncstrategy.sizeonly.Si
zeOnlySync object at 0x7f174c4de6d0>>
2016-07-05 03:29:32,422 - MainThread - botocore.hooks - DEBUG - Event choosing-s3-sync-strategy: calling handler <bound method ExactTimestampsSync.use_sync_strategy of <awscli.customizations.s3.syncstrategy.exac
ttimestamps.ExactTimestampsSync object at 0x7f174c4de190>>
2016-07-05 03:29:32,422 - MainThread - botocore.hooks - DEBUG - Event choosing-s3-sync-strategy: calling handler <bound method DeleteSync.use_sync_strategy of <awscli.customizations.s3.syncstrategy.delete.Delete
Sync object at 0x7f174c4de410>>
2016-07-05 03:29:32,422 - MainThread - awscli.customizations.s3.executor - DEBUG - Using a threadpool size of: 10
2016-07-05 03:29:32,429 - MainThread - botocore.loaders - DEBUG - Loading JSON file: /usr/local/lib/python2.7/dist-packages/botocore/data/s3/2006-03-01/paginators-1.json
2016-07-05 03:29:32,430 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.ListObjects: calling handler <function set_list_objects_encoding_type_url at 0x7f174d009230>
2016-07-05 03:29:32,430 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.ListObjects: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,430 - MainThread - botocore.hooks - DEBUG - Event before-parameter-build.s3.ListObjects: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedire
ctor object at 0x7f174c391e90>>
2016-07-05 03:29:32,431 - MainThread - botocore.hooks - DEBUG - Event before-call.s3.ListObjects: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,431 - MainThread - botocore.hooks - DEBUG - Event before-call.s3.ListObjects: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at
0x7f174c391e90>>
2016-07-05 03:29:32,431 - MainThread - botocore.endpoint - DEBUG - Making request for OperationModel(name=ListObjects) (verify_ssl=True) with params: {'body': '', 'url': u'http://localhost:8080/bbb?prefix=&encod
ing-type=url', 'headers': {'User-Agent': 'aws-cli/1.10.44 Python/2.7.6 Linux/3.13.0-91-generic botocore/1.4.34'}, 'context': {'encoding_type_auto_set': True, 'client_region': None, 'signing': {'bucket': u'bbb'},
 'has_streaming_input': False, 'client_config': <botocore.config.Config object at 0x7f174c391710>}, 'query_string': {u'prefix': u'', u'encoding-type': 'url'}, 'url_path': u'/bbb', 'method': u'GET'}
2016-07-05 03:29:32,432 - MainThread - botocore.hooks - DEBUG - Event request-created.s3.ListObjects: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f174c3916
10>>
2016-07-05 03:29:32,432 - MainThread - botocore.auth - DEBUG - Calculating signature using hmacv1 auth.
2016-07-05 03:29:32,432 - MainThread - botocore.auth - DEBUG - HTTP request method: GET
2016-07-05 03:29:32,432 - MainThread - botocore.auth - DEBUG - StringToSign:
GET


Tue, 05 Jul 2016 03:29:32 GMT
/bbb
2016-07-05 03:29:32,436 - MainThread - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [GET]>
2016-07-05 03:29:32,437 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTP connection (1): localhost
2016-07-05 03:29:32,445 - MainThread - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "GET /bbb?prefix=&encoding-type=url HTTP/1.1" 200 746
2016-07-05 03:29:32,447 - MainThread - botocore.parsers - DEBUG - Response headers: {'date': 'Tue, 05 Jul 2016 03:29:32 GMT', 'connection': 'keep-alive', 'content-type': 'application/xml', 'content-length': '746
', 'server': 'LeoFS'}
2016-07-05 03:29:32,447 - MainThread - botocore.parsers - DEBUG - Response body:
<?xml version="1.0" encoding="UTF-8"?><ListBucketResult xmlns="http://s3.amazonaws.com/doc/2006-03-01/"><Name>standalone</Name><Prefix></Prefix><Marker></Marker><NextMarker>bbb/test</NextMarker><MaxKeys>1000</Ma
xKeys><Delimiter>/</Delimiter><IsTruncated>false</IsTruncated><CommonPrefixes><Prefix>1/</Prefix></CommonPrefixes><CommonPrefixes><Prefix>2/</Prefix></CommonPrefixes><CommonPrefixes><Prefix>3/</Prefix></CommonPr
efixes><CommonPrefixes><Prefix>4/</Prefix></CommonPrefixes><Contents><Key>test</Key><LastModified>2016-07-05T03:14:57.000Z</LastModified><ETag>ea703e7aa1efda0064eaa507d9e8ab7e</ETag><Size>4</Size><StorageClass>S
TANDARD</StorageClass><Owner><ID>leofs</ID><DisplayName>leofs</DisplayName></Owner></Contents></ListBucketResult>
2016-07-05 03:29:32,448 - MainThread - botocore.hooks - DEBUG - Event needs-retry.s3.ListObjects: calling handler <botocore.retryhandler.RetryHandler object at 0x7f174c12ae10>
2016-07-05 03:29:32,449 - MainThread - botocore.retryhandler - DEBUG - No retry needed.
2016-07-05 03:29:32,450 - MainThread - botocore.hooks - DEBUG - Event needs-retry.s3.ListObjects: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object
 at 0x7f174c391e90>>
2016-07-05 03:29:32,450 - MainThread - botocore.hooks - DEBUG - Event after-call.s3.ListObjects: calling handler <function decode_list_object at 0x7f174d0092a8>
2016-07-05 03:29:32,450 - MainThread - botocore.hooks - DEBUG - Event after-call.s3.ListObjects: calling handler <function enhance_error_msg at 0x7f174c7e01b8>
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/1/02 -> bbb/1/02, file does not exist at destination
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f174c046c10>
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/1/03 -> bbb/1/03, file does not exist at destination
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729fc5710>
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/1/04 -> bbb/1/04, file does not exist at destination
2016-07-05 03:29:32,451 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729fc5690>
2016-07-05 03:29:32,452 - Thread-5 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f174c046c10>
2016-07-05 03:29:32,453 - Thread-6 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729fc5710>
2016-07-05 03:29:32,457 - Thread-7 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729fc5690>
2016-07-05 03:29:32,461 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/2/02 -> bbb/2/02, file does not exist at destination
2016-07-05 03:29:32,462 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff73d0>
2016-07-05 03:29:32,462 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/2/03 -> bbb/2/03, file does not exist at destination
2016-07-05 03:29:32,462 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff7410>
2016-07-05 03:29:32,462 - Thread-8 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff73d0>
2016-07-05 03:29:32,464 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/2/04 -> bbb/2/04, file does not exist at destination
2016-07-05 03:29:32,464 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff7d90>
2016-07-05 03:29:32,464 - Thread-9 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff7410>
2016-07-05 03:29:32,466 - Thread-10 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729ff7d90>
2016-07-05 03:29:32,469 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/4/02 -> bbb/4/02, file does not exist at destination
2016-07-05 03:29:32,469 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d81090>
2016-07-05 03:29:32,470 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/4/03 -> bbb/4/03, file does not exist at destination
2016-07-05 03:29:32,471 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d75dd0>
2016-07-05 03:29:32,471 - Thread-11 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d81090>
2016-07-05 03:29:32,476 - Thread-10 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,471 - MainThread - awscli.customizations.s3.syncstrategy.base - DEBUG - syncing: /home/vagrant/dev/s3cmd/test2/4/04 -> bbb/4/04, file does not exist at destination
2016-07-05 03:29:32,476 - Thread-12 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d75dd0>
2016-07-05 03:29:32,478 - Thread-9 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,481 - Thread-9 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,481 - Thread-9 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,480 - Thread-11 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,480 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d81410>
2016-07-05 03:29:32,482 - Thread-11 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,482 - MainThread - awscli.customizations.s3.syncstrategy.delete - DEBUG - syncing: (None) -> bbb/test (remove), file does not exist at source (/home/vagrant/dev/s3cmd/test2/test) and delete m
ode enabled
2016-07-05 03:29:32,482 - Thread-11 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,482 - Thread-11 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,482 - Thread-11 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirecto
r object at 0x7f174c391e90>>
2016-07-05 03:29:32,483 - Thread-11 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,483 - Thread-11 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,484 - Thread-11 - botocore.handlers - DEBUG - Adding expect 100 continue header to request.
2016-07-05 03:29:32,482 - Thread-13 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d81410>
2016-07-05 03:29:32,484 - MainThread - awscli.customizations.s3.executor - DEBUG - Submitting task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d816d0>
2016-07-05 03:29:32,481 - Thread-12 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,479 - Thread-8 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,480 - Thread-7 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,484 - Thread-11 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7
f174c391e90>>
2016-07-05 03:29:32,489 - Thread-11 - botocore.endpoint - DEBUG - Making request for OperationModel(name=PutObject) (verify_ssl=True) with params: {'body': <open file u'/home/vagrant/dev/s3cmd/test2/4/02', mode
'rb' at 0x7f174c3906f0>, 'url': u'http://localhost:8080/bbb/4/02', 'headers': {'Content-MD5': u'b1kCrCNwJL3QwXbLkwY9xA==', 'Expect': '100-continue', 'User-Agent': 'aws-cli/1.10.44 Python/2.7.6 Linux/3.13.0-91-ge
neric botocore/1.4.34'}, 'context': {'client_region': None, 'signing': {'bucket': u'bbb'}, 'has_streaming_input': True, 'client_config': <botocore.config.Config object at 0x7f174c391710>}, 'query_string': {}, 'u
rl_path': u'/bbb/4/02', 'method': u'PUT'}
2016-07-05 03:29:32,491 - Thread-11 - botocore.hooks - DEBUG - Event request-created.s3.PutObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f174c391610>
>
2016-07-05 03:29:32,493 - Thread-11 - botocore.auth - DEBUG - Calculating signature using hmacv1 auth.
2016-07-05 03:29:32,481 - Thread-10 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,497 - Thread-10 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,497 - Thread-10 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,497 - Thread-10 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirecto
r object at 0x7f174c391e90>>
2016-07-05 03:29:32,497 - Thread-10 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,498 - Thread-10 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,499 - Thread-10 - botocore.handlers - DEBUG - Adding expect 100 continue header to request.
2016-07-05 03:29:32,499 - Thread-10 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7
f174c391e90>>
2016-07-05 03:29:32,499 - Thread-10 - botocore.endpoint - DEBUG - Making request for OperationModel(name=PutObject) (verify_ssl=True) with params: {'body': <open file u'/home/vagrant/dev/s3cmd/test2/2/04', mode
'rb' at 0x7f174c390c90>, 'url': u'http://localhost:8080/bbb/2/04', 'headers': {'Content-MD5': u'b1kCrCNwJL3QwXbLkwY9xA==', 'Expect': '100-continue', 'User-Agent': 'aws-cli/1.10.44 Python/2.7.6 Linux/3.13.0-91-ge
neric botocore/1.4.34'}, 'context': {'client_region': None, 'signing': {'bucket': u'bbb'}, 'has_streaming_input': True, 'client_config': <botocore.config.Config object at 0x7f174c391710>}, 'query_string': {}, 'u
rl_path': u'/bbb/2/04', 'method': u'PUT'}
2016-07-05 03:29:32,507 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,493 - Thread-11 - botocore.auth - DEBUG - HTTP request method: PUT
2016-07-05 03:29:32,488 - Thread-12 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,509 - Thread-14 - awscli.customizations.s3.executor - DEBUG - Worker thread invoking task: <awscli.customizations.s3.tasks.BasicTask object at 0x7f1729d816d0>
2016-07-05 03:29:32,510 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,488 - Thread-7 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,488 - Thread-13 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_ascii_metadata at 0x7f174d008cf8>
2016-07-05 03:29:32,488 - Thread-8 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,513 - Thread-13 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function sse_md5 at 0x7f174d008410>
2016-07-05 03:29:32,513 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,509 - Thread-10 - botocore.hooks - DEBUG - Event request-created.s3.PutObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f174c391610>
>
2016-07-05 03:29:32,510 - Thread-11 - botocore.auth - DEBUG - StringToSign:
PUT
b1kCrCNwJL3QwXbLkwY9xA==

Tue, 05 Jul 2016 03:29:32 GMT
/bbb/4/02
2016-07-05 03:29:32,510 - Thread-12 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,516 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,516 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,511 - Thread-14 - botocore.hooks - DEBUG - Event before-parameter-build.s3.DeleteObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,517 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,511 - Thread-7 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,484 - Thread-9 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,512 - Thread-8 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,514 - Thread-10 - botocore.auth - DEBUG - Calculating signature using hmacv1 auth.
2016-07-05 03:29:32,518 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,520 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,514 - Thread-13 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function convert_body_to_file_like_object at 0x7f174d009320>
2016-07-05 03:29:32,515 - Thread-11 - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [PUT]>
2016-07-05 03:29:32,517 - Thread-12 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,518 - Thread-14 - botocore.hooks - DEBUG - Event before-parameter-build.s3.DeleteObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedire
ctor object at 0x7f174c391e90>>
2016-07-05 03:29:32,518 - Thread-7 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,522 - Thread-11 - botocore.awsrequest - DEBUG - Waiting for 100 Continue response.
2016-07-05 03:29:32,519 - Thread-8 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,520 - Thread-10 - botocore.auth - DEBUG - HTTP request method: PUT
2016-07-05 03:29:32,521 - Thread-13 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <function validate_bucket_name at 0x7f174d008398>
2016-07-05 03:29:32,523 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,522 - Thread-12 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirecto
r object at 0x7f174c391e90>>
2016-07-05 03:29:32,519 - Thread-9 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector
 object at 0x7f174c391e90>>
2016-07-05 03:29:32,523 - Thread-7 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector
 object at 0x7f174c391e90>>
2016-07-05 03:29:32,525 - Thread-8 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector
 object at 0x7f174c391e90>>
2016-07-05 03:29:32,527 - Thread-10 - botocore.auth - DEBUG - StringToSign:
PUT
b1kCrCNwJL3QwXbLkwY9xA==

Tue, 05 Jul 2016 03:29:32 GMT
/bbb/2/04
2016-07-05 03:29:32,529 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for worker thread (priority: 11)
2016-07-05 03:29:32,527 - Thread-13 - botocore.hooks - DEBUG - Event before-parameter-build.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirecto
r object at 0x7f174c391e90>>
2016-07-05 03:29:32,529 - Thread-7 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,527 - Thread-12 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,533 - Thread-12 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,534 - Thread-12 - botocore.handlers - DEBUG - Adding expect 100 continue header to request.
2016-07-05 03:29:32,534 - Thread-12 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7
f174c391e90>>
2016-07-05 03:29:32,535 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-5, started daemon 139738019387136)>
2016-07-05 03:29:32,529 - Thread-9 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,534 - Thread-7 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,538 - Thread-7 - botocore.handlers - DEBUG - Adding expect 100 continue header to request.
2016-07-05 03:29:32,530 - Thread-8 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function conditionally_calculate_md5 at 0x7f174d008320>
2016-07-05 03:29:32,539 - Thread-8 - botocore.hooks - DEBUG - Event before-call.s3.PutObject: calling handler <function add_expect_header at 0x7f174d0087d0>
2016-07-05 03:29:32,535 - Thread-11 - botocore.awsrequest - DEBUG - 100 Continue response seen, now sending request body.
2016-07-05 03:29:32,531 - Thread-10 - botocore.endpoint - DEBUG - Sending http request: <PreparedRequest [PUT]>
2016-07-05 03:29:32,547 - Thread-11 - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "PUT /bbb/4/02 HTTP/1.1" 200 0
2016-07-05 03:29:32,548 - Thread-11 - botocore.parsers - DEBUG - Response headers: {'date': 'Tue, 05 Jul 2016 03:29:32 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-len
gth': '0', 'server': 'LeoFS'}
2016-07-05 03:29:32,548 - Thread-11 - botocore.parsers - DEBUG - Response body:

~~ snip ~~

2016-07-05 03:29:32,648 - Thread-13 - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "PUT /bbb/4/04 HTTP/1.1" 200 0
2016-07-05 03:29:32,650 - Thread-6 - botocore.awsrequest - DEBUG - Waiting for 100 Continue response.
2016-07-05 03:29:32,653 - Thread-14 - botocore.hooks - DEBUG - Event after-call.s3.DeleteObject: calling handler <function enhance_error_msg at 0x7f174c7e01b8>
2016-07-05 03:29:32,653 - Thread-5 - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "PUT /bbb/1/02 HTTP/1.1" 200 0
2016-07-05 03:29:32,655 - Thread-1 - awscli.customizations.s3.executor - DEBUG - Received print task: PrintTask(message=u'delete: s3://bbb/test', error=False, total_parts=None, warning=None)
delete: s3://bbb/test
2016-07-05 03:29:32,656 - Thread-14 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in worker thread, shutting down worker thread.
2016-07-05 03:29:32,655 - Thread-13 - botocore.parsers - DEBUG - Response headers: {'date': 'Tue, 05 Jul 2016 03:29:32 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-len
gth': '0', 'server': 'LeoFS'}
2016-07-05 03:29:32,657 - Thread-13 - botocore.parsers - DEBUG - Response body:

2016-07-05 03:29:32,658 - Thread-13 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7f174c12ae10>
2016-07-05 03:29:32,658 - Thread-13 - botocore.retryhandler - DEBUG - No retry needed.
2016-07-05 03:29:32,658 - Thread-13 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at
 0x7f174c391e90>>
2016-07-05 03:29:32,658 - Thread-13 - botocore.hooks - DEBUG - Event after-call.s3.PutObject: calling handler <function enhance_error_msg at 0x7f174c7e01b8>
2016-07-05 03:29:32,659 - Thread-5 - botocore.parsers - DEBUG - Response headers: {'date': 'Tue, 05 Jul 2016 03:29:32 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-leng
th': '0', 'server': 'LeoFS'}
2016-07-05 03:29:32,660 - Thread-5 - botocore.parsers - DEBUG - Response body:

2016-07-05 03:29:32,661 - Thread-5 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7f174c12ae10>
2016-07-05 03:29:32,662 - Thread-5 - botocore.retryhandler - DEBUG - No retry needed.
2016-07-05 03:29:32,662 - Thread-5 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at
0x7f174c391e90>>
2016-07-05 03:29:32,662 - Thread-13 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in worker thread, shutting down worker thread.
2016-07-05 03:29:32,663 - Thread-5 - botocore.hooks - DEBUG - Event after-call.s3.PutObject: calling handler <function enhance_error_msg at 0x7f174c7e01b8>
2016-07-05 03:29:32,663 - Thread-1 - awscli.customizations.s3.executor - DEBUG - Received print task: PrintTask(message=u'upload: test2/4/04 to s3://bbb/4/04', error=False, total_parts=None, warning=None)
upload: test2/4/04 to s3://bbb/4/04
2016-07-05 03:29:32,664 - Thread-5 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in worker thread, shutting down worker thread.
2016-07-05 03:29:32,664 - Thread-1 - awscli.customizations.s3.executor - DEBUG - Received print task: PrintTask(message=u'upload: test2/1/02 to s3://bbb/1/02', error=False, total_parts=None, warning=None)
upload: test2/1/02 to s3://bbb/1/02
2016-07-05 03:29:32,660 - Thread-6 - botocore.awsrequest - DEBUG - 100 Continue response seen, now sending request body.
2016-07-05 03:29:32,671 - Thread-6 - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "PUT /bbb/1/03 HTTP/1.1" 200 0
2016-07-05 03:29:32,672 - Thread-6 - botocore.parsers - DEBUG - Response headers: {'date': 'Tue, 05 Jul 2016 03:29:32 GMT', 'connection': 'keep-alive', 'etag': '"6f5902ac237024bdd0c176cb93063dc4"', 'content-leng
th': '0', 'server': 'LeoFS'}
2016-07-05 03:29:32,672 - Thread-6 - botocore.parsers - DEBUG - Response body:

2016-07-05 03:29:32,672 - Thread-6 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7f174c12ae10>
2016-07-05 03:29:32,673 - Thread-6 - botocore.retryhandler - DEBUG - No retry needed.
2016-07-05 03:29:32,673 - Thread-6 - botocore.hooks - DEBUG - Event needs-retry.s3.PutObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at
0x7f174c391e90>>
2016-07-05 03:29:32,673 - Thread-6 - botocore.hooks - DEBUG - Event after-call.s3.PutObject: calling handler <function enhance_error_msg at 0x7f174c7e01b8>
2016-07-05 03:29:32,673 - Thread-6 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in worker thread, shutting down worker thread.
2016-07-05 03:29:32,677 - Thread-1 - awscli.customizations.s3.executor - DEBUG - Received print task: PrintTask(message=u'upload: test2/1/03 to s3://bbb/1/03', error=False, total_parts=None, warning=None)
upload: test2/1/03 to s3://bbb/1/03
2016-07-05 03:29:32,703 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-5, stopped daemon 139738019387136)>
2016-07-05 03:29:32,703 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-6, stopped daemon 139738010994432)>
2016-07-05 03:29:32,703 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-6, stopped daemon 139738010994432)>
2016-07-05 03:29:32,703 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-7, stopped daemon 139738002601728)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-7, stopped daemon 139738002601728)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-8, stopped daemon 139737994209024)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-8, stopped daemon 139737994209024)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-9, stopped daemon 139737985816320)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-9, stopped daemon 139737985816320)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-10, stopped daemon 139737977423616)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-10, stopped daemon 139737977423616)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-11, stopped daemon 139737499170560)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-11, stopped daemon 139737499170560)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-12, stopped daemon 139737490777856)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-12, stopped daemon 139737490777856)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-13, stopped daemon 139737482385152)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-13, stopped daemon 139737482385152)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for thread to shutdown: <Worker(Thread-14, stopped daemon 139737473992448)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Thread has been shutdown: <Worker(Thread-14, stopped daemon 139737473992448)>
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for result thread.
2016-07-05 03:29:32,704 - MainThread - awscli.customizations.s3.executor - DEBUG - Queueing end sentinel for IO thread.
2016-07-05 03:29:32,705 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for result thread to shutdown.
2016-07-05 03:29:32,705 - Thread-2 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in IO thread, shutting down.
2016-07-05 03:29:32,704 - Thread-1 - awscli.customizations.s3.executor - DEBUG - Shutdown request received in print thread, shutting down print thread.
2016-07-05 03:29:32,707 - MainThread - awscli.customizations.s3.executor - DEBUG - Waiting for IO thread to shutdown.
2016-07-05 03:29:32,707 - MainThread - awscli.customizations.s3.executor - DEBUG - All threads have been shutdown.

@mocchira
Copy link
Member

mocchira commented Jul 5, 2016

As it turned out that s3cmd are implemented with the almost same way as aws is,
there is no other requirements except #483 (comment) to fix this issue.
( aws may work by fixing only the delimiter ploblem )

@yosukehara yosukehara modified the milestones: 1.4.0-RC1, 1.3.0 Jul 12, 2016
@yosukehara yosukehara added v2.0 and removed v1.3 labels Sep 22, 2016
@windkit
Copy link
Contributor

windkit commented Jan 31, 2017

@yosukehara @mocchira With 1.3.2, the --delete is fixed

Data Set

$ ls -lR /tmp/test_set
/tmp/test_set:
total 12
drwxr-xr-x 2 wilson rit 4096 Jan 31 10:12 1
drwxr-xr-x 2 wilson rit 4096 Jan 31 10:12 2
drwxr-xr-x 2 wilson rit 4096 Jan 31 10:12 3

/tmp/test_set/1:
total 8
-rw-r--r-- 1 wilson rit 7 Jan 31 01:11 rand_file1
-rw-r--r-- 1 wilson rit 8 Jan 31 01:11 rand_file2

/tmp/test_set/2:
total 8
-rw-r--r-- 1 wilson rit 8 Jan 31 01:11 rand_file1
-rw-r--r-- 1 wilson rit 8 Jan 31 01:11 rand_file2

/tmp/test_set/3:
total 8
-rw-r--r-- 1 wilson rit 8 Jan 31 01:11 rand_file1
-rw-r--r-- 1 wilson rit 8 Jan 31 01:11 rand_file2

Initial Sync

$ ./s3cmd sync /tmp/test_set/ s3://test/
WARNING: Module python-magic is not available. Guessing MIME types based on file extensions.
upload: '/tmp/test_set/1/rand_file1' -> 's3://test/1/rand_file1'  [1 of 6]
 7 of 7   100% in    0s  1802.73 B/s  done
upload: '/tmp/test_set/1/rand_file2' -> 's3://test/1/rand_file2'  [2 of 6]
 8 of 8   100% in    0s   184.87 B/s  done
upload: '/tmp/test_set/2/rand_file1' -> 's3://test/2/rand_file1'  [3 of 6]
 8 of 8   100% in    0s   185.63 B/s  done
upload: '/tmp/test_set/2/rand_file2' -> 's3://test/2/rand_file2'  [4 of 6]
 8 of 8   100% in    0s   203.37 B/s  done
upload: '/tmp/test_set/3/rand_file1' -> 's3://test/3/rand_file1'  [5 of 6]
 8 of 8   100% in    0s   203.10 B/s  done
upload: '/tmp/test_set/3/rand_file2' -> 's3://test/3/rand_file2'  [6 of 6]
 8 of 8   100% in    0s   184.52 B/s  done
Done. Uploaded 47 bytes in 1.0 seconds, 47.00 B/s.

State Check

$ ./s3cmd ls --recursive s3://test/
2017-01-31 01:11         7   s3://test/1/rand_file1
2017-01-31 01:11         8   s3://test/1/rand_file2
2017-01-31 01:11         8   s3://test/2/rand_file1
2017-01-31 01:11         8   s3://test/2/rand_file2
2017-01-31 01:11         8   s3://test/3/rand_file1
2017-01-31 01:11         8   s3://test/3/rand_file2

Delete one folder

$ rm -rf /tmp/test_set/3

Sync Again with s3cmd

$ ./s3cmd sync --delete-removed /tmp/test_set/ s3://test/
delete: 's3://test/3/rand_file1'
delete: 's3://test/3/rand_file2'

Delete another folder

$ rm -rf /tmp/test_set/2/

Sync Again with aws

$ aws --endpoint-url http://192.168.100.35:8080/ s3 sync /tmp/test_set/ s3://test/ --delete
delete: s3://test/2/rand_file1
delete: s3://test/2/rand_file2

Final State

$ ./s3cmd ls --recursive s3://test/
2017-01-31 01:11         7   s3://test/1/rand_file1
2017-01-31 01:11         8   s3://test/1/rand_file2

@yosukehara yosukehara modified the milestones: 1.3.3, 2.0.0-RC1 Jan 31, 2017
@yosukehara yosukehara added v1.3 and removed v2.0 labels Jan 31, 2017
@mocchira
Copy link
Member

@windkit thanks. working on my dev boxes.
I will file an issue to add test covering those cases for s3cmd in leofs_client_test.

@jdrowe please reopen if somethings still go wrong in your env with >= 1.3.2.

@windkit
Copy link
Contributor

windkit commented Mar 13, 2017

sync.log.gz

Note that the s3cmd sync still has problem when some files have same content.

INFO: Summary: 1 local files to upload, 5 files to remote copy, 0 remote files to delete
...
DEBUG: Remote Copying from test/1/rand_file1 to test/1/rand_file2
...
DEBUG: Sending request method_string='GET', uri='/test-s3/test/1/rand_file1?acl', headers={'Authorization': 'AWS 05236:sA+ubzk2YKOBFMTNgmrTHwMO+v8=', 'x-amz-date': 'Mon, 13 Mar 2017 07:06:41 +0000'}, body=(0 bytes)
...
(File Content)

This is because s3cmd checks Object ACL before remote copy but LeoFS does not support it.
s3cmd would eventually fall back to upload the objects but the file content are displayed during the process

windkit added a commit to leo-project/leofs_client_tests that referenced this issue Mar 13, 2017
@windkit
Copy link
Contributor

windkit commented Mar 14, 2017

Object ACL Support, refer to #490

@mocchira
Copy link
Member

@windkit Thanks for reporting.

Now I can't test on my dev boxes because network between my ISP <-> github have gotten stuck while cloning leofs_client_tests, let me confirm what you described at the prev comment.

s3cmd would eventually fall back to upload the objects but the file content are displayed during the process

Could you elaborate that?
I'd expect the fall back works as expected aside from the performance degradation due the lack of Object ACL that causes copies(network transfer) between s3cmd and leofs happen instead of copies on leofs.

@windkit
Copy link
Contributor

windkit commented Mar 14, 2017

s3cmd sent a Get Object ACL request to LeoFS but LeoFS would mistakenly treat it as normal GET.
As a result, s3cmd would fail to parse the result (expect XML but binary is sent) and therefore print it as error log.

You can refer to the log file I attached in previous comment.

@mocchira
Copy link
Member

@windkit Got it.

Confirmed that
With s3cmd <= 1.5.2, works as expected.
With s3cmd 1.6.x, failed as you described (s3cmd has started using GET Object ACL in some cases

I will file as another issue like works with s3cmd 1.6.x.

@yosukehara yosukehara changed the title S3 Sync feature does not Sync directories properly S3-sync feature does not synchronize directories properly Apr 28, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants