Boto: Files with multi-byte characters are incompletely uploaded to S3 in python3

[hwkns]

This bug was very elusive. I found it while moving our codebase (a large Django project) from Python 2.7 to Python 3.4. Everything seemed to work fine until I ran collectstatic in a production-like environment (one that actually uses boto to upload static files to S3). After several files uploaded successfully, I hit a stack trace ending with:

boto.exception.S3ResponseError: S3ResponseError: 400 Bad Request
<?xml version="1.0" encoding="UTF-8"?>
<Error><Code>BadDigest</Code><Message>The Content-MD5 you specified did not match what we received.</Message><ExpectedDigest>R6/m+29/k2l39Le20oh0Dw==</ExpectedDigest><CalculatedDigest>A+iwzvzxQCkrYxlBLPqrfQ==</CalculatedDigest><RequestId>833B8C528965ABA7</RequestId><HostId>CT5inl5sUSl69I/pvPjK8ARAUmMNaTtZv0hpgBazmmfRxHLZ3k1YJSLkEGPLdENo</HostId></Error>

I made sure there were no network problems, and I made sure the file wasn't changing while I was uploading it. I was stumped, but I knew it had been caused by the py2 to py3 switch, so it was probably related to encoding (bytes vs. text). I opened up the boto source and started using ipdb to catch the exception and poke around (ipython3 --pdb -c "%run manage.py collectstatic").

I found that the file causing the stack trace could not be encoded into ASCII, so I knew I was on the right track. The current chunk looked like it was cut off at the end, and there were four more characters left to be read from fp (even though we had already finished sending data to S3):

ipdb> fp.read()
'em}\n'

Incomplete uploads could definitely cause an MD5 mismatch, so I checked the hashes myself. The "expected" digest was equal to the MD5 hash of the entire file, and the "calculated" digest was equal to the MD5 hash of the entire file minus the last 4 bytes:

ipdb> from hashlib import md5
ipdb> from binascii import b2a_base64
ipdb> m = md5(fp.file.getvalue().encode('utf-8'))
ipdb> b2a_base64(m.digest())
b'MfM1IbuOE59u/TYoKmFujQ==\n'
ipdb> m = md5(fp.file.getvalue()[:-4].encode('utf-8'))
ipdb> b2a_base64(m.digest())
b'XWWuj34xbuJ7OubGdyqXmQ==\n'
ipdb> body
b'<?xml version="1.0" encoding="UTF-8"?>\n<Error><Code>BadDigest</Code><Message>The Content-MD5 you specified did not match what we received.</Message><ExpectedDigest>MfM1IbuOE59u/TYoKmFujQ==</ExpectedDigest><CalculatedDigest>XWWuj34xbuJ7OubGdyqXmQ==</CalculatedDigest><RequestId>18AB6DDB4EE83FB0</RequestId><HostId>iiYQ2OX6dO/eNTPMYua5PUDzUxaprWzNPlkByxPWt2NNMRdGDn8BhkZ5xyRfMy1FBMw6G+8ay14=</HostId></Error>'

So, why were there 4 bytes left in the buffer that we did not upload? Suspecting encoding issues, I checked the count of characters (text) in the file's string representation vs. the count of UTF-8 bytes in the encoded file:

ipdb> len(fp.file.getvalue())
34456
ipdb> len(fp.file.getvalue().encode('utf-8'))
34460

There's our culprit. Digging into the boto source, this part of boto.s3.key.Key._send_file_internal() is where things go wrong:

bytes_togo = size
if bytes_togo and bytes_togo < self.BufferSize:
    chunk = fp.read(bytes_togo)
else:
    chunk = fp.read(self.BufferSize)

if not isinstance(chunk, bytes):
    chunk = chunk.encode('utf-8')

So, fp.read() takes a number of _characters_ to read (incorrectly named bytes_togo) and returns a _string_ (text), which is assigned as the value of chunk. Then chunk gets encoded into UTF-8, so if it contains any characters that take more than one byte to represent, len(chunk) will be larger after this encoding step. That means, after we send the chunk to S3, when we use bytes_togo -= chunk_len, we are subtracting more than we intended to. bytes_togo reaches zero before it should, and we never send the rest of the file. It's always incomplete by _n_ characters, where _n_ is the number of extra bytes needed to represent all the file's unicode characters in UTF-8.

