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)