Skip to content
This repository was archived by the owner on Oct 17, 2018. It is now read-only.

Add event ids to all log calls #110

Merged
merged 1 commit into from
Nov 18, 2015
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -111,11 +111,7 @@ private BCryptAlgorithmHandle GetHmacAlgorithmHandle(ILogger logger)
throw Error.Common_PropertyCannotBeNullOrEmpty(nameof(HashAlgorithm));
}

if (logger.IsVerboseLevelEnabled())
{
logger.LogVerboseF($"Opening CNG algorithm '{HashAlgorithm}' from provider '{HashAlgorithmProvider}' with HMAC.");
}

logger.OpeningCNGAlgorithmFromProviderWithHMAC(HashAlgorithm, HashAlgorithmProvider);
BCryptAlgorithmHandle algorithmHandle = null;

// Special-case cached providers
Expand Down Expand Up @@ -152,10 +148,7 @@ private BCryptAlgorithmHandle GetSymmetricBlockCipherAlgorithmHandle(ILogger log
throw Error.Common_PropertyMustBeNonNegative(nameof(EncryptionAlgorithmKeySize));
}

if (logger.IsVerboseLevelEnabled())
{
logger.LogVerboseF($"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode CBC.");
}
logger.OpeningCNGAlgorithmFromProviderWithChainingModeCBC(EncryptionAlgorithm, EncryptionAlgorithmProvider);

BCryptAlgorithmHandle algorithmHandle = null;

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -92,11 +92,7 @@ private BCryptAlgorithmHandle GetSymmetricBlockCipherAlgorithmHandle(ILogger log

BCryptAlgorithmHandle algorithmHandle = null;

if (logger.IsVerboseLevelEnabled())
{
logger.LogVerboseF($"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode GCM.");
}

logger.OpeningCNGAlgorithmFromProviderWithChainingModeGCM(EncryptionAlgorithm, EncryptionAlgorithmProvider);
// Special-case cached providers
if (EncryptionAlgorithmProvider == null)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -86,11 +86,7 @@ private Func<KeyedHashAlgorithm> GetKeyedHashAlgorithmFactory(ILogger logger)
throw Error.Common_PropertyCannotBeNullOrEmpty(nameof(ValidationAlgorithmType));
}

if (logger.IsVerboseLevelEnabled())
{
logger.LogVerboseF($"Using managed keyed hash algorithm '{ValidationAlgorithmType.FullName}'.");
}

logger.UsingManagedKeyedHashAlgorithm(ValidationAlgorithmType.FullName);
if (ValidationAlgorithmType == typeof(HMACSHA256))
{
return () => new HMACSHA256();
Expand Down Expand Up @@ -118,10 +114,7 @@ private Func<SymmetricAlgorithm> GetSymmetricBlockCipherAlgorithmFactory(ILogger
throw Error.Common_PropertyMustBeNonNegative(nameof(EncryptionAlgorithmKeySize));
}

if (logger.IsVerboseLevelEnabled())
{
logger.LogVerboseF($"Using managed symmetric algorithm '{EncryptionAlgorithmType.FullName}'.");
}
logger.UsingManagedSymmetricAlgorithm(EncryptionAlgorithmType.FullName);

if (EncryptionAlgorithmType == typeof(Aes))
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -48,10 +48,7 @@ public EphemeralDataProtectionProvider(IServiceProvider services)
}

var logger = services.GetLogger<EphemeralDataProtectionProvider>();
if (logger.IsWarningLevelEnabled())
{
logger.LogWarning("Using ephemeral data protection provider. Payloads will be undecipherable upon application shutdown.");
}
logger.UsingEphemeralDataProtectionProvider();

