From 1de72249c26d50ecfdbfc9740aeb99d14723cb3a Mon Sep 17 00:00:00 2001 From: Lance Bragstad Date: Fri, 2 Sep 2016 13:19:01 +0000 Subject: [PATCH] Emit log message for fernet tokens only A previous refactor improved some of the logging we had when loading Fernet keys. The log message makes sense from a token perspective since `max_active_keys` is configured for the fernet token provider. For the credential provider, it doesn't necessarily make sense because we don't expose a `max_active_keys` option through configuration. This commit makes it so the we only emit the log message when it is referencing a fernet token key repository. Change-Id: Iad04bd1340a9a59c465337dedcfcd1ea0bed4bde --- keystone/common/fernet_utils.py | 21 +++++---- keystone/tests/unit/common/test_utils.py | 56 ++++++++++++++++++++++++ 2 files changed, 68 insertions(+), 9 deletions(-) diff --git a/keystone/common/fernet_utils.py b/keystone/common/fernet_utils.py index 4650959828..d665f1b3c4 100644 --- a/keystone/common/fernet_utils.py +++ b/keystone/common/fernet_utils.py @@ -256,15 +256,18 @@ class FernetUtils(object): if len(keys) != self.max_active_keys: # Once the number of keys matches max_active_keys, this log entry - # is too repetitive to be useful. - LOG.debug( - 'Loaded %(count)d Fernet keys from %(dir)s, but ' - '`[fernet_tokens] max_active_keys = %(max)d`; perhaps there ' - 'have not been enough key rotations to reach ' - '`max_active_keys` yet?', { - 'count': len(keys), - 'max': self.max_active_keys, - 'dir': self.key_repository}) + # is too repetitive to be useful. Also note that it only makes + # sense to log this message for tokens since credentials doesn't + # have a `max_active_key` configuration option. + if self.key_repository == CONF.fernet_tokens.key_repository: + LOG.debug( + 'Loaded %(count)d Fernet keys from %(dir)s, but ' + '`[fernet_tokens] max_active_keys = %(max)d`; perhaps ' + 'there have not been enough key rotations to reach ' + '`max_active_keys` yet?', { + 'count': len(keys), + 'max': self.max_active_keys, + 'dir': self.key_repository}) # return the encryption_keys, sorted by key number, descending return [keys[x] for x in sorted(keys.keys(), reverse=True)] diff --git a/keystone/tests/unit/common/test_utils.py b/keystone/tests/unit/common/test_utils.py index 95d688ed56..db3282932a 100644 --- a/keystone/tests/unit/common/test_utils.py +++ b/keystone/tests/unit/common/test_utils.py @@ -12,16 +12,21 @@ # under the License. import datetime +import fixtures import uuid from oslo_config import fixture as config_fixture +from oslo_log import log from oslo_serialization import jsonutils import six +from keystone.common import fernet_utils from keystone.common import utils as common_utils import keystone.conf +from keystone.credential.providers import fernet as credential_fernet from keystone import exception from keystone.tests import unit +from keystone.tests.unit import ksfixtures from keystone.tests.unit import utils from keystone.version import service @@ -204,3 +209,54 @@ class ServiceHelperTests(unit.BaseTestCase): def test_fail_gracefully(self): self.assertRaises(unit.UnexpectedExit, self._do_test) + + +class FernetUtilsTestCase(unit.BaseTestCase): + + def setUp(self): + super(FernetUtilsTestCase, self).setUp() + self.config_fixture = self.useFixture(config_fixture.Config(CONF)) + + def test_debug_message_logged_when_loading_fernet_token_keys(self): + self.useFixture( + ksfixtures.KeyRepository( + self.config_fixture, + 'fernet_tokens', + CONF.fernet_tokens.max_active_keys + ) + ) + logging_fixture = self.useFixture(fixtures.FakeLogger(level=log.DEBUG)) + fernet_utilities = fernet_utils.FernetUtils( + CONF.fernet_tokens.key_repository, + CONF.fernet_tokens.max_active_keys + ) + fernet_utilities.load_keys() + expected_debug_message = ( + 'Loaded 2 Fernet keys from %(dir)s, but `[fernet_tokens] ' + 'max_active_keys = %(max)d`; perhaps there have not been enough ' + 'key rotations to reach `max_active_keys` yet?') % { + 'dir': CONF.fernet_tokens.key_repository, + 'max': CONF.fernet_tokens.max_active_keys} + self.assertIn(expected_debug_message, logging_fixture.output) + + def test_debug_message_not_logged_when_loading_fernet_credential_key(self): + self.useFixture( + ksfixtures.KeyRepository( + self.config_fixture, + 'credential', + CONF.fernet_tokens.max_active_keys + ) + ) + logging_fixture = self.useFixture(fixtures.FakeLogger(level=log.DEBUG)) + fernet_utilities = fernet_utils.FernetUtils( + CONF.credential.key_repository, + credential_fernet.MAX_ACTIVE_KEYS + ) + fernet_utilities.load_keys() + debug_message = ( + 'Loaded 2 Fernet keys from %(dir)s, but `[fernet_tokens] ' + 'max_active_keys = %(max)d`; perhaps there have not been enough ' + 'key rotations to reach `max_active_keys` yet?') % { + 'dir': CONF.credential.key_repository, + 'max': credential_fernet.MAX_ACTIVE_KEYS} + self.assertNotIn(debug_message, logging_fixture.output)