Repository: boto/botocore
Pull request #1315 (2017-11-16 17:51:14)

Add history recorder
cc @dstufft @jamesls @kyleknap @joguSD @JordonPhillips 

codecov-io: # [Codecov](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=h1) Report
> Merging [#1315](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=desc) into [develop](https://codecov.io/gh/boto/botocore/commit/7c9a03f61ab48ca177a39a3affd52a2de7410f5b?src=pr&el=desc) will **increase** coverage by `0.01%`.
> The diff coverage is `100%`.

[![Impacted file tree graph](https://codecov.io/gh/boto/botocore/pull/1315/graphs/tree.svg?token=QOLXw6XSza&src=pr&height=150&width=650)](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree)

```diff
@@             Coverage Diff             @@
##           develop    #1315      +/-   ##
===========================================
+ Coverage    98.05%   98.06%   +0.01%     
===========================================
  Files           45       46       +1     
  Lines         7421     7460      +39     
===========================================
+ Hits          7277     7316      +39     
  Misses         144      144
```


| [Impacted Files](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [botocore/utils.py](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree#diff-Ym90b2NvcmUvdXRpbHMucHk=) | `95.99% <ø> (ø)` | :arrow_up: |
| [botocore/client.py](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree#diff-Ym90b2NvcmUvY2xpZW50LnB5) | `99.73% <100%> (ø)` | :arrow_up: |
| [botocore/history.py](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree#diff-Ym90b2NvcmUvaGlzdG9yeS5weQ==) | `100% <100%> (ø)` | |
| [botocore/endpoint.py](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=tree#diff-Ym90b2NvcmUvZW5kcG9pbnQucHk=) | `97.33% <100%> (+0.13%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=footer). Last update [7c9a03f...d4af8b6](https://codecov.io/gh/boto/botocore/pull/1315?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/botocore/client.py b/botocore/client.py
index 6c1884b34..35f4c0c4d 100644
--- a/botocore/client.py
+++ b/botocore/client.py
@@ -37,9 +37,11 @@ from botocore import UNSIGNED
 # Keep this imported.  There's pre-existing code that uses
 # "from botocore.client import Config".
 from botocore.config import Config
+from botocore.history import get_global_history_recorder
 
 
 logger = logging.getLogger(__name__)
+history_recorder = get_global_history_recorder()
 
 
 class ClientCreator(object):
@@ -566,6 +568,11 @@ class BaseClient(object):
     def _make_api_call(self, operation_name, api_params):
         operation_model = self._service_model.operation_model(operation_name)
         service_name = self._service_model.service_name
+        history_recorder.record('API_CALL', {
+            'service': service_name,
+            'operation': operation_name,
+            'params': api_params,
+        })
         if operation_model.deprecated:
             logger.debug('Warning: %s.%s() is deprecated',
                          service_name, operation_name)
diff --git a/botocore/endpoint.py b/botocore/endpoint.py
index 64ccfbd2c..5fc6a1011 100644
--- a/botocore/endpoint.py
+++ b/botocore/endpoint.py
@@ -31,10 +31,12 @@ from botocore.compat import filter_ssl_warnings
 from botocore.utils import is_valid_endpoint_url
 from botocore.hooks import first_non_none_response
 from botocore.response import StreamingBody
+from botocore.history import get_global_history_recorder
 from botocore import parsers
 
 
 logger = logging.getLogger(__name__)
+history_recorder = get_global_history_recorder()
 DEFAULT_TIMEOUT = 60
 MAX_POOL_CONNECTIONS = 10
 filter_ssl_warnings()
@@ -198,6 +200,13 @@ class Endpoint(object):
         # If no exception occurs then exception is None.
         try:
             logger.debug("Sending http request: %s", request)
+            history_recorder.record('HTTP_REQUEST', {
+                'method': request.method,
+                'headers': request.headers,
+                'streaming': operation_model.has_streaming_input,
+                'url': request.url,
+                'body': request.body
+            })
             http_response = self.http_session.send(
                 request, verify=self.verify,
                 stream=operation_model.has_streaming_output,
@@ -227,10 +236,17 @@ class Endpoint(object):
         # This returns the http_response and the parsed_data.
         response_dict = convert_to_response_dict(http_response,
                                                  operation_model)
+
+        http_response_record_dict = response_dict.copy()
+        http_response_record_dict['streaming'] = \
+            operation_model.has_streaming_output
+        history_recorder.record('HTTP_RESPONSE', http_response_record_dict)
+
         parser = self._response_parser_factory.create_parser(
             operation_model.metadata['protocol'])
         parsed_response = parser.parse(
             response_dict, operation_model.output_shape)
+        history_recorder.record('PARSED_RESPONSE', parsed_response)
         return (http_response, parsed_response), None
 
     def _looks_like_dns_error(self, e):
diff --git a/botocore/history.py b/botocore/history.py
new file mode 100644
index 000000000..c8265be99
--- /dev/null
+++ b/botocore/history.py
@@ -0,0 +1,59 @@
+# Copyright 2017 Amazon.com, Inc. or its affiliates. All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"). You
+# may not use this file except in compliance with the License. A copy of
+# the License is located at
+#
+# http://aws.amazon.com/apache2.0/
+#
+# or in the "license" file accompanying this file. This file is
+# distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF
+# ANY KIND, either express or implied. See the License for the specific
+# language governing permissions and limitations under the License.
+
+import threading
+import logging
+
+
+HISTORY_RECORDER = None
+logger = logging.getLogger(__name__)
+
+
+class BaseHistoryHandler(object):
+    def emit(self, event_type, payload, source):
+        raise NotImplementedError('emit()')
+
+
+class HistoryRecorder(object):
+    def __init__(self):
+        self._enabled = False
+        self._handlers = []
+        self._lock = threading.Lock()
+
+    def enable(self):
+        self._enabled = True
+
+    def disable(self):
+        self._enabled = False
+
+    def add_handler(self, handler):
+        self._handlers.append(handler)
+
+    def record(self, event_type, payload, source='BOTOCORE'):
+        if self._enabled and self._handlers:
+            with self._lock:
+                for handler in self._handlers:
+                    try:
+                        handler.emit(event_type, payload, source)
+                    except Exception:
+                        # Never let the process die because we had a failure in
+                        # a record collection handler.
+                        logger.debug("Exception raised in %s.", handler,
+                                     exc_info=True)
+
+
+def get_global_history_recorder():
+    global HISTORY_RECORDER
+    if HISTORY_RECORDER is None:
+        HISTORY_RECORDER = HistoryRecorder()
+    return HISTORY_RECORDER
diff --git a/botocore/utils.py b/botocore/utils.py
index 59cf34925..107dcce7b 100644
--- a/botocore/utils.py
+++ b/botocore/utils.py
@@ -930,7 +930,6 @@ class S3RegionRedirector(object):
             " %s; Please configure the proper region to avoid multiple "
             "unnecessary redirects and signing attempts." % (
                 client_region, bucket, new_region))
-
         endpoint = self._endpoint_resolver.resolve('s3', new_region)
         endpoint = endpoint['endpoint_url']
 


Test patch:
diff --git a/tests/functional/test_history.py b/tests/functional/test_history.py
new file mode 100644
index 000000000..379339d87
--- /dev/null
+++ b/tests/functional/test_history.py
@@ -0,0 +1,150 @@
+from contextlib import contextmanager
+
+import mock
+
+from tests import BaseSessionTest
+from botocore.history import BaseHistoryHandler
+from botocore.history import get_global_history_recorder
+
+
+class RecordingHandler(BaseHistoryHandler):
+    def __init__(self):
+        self.recorded_calls = []
+
+    def emit(self, event_type, payload, source):
+        self.recorded_calls.append((event_type, payload, source))
+
+
+class TestRecordStatementsInjections(BaseSessionTest):
+
+    def setUp(self):
+        super(TestRecordStatementsInjections, self).setUp()
+        self.client = self.session.create_client('s3', 'us-west-2')
+        self.s3_response_body = (
+            '<ListAllMyBucketsResult '
+            '    xmlns="http://s3.amazonaws.com/doc/2006-03-01/">'
+            '  <Owner>'
+            '    <ID>d41d8cd98f00b204e9800998ecf8427e</ID>'
+            '    <DisplayName>foo</DisplayName>'
+            '  </Owner>'
+            '  <Buckets>'
+            '    <Bucket>'
+            '      <Name>bar</Name>'
+            '      <CreationDate>1912-06-23T22:57:02.000Z</CreationDate>'
+            '    </Bucket>'
+            '  </Buckets>'
+            '</ListAllMyBucketsResult>'
+        ).encode('utf-8')
+        self.recording_handler = RecordingHandler()
+        history_recorder = get_global_history_recorder()
+        history_recorder.enable()
+        history_recorder.add_handler(self.recording_handler)
+
+    def _get_all_events_of_type(self, event_type):
+        recorded_calls = self.recording_handler.recorded_calls
+        matching = [call for call in recorded_calls
+                    if call[0] == event_type]
+        return matching
+
+    @contextmanager
+    def patch_http_layer(self, response, status_code=200):
+        with mock.patch('botocore.endpoint.Session.send') as send:
+            send.return_value = mock.Mock(status_code=status_code,
+                                          headers={},
+                                          content=response)
+            yield send
+
+    def test_does_record_api_call(self):
+        with self.patch_http_layer(self.s3_response_body):
+            self.client.list_buckets()
+
+        api_call_events = self._get_all_events_of_type('API_CALL')
+        self.assertEqual(len(api_call_events), 1)
+        event = api_call_events[0]
+        event_type, payload, source = event
+        self.assertEqual(payload, {
+                'operation': u'ListBuckets',
+                'params': {},
+                'service': 's3'
+        })
+        self.assertEqual(source, 'BOTOCORE')
+
+    def test_does_record_http_request(self):
+        with self.patch_http_layer(self.s3_response_body):
+            self.client.list_buckets()
+
+        http_request_events = self._get_all_events_of_type('HTTP_REQUEST')
+        self.assertEqual(len(http_request_events), 1)
+        event = http_request_events[0]
+        event_type, payload, source = event
+
+        method = payload['method']
+        self.assertEqual(method, u'GET')
+
+        # The header values vary too much per request to verify them here.
+        # Instead just check the presense of each expected header.
+        headers = payload['headers']
+        for expected_header in ['Authorization', 'User-Agent', 'X-Amz-Date',
+                                'X-Amz-Content-SHA256']:
+            self.assertIn(expected_header, headers)
+
+        body = payload['body']
+        self.assertIsNone(body)
+
+        streaming = payload['streaming']
+        self.assertEquals(streaming, False)
+
+        url = payload['url']
+        self.assertEquals(url, 'https://s3.us-west-2.amazonaws.com/')
+
+        self.assertEqual(source, 'BOTOCORE')
+
+    def test_does_record_http_response(self):
+        with self.patch_http_layer(self.s3_response_body):
+            self.client.list_buckets()
+
+        http_response_events = self._get_all_events_of_type('HTTP_RESPONSE')
+        self.assertEqual(len(http_response_events), 1)
+        event = http_response_events[0]
+        event_type, payload, source = event
+
+        self.assertEqual(payload, {
+                'status_code': 200,
+                'headers': {},
+                'streaming': False,
+                'body': self.s3_response_body
+            }
+        )
+        self.assertEqual(source, 'BOTOCORE')
+
+    def test_does_record_parsed_response(self):
+        with self.patch_http_layer(self.s3_response_body):
+            self.client.list_buckets()
+
+        parsed_response_events = self._get_all_events_of_type(
+            'PARSED_RESPONSE')
+        self.assertEqual(len(parsed_response_events), 1)
+        event = parsed_response_events[0]
+        event_type, payload, source = event
+
+        # Given that the request contains headers with a user agent string
+        # a date and a signature we need to disassemble the call and manually
+        # assert the interesting bits since mock can only assert if the args
+        # all match exactly.
+        owner = payload['Owner']
+        self.assertEqual(owner, {
+            'DisplayName': 'foo',
+            'ID': 'd41d8cd98f00b204e9800998ecf8427e'
+        })
+
+        buckets = payload['Buckets']
+        self.assertEqual(len(buckets), 1)
+        bucket = buckets[0]
+        self.assertEqual(bucket['Name'], 'bar')
+
+        metadata = payload['ResponseMetadata']
+        self.assertEqual(metadata, {
+            'HTTPHeaders': {},
+            'HTTPStatusCode': 200,
+            'RetryAttempts': 0
+        })
diff --git a/tests/unit/test_history.py b/tests/unit/test_history.py
new file mode 100644
index 000000000..d38459e14
--- /dev/null
+++ b/tests/unit/test_history.py
@@ -0,0 +1,90 @@
+from tests import unittest
+
+import mock
+
+from botocore.history import HistoryRecorder
+from botocore.history import BaseHistoryHandler
+from botocore.history import get_global_history_recorder
+
+
+class TerribleError(Exception):
+    pass
+
+
+class ExceptionThrowingHandler(BaseHistoryHandler):
+    def emit(self, event_type, payload, source):
+        raise TerribleError('Bad behaving handler')
+
+
+class TestHistoryRecorder(unittest.TestCase):
+    def test_can_attach_and_call_handler_emit(self):
+        mock_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.enable()
+        recorder.add_handler(mock_handler)
+        recorder.record('foo', 'bar', source='source')
+
+        mock_handler.emit.assert_called_with('foo', 'bar', 'source')
+
+    def test_can_call_multiple_handlers(self):
+        first_handler = mock.Mock(spec=BaseHistoryHandler)
+        second_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.enable()
+        recorder.add_handler(first_handler)
+        recorder.add_handler(second_handler)
+        recorder.record('foo', 'bar', source='source')
+
+        first_handler.emit.assert_called_with('foo', 'bar', 'source')
+        second_handler.emit.assert_called_with('foo', 'bar', 'source')
+
+    def test_does_use_botocore_source_by_default(self):
+        mock_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.enable()
+        recorder.add_handler(mock_handler)
+        recorder.record('foo', 'bar')
+
+        mock_handler.emit.assert_called_with('foo', 'bar', 'BOTOCORE')
+
+    def test_does_not_call_handlers_when_never_enabled(self):
+        mock_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.add_handler(mock_handler)
+        recorder.record('foo', 'bar')
+
+        mock_handler.emit.assert_not_called()
+
+    def test_does_not_call_handlers_when_disabled(self):
+        mock_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.enable()
+        recorder.disable()
+        recorder.add_handler(mock_handler)
+        recorder.record('foo', 'bar')
+
+        mock_handler.emit.assert_not_called()
+
+    def test_can_ignore_handler_exceptions(self):
+        mock_handler = mock.Mock(spec=BaseHistoryHandler)
+        recorder = HistoryRecorder()
+        recorder.enable()
+        bad_handler = ExceptionThrowingHandler()
+        recorder.add_handler(bad_handler)
+        recorder.add_handler(mock_handler)
+        try:
+            recorder.record('foo', 'bar')
+        except TerribleError:
+            self.fail('Should not have raised a TerribleError')
+        mock_handler.emit.assert_called_with('foo', 'bar', 'BOTOCORE')
+
+
+class TestGetHistoryRecorder(unittest.TestCase):
+    def test_can_get_history_recorder(self):
+        recorder = get_global_history_recorder()
+        self.assertTrue(isinstance(recorder, HistoryRecorder))
+
+    def test_does_reuse_history_recorder(self):
+        recorder_1 = get_global_history_recorder()
+        recorder_2 = get_global_history_recorder()
+        self.assertIs(recorder_1, recorder_2)