Actually fix MostRecentProvider reuse bug

CHANGELOG.rst

@@ -2,6 +2,14 @@
 Changelog
 *********
 
+1.0.7 -- 2018-01-xx
+===================
+
+Bugfixes
+--------
+* Fix :class:`MostRecentProvider` cache reuse bug.
+  `#105 <https://github.com/aws/aws-dynamodb-encryption-python/pull/105>`_
+
 1.0.6 -- 2018-01-15
 ===================
 

src/dynamodb_encryption_sdk/encrypted/item.py

@@ -70,7 +70,6 @@ def encrypt_dynamodb_item(item, crypto_config):
                 'Reserved attribute name "{}" is not allowed in plaintext item.'.format(reserved_name.value)
             )
 
-    crypto_config.materials_provider.refresh()
     encryption_materials = crypto_config.encryption_materials()
 
     inner_material_description = encryption_materials.material_description.copy()

src/dynamodb_encryption_sdk/internal/utils.py

@@ -59,10 +59,8 @@ class TableInfoCache(object):
     _client = attr.ib(validator=attr.validators.instance_of(botocore.client.BaseClient))
     _auto_refresh_table_indexes = attr.ib(validator=attr.validators.instance_of(bool))
 
-    def __init__(
-        self, client, auto_refresh_table_indexes  # type: botocore.client.BaseClient  # type: bool
-    ):  # noqa=D107
-        # type: (...) -> None
+    def __init__(self, client, auto_refresh_table_indexes):  # noqa=D107
+        # type: (botocore.client.BaseClient, bool) -> None
         # Workaround pending resolution of attrs/mypy interaction.
         # https://github.com/python/mypy/issues/2088
         # https://github.com/python-attrs/attrs/issues/215

src/dynamodb_encryption_sdk/material_providers/most_recent.py

@@ -112,6 +112,7 @@ def get(self, name):
     def clear(self):
         # type: () -> None
         """Clear the cache."""
+        _LOGGER.debug("Clearing cache")
         with self._cache_lock:
             self._cache = OrderedDict()  # type: OrderedDict[Any, Any] # pylint: disable=attribute-defined-outside-init
 
@@ -163,8 +164,10 @@ def decryption_materials(self, encryption_context):
         """
         version = self._provider_store.version_from_material_description(encryption_context.material_description)
         try:
+            _LOGGER.debug("Looking in cache for decryption materials provider version %d", version)
             provider = self._cache.get(version)
         except KeyError:
+            _LOGGER.debug("Decryption materials provider not found in cache")
             try:
                 provider = self._provider_store.provider(self._material_name, version)
             except InvalidVersionError:
@@ -183,6 +186,7 @@ def _ttl_action(self):
         :rtype: TtlActions
         """
         if self._version is None:
+            _LOGGER.debug("TTL Expired because no version is known")
             return TtlActions.EXPIRED
 
         time_since_updated = time.time() - self._last_updated
@@ -193,6 +197,7 @@ def _ttl_action(self):
         elif time_since_updated < self._version_ttl + _GRACE_PERIOD:
             return TtlActions.GRACE_PERIOD
 
+        _LOGGER.debug("TTL Expired because known version has expired")
         return TtlActions.EXPIRED
 
     def _get_max_version(self):
@@ -260,6 +265,8 @@ def _get_most_recent_version(self, allow_local):
         finally:
             self._lock.release()
 
+        _LOGGER.debug("New latest version is %d", self._version)
+
         return provider
 
     def encryption_materials(self, encryption_context):