[hwkns]

After further thought and investigation, the problem here is the _assumption_ that fp is a file-like object whose read() method returns bytes. This assumption is stated in docstrings and apparent in the code, but it is not enforced.

I have traced the root cause of my own issue to django-pipeline's use of smart_str when creating the ContentFile to send to the storage backend:

def save_file(self, path, content):
    return self.storage.save(path, ContentFile(smart_str(content)))

This was the right thing to do at the time (before Django was made py3 compatible) to force the ContentFile to contain bytes, but now, in py3, it forces the ContentFile to contain text.

Regardless, since boto.s3 does not support text-based fp input, it should enforce that lack of support by throwing an exception if text is detected, instead of carrying on and letting S3 respond with a misleading BadDigest error.

[meshy]

@hwkns Thank-you very much for this detailed bug report. We wouldn't have been able to find a workaround without it :).

We were able to find the problem utf8 chars in our css with ag "[\x80-\xFF]", and are replacing them with escaped chars for the mo.

(ack "[\x80-\xFF]" also worked.)

Thanks again! :)

[tawanda]

mine is happening with a generated CSV

@meshy @hwkns any idea how to go about stripping those characters, here is my code

        file_name = '{}-sms-audit-log.csv'.format(timezone.now())
        content = StringIO()
        writer = csv.writer(content)

        writer.writerow(
            [
                'date',
                'description',
                'details',
                'credits',
            ]
        )

        for transaction in sms_transactions:
            writer.writerow([
                transaction.date.strftime("%A %d %B %Y  %H:%MHRS"),
                transaction.description,
                transaction.details,
                transaction.credits,
            ])
        logger.debug("Finished writing csv rows")
        content.seek(0)

        read_content = content.read()
        logger.debug("Finished reading csv, Saving")

        content_file = ContentFile(read_content, name=file_name)
        logger.debug("Finished creating content file")

        invoice.audit_log = content_file

        logger.debug("Saving CSV to invoice")

        invoice.save()

The trace:

