b2.py 0.3.6 occasionally completely barfs on uploads

[vitorio]

This was B2 support tickets #187260 and #191398, Nilay suggested I post here instead.

I'm trying out B2 as a secondary store alongside Glacier, and I'm (ab)using b2.py as an import in a Python script that regularly uploads files to both.

Every few days, B2 will completely barf on uploads. It happened January 13th, and it happened on the 8th before that, and the 4th before that. The traceback looks like this:

B2 exception for /home/iverad/WWJ/ive3rad_wwj_2016_01_13_21_22_12.aac:
Traceback (most recent call last):
File "iveradvpsdel.py", line 177, in <module>
b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
File "/home/iverad/b2.py", line 728, in upload_file
response = post_file(url, headers, local_file, exit_on_error=False)
File "/home/iverad/b2.py", line 331, in post_file
with OpenUrl(url, data_file, headers, exit_on_error) as response_file:
File "/home/iverad/b2.py", line 298, in __enter__
self.file = urllib2.urlopen(request)
File "/usr/lib/python2.7/urllib2.py", line 154, in urlopen
return opener.open(url, data, timeout)
File "/usr/lib/python2.7/urllib2.py", line 431, in open
response = self._open(req, data)
File "/usr/lib/python2.7/urllib2.py", line 449, in _open
'_open', req)
File "/usr/lib/python2.7/urllib2.py", line 409, in _call_chain
result = func(*args)
File "/usr/lib/python2.7/urllib2.py", line 1240, in https_open
context=self._context)
File "/usr/lib/python2.7/urllib2.py", line 1200, in do_open
r = h.getresponse(buffering=True)
File "/usr/lib/python2.7/httplib.py", line 1073, in getresponse
response.begin()
File "/usr/lib/python2.7/httplib.py", line 415, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.7/httplib.py", line 379, in _read_status
raise BadStatusLine(line)
BadStatusLine: ''

Or this:

B2 exception for /home/iverad/KDKA/ive3rad_kdka_2016_01_13_21_22_14.aac:
Traceback (most recent call last):
File "iveradvpsdel.py", line 177, in <module>
b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
File "/home/iverad/b2.py", line 728, in upload_file
response = post_file(url, headers, local_file, exit_on_error=False)
File "/home/iverad/b2.py", line 331, in post_file
with OpenUrl(url, data_file, headers, exit_on_error) as response_file:
File "/home/iverad/b2.py", line 298, in __enter__
self.file = urllib2.urlopen(request)
File "/usr/lib/python2.7/urllib2.py", line 154, in urlopen
return opener.open(url, data, timeout)
File "/usr/lib/python2.7/urllib2.py", line 431, in open
response = self._open(req, data)
File "/usr/lib/python2.7/urllib2.py", line 449, in _open
'_open', req)
File "/usr/lib/python2.7/urllib2.py", line 409, in _call_chain
result = func(*args)
File "/usr/lib/python2.7/urllib2.py", line 1240, in https_open
context=self._context)
File "/usr/lib/python2.7/urllib2.py", line 1197, in do_open
raise URLError(err)
URLError: <urlopen error [Errno 111] Connection refused>

Right now I'm just letting b2.py do its thing, it retries five times (or whatever) and then gives up, and it just logs these errors for me to eventually manually retry later.

Is there something else I could/should be doing?

[vitorio]

It happened again the morning of January 20, starting at 2016-01-20T15:38:31.408646+00:00 UTC, a batch of ~180 files completely failed to transfer to B2.

All of the failures look the same:

B2 exception for /home/iverad/KDKA/ive2rad_kdka_2016_01_20_12_36_01.aac:
Traceback (most recent call last):
  File "iveradvpsdel.py", line 177, in <module>
    b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
  File "/home/iverad/b2.py", line 715, in upload_file
    bucket_upload_data = ensure_upload_data(bucket_id, info)
  File "/home/iverad/b2.py", line 606, in ensure_upload_data
    response = post_json(url, params, auth_token)
  File "/home/iverad/b2.py", line 321, in post_json
    json_text = f.read()
AttributeError: 'NoneType' object has no attribute ‘read'

The subsequent batches starting 30 minutes after that were fine.

Had another one January 21 starting 2016-01-21T17:47:40.056902+00:00 UTC, just a single file within a batch this time:

