[REST] az rest: Dump request and response (#12117)

src/azure-cli-core/azure/cli/core/tests/test_util.py

@@ -346,12 +346,12 @@ def test_configured_default_setter(self):
         self.assertTrue(config.use_local_config)
 
     @mock.patch('azure.cli.core._profile.Profile.get_raw_token', autospec=True)
-    @mock.patch('requests.request', autospec=True)
-    def test_send_raw_requests(self, request_mock, get_raw_token_mock):
+    @mock.patch('requests.Session.send', autospec=True)
+    def test_send_raw_requests(self, send_mock, get_raw_token_mock):
         from azure.cli.core.commands.client_factory import UA_AGENT
         return_val = mock.MagicMock()
         return_val.is_ok = True
-        request_mock.return_value = return_val
+        send_mock.return_value = return_val
         get_raw_token_mock.return_value = ("Bearer", "eyJ0eXAiOiJKV1", None), None, None
 
         cli_ctx = DummyCli()
@@ -361,68 +361,70 @@ def test_send_raw_requests(self, request_mock, get_raw_token_mock):
         }
         test_arm_active_directory_resource_id = 'https://management.core.windows.net/'
         test_arm_endpoint = 'https://management.azure.com/'
-
         arm_resource_id = '/subscriptions/01/resourcegroups/02?api-version=2019-07-01'
         full_arm_rest_url = test_arm_endpoint.rstrip('/') + arm_resource_id
-        tets_uri_parameters = ['p1=v1', "{'p2': 'v2'}"]
         test_body = '{"b1": "v1"}'
 
         expected_header = {
             'User-Agent': UA_AGENT,
+            'Accept-Encoding': 'gzip, deflate',
+            'Accept': '*/*',
+            'Connection': 'keep-alive',
             'Content-Type': 'application/json',
             'CommandName': 'rest',
-            'ParameterSetName': 'method uri'
+            'ParameterSetName': 'method uri',
+            'Content-Length': '12'
         }
         expected_header_with_auth = expected_header.copy()
         expected_header_with_auth['Authorization'] = 'Bearer eyJ0eXAiOiJKV1'
 
         # Test Authorization header is skipped