_dataProtectionProvider = new KeyRingBasedDataProtectionProvider(keyringProvider, services);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -54,10 +54,7 @@ private bool CanCreateAuthenticatedEncryptor(IKey key)
}
catch (Exception ex)
{
if (_logger.IsWarningLevelEnabled())
{
_logger.LogWarningF(ex, $"Key {key.KeyId:B} is ineligible to be the default key because its {nameof(IKey.CreateEncryptorInstance)} method failed.");
}
_logger.KeyIsIneligibleToBeTheDefaultKeyBecauseItsMethodFailed(key.KeyId, nameof(IKey.CreateEncryptorInstance), ex);
return false;
}
}
Expand All @@ -72,18 +69,12 @@ private IKey FindDefaultKey(DateTimeOffset now, IEnumerable<IKey> allKeys, out I

if (preferredDefaultKey != null)
{
if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerboseF($"Considering key {preferredDefaultKey.KeyId:B} with expiration date {preferredDefaultKey.ExpirationDate:u} as default key.");
}
_logger.ConsideringKeyWithExpirationDateAsDefaultKey(preferredDefaultKey.KeyId, preferredDefaultKey.ExpirationDate);

// if the key has been revoked or is expired, it is no longer a candidate
if (preferredDefaultKey.IsRevoked || preferredDefaultKey.IsExpired(now) || !CanCreateAuthenticatedEncryptor(preferredDefaultKey))
{
if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerboseF($"Key {preferredDefaultKey.KeyId:B} is no longer under consideration as default key because it is expired, revoked, or cannot be deciphered.");
}
_logger.KeyIsNoLongerUnderConsiderationAsDefault(preferredDefaultKey.KeyId);
preferredDefaultKey = null;
}
}
Expand All @@ -104,9 +95,9 @@ private IKey FindDefaultKey(DateTimeOffset now, IEnumerable<IKey> allKeys, out I
&& !key.IsExpired(now + _keyPropagationWindow)
&& !key.IsRevoked);

if (callerShouldGenerateNewKey && _logger.IsVerboseLevelEnabled())
if (callerShouldGenerateNewKey)
{
_logger.LogVerbose("Default key expiration imminent and repository contains no viable successor. Caller should generate a successor.");
_logger.DefaultKeyExpirationImminentAndRepository();
}

fallbackKey = null;
Expand All @@ -127,10 +118,7 @@ orderby key.CreationDate ascending
where !key.IsRevoked && CanCreateAuthenticatedEncryptor(key)
select key).FirstOrDefault();

if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerbose("Repository contains no viable default key. Caller should generate a key with immediate activation.");
}
_logger.RepositoryContainsNoViableDefaultKey();

callerShouldGenerateNewKey = true;
return null;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,7 @@ public byte[] Protect(byte[] plaintext)

if (_logger.IsDebugLevelEnabled())
{
_logger.LogDebugF($"Performing protect operation to key {defaultKeyId:B} with purposes {JoinPurposesForLog(Purposes)}.");
_logger.PerformingProtectOperationToKeyWithPurposes(defaultKeyId, JoinPurposesForLog(Purposes));
}

// We'll need to apply the default key id to the template if it hasn't already been applied.
Expand Down Expand Up @@ -236,7 +236,7 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked

if (_logger.IsDebugLevelEnabled())
{
_logger.LogDebugF($"Performing unprotect operation to key {keyIdFromPayload:B} with purposes {JoinPurposesForLog(Purposes)}.");
_logger.PerformingUnprotectOperationToKeyWithPurposes(keyIdFromPayload, JoinPurposesForLog(Purposes));
}

// Find the correct encryptor in the keyring.
Expand All @@ -245,10 +245,7 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked
var requestedEncryptor = currentKeyRing.GetAuthenticatedEncryptorByKeyId(keyIdFromPayload, out keyWasRevoked);
if (requestedEncryptor == null)
{
if (_logger.IsDebugLevelEnabled())
{
_logger.LogDebugF($"Key {keyIdFromPayload:B} was not found in the key ring. Unprotect operation cannot proceed.");
}
_logger.KeyWasNotFoundInTheKeyRingUnprotectOperationCannotProceed(keyIdFromPayload);
throw Error.Common_KeyNotFound(keyIdFromPayload);
}

