Add logging to the library

ChangeLog.md

@@ -2,6 +2,11 @@
 
 > See [BreakingChanges](BreakingChanges.md) for a detailed list of API breaks.
 
+## Version XX.XX.XX:
+
+### All:
+- Added logging to the library, the name of the logger is 'azure.storage'. User must add handlers to the logger to output logs.
+
 ## Version 0.36.0:
 
 ### Blob:

README.rst

@@ -112,6 +112,34 @@ Usage
 To use this SDK to call Microsoft Azure storage services, you need to
 first `create an account`_.
 
+Logging
+-----------
+
+To make debugging easier, it is recommended to turn on logging for the logger named 'azure.storage'.
+Here are two example configurations:
+
+.. code:: python
+
+    # Basic configuration: configure the root logger, including 'azure.storage'
+    logging.basicConfig(format='%(asctime)s %(name)-20s %(levelname)-5s %(message)s', level=logging.INFO)
+
+.. code:: python
+
+    # More advanced configuration allowing more control
+    logger = logging.getLogger('azure.storage')
+    handler = logging.StreamHandler()
+    formatter = logging.Formatter('%(asctime)s %(name)-20s %(levelname)-5s %(message)s')
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    logger.setLevel(logging.INFO)
+
+Here is how we use the logging levels, it is recommended to use INFO:
+
+-  DEBUG: log strings to sign
+-  INFO: log outgoing requests and responses, as well as retry attempts
+-  WARNING: not used
+-  ERROR: log calls that still failed after all the retries
+
 Code Sample
 -----------
 

azure/storage/_auth.py

@@ -16,6 +16,9 @@ from ._common_conversion import (
     _sign_string,
 )
 
+import logging
+logger = logging.getLogger(__name__)
+
 
 class _StorageSharedKeyAuthentication(object):
     def __init__(self, account_name, account_key):
@@ -70,6 +73,7 @@ class _StorageSharedKeyAuthentication(_StorageSharedKeyAuthentication):
             self._get_canonicalized_resource_query(request)
 
         self._add_authorization_header(request, string_to_sign)
+        logger.debug("String_to_sign=%s", string_to_sign)
 
     def _get_canonicalized_resource_query(self, request):
         sorted_queries = [(name, value) for name, value in request.query.items()]
@@ -95,6 +99,7 @@ class _StorageTableSharedKeyAuthentication(_StorageSharedKeyAuthentication):
             self._get_canonicalized_resource_query(request)
 
         self._add_authorization_header(request, string_to_sign)
+        logger.debug("String_to_sign=%s", string_to_sign)
 
     def _get_canonicalized_resource_query(self, request):
         for name, value in request.query.items():

azure/storage/_http/httpclient.py

@@ -14,6 +14,9 @@
 #--------------------------------------------------------------------------
 import base64
 import sys