-        send_raw_request(cli_ctx, 'PUT', arm_resource_id, uri_parameters=tets_uri_parameters, body=test_body,
+        # Mock Put Blob https://docs.microsoft.com/en-us/rest/api/storageservices/put-blob
+        # Authenticate with service SAS https://docs.microsoft.com/en-us/rest/api/storageservices/create-service-sas
+        sas_token = ['sv=2019-02-02', 'srt=s', "{'ss': 'bf'}"]
+        send_raw_request(cli_ctx, 'PUT', 'https://myaccount.blob.core.windows.net/mycontainer/myblob?timeout=30',
+                         uri_parameters=sas_token, body=test_body,
                          skip_authorization_header=True, generated_client_request_id_name=None)
 
         get_raw_token_mock.assert_not_called()
-        request_mock.assert_called_with('PUT', full_arm_rest_url,
-                                        params={'p1': 'v1', 'p2': 'v2'}, data=test_body,
-                                        headers=expected_header, verify=(not should_disable_connection_verify()))
+        request = send_mock.call_args.args[1]
+        self.assertEqual(request.method, 'PUT')
+        self.assertEqual(request.url, 'https://myaccount.blob.core.windows.net/mycontainer/myblob?timeout=30&sv=2019-02-02&srt=s&ss=bf')
+        self.assertEqual(request.body, '{"b1": "v1"}')
+        self.assertDictEqual(dict(request.headers), expected_header)
+        self.assertEqual(send_mock.call_args.kwargs["verify"], not should_disable_connection_verify())
 
-        # Test uri /subscriptions/01/resourcegroups/02?api-version=2019-07-01
-        send_raw_request(cli_ctx, 'PUT', arm_resource_id, uri_parameters=tets_uri_parameters, body=test_body,
-                         generated_client_request_id_name=None)
+        # Test ARM resource ID /subscriptions/01/resourcegroups/02?api-version=2019-07-01
+        send_raw_request(cli_ctx, 'GET', arm_resource_id)
 
         get_raw_token_mock.assert_called_with(mock.ANY, test_arm_active_directory_resource_id)
-        request_mock.assert_called_with('PUT', full_arm_rest_url,
-                                        params={'p1': 'v1', 'p2': 'v2'}, data=test_body,
-                                        headers=expected_header_with_auth, verify=(not should_disable_connection_verify()))
+        request = send_mock.call_args.args[1]
+        self.assertEqual(request.url, 'https://management.azure.com/subscriptions/01/resourcegroups/02?api-version=2019-07-01')
 
-        # Test uri https://management.azure.com/subscriptions/01/resourcegroups/02?api-version=2019-07-01
-        send_raw_request(cli_ctx, 'PUT', full_arm_rest_url, uri_parameters=tets_uri_parameters,
-                         body=test_body, generated_client_request_id_name=None)
+        # Test full ARM URL https://management.azure.com/subscriptions/01/resourcegroups/02?api-version=2019-07-01
+        send_raw_request(cli_ctx, 'GET', full_arm_rest_url)
 
         get_raw_token_mock.assert_called_with(mock.ANY, test_arm_active_directory_resource_id)
-        request_mock.assert_called_with('PUT', full_arm_rest_url,
-                                        params={'p1': 'v1', 'p2': 'v2'}, data=test_body,
-                                        headers=expected_header_with_auth, verify=(not should_disable_connection_verify()))
+        request = send_mock.call_args.args[1]
+        self.assertEqual(request.url, 'https://management.azure.com/subscriptions/01/resourcegroups/02?api-version=2019-07-01')
 
-        # Test uri https://management.azure.com:443/subscriptions/01/resourcegroups/02?api-version=2019-07-01
-        # Port is included
+        # Test full ARM URL with port https://management.azure.com:443/subscriptions/01/resourcegroups/02?api-version=2019-07-01
         test_arm_endpoint_with_port = 'https://management.azure.com:443/'
         full_arm_rest_url_with_port = test_arm_endpoint_with_port.rstrip('/') + arm_resource_id
-        send_raw_request(cli_ctx, 'PUT', full_arm_rest_url_with_port, uri_parameters=tets_uri_parameters,
-                         body=test_body, generated_client_request_id_name=None)
+        send_raw_request(cli_ctx, 'GET', full_arm_rest_url_with_port)
 
         get_raw_token_mock.assert_called_with(mock.ANY, test_arm_active_directory_resource_id)
-        request_mock.assert_called_with('PUT', full_arm_rest_url_with_port,
-                                        params={'p1': 'v1', 'p2': 'v2'}, data=test_body,
-                                        headers=expected_header_with_auth, verify=(not should_disable_connection_verify()))
+        request = send_mock.call_args.args[1]
+        self.assertEqual(request.url, 'https://management.azure.com:443/subscriptions/01/resourcegroups/02?api-version=2019-07-01')
 
-        # Test uri https://graph.microsoft.com/beta/appRoleAssignments/01
+        # Test MS Graph API https://graph.microsoft.com/beta/appRoleAssignments/01
         send_raw_request(cli_ctx, 'PATCH', 'https://graph.microsoft.com/beta/appRoleAssignments/01',
-                         uri_parameters=tets_uri_parameters, body=test_body, generated_client_request_id_name=None)
+                         body=test_body, generated_client_request_id_name=None)
 
         get_raw_token_mock.assert_called_with(mock.ANY, 'https://graph.microsoft.com/')
-        request_mock.assert_called_with('PATCH', 'https://graph.microsoft.com/beta/appRoleAssignments/01',
-                                        params={'p1': 'v1', 'p2': 'v2'}, data=test_body,
-                                        headers=expected_header_with_auth, verify=(not should_disable_connection_verify()))
+        request = send_mock.call_args.args[1]
+        self.assertEqual(request.method, 'PATCH')
+        self.assertEqual(request.url, 'https://graph.microsoft.com/beta/appRoleAssignments/01')
 
     @staticmethod
     def _get_mock_HttpOperationError(response_text):

src/azure-cli-core/azure/cli/core/util.py

@@ -13,6 +13,7 @@
 import ssl
 import six
 import re
+import logging
 
 from six.moves.urllib.request import urlopen  # pylint: disable=import-error
 from knack.log import get_logger
@@ -540,7 +541,7 @@ def send_raw_request(cli_ctx, method, uri, headers=None, uri_parameters=None,  #
                      body=None, skip_authorization_header=False, resource=None, output_file=None,
                      generated_client_request_id_name='x-ms-client-request-id'):
     import uuid
