From 477669f62075d0fa9bfae55abf5fe0674f59df63 Mon Sep 17 00:00:00 2001 From: Peter Date: Thu, 7 Apr 2016 10:04:33 -0400 Subject: [PATCH] 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 | 36 ++++++++++ .../tests/unit/services/server/test_engine.py | 70 +++++++++---------- 2 files changed, 71 insertions(+), 35 deletions(-) diff --git a/kmip/services/server/engine.py b/kmip/services/server/engine.py index 42ef68d..c90d355 100644 --- a/kmip/services/server/engine.py +++ b/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() diff --git a/kmip/tests/unit/services/server/test_engine.py b/kmip/tests/unit/services/server/test_engine.py index edcdf47..f969557 100644 --- a/kmip/tests/unit/services/server/test_engine.py +++ b/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)