Jul 1 15:10:01 tawanda2 supervisor-celery.log DEBUG /Worker-6] Final headers: {'Expect': '100-Continue', 'Date': 'Fri, 01 Jul 2016 13:10:02 GMT', 'Authorization': 'AWS ', 'Content-Length': '87793', 'Content-MD5': 'KikjNzRnGGkTXZ0VPcXyEQ==', 'x-amz-acl': 'public-read', 'Content-Type': 'text/csv', 'User-Agent': 'Boto/2.40.0 Python/3.4.3 Linux/3.13.0-83-generic'}
Jul 1 15:10:02 tawanda2 supervisor-celery.log ERROR /MainProcess] Task invoice.periodic.send[bec7a832-7c14-47e6-ba62-46fc59bb264a] raised unexpected: S3ResponseError: 400 Bad Request
Jul 1 15:10:02 tawanda2 supervisor-celery.log  <?xml version="1.0" encoding="UTF-8"?>
Jul 1 15:10:02 tawanda2 supervisor-celery.log  <Error><Code>BadDigest</Code><Message>The Content-MD5 you specified did not match what we received.</Message><ExpectedDigest>KikjNzRnGGkTXZ0VPcXyEQ==</ExpectedDigest><CalculatedDigest>w0JiOQJZz6R/fv0y6fM1wg==</CalculatedDigest><RequestId>98C357130111C22B</RequestId></Error>
Jul 1 15:10:02 tawanda2 supervisor-celery.log  Traceback (most recent call last):
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/celery/app/trace.py", line 240, in trace_task
Jul 1 15:10:02 tawanda2 supervisor-celery.log     R = retval = fun(*args, **kwargs)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/celery/app/trace.py", line 438, in __protected_call__
Jul 1 15:10:02 tawanda2 supervisor-celery.log     return self.run(*args, **kwargs)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/www/siegesms/siegesms/apps/invoicing/tasks.py", line 174, in run
Jul 1 15:10:02 tawanda2 supervisor-celery.log     invoice.save()
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/www/siegesms/siegesms/apps/invoicing/models.py", line 111, in save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     super().save()
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/base.py", line 708, in save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     force_update=force_update, update_fields=update_fields)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/base.py", line 736, in save_base
Jul 1 15:10:02 tawanda2 supervisor-celery.log     updated = self._save_table(raw, cls, force_insert, force_update, using, update_fields)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/base.py", line 798, in _save_table
Jul 1 15:10:02 tawanda2 supervisor-celery.log     for f in non_pks]
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/base.py", line 798, in <listcomp>
Jul 1 15:10:02 tawanda2 supervisor-celery.log     for f in non_pks]
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/fields/files.py", line 311, in pre_save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     file.save(file.name, file, save=False)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/db/models/fields/files.py", line 93, in save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     self.name = self.storage.save(name, content, max_length=self.field.max_length)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/django/core/files/storage.py", line 63, in save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     name = self._save(name, content)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/storages/backends/s3boto.py", line 417, in _save
Jul 1 15:10:02 tawanda2 supervisor-celery.log     self._save_content(key, content, headers=headers)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/storages/backends/s3boto.py", line 428, in _save_content
Jul 1 15:10:02 tawanda2 supervisor-celery.log     rewind=True, **kwargs)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/s3/key.py", line 1293, in set_contents_from_file
Jul 1 15:10:02 tawanda2 supervisor-celery.log     chunked_transfer=chunked_transfer, size=size)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/s3/key.py", line 750, in send_file
Jul 1 15:10:02 tawanda2 supervisor-celery.log     chunked_transfer=chunked_transfer, size=size)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/s3/key.py", line 951, in _send_file_internal
Jul 1 15:10:02 tawanda2 supervisor-celery.log     query_args=query_args
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/s3/connection.py", line 668, in make_request
Jul 1 15:10:02 tawanda2 supervisor-celery.log     retry_handler=retry_handler
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/connection.py", line 1071, in make_request
Jul 1 15:10:02 tawanda2 supervisor-celery.log     retry_handler=retry_handler)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/connection.py", line 940, in _mexe
Jul 1 15:10:02 tawanda2 supervisor-celery.log     request.body, request.headers)
Jul 1 15:10:02 tawanda2 supervisor-celery.log   File "/home/siege1/.virtualenvs/siegesms/lib/python3.4/site-packages/boto/s3/key.py", line 884, in sender
Jul 1 15:10:02 tawanda2 supervisor-celery.log     response.status, response.reason, body)
Jul 1 15:10:02 tawanda2 supervisor-celery.log  boto.exception.S3ResponseError: S3ResponseError: 400 Bad Request
Jul 1 15:10:02 tawanda2 supervisor-celery.log  <?xml version="1.0" encoding="UTF-8"?>
Jul 1 15:10:02 tawanda2 supervisor-celery.log  <Error><Code>BadDigest</Code><Message>The Content-MD5 you specified did not match what we received.</Message><ExpectedDigest>KikjNzRnGGkTXZ0VPcXyEQ==</ExpectedDigest><CalculatedDigest>w0JiOQJZz6R/fv0y6fM1wg==</CalculatedDigest><RequestId>98C357130111C22B</RequestId></Error>

[hwkns]

@tawanda just encode the text into UTF-8 bytes before creating the ContentFile:

read_content = content.read()
read_content = read_content.encode('utf-8')
content_file = ContentFile(read_content, name=file_name)

That should be sufficient.

[tawanda]

Thanks so much, let me give it a try

On 02 Jul 2016, at 06:50, Daniel Hawkins [email protected] wrote:

@tawanda just encode the text into UTF-8 bytes before creating the ContentFile:

read_content = content.read()
read_content = read_content.encode('utf-8')
content_file = ContentFile(read_content, name=file_name)
That should be sufficient.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[tawanda]

Many thanks @hwkns it worked like a charm