-    import requests
+    from requests import Session, Request
     from azure.cli.core.commands.client_factory import UA_AGENT
 
     result = {}
@@ -623,9 +624,16 @@ def send_raw_request(cli_ctx, method, uri, headers=None, uri_parameters=None,  #
             logger.warning("Can't derive appropriate Azure AD resource from --url to acquire an access token. "
                            "If access token is required, use --resource to specify the resource")
     try:
-        r = requests.request(method, uri, params=uri_parameters, data=body, headers=headers,
-                             verify=not should_disable_connection_verify())
-        logger.debug("Response Header : %s", r.headers if r else '')
+        # https://requests.readthedocs.io/en/latest/user/advanced/#prepared-requests
+        s = Session()
+        req = Request(method=method, url=uri, headers=headers, params=uri_parameters, data=body)
+        prepped = s.prepare_request(req)
+
+        # Merge environment settings into session
+        settings = s.merge_environment_settings(prepped.url, {}, None, not should_disable_connection_verify(), None)
+        _log_request(prepped)
+        r = s.send(prepped, **settings)
+        _log_response(r)
     except Exception as ex:  # pylint: disable=broad-except
         raise CLIError(ex)
 
@@ -641,6 +649,69 @@ def send_raw_request(cli_ctx, method, uri, headers=None, uri_parameters=None,  #
     return r
 
 
+def _log_request(request):
+    """Log a client request. Copied from msrest
+    https://github.com/Azure/msrest-for-python/blob/3653d29fc44da408898b07c710290a83d196b777/msrest/http_logger.py#L39
+    """
+    if not logger.isEnabledFor(logging.DEBUG):
+        return
+
+    try:
+        logger.info("Request URL: %r", request.url)
+        logger.info("Request method: %r", request.method)
+        logger.info("Request headers:")
+        for header, value in request.headers.items():
+            if header.lower() == 'authorization':
+                value = value[:15] + '*****'
+            logger.info("    %r: %r", header, value)
+        logger.info("Request body:")
+
+        # We don't want to log the binary data of a file upload.
+        import types
+        if isinstance(request.body, types.GeneratorType):
+            logger.info("File upload")
+        else:
+            logger.info(str(request.body))
+    except Exception as err:  # pylint: disable=broad-except
+        logger.info("Failed to log request: %r", err)
+
+
+def _log_response(response, **kwargs):
+    """Log a server response. Copied from msrest
+    https://github.com/Azure/msrest-for-python/blob/3653d29fc44da408898b07c710290a83d196b777/msrest/http_logger.py#L68
+    """
+    if not logger.isEnabledFor(logging.DEBUG):
+        return None
+
+    try:
+        logger.info("Response status: %r", response.status_code)
+        logger.info("Response headers:")
+        for res_header, value in response.headers.items():
+            logger.info("    %r: %r", res_header, value)
+
+        # We don't want to log binary data if the response is a file.
+        logger.info("Response content:")
+        pattern = re.compile(r'attachment; ?filename=["\w.]+', re.IGNORECASE)
+        header = response.headers.get('content-disposition')
+
+        if header and pattern.match(header):
+            filename = header.partition('=')[2]
+            logger.info("File attachments: %s", filename)
+        elif response.headers.get("content-type", "").endswith("octet-stream"):
+            logger.info("Body contains binary data.")
+        elif response.headers.get("content-type", "").startswith("image"):
+            logger.info("Body contains image data.")
+        else:
+            if kwargs.get('stream', False):
+                logger.info("Body is streamable")
+            else:
+                logger.info(response.content.decode("utf-8-sig"))
+        return response
+    except Exception as err:  # pylint: disable=broad-except
+        logger.info("Failed to log response: %s", repr(err))
+        return response
+
+
 class ConfiguredDefaultSetter(object):
 
     def __init__(self, cli_config, use_local_config=None):

src/azure-cli/HISTORY.rst

@@ -665,7 +665,8 @@ Release History
 * Add new command `az reservations reservation-order calculate` to calculate the price for a reservation
 * Add new command `az reservations reservation-order purchase` to purchase a new reservation
 
-**Rest**
+**REST**
+
 * `az rest` is now GA
 
 **SQL**