Skip to content

Instantly share code, notes, and snippets.

@jessewiles
Created September 22, 2017 20:11
Show Gist options
  • Save jessewiles/79da07545a4dffae96c9d986f3bdb6ae to your computer and use it in GitHub Desktop.
Save jessewiles/79da07545a4dffae96c9d986f3bdb6ae to your computer and use it in GitHub Desktop.
Log supporting ACLs as cause of S3 upload error
[2017-02-31 16:48:37,026] [INFO] [MainProcess] [Main:init:144] Starting mongodb-consistent-backup version 1.1.0 (git commit: ggggggggggggggggggggg)\
[2017-02-31 16:48:37,026] [INFO] [MainProcess] [Main:init:145] Loaded config: {\"archive\": {\"method\": \"tar\", \"tar\": {\"compression\": \"gzip\"}, \"zbackup\": {\"binary\": \"/usr/bin/zbackup\", \"cache_mb\": 128, \"compression\": \"lzma\"}}, \"authdb\": \"admin\", \"backup\": {\"location\": \"/tmp/backups\", \"method\": \"mongodump\", \"mongodump\": {\"binary\": \"/mongodb/bin/mongodump\", \"compression\": \"auto\"}, \"name\": \"NNNNNNNNNNNNNNNNNN\"}, \"environment\": \"production\", \"host\": \"xx.xx.xx.xxx\", \"lock_file\": \"/tmp/mongodb-consistent-backup.lock\", \"notify\": {\"method\": \"none\"}, \"oplog\": {\"compression\": \"none\", \"flush\": {\"max_docs\": 1000, \"max_secs\": 1}, \"tailer\": {\"enabled\": \"true\", \"status_interval\": 30}}, \"password\": \"******\", \"port\": 27017, \"replication\": {\"max_lag_secs\": 10, \"max_priority\": 1000}, \"sharding\": {\"balancer\": {\"ping_secs\": 3, \"wait_secs\": 300}}, \"upload\": {\"gs\": {\"threads\": 4}, \"method\": \"s3\", \"s3\": {\"access_key\": \"XXXXXXXXXXXXX\", \"bucket_name\": \"some-great-bucket\", \"bucket_prefix\": \"bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc\", \"chunk_size_mb\": 50, \"region\": \"us-east-1\", \"retries\": 5, \"secret_key\": \"******\", \"secure\": true, \"threads\": 4}}, \"username\": \"rotoroota\", \"verbose\": true}\
[2017-02-31 16:48:37,027] [INFO] [MainProcess] [Stage:init:31] Notify stage disabled, skipping\
[2017-02-31 16:48:37,027] [DEBUG] [MainProcess] [DB:connect:35] Getting MongoDB connection to xx.xx.xx.xxx:27017 (replicaSet=None, readPreference=secondaryPreferred)\
[2017-02-31 16:48:37,137] [DEBUG] [MainProcess] [DB:auth_if_required:59] Authenticating connection with username: rotoroota\
[2017-02-31 16:48:37,318] [INFO] [MainProcess] [State:init:135] Initializing root state directory /tmp/backups/NNNNNNNNNNNNNNNNNN\
[2017-02-31 16:48:37,318] [INFO] [MainProcess] [State:load_backups:153] Found 0 existing completed backups for set\
[2017-02-31 16:48:37,318] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,318] [DEBUG] [MainProcess] [State:write:62] Writing StateRoot state file: /tmp/backups/NNNNNNNNNNNNNNNNNN/mongodb-consistent-backup_META/meta.bson\
[2017-02-31 16:48:37,318] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,319] [INFO] [MainProcess] [State:init:119] Initializing backup state directory: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648\
[2017-02-31 16:48:37,319] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,319] [DEBUG] [MainProcess] [State:write:62] Writing StateBackup state file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META/meta.bson\
[2017-02-31 16:48:37,319] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,190] [DEBUG] [MainProcess] [Stage:init:48] Loaded stage mongodb_consistent_backup.Archive with task Tar\
[2017-02-31 16:48:37,190] [DEBUG] [MainProcess] [S3Session:connect:44] Connecting to AWS S3 with Access Key: XXXXXXXXXXXXX\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [provider:get_credentials:280] Using access key provided by client.\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [provider:get_credentials:307] Using secret key provided by client.\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [S3Session:connect:52] Successfully connected to AWS S3 with Access Key: XXXXXXXXXXXXX\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [S3Session:get_bucket:60] Connecting to AWS S3 Bucket: some-great-bucket\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [connection:make_request:655] path=/\
[2017-02-31 16:48:37,219] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/\
[2017-02-31 16:48:37,220] [DEBUG] [MainProcess] [connection:_mexe:897] Method: HEAD\
[2017-02-31 16:48:37,220] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /\
[2017-02-31 16:48:37,226] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:37,226] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [connection:new_http_connection:745] establishing HTTPS connection: host=some-great-bucket.s3.amazonaws.com, kwargs={\\'port\\': 443, \\'timeout\\': 15}\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:37,227] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
HEAD\
\
\
Mon, 31 Feb 2017 16:48:37 GMT\
/some-great-bucket/\
[2017-02-31 16:48:37,228] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:vvvvvvvvvvvvvvvvv=\
[2017-02-31 16:48:37,228] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:37 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:vvvvvvvvvvvvvvvvv=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:37,319] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-bucket-region\\', \\'us-east-1\\'), (\\'x-amz-id-2\\', \\'++++++++++++++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:38 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:37,320] [DEBUG] [MainProcess] [Stage:init:48] Loaded stage mongodb_consistent_backup.Upload with task S3\
[2017-02-31 16:48:37,320] [INFO] [MainProcess] [Main:run:269] Running backup in replset mode using seed node(s): xx.xx.xx.xxx:27017\
[2017-02-31 16:48:37,325] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,325] [DEBUG] [MainProcess] [State:write:62] Writing StateBackupReplset state file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/mongodb-consistent-backup_META/replset.bson\
[2017-02-31 16:48:37,325] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:37,346] [DEBUG] [MainProcess] [Mongodump:can_gzip:69] Mongodump binary supports gzip\
[2017-02-31 16:48:37,346] [INFO] [MainProcess] [Mongodump:choose_compression:62] Mongodump binary supports gzip compression, auto-enabling gzip compression\
[2017-02-31 16:48:37,346] [INFO] [MainProcess] [Task:compression:38] Setting Mongodump compression method: gzip\
[2017-02-31 16:48:37,346] [DEBUG] [MainProcess] [Stage:init:48] Loaded stage mongodb_consistent_backup.Backup with task Mongodump\
[2017-02-31 16:48:37,346] [INFO] [MainProcess] [Main:run:297] Backup method supports compression, disabling compression in archive step\
[2017-02-31 16:48:37,346] [INFO] [MainProcess] [Task:compression:38] Setting Tar compression method: none\
[2017-02-31 16:48:37,353] [INFO] [MainProcess] [Stage:run:82] Running stage mongodb_consistent_backup.Backup with task: Mongodump\
[2017-02-31 16:48:37,374] [INFO] [MainProcess] [Replset:find_primary:155] Found PRIMARY: yyyyyyyyyyyyyyyyyyyyy/xx.xx.xxx.xx:27017 with optime Timestamp(0000000000, 1)\
[2017-02-31 16:48:37,374] [INFO] [MainProcess] [Replset:find_secondary:233] Found SECONDARY yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017: {\\'priority\\': 1, \\'lag\\': 0, \\'optime\\': Timestamp(0000000000, 1), \\'score\\': 100}\
[2017-02-31 16:48:37,374] [INFO] [MainProcess] [Replset:find_secondary:318] Found ARBITER yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xx:27017, skipping\
[2017-02-31 16:48:37,374] [INFO] [MainProcess] [Replset:find_secondary:243] Choosing SECONDARY yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017 for replica set yyyyyyyyyyyyyyyyyyyyy (score: 100)\
[2017-02-31 16:48:37,376] [INFO] [MainProcess] [Mongodump:run:155] Starting backups using mongodump r3.2.8 (options: threads_per_dump=1, mongodump=r3.2.8, git=2214d4d6561574f962c1dc72fefce4fe13143023, compression=gzip)\
[2017-02-31 16:48:37,386] [INFO] [MongodumpThread-2] [MongodumpThread:run:140] Starting mongodump backup of yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017\
[2017-02-31 16:48:37,394] [DEBUG] [MongodumpThread-2] [MongodumpThread:run:151] Running mongodump cmd: [\\'/mongodb/bin/mongodump\\', \\'--host\\', u\\'xx.xx.xx.xxx\\', \\'--port\\', \\'27017\\', \\'--oplog\\', \\'--out\\', u\\'/tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/dump\\', \\'--numParallelCollections=1\\', \\'--gzip\\', \\'--readPreference=secondary\\', \\'-u\\', \\'rotoroota\\', \\'-p\\', \\'\"\"\\']\
[2017-02-31 16:48:37,412] [DEBUG] [MongodumpThread-2] [MongodumpThread:handle_password_prompt:75] Received password prompt from mongodump, writing password to stdin\
[2017-02-31 16:48:37,413] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tEnter password:\
[2017-02-31 16:48:37,561] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting admin.system.indexes to\
[2017-02-31 16:48:37,571] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tdone dumping admin.system.indexes (3 documents)\
[2017-02-31 16:48:37,571] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting mytestingdb.system.indexes to\
[2017-02-31 16:48:37,580] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tdone dumping mytestingdb.system.indexes (1 document)\
[2017-02-31 16:48:37,580] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting admin.system.users to\
[2017-02-31 16:48:37,590] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tdone dumping admin.system.users (3 documents)\
[2017-02-31 16:48:37,591] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting admin.system.version to\
[2017-02-31 16:48:37,596] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tdone dumping admin.system.version (1 document)\
[2017-02-31 16:48:37,606] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting mytestingdb.or_init to\
[2017-02-31 16:48:37,616] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\tdone dumping mytestingdb.or_init (1 document)\
[2017-02-31 16:48:37,634] [INFO] [MongodumpThread-2] [MongodumpThread:wait:107] yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017:\\twriting captured oplog to\
[2017-02-31 16:48:37,648] [DEBUG] [MongodumpThread-2] [Oplog:open:36] Opening oplog file /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/dump/oplog.bson\
[2017-02-31 16:48:37,649] [DEBUG] [MongodumpThread-2] [Oplog:load:53] Reading oplog file /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy/dump/oplog.bson\
[2017-02-31 16:48:37,656] [INFO] [MongodumpThread-2] [MongodumpThread:run:176] Backup yyyyyyyyyyyyyyyyyyyyy/xx.xx.xx.xxx:27017 completed in 0.27 seconds, 0 oplog changes\
[2017-02-31 16:48:41,380] [INFO] [MainProcess] [Mongodump:wait:107] All mongodump backups completed successfully\
[2017-02-31 16:48:41,381] [INFO] [MainProcess] [Stage:run:91] Completed running stage mongodb_consistent_backup.Backup with task Mongodump in 4.03 seconds\
[2017-02-31 16:48:41,381] [DEBUG] [MainProcess] [Lock:acquire:20] Acquired exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:41,381] [DEBUG] [MainProcess] [State:write:62] Writing StateBackup state file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META/meta.bson\
[2017-02-31 16:48:41,382] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/mongodb-consistent-backup_META.lock\
[2017-02-31 16:48:41,382] [DEBUG] [MainProcess] [DB:close:145] Closing connection to: xx.xx.xx.xxx:27017\
[2017-02-31 16:48:41,382] [INFO] [MainProcess] [Stage:run:82] Running stage mongodb_consistent_backup.Archive with task: Tar\
[2017-02-31 16:48:41,400] [INFO] [MainProcess] [Tar:run:56] Archiving backup directories with pool of 1 thread(s)\
[2017-02-31 16:48:41,401] [DEBUG] [MainProcess] [Tar:wait:45] Waiting for 1 tar thread(s) to stop\
[2017-02-31 16:48:41,403] [CRITICAL] [PoolWorker-3] [TarThread:run:52] Output file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar already exists!\
[2017-02-31 16:48:41,410] [DEBUG] [MainProcess] [Tar:done:36] Archiving completed for: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy\
[2017-02-31 16:48:43,403] [DEBUG] [MainProcess] [Tar:wait:48] Stopped all tar threads\
[2017-02-31 16:48:43,404] [INFO] [MainProcess] [Stage:run:91] Completed running stage mongodb_consistent_backup.Archive with task Tar in 2.02 seconds\
[2017-02-31 16:48:43,404] [INFO] [MainProcess] [Stage:run:82] Running stage mongodb_consistent_backup.Upload with task: S3\
[2017-02-31 16:48:43,404] [INFO] [MainProcess] [S3:run:80] Starting multipart AWS S3 upload to key: some-great-bucketbbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar using 4 threads, 50mb chunks, 5 retries\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploads\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploads\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:_mexe:897] Method: POST\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploads\
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:43,404] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
POST\
\
\
Mon, 31 Feb 2017 16:48:43 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploads\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:wwwwwwwwww\
[2017-02-31 16:48:43,405] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:43 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:wwwwwwwwww\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:43,406] [DEBUG] [MainProcess] [connection:_mexe:1015] encountered BadStatusLine exception, reconnecting\
[2017-02-31 16:48:43,406] [DEBUG] [MainProcess] [connection:new_http_connection:745] establishing HTTPS connection: host=some-great-bucket.s3.amazonaws.com, kwargs={\\'port\\': 443, \\'timeout\\': 15}\
[2017-02-31 16:48:44,147] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,147] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
POST\
\
\
Mon, 31 Feb 2017 16:48:43 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploads\
[2017-02-31 16:48:44,147] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:wwwwwwwwww\
[2017-02-31 16:48:44,147] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:43 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:wwwwwwwwww\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,319] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'++++++++++++++++++++++++++=\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'server\\', \\'AmazonS3\\')]\
[2017-02-31 16:48:44,319] [DEBUG] [MainProcess] [bucket:initiate_multipart_upload:1757] <?xml version=\"1.0\" encoding=\"UTF-8\"?>\
<InitiateMultipartUploadResult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><Bucket>some-great-bucket</Bucket><Key>bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar</Key><UploadId>121212121212121212121212</UploadId></InitiateMultipartUploadResult>\
[2017-02-31 16:48:44,221] [DEBUG] [MainProcess] [S3Session:connect:44] Connecting to AWS S3 with Access Key: XXXXXXXXXXXXX\
[2017-02-31 16:48:44,222] [DEBUG] [MainProcess] [provider:get_credentials:280] Using access key provided by client.\
[2017-02-31 16:48:44,222] [DEBUG] [MainProcess] [provider:get_credentials:307] Using secret key provided by client.\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [S3Session:connect:52] Successfully connected to AWS S3 with Access Key: XXXXXXXXXXXXX\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [S3Session:get_bucket:60] Connecting to AWS S3 Bucket: some-great-bucket\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:make_request:655] path=/\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:897] Method: HEAD\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,223] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,241] [DEBUG] [MainProcess] [connection:new_http_connection:745] establishing HTTPS connection: host=some-great-bucket.s3.amazonaws.com, kwargs={\\'port\\': 443, \\'timeout\\': 15}\
[2017-02-31 16:48:44,241] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,241] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
HEAD\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/\
[2017-02-31 16:48:44,242] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:hhhhhhhhhhhhhhhhh=\
[2017-02-31 16:48:44,242] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:hhhhhhhhhhhhhhhhh=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,266] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-bucket-region\\', \\'us-east-1\\'), (\\'x-amz-id-2\\', \\'++++++++++++++++++++++++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'UUUUUUUUUUUUUUU\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,275] [DEBUG] [PoolWorker-6] [connection:make_request:655] path=/\
[2017-02-31 16:48:44,275] [DEBUG] [PoolWorker-6] [connection:make_request:657] auth_path=/some-great-bucket/\
[2017-02-31 16:48:44,275] [DEBUG] [PoolWorker-6] [connection:make_request:661] path=/?uploads\
[2017-02-31 16:48:44,275] [DEBUG] [PoolWorker-6] [connection:make_request:663] auth_path=/some-great-bucket/?uploads\
[2017-02-31 16:48:44,275] [DEBUG] [PoolWorker-6] [connection:_mexe:897] Method: GET\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:898] Path: /?uploads\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:new_http_connection:745] establishing HTTPS connection: host=some-great-bucket.s3.amazonaws.com, kwargs={\\'port\\': 443, \\'timeout\\': 15}\
[2017-02-31 16:48:44,276] [DEBUG] [PoolWorker-6] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,277] [DEBUG] [PoolWorker-6] [auth:add_auth:318] StringToSign:\
GET\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/?uploads\
[2017-02-31 16:48:44,277] [DEBUG] [PoolWorker-6] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:fffffffffffffffffffff=\
[2017-02-31 16:48:44,277] [DEBUG] [PoolWorker-6] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:fffffffffffffffffffff=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,453] [DEBUG] [PoolWorker-6] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'zzzzzzzzzzzzzzzzzzzzzzzz=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'33106F69595E2A38\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,454] [DEBUG] [PoolWorker-6] [bucket:_get_all:402] <?xml version=\"1.0\" encoding=\"UTF-8\"?>\
<ListMultipartUploadsResult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><Bucket>some-great-bucket</Bucket><KeyMarker></KeyMarker><UploadIdMarker></UploadIdMarker><NextKeyMarker>bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar</NextKeyMarker><NextUploadIdMarker>121212121212121212121212</NextUploadIdMarker><MaxUploads>1000</MaxUploads><IsTruncated>false</IsTruncated><Upload><Key>bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar</Key><UploadId>121212121212121212121212</UploadId><Initiator><ID>arn:aws:iam::533013890653:user/cloud-worker-staging</ID><DisplayName>cloud-worker-staging</DisplayName></Initiator><Owner><ID>idididididididididididididid</ID><DisplayName>bb83126f306f400e87721c0482fcd983</DisplayName></Owner><StorageClass>STANDARD</StorageClass><Initiated>2017-02-31T16:48:45.000Z</Initiated></Upload></ListMultipartUploadsResult>\
[2017-02-31 16:48:44,454] [INFO] [PoolWorker-6] [S3UploadThread:run:34] Uploading file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar (part num: 1)\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212&partNumber=1\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212&partNumber=1\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:897] Method: PUT\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212&partNumber=1\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:900] Headers: {\\'Content-Length\\': \\'20480\\', \\'Content-MD5\\': u\\'OMbzKET5OsgfLh2K0dY7bA==\\', \\'Content-Type\\': \\'application/x-tar\\', \\'Expect\\': \\'100-Continue\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,457] [DEBUG] [PoolWorker-6] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,458] [DEBUG] [PoolWorker-6] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,458] [DEBUG] [PoolWorker-6] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,458] [DEBUG] [PoolWorker-6] [auth:add_auth:318] StringToSign:\
PUT\
OMbzKET5OsgfLh2K0dY7bA==\
application/x-tar\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?partNumber=1&uploadId=121212121212121212121212\
[2017-02-31 16:48:44,458] [DEBUG] [PoolWorker-6] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:ddddddddddddddddd=\
[2017-02-31 16:48:44,465] [DEBUG] [PoolWorker-6] [connection:_mexe:936] Final headers: {\\'Content-Length\\': \\'20480\\', \\'Content-MD5\\': \\'0987654321==\\', \\'Expect\\': \\'100-Continue\\', \\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\', \\'Content-Type\\': \\'application/x-tar\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:ddddddddddddddddd=\\'}\
[2017-02-31 16:48:44,594] [DEBUG] [PoolWorker-6] [connection:_mexe:945] Response headers: [(\\'content-length\\', \\'0\\'), (\\'x-amz-id-2\\', \\'++++++++++++++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'x-amz-request-id\\', \\'99999999999999\\'), (\\'etag\\', \\'\"3333333333333333\"\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\')]\
[2017-02-31 16:48:44,594] [DEBUG] [PoolWorker-6] [S3UploadThread:run:37] Uploaded file: /tmp/backups/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar (part num: 1)\
[2017-02-31 16:48:44,634] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,634] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,634] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,634] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,634] [DEBUG] [MainProcess] [connection:_mexe:897] Method: GET\
[2017-02-31 16:48:44,635] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,635] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,636] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,636] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,636] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,636] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,636] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,637] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
GET\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,637] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:qqqqqqqqqqqqqq=\
[2017-02-31 16:48:44,637] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:qqqqqqqqqqqqqq=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,673] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'+++++\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:_mexe:897] Method: GET\
[2017-02-31 16:48:44,674] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
GET\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:qqqqqqqqqqqqqq=\
[2017-02-31 16:48:44,675] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:qqqqqqqqqqqqqq=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,731] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,731] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,731] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,731] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,731] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:897] Method: POST\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:899] Data: <CompleteMultipartUpload>\
<Part>\
<PartNumber>1</PartNumber>\
<ETag>\"38c6f32844f93ac81f2e1d8ad1d63b6c\"</ETag>\
</Part>\
</CompleteMultipartUpload>\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {\\'Content-Type\\': \\'text/xml\\'}\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
POST\
\
text/xml\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,719] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:llllllllllllllllllllll=\
[2017-02-31 16:48:44,720] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'154\\', \\'Content-Type\\': \\'text/xml\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:llllllllllllllllllllll=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,787] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'++++++++++++++++++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,823] [DEBUG] [MainProcess] [bucket:complete_multipart_upload:1788] <?xml version=\"1.0\" encoding=\"UTF-8\"?>\
\
<CompleteMultipartUploadResult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><Location>https://some-great-bucket.s3.amazonaws.com/bbbbbbbbbbbbbbbbbbbb%2Fccccccccccccccccccccccc%2FNNNNNNNNNNNNNNNNNN%2F20170231_1648%2Fyyyyyyyyyyyyyyyyyyyyy.tar</Location><Bucket>some-great-bucket</Bucket><Key>bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar</Key><ETag>&quot;ce5fc201d58d4ba5460df53da2fcd1e6-1&quot;</ETag></CompleteMultipartUploadResult>\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:897] Method: HEAD\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,824] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,825] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
HEAD\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,825] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:oooooooooooooooo=\
[2017-02-31 16:48:44,825] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:oooooooooooooooo=\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,836] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'++++++++++++++++++++++++++++++=\\'), (\\'server\\', \\'AmazonS3\\'), (\\'transfer-encoding\\', \\'chunked\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:43 GMT\\'), (\\'content-type\\', \\'application/xml\\')]\
[2017-02-31 16:48:44,836] [ERROR] [MainProcess] [S3:run:130] Uploading to AWS S3 failed! Error: S3ResponseError: 403 Forbidden\
\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:897] Method: DELETE\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,837] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,838] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
DELETE\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,838] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:tttttttttttttttttttttt\
[2017-02-31 16:48:44,838] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:tttttttttttttttttttttt\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,870] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'+++++++++++++++++++++++++++++++=\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'server\\', \\'AmazonS3\\')]\
[2017-02-31 16:48:44,870] [DEBUG] [MainProcess] [bucket:cancel_multipart_upload:3119] \
[2017-02-31 16:48:44,870] [ERROR] [MainProcess] [Stage:run:94] Stage mongodb_consistent_backup.Upload did not complete!\
[2017-02-31 16:48:44,870] [DEBUG] [MainProcess] [Stage:close:59] Calling close on backup stage mongodb_consistent_backup.Upload with task S3\
[2017-02-31 16:48:44,870] [ERROR] [MainProcess] [S3:close:138] Terminating multipart AWS S3 upload threads\
[2017-02-31 16:48:44,871] [ERROR] [MainProcess] [S3:close:143] Cancelling incomplete multipart AWS S3 upload\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:make_request:655] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:make_request:657] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:make_request:661] path=/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:make_request:663] auth_path=/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:_mexe:897] Method: DELETE\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:_mexe:898] Path: /bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:_mexe:899] Data: \
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:_mexe:900] Headers: {}\
[2017-02-31 16:48:44,871] [DEBUG] [MainProcess] [connection:_mexe:901] Host: some-great-bucket.s3.amazonaws.com\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [connection:_mexe:902] Port: 443\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [connection:_mexe:903] Params: {}\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [connection:_mexe:926] Token: None\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [auth:add_auth:318] StringToSign:\
DELETE\
\
\
Mon, 31 Feb 2017 16:48:44 GMT\
/some-great-bucket/bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc/NNNNNNNNNNNNNNNNNN/20170231_1648/yyyyyyyyyyyyyyyyyyyyy.tar?uploadId=121212121212121212121212\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [auth:add_auth:192] Signature:\
AWS XXXXXXXXXXXXX:tttttttttttttttttttttt\
[2017-02-31 16:48:44,872] [DEBUG] [MainProcess] [connection:_mexe:936] Final headers: {\\'Date\\': \\'Mon, 31 Feb 2017 16:48:44 GMT\\', \\'Content-Length\\': \\'0\\', \\'Authorization\\': u\\'AWS XXXXXXXXXXXXX:tttttttttttttttttttttt\\', \\'User-Agent\\': \\'Boto/2.47.0 Python/2.7.12 Linux/4.4.0-47-generic\\'}\
[2017-02-31 16:48:44,917] [DEBUG] [MainProcess] [connection:_mexe:945] Response headers: [(\\'x-amz-id-2\\', \\'+++++++++++++++++++++++++++=\\'), (\\'date\\', \\'Mon, 31 Feb 2017 16:48:45 GMT\\'), (\\'x-amz-request-id\\', \\'0987654321\\'), (\\'server\\', \\'AmazonS3\\')]\
[2017-02-31 16:48:44,917] [DEBUG] [MainProcess] [bucket:cancel_multipart_upload:3119] \
[2017-02-31 16:48:44,917] [CRITICAL] [MainProcess] [Main:exception:219] Problem performing upload of backup! Error: Stage mongodb_consistent_backup.Upload did not complete!\
[2017-02-31 16:48:44,931] [INFO] [MainProcess] [Main:cleanup_and_exit:175] Starting cleanup procedure! Stopping running threads\
[2017-02-31 16:48:44,924] [DEBUG] [MainProcess] [DB:close:145] Closing connection to: xx.xx.xx.xxx:27017\
[2017-02-31 16:48:44,931] [INFO] [MainProcess] [Main:cleanup_and_exit:205] Cleanup complete, exiting\
[2017-02-31 16:48:44,931] [DEBUG] [MainProcess] [Lock:release:30] Releasing exclusive lock on file: /tmp/mongodb-consistent-backup.lock', u'stdout': u''}, u'id': u'NNNNNNNNNNNNNNNNNN', u'name': u'/mongodb_consistent_backup/mongodb-consistent-backup -v -n NNNNNNNNNNNNNNNNNN -H xx.xx.xx.xxx -P 27017 -l /tmp/backups -u rotoroota -p ppppppppppppppppppppp -a admin --backup.mongodump.binary /mongodb/bin/mongodump --upload.method s3 --upload.s3.access_key XXXXXXXXXXXXX --upload.s3.secret_key xxxxxxxxxxxxxxxxxxxxx --upload.s3.bucket_name some-great-bucket --upload.s3.bucket_prefix bbbbbbbbbbbbbbbbbbbb/ccccccccccccccccccccccc'}]}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment