openstack/ironic-python-agent
Code Issues Proposed changes

Log the number of bytes downloaded

Browse Source 
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.

Note:
- A slightly odd backport because we touched nearby code for
  changes to handle checksum auto-detection.
- Also accounts for the fix in I458d88bf14b55253179488cb771ae42e7b8c84d7

Change-Id: Id71b167f4e330d54b9afddf95f1a2ef9e40398bf
(cherry picked from commit c65ad42ff1)
This commit is contained in:
Julia Kreger
2023-07-05 10:06:29 -07:00
parent 2fe6a4588c
commit 33188d91f9
3 changed files with 90 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files

41
ironic_python_agent/extensions/standby.py
View File

@@ -82,8 +82,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
@@ -292,6 +292,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
# Determine the hash algorithm and value will be used for calculation
# and verification, fallback to md5 if algorithm is not set or not
@@ -331,6 +333,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: {} '
@@ -363,7 +367,13 @@ class ImageDownload(object):
# this code.
if chunk:
self._last_chunk_time = time.time()
self._hash_algo.update(chunk)
if isinstance(chunk, str):
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):
@@ -400,6 +410,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.
@@ -438,9 +460,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)
@@ -603,7 +628,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

52
ironic_python_agent/tests/unit/extensions/test_standby.py
View File

@@ -373,13 +373,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.md5', autospec=True)
@mock.patch('builtins.open', autospec=True)
@mock.patch('requests.get', autospec=True)
def test_download_image(self, requests_mock, open_mock, md5_mock):
def test_download_image(self, requests_mock, open_mock, md5_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
@@ -396,6 +399,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': 'abc123'})
]
log_mock.assert_has_calls(log_mock_calls)
@mock.patch('hashlib.md5', autospec=True)
@mock.patch('builtins.open', autospec=True)
@@ -465,6 +485,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)
@@ -1199,6 +1220,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.md5', autospec=True)
@@ -1206,9 +1228,11 @@ class TestStandbyExtension(base.IronicAgentTest):
@mock.patch('requests.get', autospec=True)
def test_stream_raw_image_onto_device(self, requests_mock, open_mock,
md5_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()
@@ -1234,6 +1258,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': 'abc123'}),
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.md5', autospec=True)
@mock.patch('builtins.open', autospec=True)
@@ -1246,6 +1289,7 @@ class TestStandbyExtension(base.IronicAgentTest):
response = requests_mock.return_value
response.status_code = 200
response.iter_content.return_value = ['some', 'content']
response.headers = {}
file_mock = mock.Mock()
open_mock.return_value.__enter__.return_value = file_mock
file_mock.write.side_effect = Exception('Surprise!!!1!')
@@ -1296,6 +1340,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)

5
releasenotes/notes/log-download-size-57982fa8df336520.yaml Normal file
View File

@@ -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.