+import logging
+
+logger = logging.getLogger(__name__)
 
 if sys.version_info < (3,):
     from httplib import (
@@ -115,11 +118,11 @@ class _HTTPClient(object):
 
         # Parse the response
         status = int(response.status_code)
-        respheaders = {}
+        response_headers = {}
         for key, name in response.headers.items():
-            respheaders[key.lower()] = name
+            response_headers[key.lower()] = name
 
-        wrap = HTTPResponse(status, response.reason, respheaders, response.content)
+        wrap = HTTPResponse(status, response.reason, response_headers, response.content)
         response.close()
 
         return wrap

azure/storage/storageclient.py

@@ -18,6 +18,9 @@ import copy
 import requests
 from time import sleep
 from abc import ABCMeta
+import logging
+
+logger = logging.getLogger(__name__)
 
 from azure.common import (
     AzureException,
@@ -43,8 +46,8 @@ from ._error import (
     _http_error_handler,
 )
 
-class StorageClient(object):
 
+class StorageClient(object):
     '''
     This is the base class for service objects. Service objects are used to do 
     all requests to Storage. This class cannot be instantiated directly.
@@ -187,6 +190,22 @@ class StorageClient(object):
             request.host = request.host_locations.get(self.location_mode)
             retry_context.location_mode = self.location_mode
 
+    @staticmethod
+    def extract_date_and_request_id(retry_context):
+        if getattr(retry_context, 'response', None) is None:
+            return ""
+        resp = retry_context.response
+
+        if 'date' in resp.headers and 'x-ms-request-id' in resp.headers:
+            return str.format("Server-Timestamp={0}, Server-Request-ID={1}",
+                              resp.headers['date'], resp.headers['x-ms-request-id'])
+        elif 'date' in resp.headers:
+            return str.format("Server-Timestamp={0}", resp.headers['date'])
+        elif 'x-ms-request-id' in resp.headers:
+            return str.format("Server-Request-ID={0}", resp.headers['x-ms-request-id'])
+        else:
+            return ""
+
     def _perform_request(self, request, parser=None, parser_args=None, operation_context=None):
         '''
         Sends the request and return response. Catches HTTPError and hands it
@@ -200,6 +219,7 @@ class StorageClient(object):
 
         # Apply common settings to the request
         _update_request(request)
+        client_request_id_prefix = str.format("Client-Request-ID={0}", request.headers['x-ms-client-request-id'])
 
         while (True):
             try:
@@ -218,6 +238,14 @@ class StorageClient(object):
                     # Set the request context
                     retry_context.request = request
 
+                    # Log the request before it goes out
+                    logger.info("%s Outgoing request: Method=%s, Path=%s, Query=%s, Headers=%s.",
+                                client_request_id_prefix,
+                                request.method,
+                                request.path,
+                                request.query,
+                                str(request.headers).replace('\n', ''))
+
                     # Perform the request
                     response = self._httpclient.perform_request(request)
 
@@ -228,11 +256,21 @@ class StorageClient(object):
                     # Set the response context
                     retry_context.response = response
 
+                    # Log the response when it comes back
+                    logger.info("%s Receiving Response: "
+                                "%s, HTTP Status Code=%s, Message=%s, Headers=%s.",
+                                client_request_id_prefix,
+                                self.extract_date_and_request_id(retry_context),
+                                response.status,
+                                response.message,
+                                str(request.headers).replace('\n', ''))
+
                     # Parse and wrap HTTP errors in AzureHttpError which inherits from AzureException
                     if response.status >= 300:
                         # This exception will be caught by the general error handler
                         # and raised as an azure http exception
-                        _http_error_handler(HTTPError(response.status, response.message, response.headers, response.body))
+                        _http_error_handler(
+                            HTTPError(response.status, response.message, response.headers, response.body))
 
                     # Parse the response
                     if parser:
@@ -260,12 +298,32 @@ class StorageClient(object):
                             msg = ex.args[0]
                         raise AzureException('{}: {}'.format(ex.__class__.__name__, msg))
 
-
             except AzureException as ex:
+                # only parse the strings used for logging if logging is at least enabled for CRITICAL
+                if logger.isEnabledFor(logging.CRITICAL):
+                    exception_str_in_one_line = str(ex).replace('\n', '')
+                    status_code = retry_context.response.status if retry_context.response is not None else 'Unknown'
+                    timestamp_and_request_id = self.extract_date_and_request_id(retry_context)
+
+                logger.info("%s Operation failed: checking if the operation should be retried. "
+                            "Current retry count=%s, %s, HTTP status code=%s, Exception=%s.",
+                            client_request_id_prefix,
+                            retry_context.count if hasattr(retry_context, 'count') else 0,
+                            timestamp_and_request_id,
+                            status_code,
+                            exception_str_in_one_line)
+
                 # Decryption failures (invalid objects, invalid algorithms, data unencrypted in strict mode, etc)
                 # will not be resolved with retries.
                 if str(ex) == _ERROR_DECRYPTION_FAILURE:
+                    logger.error("%s Encountered decryption failure: this cannot be retried. "
+                                 "%s, HTTP status code=%s, Exception=%s.",
+                                 client_request_id_prefix,
+                                 timestamp_and_request_id,
+                                 status_code,
+                                 exception_str_in_one_line)
                     raise ex
+
                 # Determine whether a retry should be performed and if so, how 
                 # long to wait before performing retry.
                 retry_interval = self.retry(retry_context)
@@ -274,9 +332,21 @@ class StorageClient(object):
                     if self.retry_callback:
                         self.retry_callback(retry_context)
 
+                    logger.info(
+                        "%s Retry policy is allowing a retry: Retry count=%s, Interval=%s.",
+                        client_request_id_prefix,
+                        retry_context.count,
+                        retry_interval)
+
                     # Sleep for the desired retry interval
                     sleep(retry_interval)
                 else:
+                    logger.error("%s Retry policy did not allow for a retry: "
+                                 "%s, HTTP status code=%s, Exception=%s.",
+                                 client_request_id_prefix,
+                                 timestamp_and_request_id,
+                                 status_code,
+                                 exception_str_in_one_line)
                     raise ex
             finally:
                 # If this is a location locked operation and the location is not set, 

tests/testcase.py

@@ -32,13 +32,9 @@ import random
 import tests.settings_real as settings
 import tests.settings_fake as fake_settings
 
-should_log = os.getenv('SDK_TESTS_LOG', '0')
-if should_log.lower() == 'true' or should_log == '1':
+# Configure logging to output to console
 import logging
-    logger = logging.getLogger('azure.common.filters')
-    logger.setLevel(logging.DEBUG)
-    logger.addHandler(logging.StreamHandler())
-
+logging.basicConfig(format='%(asctime)s %(name)-20s %(levelname)-5s %(message)s', level=logging.INFO)
 
 class TestMode(object):
     none = 'None'.lower() # this will be for unit test, no need for any recordings