From c65ad42ff1571a4658bc64c12093b0dc4320c805 Mon Sep 17 00:00:00 2001 From: Julia Kreger Date: Wed, 5 Jul 2023 10:06:29 -0700 Subject: [PATCH] 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 --- ironic_python_agent/extensions/standby.py | 38 +++++++++++--- .../log-download-size-57982fa8df336520.yaml | 5 ++ .../tests/unit/extensions/test_standby.py | 52 ++++++++++++++++++- 3 files changed, 87 insertions(+), 8 deletions(-) create mode 100644 ironic_python_agent/releasenotes/notes/log-download-size-57982fa8df336520.yaml diff --git a/ironic_python_agent/extensions/standby.py b/ironic_python_agent/extensions/standby.py index e98ae528b..53b1903c8 100644 --- a/ironic_python_agent/extensions/standby.py +++ b/ironic_python_agent/extensions/standby.py @@ -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 diff --git a/ironic_python_agent/releasenotes/notes/log-download-size-57982fa8df336520.yaml b/ironic_python_agent/releasenotes/notes/log-download-size-57982fa8df336520.yaml new file mode 100644 index 000000000..ee8e26c40 --- /dev/null +++ b/ironic_python_agent/releasenotes/notes/log-download-size-57982fa8df336520.yaml @@ -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. diff --git a/ironic_python_agent/tests/unit/extensions/test_standby.py b/ironic_python_agent/tests/unit/extensions/test_standby.py index 07e0d89d6..c015c036b 100644 --- a/ironic_python_agent/tests/unit/extensions/test_standby.py +++ b/ironic_python_agent/tests/unit/extensions/test_standby.py @@ -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)