Merge "Log the number of bytes downloaded"

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

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.

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)