Expand All @@ -264,18 +261,12 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked
{
if (allowOperationsOnRevokedKeys)
{
if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerboseF($"Key {keyIdFromPayload:B} was revoked. Caller requested unprotect operation proceed regardless.");
}
_logger.KeyWasRevokedCallerRequestedUnprotectOperationProceedRegardless(keyIdFromPayload);
status = UnprotectStatus.DecryptionKeyWasRevoked;
}
else
{
if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerboseF($"Key {keyIdFromPayload:B} was revoked. Unprotect operation cannot proceed.");
}
_logger.KeyWasRevokedUnprotectOperationCannotProceed(keyIdFromPayload);
throw Error.Common_KeyRevoked(keyIdFromPayload);
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -45,10 +45,7 @@ private CacheableKeyRing CreateCacheableKeyRingCore(DateTimeOffset now, IKey key
return CreateCacheableKeyRingCoreStep2(now, cacheExpirationToken, defaultKeyPolicy.DefaultKey, allKeys);
}

if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerbose("Policy resolution states that a new key should be added to the key ring.");
}
_logger.PolicyResolutionStatesThatANewKeyShouldBeAddedToTheKeyRing();

// We shouldn't call CreateKey more than once, else we risk stack diving. This code path shouldn't
// get hit unless there was an ineligible key with an activation date slightly later than the one we
Expand All @@ -69,18 +66,12 @@ private CacheableKeyRing CreateCacheableKeyRingCore(DateTimeOffset now, IKey key
var keyToUse = defaultKeyPolicy.DefaultKey ?? defaultKeyPolicy.FallbackKey;
if (keyToUse == null)
{
if (_logger.IsErrorLevelEnabled())
{
_logger.LogError("The key ring does not contain a valid default key, and the key manager is configured with auto-generation of keys disabled.");
}
_logger.KeyRingDoesNotContainValidDefaultKey();
throw new InvalidOperationException(Resources.KeyRingProvider_NoDefaultKey_AutoGenerateDisabled);
}
else
{
if (_logger.IsWarningLevelEnabled())
{
_logger.LogWarningF($"Policy resolution states that a new key should be added to the key ring, but automatic generation of keys is disabled. Using fallback key {keyToUse.KeyId:B} with expiration {keyToUse.ExpirationDate:u} as default key.");
}
_logger.UsingFallbackKeyWithExpirationAsDefaultKey(keyToUse.KeyId, keyToUse.ExpirationDate);
return CreateCacheableKeyRingCoreStep2(now, cacheExpirationToken, keyToUse, allKeys);
}
}
Expand Down Expand Up @@ -109,10 +100,7 @@ private CacheableKeyRing CreateCacheableKeyRingCoreStep2(DateTimeOffset now, Can
// Invariant: our caller ensures that CreateEncryptorInstance succeeded at least once
Debug.Assert(defaultKey.CreateEncryptorInstance() != null);

if (_logger.IsVerboseLevelEnabled())
{
_logger.LogVerboseF($"Using key {defaultKey.KeyId:B} as the default key.");
}
_logger.UsingKeyAsDefaultKey(defaultKey.KeyId);

DateTimeOffset nextAutoRefreshTime = now + GetRefreshPeriodWithJitter(_keyManagementOptions.KeyRingRefreshPeriod);

Expand Down Expand Up @@ -165,9 +153,9 @@ internal IKeyRing GetCurrentKeyRingCore(DateTime utcNow)
return existingCacheableKeyRing.KeyRing;
}

if (existingCacheableKeyRing != null && _logger.IsVerboseLevelEnabled())
if (existingCacheableKeyRing != null)
{
_logger.LogVerbose("Existing cached key ring is expired. Refreshing.");
_logger.ExistingCachedKeyRingIsExpired();
}

// It's up to us to refresh the cached keyring.
Expand All @@ -180,16 +168,13 @@ internal IKeyRing GetCurrentKeyRingCore(DateTime utcNow)
}
catch (Exception ex)
{
if (_logger.IsErrorLevelEnabled())
if (existingCacheableKeyRing != null)
{
_logger.ErrorOccurredWhileRefreshingKeyRing(ex);
}
else
{
if (existingCacheableKeyRing != null)
{
_logger.LogError(ex, "An error occurred while refreshing the key ring. Will try again in 2 minutes.");
}
else
{
_logger.LogError(ex, "An error occurred while reading the key ring.");
}
_logger.ErrorOccurredWhileReadingKeyRing(ex);
}

// Failures that occur while refreshing the keyring are most likely transient, perhaps due to a
Expand Down
Loading