Log the number of bytes downloaded
When troubleshooting download issues, which may present as checksum validation failures, it is difficult to understand if the *entire* file was downloaded due to the way HTTP works. In that, a download may start with a successful result code, and the content is streamed out until the socket is closed. But with HTTP there is no way to know if that socket closed prematurely and the original server size is *also* an optional field, so just log the size we got to so we don't drive the humans [more-]insane. Also now logs the (optional) content-length field if supplied by the server. Change-Id: Id71b167f4e330d54b9afddf95f1a2ef9e40398bf
This commit is contained in:
Julia Kreger
Jay Faulkner
parent
119981a818
commit
c65ad42ff1
@ -83,8 +83,8 @@ def _download_with_proxy(image_info, url, image_id):
|
||||
timeout=CONF.image_download_connection_timeout)
|
||||
if resp.status_code != 200:
|
||||
msg = ('Received status code {} from {}, expected 200. '
|
||||
'Response body: {}').format(resp.status_code, url,
|
||||
resp.text)
|
||||
'Response body: {} Response headers: {}').format(
|
||||
resp.status_code, url, resp.text, resp.headers)
|
||||
raise errors.ImageDownloadError(image_id, msg)
|
||||
except (errors.ImageDownloadError, requests.RequestException) as e:
|
||||
if (attempt == CONF.image_download_connection_retries
|
||||
@ -376,6 +376,8 @@ class ImageDownload(object):
|
||||
self._time = time_obj or time.time()
|
||||
self._image_info = image_info
|
||||
self._request = None
|
||||
self._bytes_transferred = 0
|
||||
self._expected_size = None
|
||||
checksum = image_info.get('checksum')
|
||||
retrieved_checksum = False
|
||||
|
||||
@ -440,6 +442,8 @@ class ImageDownload(object):
|
||||
LOG.info("Attempting to download image from %s", url)
|
||||
self._request = _download_with_proxy(image_info, url,
|
||||
image_info['id'])
|
||||
self._expected_size = self._request.headers.get(
|
||||
'Content-Length')
|
||||
except errors.ImageDownloadError as e:
|
||||
failtime = time.time() - self._time
|
||||
log_msg = ('URL: {}; time: {} '
|
||||
@ -473,9 +477,12 @@ class ImageDownload(object):
|
||||
if chunk:
|
||||
self._last_chunk_time = time.time()
|
||||
if isinstance(chunk, str):
|
||||
self._hash_algo.update(chunk.encode())
|
||||
encoded_data = chunk.encode()
|
||||
self._hash_algo.update(encoded_data)
|
||||
self._bytes_transferred += len(encoded_data)
|
||||
else:
|
||||
self._hash_algo.update(chunk)
|
||||
self._bytes_transferred += len(chunk)
|
||||
yield chunk
|
||||
elif (time.time() - self._last_chunk_time
|
||||
> CONF.image_download_connection_timeout):
|
||||
@ -512,6 +519,18 @@ class ImageDownload(object):
|
||||
self._expected_hash_value,
|
||||
checksum)
|
||||
|
||||
@property
|
||||
def bytes_transferred(self):
|
||||
"""Property value to return the number of bytes transferred."""
|
||||
return self._bytes_transferred
|
||||
|
||||
@property
|
||||
def content_length(self):
|
||||
"""Property value to return the server indicated length."""
|
||||
# If none, there is nothing we can do, the server didn't have
|
||||
# a response.
|
||||
return self._expected_size
|
||||
|
||||
|
||||
def _download_image(image_info):
|
||||
"""Downloads the specified image to the local file system.
|
||||
@ -550,9 +569,12 @@ def _download_image(image_info):
|
||||
|
||||
totaltime = time.time() - starttime
|
||||
LOG.info("Image downloaded from %(image_location)s "
|
||||
"in %(totaltime)s seconds",
|
||||
"in %(totaltime)s seconds. Transferred %(size)s bytes. "
|
||||
"Server originaly reported: %(reported)s.",
|
||||
{'image_location': image_location,
|
||||
'totaltime': totaltime})
|
||||
'totaltime': totaltime,
|
||||
'size': image_download.bytes_transferred,
|
||||
'reported': image_download.content_length})
|
||||
image_download.verify_image(image_location)
|
||||
|
||||
|
||||
@ -722,7 +744,11 @@ class StandbyExtension(base.BaseAgentExtension):
|
||||
|
||||
totaltime = time.time() - starttime
|
||||
LOG.info("Image streamed onto device %(device)s in %(totaltime)s "
|
||||
"seconds", {'device': device, 'totaltime': totaltime})
|
||||
"seconds for %(size)s bytes. Server originaly reported "
|
||||
"%(reported)s.",
|
||||
{'device': device, 'totaltime': totaltime,
|
||||
'size': image_download.bytes_transferred,
|
||||
'reported': image_download.content_length})
|
||||
# Verify if the checksum of the streamed image is correct
|
||||
image_download.verify_image(device)
|
||||
# Fix any gpt partition
|
||||
|
||||
@ -0,0 +1,5 @@
|
||||
---
|
||||
other:
|
||||
- |
|
||||
The agent now logs the size of data transferred when downloading images,
|
||||
which can be helpful in troubleshooting image download issues.
|
||||
@ -412,13 +412,16 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
|
||||
self.assertEqual(expected_uuid, work_on_disk_mock.return_value)
|
||||
|
||||
@mock.patch('ironic_python_agent.extensions.standby.LOG', autospec=True)
|
||||
@mock.patch('hashlib.new', autospec=True)
|
||||
@mock.patch('builtins.open', autospec=True)
|
||||
@mock.patch('requests.get', autospec=True)
|
||||
def test_download_image(self, requests_mock, open_mock, hash_mock):
|
||||
def test_download_image(self, requests_mock, open_mock, hash_mock,
|
||||
log_mock):
|
||||
image_info = _build_fake_image_info()
|
||||
response = requests_mock.return_value
|
||||
response.status_code = 200
|
||||
response.headers = {}
|
||||
response.iter_content.return_value = ['some', 'content']
|
||||
file_mock = mock.Mock()
|
||||
open_mock.return_value.__enter__.return_value = file_mock
|
||||
@ -435,6 +438,23 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
write.assert_any_call('some')
|
||||
write.assert_any_call('content')
|
||||
self.assertEqual(2, write.call_count)
|
||||
log_mock_calls = [
|
||||
mock.call.info('Attempting to download image from %s',
|
||||
'http://example.org'),
|
||||
mock.call.info('Image downloaded from %(image_location)s in '
|
||||
'%(totaltime)s seconds. Transferred %(size)s '
|
||||
'bytes. Server originaly reported: %(reported)s.',
|
||||
{'image_location': mock.ANY,
|
||||
'totaltime': mock.ANY,
|
||||
'size': 11,
|
||||
'reported': None}),
|
||||
mock.call.debug('Verifying image at %(image_location)s against '
|
||||
'%(algo_name)s checksum %(checksum)s',
|
||||
{'image_location': mock.ANY,
|
||||
'algo_name': mock.ANY,
|
||||
'checksum': 'fake-checksum'})
|
||||
]
|
||||
log_mock.assert_has_calls(log_mock_calls)
|
||||
|
||||
@mock.patch('hashlib.new', autospec=True)
|
||||
@mock.patch('builtins.open', autospec=True)
|
||||
@ -510,6 +530,7 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
image_location = '/foo/bar'
|
||||
image_download = standby.ImageDownload(image_info)
|
||||
image_download.verify_image(image_location)
|
||||
self.assertEqual(0, image_download.bytes_transferred)
|
||||
|
||||
@mock.patch('hashlib.new', autospec=True)
|
||||
@mock.patch('builtins.open', autospec=True)
|
||||
@ -1267,6 +1288,7 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
write_mock.assert_called_once_with(image_info, device,
|
||||
'configdrive_data')
|
||||
|
||||
@mock.patch('ironic_python_agent.extensions.standby.LOG', autospec=True)
|
||||
@mock.patch('ironic_lib.disk_utils.block_uuid', autospec=True)
|
||||
@mock.patch('ironic_lib.disk_utils.fix_gpt_partition', autospec=True)
|
||||
@mock.patch('hashlib.new', autospec=True)
|
||||
@ -1274,9 +1296,11 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
@mock.patch('requests.get', autospec=True)
|
||||
def test_stream_raw_image_onto_device(self, requests_mock, open_mock,
|
||||
hash_mock, fix_gpt_mock,
|
||||
block_uuid_mock):
|
||||
block_uuid_mock,
|
||||
mock_log):
|
||||
image_info = _build_fake_image_info()
|
||||
response = requests_mock.return_value
|
||||
response.headers = {'Content-Length': 11}
|
||||
response.status_code = 200
|
||||
response.iter_content.return_value = ['some', 'content']
|
||||
file_mock = mock.Mock()
|
||||
@ -1307,6 +1331,25 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
'aaaabbbb',
|
||||
self.agent_extension.partition_uuids['root uuid']
|
||||
)
|
||||
mock_log_calls = [
|
||||
mock.call.info('Attempting to download image from %s',
|
||||
'http://example.org'),
|
||||
mock.call.info('Image streamed onto device %(device)s in '
|
||||
'%(totaltime)s seconds for %(size)s bytes. '
|
||||
'Server originaly reported %(reported)s.',
|
||||
{'device': '/dev/foo',
|
||||
'totaltime': mock.ANY,
|
||||
'size': 11,
|
||||
'reported': 11}),
|
||||
mock.call.debug('Verifying image at %(image_location)s '
|
||||
'against %(algo_name)s checksum %(checksum)s',
|
||||
{'image_location': '/dev/foo',
|
||||
'algo_name': mock.ANY,
|
||||
'checksum': 'fake-checksum'}),
|
||||
mock.call.info('%(device)s UUID is now %(root_uuid)s',
|
||||
{'device': '/dev/foo', 'root_uuid': 'aaaabbbb'})
|
||||
]
|
||||
mock_log.assert_has_calls(mock_log_calls)
|
||||
|
||||
@mock.patch('hashlib.new', autospec=True)
|
||||
@mock.patch('builtins.open', autospec=True)
|
||||
@ -1318,6 +1361,7 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
image_info = _build_fake_image_info()
|
||||
response = requests_mock.return_value
|
||||
response.status_code = 200
|
||||
response.headers = {}
|
||||
response.iter_content.return_value = [b'some', b'content']
|
||||
file_mock = mock.Mock()
|
||||
open_mock.return_value.__enter__.return_value = file_mock
|
||||
@ -1369,6 +1413,10 @@ class TestStandbyExtension(base.IronicAgentTest):
|
||||
def iter_content(self, chunk_size):
|
||||
return self
|
||||
|
||||
@property
|
||||
def headers(self):
|
||||
return {}
|
||||
|
||||
self.config(image_download_connection_timeout=1)
|
||||
self.config(image_download_connection_retries=2)
|
||||
self.config(image_download_connection_retry_interval=0)
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user