Updating the KmipEngine logging for operation handling

This change adds some additional logging statements when processing
individual KMIP operations, providing additional information on
operation input and output. The associated tests have been updated
accordingly.

kmip/services/server/engine.py

@@ -714,6 +714,12 @@ class KmipEngine(object):
         # commit is called. This makes future support for UNDO problematic.
         self._data_session.commit()
 
+        self._logger.info(
+            "Created a SymmetricKey with ID: {0}".format(
+                managed_object.unique_identifier
+            )
+        )
+
         response_payload = create.CreateResponsePayload(
             object_type=payload.object_type,
             unique_identifier=attributes.UniqueIdentifier(
@@ -875,6 +881,17 @@ class KmipEngine(object):
         # commit is called. This makes future support for UNDO problematic.
         self._data_session.commit()
 
+        self._logger.info(
+            "Created a PublicKey with ID: {0}".format(
+                public_key.unique_identifier
+            )
+        )
+        self._logger.info(
+            "Created a PrivateKey with ID: {0}".format(
+                private_key.unique_identifier
+            )
+        )
+
         response_payload = create_key_pair.CreateKeyPairResponsePayload(
             private_key_uuid=attributes.PrivateKeyUniqueIdentifier(
                 str(private_key.unique_identifier)
@@ -936,6 +953,13 @@ class KmipEngine(object):
         # commit is called. This makes future support for UNDO problematic.
         self._data_session.commit()
 
+        self._logger.info(
+            "Registered a {0} with ID: {1}".format(
+                ''.join([x.capitalize() for x in object_type.name.split('_')]),
+                managed_object.unique_identifier
+            )
+        )
+
         response_payload = register.RegisterResponsePayload(
             unique_identifier=attributes.UniqueIdentifier(
                 str(managed_object.unique_identifier)
@@ -993,6 +1017,14 @@ class KmipEngine(object):
                     )
                 )
 
+        object_type = managed_object.object_type.name
+        self._logger.info(
+            "Getting a {0} with ID: {1}".format(
+                ''.join([x.capitalize() for x in object_type.split('_')]),
+                managed_object.unique_identifier
+            )
+        )
+
         core_secret = self._build_core_object(managed_object)
 
         response_payload = get.GetResponsePayload(
@@ -1018,6 +1050,10 @@ class KmipEngine(object):
         # 1. Check object state. If invalid, error out.
         # 2. Check object deactivation date. If invalid, error out.
 
+        self._logger.info(
+            "Destroying an object with ID: {0}".format(unique_identifier)
+        )
+
         self._data_session.query(objects.ManagedObject).filter(
             objects.ManagedObject.unique_identifier == unique_identifier
         ).delete()

kmip/tests/unit/services/server/test_engine.py

@@ -1482,7 +1482,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
 
@@ -1545,7 +1545,7 @@ class TestKmipEngine(testtools.TestCase):
             *args
         )
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
 
@@ -1602,7 +1602,7 @@ class TestKmipEngine(testtools.TestCase):
             *args
         )
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
         e._logger.reset_mock()
@@ -1647,7 +1647,7 @@ class TestKmipEngine(testtools.TestCase):
             *args
         )
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
         e._logger.reset_mock()
@@ -1689,7 +1689,7 @@ class TestKmipEngine(testtools.TestCase):
             *args
         )
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
         e._logger.reset_mock()
@@ -1755,7 +1755,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
 
@@ -1888,7 +1888,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -1954,7 +1954,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2020,7 +2020,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2086,7 +2086,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2150,7 +2150,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2214,7 +2214,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2296,7 +2296,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2365,7 +2365,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_create_key_pair,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
         e._logger.reset_mock()
@@ -2437,7 +2437,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Register"
         )
 
@@ -2551,7 +2551,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -2581,7 +2581,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -2627,7 +2627,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_get,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
 
@@ -2647,7 +2647,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_get,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
 
@@ -2685,7 +2685,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
 
@@ -2726,7 +2726,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_get,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
 
@@ -2758,7 +2758,7 @@ class TestKmipEngine(testtools.TestCase):
             e._process_get,
             *args
         )
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
 
@@ -2792,7 +2792,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(str(id_a), response_payload.unique_identifier.value)
@@ -2818,7 +2818,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(str(id_b), response_payload.unique_identifier.value)
@@ -3030,7 +3030,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Create"
         )
 
@@ -3048,7 +3048,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -3087,7 +3087,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(str(uid), response_payload.unique_identifier.value)
@@ -3166,7 +3166,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: CreateKeyPair"
         )
 
@@ -3186,7 +3186,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -3224,7 +3224,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -3264,7 +3264,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(
@@ -3298,7 +3298,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(
@@ -3391,7 +3391,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Register"
         )
 
@@ -3409,7 +3409,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Get"
         )
         self.assertEqual(
@@ -3446,7 +3446,7 @@ class TestKmipEngine(testtools.TestCase):
         e._data_session.commit()
         e._data_session = e._data_store_session_factory()
 
-        e._logger.info.assert_called_once_with(
+        e._logger.info.assert_any_call(
             "Processing operation: Destroy"
         )
         self.assertEqual(str(uid), response_payload.unique_identifier.value)