@@ -271,28 +278,32 @@ def encryption_materials(self, encryption_context):
         """
         ttl_action = self._ttl_action()
 
+        _LOGGER.debug('TTL Action "%s" when getting encryption materials', ttl_action.name)
+
         provider = None
 
         if ttl_action is TtlActions.LIVE:
             try:
-                _LOGGER.debug("Looking in cache for materials provider version %d", self._version)
+                _LOGGER.debug("Looking in cache for encryption materials provider version %d", self._version)
                 provider = self._cache.get(self._version)
             except KeyError:
-                _LOGGER.debug("Provider not found in cache")
+                _LOGGER.debug("Encryption materials provider not found in cache")
                 ttl_action = TtlActions.EXPIRED
 
         if provider is None:
             # Just get the latest local version if we cannot acquire the lock.
             # Otherwise, block until we can acquire the lock.
             allow_local = bool(ttl_action is TtlActions.GRACE_PERIOD)
 
+            _LOGGER.debug("Getting most recent materials provider version")
             provider = self._get_most_recent_version(allow_local)
 
         return provider.encryption_materials(encryption_context)
 
     def refresh(self):
         # type: () -> None
         """Clear all local caches for this provider."""
+        _LOGGER.debug("Refreshing MostRecentProvider instance.")
         with self._lock:
             self._cache.clear()
             self._version = None  # type: int # pylint: disable=attribute-defined-outside-init

src/dynamodb_encryption_sdk/material_providers/store/meta.py

@@ -11,6 +11,7 @@
 # ANY KIND, either express or implied. See the License for the specific
 # language governing permissions and limitations under the License.
 """Meta cryptographic provider store."""
+import logging
 from enum import Enum
 
 import attr
@@ -22,7 +23,7 @@
 from dynamodb_encryption_sdk.delegated_keys.jce import JceNameLocalDelegatedKey
 from dynamodb_encryption_sdk.encrypted.table import EncryptedTable
 from dynamodb_encryption_sdk.exceptions import InvalidVersionError, NoKnownVersionError, VersionAlreadyExistsError
-from dynamodb_encryption_sdk.identifiers import EncryptionKeyType, KeyEncodingType
+from dynamodb_encryption_sdk.identifiers import LOGGER_NAME, EncryptionKeyType, KeyEncodingType
 from dynamodb_encryption_sdk.material_providers import CryptographicMaterialsProvider
 from dynamodb_encryption_sdk.material_providers.wrapped import WrappedCryptographicMaterialsProvider
 
@@ -36,6 +37,7 @@
 
 
 __all__ = ("MetaStore",)
+_LOGGER = logging.getLogger(LOGGER_NAME)
 
 
 class MetaStoreAttributeNames(Enum):
@@ -104,6 +106,7 @@ def create_table(cls, client, table_name, read_units, write_units):
         :param int read_units: Read capacity units to provision
         :param int write_units: Write capacity units to provision
         """