B2 exception for /home/iverad/KOMO/ive2rad_komo_2016_01_21_14_45_23.mp3:
Traceback (most recent call last):
  File "iveradvpsdel.py", line 177, in <module>
    b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
  File "/home/iverad/b2.py", line 715, in upload_file
    bucket_upload_data = ensure_upload_data(bucket_id, info)
  File "/home/iverad/b2.py", line 606, in ensure_upload_data
    response = post_json(url, params, auth_token)
  File "/home/iverad/b2.py", line 320, in post_json
    with OpenUrl(url, data, headers) as f:
  File "/home/iverad/b2.py", line 298, in __enter__
    self.file = urllib2.urlopen(request)
  File "/usr/lib/python2.7/urllib2.py", line 154, in urlopen
    return opener.open(url, data, timeout)
  File "/usr/lib/python2.7/urllib2.py", line 431, in open
    response = self._open(req, data)
  File "/usr/lib/python2.7/urllib2.py", line 449, in _open
    '_open', req)
  File "/usr/lib/python2.7/urllib2.py", line 409, in _call_chain
    result = func(*args)
  File "/usr/lib/python2.7/urllib2.py", line 1240, in https_open
    context=self._context)
  File "/usr/lib/python2.7/urllib2.py", line 1197, in do_open
    raise URLError(err)
URLError: <urlopen error [Errno 104] Connection reset by peer>

Saw several more of these midday January 22, same type of traceback.

Also, these happen from two different servers that are uploading to B2, in two different geographic locations with two different providers.

February 7:

B2 exception for /home/iverad/WBBR/ive2rad_wbbr_2016_02_08_00_42_34.aac:
Traceback (most recent call last):
File "iveradvpsdel.py", line 177, in <module>
b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
File "/home/iverad/b2.py", line 715, in upload_file
bucket_upload_data = ensure_upload_data(bucket_id, info)
File "/home/iverad/b2.py", line 606, in ensure_upload_data
response = post_json(url, params, auth_token)
File "/home/iverad/b2.py", line 321, in post_json
json_text = f.read()
AttributeError: 'NoneType' object has no attribute 'read'

February 23:

B2 exception for /home/iverad/WTOP/ive3rad_wtop_2016_02_23_12_23_08.aac:
Traceback (most recent call last):
File "iveradvpsdel.py", line 177, in <module>
b2.upload_file(['--contentType', content_type, B2_BUCKET_NAME, b, b2_name])
File "/home/iverad/b2.py", line 715, in upload_file
bucket_upload_data = ensure_upload_data(bucket_id, info)
File "/home/iverad/b2.py", line 606, in ensure_upload_data
response = post_json(url, params, auth_token)
File "/home/iverad/b2.py", line 321, in post_json
json_text = f.read()
AttributeError: 'NoneType' object has no attribute ‘read'

They're a little less frequent now, every couple of weeks instead of every few days.

[ppolewicz]

There are 3 issues really reported here:

1. When you get a AttributeError: 'NoneType' object has no attribute ‘read', it should not happen. In such case, we should handle it gracefully and retry... Fixing it now by a specific code for such issue does not make much sense as this issue is specific to urllib2, which we are now switching for requests. That will solve this issue and other problems along with it.
2. Connection reset: sever-side issue. B2 service is in beta and from time to time it does something crazy like close a connection without an apparent reason. Backblaze is working fast on resolving those issues as their service matures, so in the future it their servers are less and less likely to become overloaded and you should not see those. As you said, this problem was temporary and their ops team seems to have taken care of it rather quickly.
3. BadStatusLine: same as 2.

Also, please upgrade to new version of b2 command line tool - we are improving it continuously with weekly releases.

[vitorio]

Thanks for the reply, @ppolewicz. There's a related issue to 2 I've started seeing, but haven't captured data for yet, where I believe the B2 service keeps the connection open, but stops accepting data, so my uploads appear to hang indefinitely, and never recover.

Is this something you/others have seen?

I'll be sure to upgrade b2 as I add in debugging to log data about this.

[ppolewicz]

That might be #16 or another server-side issue

[ppolewicz]

The http communication layer as well as the retrying has been reworked recently. Also B2 experienced upgrades on the server side. As this issue has not been observed for a while now, I am going to close this ticket. If the problem reoccurs, please file a new one and reference this one.