Merge "Refactoring to reduce noise in log files"

4 files changed, 23 insertions, 65 deletions

diff --git a/oslo/vmware/api.py b/oslo/vmware/api.py
index 352130a..65fe903 100644
--- a/oslo/vmware/api.py
+++ b/oslo/vmware/api.py
@@ -86,15 +86,12 @@ class RetryDecorator(object):
             func_name = f.__name__
             result = None
             try:
-                LOG.debug("Invoking %(func_name)s; retry count is "
-                          "%(retry_count)d.",
-                          {'func_name': func_name,
-                           'retry_count': self._retry_count})
+                if self._retry_count:
+                    LOG.debug("Invoking %(func_name)s; retry count is "
+                              "%(retry_count)d.",
+                              {'func_name': func_name,
+                               'retry_count': self._retry_count})
                 result = f(*args, **kwargs)
-                LOG.debug("Function %(func_name)s returned successfully "
-                          "after %(retry_count)d retries.",
-                          {'func_name': func_name,
-                           'retry_count': self._retry_count})
             except self._exceptions:
                 with excutils.save_and_reraise_exception() as ctxt:
                     LOG.warn(_LW("Exception which is in the suggested list of "
@@ -284,9 +281,6 @@ class VMwareAPISession(object):
                         exceptions=(exceptions.VimSessionOverLoadException,
                                     exceptions.VimConnectionException))
         def _invoke_api(module, method, *args, **kwargs):
-            LOG.debug("Invoking method %(module)s.%(method)s.",
-                      {'module': module,
-                       'method': method})
             try:
                 api_method = getattr(module, method)
                 return api_method(*args, **kwargs)
diff --git a/oslo/vmware/image_transfer.py b/oslo/vmware/image_transfer.py
index a86773d..fde72e7 100644
--- a/oslo/vmware/image_transfer.py
+++ b/oslo/vmware/image_transfer.py
@@ -74,7 +74,6 @@ class BlockingQueue(queue.LightQueue):
 
         :param data: data to be written
         """
-        LOG.debug("Writing %d data items into the queue.", len(data))
         self.put(data)
 
     # Below methods are provided in order to enable treating the queue
diff --git a/oslo/vmware/rw_handles.py b/oslo/vmware/rw_handles.py
index 6520276..e2f3358 100644
--- a/oslo/vmware/rw_handles.py
+++ b/oslo/vmware/rw_handles.py
@@ -38,6 +38,7 @@ from oslo.vmware import vim_util
 
 LOG = logging.getLogger(__name__)
 
+MIN_PROGRESS_DIFF_TO_LOG = 25
 READ_CHUNKSIZE = 65536
 USER_AGENT = 'OpenStack-ESX-Adapter'
 
@@ -56,6 +57,7 @@ class FileHandle(object):
         """
         self._eof = False
         self._file_handle = file_handle
+        self._last_logged_progress = 0
 
     def close(self):
         """Close the file handle."""
@@ -133,7 +135,6 @@ class FileHandle(object):
 
     def _find_vmdk_url(self, lease_info, host, port):
         """Find the URL corresponding to a VMDK file in lease info."""
-        LOG.debug("Finding VMDK URL from lease info.")
         url = None
         for deviceUrl in lease_info.deviceUrl:
             if deviceUrl.disk:
@@ -146,6 +147,13 @@ class FileHandle(object):
         LOG.debug("Found VMDK URL: %s from lease info.", url)
         return url
 
+    def _log_progress(self, progress):
+        """Log data transfer progress."""
+        if (progress == 100 or (progress - self._last_logged_progress >=
+                                MIN_PROGRESS_DIFF_TO_LOG)):
+            LOG.debug("Data transfer progress is %(progress)d%%.", progress)
+            self._last_logged_progress = progress
+
 
 class FileWriteHandle(FileHandle):
     """Write handle for a file in VMware server."""
@@ -199,8 +207,6 @@ class FileWriteHandle(FileHandle):
             conn.putheader('Content-Length', file_size)
             conn.putheader('Cookie', self._build_vim_cookie_header(cookies))
             conn.endheaders()
-            LOG.debug("Created HTTP connection to write to file with "
-                      "URL = %s.", url)
             return conn
         except (httplib.InvalidURL, httplib.CannotSendRequest,
                 httplib.CannotSendHeader) as excep:
@@ -215,7 +221,6 @@ class FileWriteHandle(FileHandle):
         :param data: data to be written
         :raises: VimConnectionException, VimException
         """
-        LOG.debug("Writing data to %s.", self._url)
         try:
             self._file_handle.send(data)
         except (socket.error, httplib.NotConnected) as excep:
@@ -241,7 +246,6 @@ class FileWriteHandle(FileHandle):
             LOG.warn(_LW("Error occurred while reading the HTTP response."),
                      exc_info=True)
         super(FileWriteHandle, self).close()
-        LOG.debug("Closed write handle for %s.", self._url)
 
     def __str__(self):
         return "File write handle for %s" % self._url
@@ -346,9 +350,6 @@ class VmdkWriteHandle(FileHandle):
             conn.putheader('Cookie', self._build_vim_cookie_header(cookies))
             conn.putheader('Content-Type', 'binary/octet-stream')
             conn.endheaders()
-            LOG.debug("Created HTTP connection to write to VMDK file with "
-                      "URL = %s.",
-                      url)
             return conn
         except (httplib.InvalidURL, httplib.CannotSendRequest,
                 httplib.CannotSendHeader) as excep:
@@ -363,15 +364,9 @@ class VmdkWriteHandle(FileHandle):
         :param data: data to be written
         :raises: VimConnectionException, VimException
         """
-        LOG.debug("Writing data to VMDK file with URL = %s.", self._url)
-
         try:
             self._file_handle.send(data)
             self._bytes_written += len(data)
-            LOG.debug("Total %(bytes_written)d bytes written to VMDK file "
-                      "with URL = %(url)s.",
-                      {'bytes_written': self._bytes_written,
-                       'url': self._url})
         except (socket.error, httplib.NotConnected) as excep:
             excep_msg = _("Connection error occurred while writing data to"
                           " %s.") % self._url
@@ -386,6 +381,7 @@ class VmdkWriteHandle(FileHandle):
             LOG.exception(excep_msg)
             raise exceptions.VimException(excep_msg, excep)
 
+    # TODO(vbala) Move this method to FileHandle.
     def update_progress(self):
         """Updates progress to lease.
 
@@ -395,20 +391,14 @@ class VmdkWriteHandle(FileHandle):
         :raises: VimException, VimFaultException, VimAttributeException,
                  VimSessionOverLoadException, VimConnectionException
         """
-        percent = int(float(self._bytes_written) / self._vmdk_size * 100)
-        LOG.debug("Calling VIM API to update write progress of VMDK file"
-                  " with URL = %(url)s to %(percent)d%%.",
-                  {'url': self._url,
-                   'percent': percent})
+        progress = int(float(self._bytes_written) / self._vmdk_size * 100)
+        self._log_progress(progress)
+
         try:
             self._session.invoke_api(self._session.vim,
                                      'HttpNfcLeaseProgress',
                                      self._lease,
-                                     percent=percent)
-            LOG.debug("Updated write progress of VMDK file with "
-                      "URL = %(url)s to %(percent)d%%.",
-                      {'url': self._url,
-                       'percent': percent})
+                                     percent=progress)
         except exceptions.VimException:
             with excutils.save_and_reraise_exception():
                 LOG.exception(_LE("Error occurred while updating the "
@@ -437,7 +427,6 @@ class VmdkWriteHandle(FileHandle):
                 self._session.invoke_api(self._session.vim,
                                          'HttpNfcLeaseComplete',
                                          self._lease)
-                LOG.debug("Lease for %s released.", self._url)
             else:
                 LOG.debug("Lease for %(url)s is in state: %(state)s; no "
                           "need to release.",
@@ -512,7 +501,6 @@ class VmdkReadHandle(FileHandle):
                        'Cookie': self._build_vim_cookie_header(cookies)}
             request = urllib2.Request(url, None, headers)
             conn = urllib2.urlopen(request)
-            LOG.debug("URL: %s opened for reading.", url)
             return conn
         except Exception as excep:
             # TODO(vbala) We need to catch and raise specific exceptions
@@ -530,15 +518,9 @@ class VmdkReadHandle(FileHandle):
         :returns: the data
         :raises: VimException
         """
-        LOG.debug("Reading data from VMDK file with URL = %s.", self._url)
-
         try:
             data = self._file_handle.read(READ_CHUNKSIZE)
             self._bytes_read += len(data)
-            LOG.debug("Total %(bytes_read)d bytes read from VMDK file "
-                      "with URL = %(url)s.",
-                      {'bytes_read': self._bytes_read,
-                       'url': self._url})
             return data
         except Exception as excep:
             # TODO(vbala) We need to catch and raise specific exceptions
@@ -558,20 +540,14 @@ class VmdkReadHandle(FileHandle):
         :raises: VimException, VimFaultException, VimAttributeException,
                  VimSessionOverLoadException, VimConnectionException
         """
-        percent = int(float(self._bytes_read) / self._vmdk_size * 100)
-        LOG.debug("Calling VIM API to update read progress of VMDK file"
-                  " with URL = %(url)s to %(percent)d%%.",
-                  {'url': self._url,
-                   'percent': percent})
+        progress = int(float(self._bytes_read) / self._vmdk_size * 100)
+        self._log_progress(progress)
+
         try:
             self._session.invoke_api(self._session.vim,
                                      'HttpNfcLeaseProgress',
                                      self._lease,
-                                     percent=percent)
-            LOG.debug("Updated read progress of VMDK file with "
-                      "URL = %(url)s to %(percent)d%%.",
-                      {'url': self._url,
-                       'percent': percent})
+                                     percent=progress)
         except exceptions.VimException:
             with excutils.save_and_reraise_exception():
                 LOG.exception(_LE("Error occurred while updating the "
@@ -599,7 +575,6 @@ class VmdkReadHandle(FileHandle):
                 self._session.invoke_api(self._session.vim,
                                          'HttpNfcLeaseComplete',
                                          self._lease)
-                LOG.debug("Lease for %s released.", self._url)
             else:
                 LOG.debug("Lease for %(url)s is in state: %(state)s; no "
                           "need to release.",
@@ -636,7 +611,6 @@ class ImageReadHandle(object):
         """
         try:
             data = next(self._iter)
-            LOG.debug("Read %d bytes from the image iterator.", len(data))
             return data
         except StopIteration:
             LOG.debug("Completed reading data from the image iterator.")
diff --git a/oslo/vmware/service.py b/oslo/vmware/service.py
index db6f2b5..6ab945c 100644
--- a/oslo/vmware/service.py
+++ b/oslo/vmware/service.py
@@ -102,7 +102,6 @@ class Service(object):
         :param response: response from RetrievePropertiesEx API call
         :raises: VimFaultException
         """
-        LOG.debug("Checking RetrievePropertiesEx API response for faults.")
         fault_list = []
         details = {}
         if not response:
@@ -134,7 +133,6 @@ class Service(object):
             raise exceptions.VimFaultException(fault_list,
                                                fault_string,
                                                details=details)
-        LOG.debug("No faults found in RetrievePropertiesEx API response.")
 
     @property
     def service_content(self):
@@ -174,16 +172,9 @@ class Service(object):
                 if managed_object is None:
                     return
                 request = getattr(self.client.service, attr_name)
-                LOG.debug("Invoking %(attr_name)s on %(moref)s.",
-                          {'attr_name': attr_name,
-                           'moref': managed_object})
                 response = request(managed_object, **kwargs)
                 if (attr_name.lower() == 'retrievepropertiesex'):
                     Service._retrieve_properties_ex_fault_checker(response)
-                LOG.debug("Invocation of %(attr_name)s on %(moref)s "
-                          "completed successfully.",
-                          {'attr_name': attr_name,
-                           'moref': managed_object})
                 return response
             except exceptions.VimFaultException:
                 # Catch the VimFaultException that is raised by the fault