+        _LOGGER.debug("Creating MetaStore table")
         try:
             client.create_table(
                 TableName=table_name,
@@ -127,6 +130,7 @@ def _load_materials(self, material_name, version):
         :returns: Materials loaded into delegated keys
         :rtype: tuple(JceNameLocalDelegatedKey)
         """
+        _LOGGER.debug('Loading material "%s" version %d from MetaStore table', material_name, version)
         key = {MetaStoreAttributeNames.PARTITION.value: material_name, MetaStoreAttributeNames.SORT.value: version}
         response = self._encrypted_table.get_item(Key=key)
         try:
@@ -168,6 +172,7 @@ def _save_materials(self, material_name, version, encryption_key, signing_key):
         :param int version: Version of material to locate
         :raises VersionAlreadyExistsError: if the specified version already exists
         """
+        _LOGGER.debug('Saving material "%s" version %d to MetaStore table', material_name, version)
         item = {
             MetaStoreAttributeNames.PARTITION.value: material_name,
             MetaStoreAttributeNames.SORT.value: version,

test/functional/functional_test_utils.py

@@ -16,15 +16,14 @@
 import base64
 import copy
 import itertools
-import logging
 import os
 from collections import defaultdict
 from decimal import Decimal
 
 import boto3
 import pytest
-import six
 from boto3.dynamodb.types import Binary
+from botocore.exceptions import NoRegionError
 from moto import mock_dynamodb2
 
 from dynamodb_encryption_sdk.delegated_keys.jce import JceNameLocalDelegatedKey
@@ -34,6 +33,7 @@
 from dynamodb_encryption_sdk.encrypted.table import EncryptedTable
 from dynamodb_encryption_sdk.identifiers import CryptoAction
 from dynamodb_encryption_sdk.internal.identifiers import ReservedAttributes
+from dynamodb_encryption_sdk.material_providers.most_recent import MostRecentProvider
 from dynamodb_encryption_sdk.material_providers.static import StaticCryptographicMaterialsProvider
 from dynamodb_encryption_sdk.material_providers.store.meta import MetaStore
 from dynamodb_encryption_sdk.material_providers.wrapped import WrappedCryptographicMaterialsProvider
@@ -44,11 +44,12 @@
 RUNNING_IN_TRAVIS = "TRAVIS" in os.environ
 _DELEGATED_KEY_CACHE = defaultdict(lambda: defaultdict(dict))
 TEST_TABLE_NAME = "my_table"
+TEST_REGION_NAME = "us-west-2"
 TEST_INDEX = {
     "partition_attribute": {"type": "S", "value": "test_value"},
     "sort_attribute": {"type": "N", "value": Decimal("99.233")},
 }
-SECONARY_INDEX = {
+SECONDARY_INDEX = {
     "secondary_index_1": {"type": "B", "value": Binary(b"\x00\x01\x02")},
     "secondary_index_2": {"type": "S", "value": "another_value"},
 }
@@ -76,8 +77,8 @@
 
 @pytest.fixture
 def example_table():
-    mock_dynamodb2().start()
-    ddb = boto3.client("dynamodb", region_name="us-west-2")
+    mock_dynamodb2().start(reset=False)
+    ddb = boto3.client("dynamodb", region_name=TEST_REGION_NAME)
     ddb.create_table(
         TableName=TEST_TABLE_NAME,
         KeySchema=[
@@ -95,9 +96,9 @@ def example_table():
 
 
 @pytest.fixture
-def table_with_local_seconary_indexes():
-    mock_dynamodb2().start()
-    ddb = boto3.client("dynamodb", region_name="us-west-2")
+def table_with_local_secondary_indexes():
+    mock_dynamodb2().start(reset=False)
+    ddb = boto3.client("dynamodb", region_name=TEST_REGION_NAME)
     ddb.create_table(
         TableName=TEST_TABLE_NAME,
         KeySchema=[
@@ -118,7 +119,7 @@ def table_with_local_seconary_indexes():
         ],
         AttributeDefinitions=[
             {"AttributeName": name, "AttributeType": value["type"]}
-            for name, value in list(TEST_INDEX.items()) + list(SECONARY_INDEX.items())
+            for name, value in list(TEST_INDEX.items()) + list(SECONDARY_INDEX.items())
         ],
         ProvisionedThroughput={"ReadCapacityUnits": 100, "WriteCapacityUnits": 100},
     )
@@ -128,9 +129,9 @@ def table_with_local_seconary_indexes():
 
 
 @pytest.fixture
-def table_with_global_seconary_indexes():
-    mock_dynamodb2().start()
-    ddb = boto3.client("dynamodb", region_name="us-west-2")
+def table_with_global_secondary_indexes():
+    mock_dynamodb2().start(reset=False)
+    ddb = boto3.client("dynamodb", region_name=TEST_REGION_NAME)
     ddb.create_table(
         TableName=TEST_TABLE_NAME,
         KeySchema=[
@@ -153,7 +154,7 @@ def table_with_global_seconary_indexes():
         ],
         AttributeDefinitions=[
             {"AttributeName": name, "AttributeType": value["type"]}
-            for name, value in list(TEST_INDEX.items()) + list(SECONARY_INDEX.items())
+            for name, value in list(TEST_INDEX.items()) + list(SECONDARY_INDEX.items())
         ],
         ProvisionedThroughput={"ReadCapacityUnits": 100, "WriteCapacityUnits": 100},
     )
@@ -650,22 +651,100 @@ def client_cycle_batch_items_check_paginators(
 
 
 def build_metastore():
-    client = boto3.client("dynamodb", region_name="us-west-2")
+    client = boto3.client("dynamodb", region_name=TEST_REGION_NAME)
     table_name = base64.urlsafe_b64encode(os.urandom(32)).decode("utf-8").replace("=", ".")
 
     MetaStore.create_table(client, table_name, 1, 1)
     waiter = client.get_waiter("table_exists")
     waiter.wait(TableName=table_name)
 
-    table = boto3.resource("dynamodb", region_name="us-west-2").Table(table_name)
-    yield MetaStore(table, build_static_jce_cmp("AES", 256, "HmacSHA256", 256))
+    table = boto3.resource("dynamodb", region_name=TEST_REGION_NAME).Table(table_name)
+    return MetaStore(table, build_static_jce_cmp("AES", 256, "HmacSHA256", 256)), table_name
 
+
+def delete_metastore(table_name):
+    client = boto3.client("dynamodb", region_name=TEST_REGION_NAME)
     client.delete_table(TableName=table_name)
-    waiter = client.get_waiter("table_not_exists")
-    waiter.wait(TableName=table_name)
+    # It sometimes takes a long time to delete a table.
+    # If hanging, asynchronously deleting tables becomes an issue,
+    # come back to this.
+    # Otherwise, let's just let them take care of themselves.
+    # waiter = client.get_waiter("table_not_exists")
+    # waiter.wait(TableName=table_name)
 
 
 @pytest.fixture
 def mock_metastore():
     with mock_dynamodb2():
-        yield next(build_metastore())
+        metastore, table_name = build_metastore()
+        yield metastore
+        delete_metastore(table_name)
+
+
+def _count_entries(records, *messages):
+    count = 0
+
+    for record in records:
+        if all((message in record.getMessage() for message in messages)):
+            count += 1
+
+    return count
+
+
+def _count_puts(records, table_name):
+    return _count_entries(records, '"TableName": "{}"'.format(table_name), "OperationModel(name=PutItem)")
+
+
+def _count_gets(records, table_name):
+    return _count_entries(records, '"TableName": "{}"'.format(table_name), "OperationModel(name=GetItem)")
+
+
+def check_metastore_cache_use_encrypt(metastore, table_name, log_capture):
+    try:
+        table = boto3.resource("dynamodb").Table(table_name)
+    except NoRegionError:
+        table = boto3.resource("dynamodb", region_name=TEST_REGION_NAME).Table(table_name)
+
+    most_recent_provider = MostRecentProvider(provider_store=metastore, material_name="test", version_ttl=600.0)
+    e_table = EncryptedTable(table=table, materials_provider=most_recent_provider)
+
+    item = diverse_item()
+    item.update(TEST_KEY)
+    e_table.put_item(Item=item)
+    e_table.put_item(Item=item)
+    e_table.put_item(Item=item)
+    e_table.put_item(Item=item)
+
+    try:
+        primary_puts = _count_puts(log_capture.records, e_table.name)
+        metastore_puts = _count_puts(log_capture.records, metastore._table.name)
+
+        assert primary_puts == 4
+        assert metastore_puts == 1
+
+        e_table.get_item(Key=TEST_KEY)
+        e_table.get_item(Key=TEST_KEY)
+        e_table.get_item(Key=TEST_KEY)
+
+        primary_gets = _count_gets(log_capture.records, e_table.name)
+        metastore_gets = _count_gets(log_capture.records, metastore._table.name)
+        metastore_puts = _count_puts(log_capture.records, metastore._table.name)
+
+        assert primary_gets == 3
+        assert metastore_gets == 0
+        assert metastore_puts == 1
+
+        most_recent_provider.refresh()
+
+        e_table.get_item(Key=TEST_KEY)
+        e_table.get_item(Key=TEST_KEY)
+        e_table.get_item(Key=TEST_KEY)
+
+        primary_gets = _count_gets(log_capture.records, e_table.name)
+        metastore_gets = _count_gets(log_capture.records, metastore._table.name)
+
+        assert primary_gets == 6
+        assert metastore_gets == 1
+
+    finally:
+        e_table.delete_item(Key=TEST_KEY)

test/functional/material_providers/test_most_recent.py

@@ -21,6 +21,13 @@
 from dynamodb_encryption_sdk.material_providers.most_recent import MostRecentProvider
 from dynamodb_encryption_sdk.material_providers.store import ProviderStore
 
+from ..functional_test_utils import (  # pylint: disable=unused-import
+    TEST_TABLE_NAME,
+    check_metastore_cache_use_encrypt,
+    example_table,
+    mock_metastore,
+)
+
 pytestmark = [pytest.mark.functional, pytest.mark.local]
 
 
@@ -130,3 +137,7 @@ def test_decryption_materials_cache_use():
     expected_calls.append(("version_from_material_description", 0))
 
     assert store.provider_calls == expected_calls
+
+
+def test_cache_use_encrypt(mock_metastore, example_table, caplog):
+    check_metastore_cache_use_encrypt(mock_metastore, TEST_TABLE_NAME, caplog)