From 711d4b3e337e32ff9aaff7a74b2b43daea7ed50c Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Fri, 13 Nov 2015 14:06:35 -0800 Subject: [PATCH] Add event ids to all publication sites --- .../CngCbcAuthenticatedEncryptionOptions.cs | 4 +- .../CngGcmAuthenticatedEncryptionOptions.cs | 2 +- .../ManagedAuthenticatedEncryptionOptions.cs | 4 +- .../DataProtectionEventId.cs | 27 ++++++++ .../DataProtectionServices.cs | 10 +-- .../EphemeralDataProtectionProvider.cs | 2 +- .../KeyManagement/DefaultKeyResolver.cs | 10 +-- .../KeyRingBasedDataProtector.cs | 10 +-- .../KeyManagement/KeyRingProvider.cs | 14 ++--- .../KeyManagement/XmlKeyManager.cs | 36 +++++------ .../LoggingExtensions.cs | 61 ++++++++++++++----- .../Repositories/EphemeralXmlRepository.cs | 2 +- .../Repositories/FileSystemXmlRepository.cs | 6 +- .../Repositories/RegistryXmlRepository.cs | 4 +- .../XmlEncryption/CertificateXmlEncryptor.cs | 6 +- .../XmlEncryption/DpapiNGXmlDecryptor.cs | 4 +- .../XmlEncryption/DpapiNGXmlEncryptor.cs | 4 +- .../XmlEncryption/DpapiXmlDecryptor.cs | 4 +- .../XmlEncryption/DpapiXmlEncryptor.cs | 6 +- .../XmlEncryption/NullXmlEncryptor.cs | 2 +- 20 files changed, 137 insertions(+), 81 deletions(-) create mode 100644 src/Microsoft.AspNet.DataProtection/DataProtectionEventId.cs diff --git a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngCbcAuthenticatedEncryptionOptions.cs b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngCbcAuthenticatedEncryptionOptions.cs index bd187df3..a44218bb 100644 --- a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngCbcAuthenticatedEncryptionOptions.cs +++ b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngCbcAuthenticatedEncryptionOptions.cs @@ -113,7 +113,7 @@ private BCryptAlgorithmHandle GetHmacAlgorithmHandle(ILogger logger) if (logger.IsVerboseLevelEnabled()) { - logger.LogVerboseF($"Opening CNG algorithm '{HashAlgorithm}' from provider '{HashAlgorithmProvider}' with HMAC."); + logger.LogVerbose(DataProtectionEventId.CngCbcAuthenticatedEncryptionOptions, $"Opening CNG algorithm '{HashAlgorithm}' from provider '{HashAlgorithmProvider}' with HMAC."); } BCryptAlgorithmHandle algorithmHandle = null; @@ -154,7 +154,7 @@ private BCryptAlgorithmHandle GetSymmetricBlockCipherAlgorithmHandle(ILogger log if (logger.IsVerboseLevelEnabled()) { - logger.LogVerboseF($"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode CBC."); + logger.LogVerbose(DataProtectionEventId.CngCbcAuthenticatedEncryptionOptions, $"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode CBC."); } BCryptAlgorithmHandle algorithmHandle = null; diff --git a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngGcmAuthenticatedEncryptionOptions.cs b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngGcmAuthenticatedEncryptionOptions.cs index 99ab80cd..7a6620d8 100644 --- a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngGcmAuthenticatedEncryptionOptions.cs +++ b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/CngGcmAuthenticatedEncryptionOptions.cs @@ -94,7 +94,7 @@ private BCryptAlgorithmHandle GetSymmetricBlockCipherAlgorithmHandle(ILogger log if (logger.IsVerboseLevelEnabled()) { - logger.LogVerboseF($"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode GCM."); + logger.LogVerbose(DataProtectionEventId.CngGcmAuthenticatedEncryptionOptions, $"Opening CNG algorithm '{EncryptionAlgorithm}' from provider '{EncryptionAlgorithmProvider}' with chaining mode GCM."); } // Special-case cached providers diff --git a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/ManagedAuthenticatedEncryptionOptions.cs b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/ManagedAuthenticatedEncryptionOptions.cs index c3bddbe5..f5819ac2 100644 --- a/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/ManagedAuthenticatedEncryptionOptions.cs +++ b/src/Microsoft.AspNet.DataProtection/AuthenticatedEncryption/ManagedAuthenticatedEncryptionOptions.cs @@ -88,7 +88,7 @@ private Func GetKeyedHashAlgorithmFactory(ILogger logger) if (logger.IsVerboseLevelEnabled()) { - logger.LogVerboseF($"Using managed keyed hash algorithm '{ValidationAlgorithmType.FullName}'."); + logger.LogVerbose(DataProtectionEventId.ManagedAuthenticatedEncryptionOptions, $"Using managed keyed hash algorithm '{ValidationAlgorithmType.FullName}'."); } if (ValidationAlgorithmType == typeof(HMACSHA256)) @@ -120,7 +120,7 @@ private Func GetSymmetricBlockCipherAlgorithmFactory(ILogger if (logger.IsVerboseLevelEnabled()) { - logger.LogVerboseF($"Using managed symmetric algorithm '{EncryptionAlgorithmType.FullName}'."); + logger.LogVerbose(DataProtectionEventId.ManagedAuthenticatedEncryptionOptions, $"Using managed symmetric algorithm '{EncryptionAlgorithmType.FullName}'."); } if (EncryptionAlgorithmType == typeof(Aes)) diff --git a/src/Microsoft.AspNet.DataProtection/DataProtectionEventId.cs b/src/Microsoft.AspNet.DataProtection/DataProtectionEventId.cs new file mode 100644 index 00000000..10cd11e3 --- /dev/null +++ b/src/Microsoft.AspNet.DataProtection/DataProtectionEventId.cs @@ -0,0 +1,27 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +namespace Microsoft.AspNet.DataProtection +{ + public enum DataProtectionEventId + { + KeyServices = 1, + XmlKeyManager, + KeyRingProvider, + CertificateXmlEncryptor, + DpapiNGXmlEncryptor, + DpapiNGXmlDecryptor, + DpapiXmlEncryptor, + DpapiXmlDecryptor, + NullXmlDecryptor, + DefaultKeyResolver, + RegistryXmlRepository, + EphemeralXmlRepository, + FileSystemXmlRepository, + KeyRingBasedDataProtector, + EphemeralDataProtectionProvider, + CngGcmAuthenticatedEncryptionOptions, + ManagedAuthenticatedEncryptionOptions, + CngCbcAuthenticatedEncryptionOptions + } +} diff --git a/src/Microsoft.AspNet.DataProtection/DataProtectionServices.cs b/src/Microsoft.AspNet.DataProtection/DataProtectionServices.cs index 862aa069..1c08e091 100644 --- a/src/Microsoft.AspNet.DataProtection/DataProtectionServices.cs +++ b/src/Microsoft.AspNet.DataProtection/DataProtectionServices.cs @@ -44,7 +44,7 @@ public static IEnumerable GetDefaultServices() { if (log.IsInformationLevelEnabled()) { - log.LogInformationF($"Azure Web Sites environment detected. Using '{azureWebSitesKeysFolder.FullName}' as key repository; keys will not be encrypted at rest."); + log.LogInformation(DataProtectionEventId.KeyServices, $"Azure Web Sites environment detected. Using '{azureWebSitesKeysFolder.FullName}' as key repository; keys will not be encrypted at rest."); } // Cloud DPAPI isn't yet available, so we don't encrypt keys at rest. @@ -69,11 +69,11 @@ public static IEnumerable GetDefaultServices() { if (keyEncryptorDescriptor != null) { - log.LogInformationF($"User profile is available. Using '{localAppDataKeysFolder.FullName}' as key repository and Windows DPAPI to encrypt keys at rest."); + log.LogInformation(DataProtectionEventId.KeyServices, $"User profile is available. Using '{localAppDataKeysFolder.FullName}' as key repository and Windows DPAPI to encrypt keys at rest."); } else { - log.LogInformationF($"User profile is available. Using '{localAppDataKeysFolder.FullName}' as key repository; keys will not be encrypted at rest."); + log.LogInformation(DataProtectionEventId.KeyServices, $"User profile is available. Using '{localAppDataKeysFolder.FullName}' as key repository; keys will not be encrypted at rest."); } } } @@ -93,7 +93,7 @@ public static IEnumerable GetDefaultServices() if (log.IsInformationLevelEnabled()) { - log.LogInformationF($"User profile not available. Using '{regKeyStorageKey.Name}' as key repository and Windows DPAPI to encrypt keys at rest."); + log.LogInformation(DataProtectionEventId.KeyServices, $"User profile not available. Using '{regKeyStorageKey.Name}' as key repository and Windows DPAPI to encrypt keys at rest."); } } else @@ -104,7 +104,7 @@ public static IEnumerable GetDefaultServices() if (log.IsWarningLevelEnabled()) { - log.LogWarning("Neither user profile nor HKLM registry available. Using an ephemeral key repository. Protected data will be unavailable when application exits."); + log.LogWarning(DataProtectionEventId.KeyServices, $"Neither user profile nor HKLM registry available. Using an ephemeral key repository. Protected data will be unavailable when application exits."); } } } diff --git a/src/Microsoft.AspNet.DataProtection/EphemeralDataProtectionProvider.cs b/src/Microsoft.AspNet.DataProtection/EphemeralDataProtectionProvider.cs index 7ee3de1a..baed4394 100644 --- a/src/Microsoft.AspNet.DataProtection/EphemeralDataProtectionProvider.cs +++ b/src/Microsoft.AspNet.DataProtection/EphemeralDataProtectionProvider.cs @@ -50,7 +50,7 @@ public EphemeralDataProtectionProvider(IServiceProvider services) var logger = services.GetLogger(); if (logger.IsWarningLevelEnabled()) { - logger.LogWarning("Using ephemeral data protection provider. Payloads will be undecipherable upon application shutdown."); + logger.LogWarning(DataProtectionEventId.EphemeralDataProtectionProvider, $"Using ephemeral data protection provider. Payloads will be undecipherable upon application shutdown."); } _dataProtectionProvider = new KeyRingBasedDataProtectionProvider(keyringProvider, services); diff --git a/src/Microsoft.AspNet.DataProtection/KeyManagement/DefaultKeyResolver.cs b/src/Microsoft.AspNet.DataProtection/KeyManagement/DefaultKeyResolver.cs index 242221eb..d7e43c70 100644 --- a/src/Microsoft.AspNet.DataProtection/KeyManagement/DefaultKeyResolver.cs +++ b/src/Microsoft.AspNet.DataProtection/KeyManagement/DefaultKeyResolver.cs @@ -56,7 +56,7 @@ private bool CanCreateAuthenticatedEncryptor(IKey key) { 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.LogWarning(DataProtectionEventId.DefaultKeyResolver, ex, $"Key {key.KeyId:B} is ineligible to be the default key because its {nameof(IKey.CreateEncryptorInstance)} method failed."); } return false; } @@ -74,7 +74,7 @@ private IKey FindDefaultKey(DateTimeOffset now, IEnumerable allKeys, out I { if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Considering key {preferredDefaultKey.KeyId:B} with expiration date {preferredDefaultKey.ExpirationDate:u} as default key."); + _logger.LogVerbose(DataProtectionEventId.DefaultKeyResolver, $"Considering key {preferredDefaultKey.KeyId:B} with expiration date {preferredDefaultKey.ExpirationDate:u} as default key."); } // if the key has been revoked or is expired, it is no longer a candidate @@ -82,7 +82,7 @@ private IKey FindDefaultKey(DateTimeOffset now, IEnumerable allKeys, out I { 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.LogVerbose(DataProtectionEventId.DefaultKeyResolver, $"Key {preferredDefaultKey.KeyId:B} is no longer under consideration as default key because it is expired, revoked, or cannot be deciphered."); } preferredDefaultKey = null; } @@ -106,7 +106,7 @@ private IKey FindDefaultKey(DateTimeOffset now, IEnumerable allKeys, out I if (callerShouldGenerateNewKey && _logger.IsVerboseLevelEnabled()) { - _logger.LogVerbose("Default key expiration imminent and repository contains no viable successor. Caller should generate a successor."); + _logger.LogVerbose(DataProtectionEventId.DefaultKeyResolver, "Default key expiration imminent and repository contains no viable successor. Caller should generate a successor."); } fallbackKey = null; @@ -129,7 +129,7 @@ orderby key.CreationDate ascending if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerbose("Repository contains no viable default key. Caller should generate a key with immediate activation."); + _logger.LogVerbose(DataProtectionEventId.DefaultKeyResolver, "Repository contains no viable default key. Caller should generate a key with immediate activation."); } callerShouldGenerateNewKey = true; diff --git a/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingBasedDataProtector.cs b/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingBasedDataProtector.cs index 0a29811b..33d323a5 100644 --- a/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingBasedDataProtector.cs +++ b/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingBasedDataProtector.cs @@ -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.LogDebug(DataProtectionEventId.KeyRingBasedDataProtector, $"Performing protect operation to key {defaultKeyId:B} with purposes {JoinPurposesForLog(Purposes)}."); } // We'll need to apply the default key id to the template if it hasn't already been applied. @@ -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.LogDebug(DataProtectionEventId.KeyRingBasedDataProtector, $"Performing unprotect operation to key {keyIdFromPayload:B} with purposes {JoinPurposesForLog(Purposes)}."); } // Find the correct encryptor in the keyring. @@ -247,7 +247,7 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked { if (_logger.IsDebugLevelEnabled()) { - _logger.LogDebugF($"Key {keyIdFromPayload:B} was not found in the key ring. Unprotect operation cannot proceed."); + _logger.LogDebug(DataProtectionEventId.KeyRingBasedDataProtector, $"Key {keyIdFromPayload:B} was not found in the key ring. Unprotect operation cannot proceed."); } throw Error.Common_KeyNotFound(keyIdFromPayload); } @@ -266,7 +266,7 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked { if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Key {keyIdFromPayload:B} was revoked. Caller requested unprotect operation proceed regardless."); + _logger.LogVerbose(DataProtectionEventId.KeyRingBasedDataProtector, $"Key {keyIdFromPayload:B} was revoked. Caller requested unprotect operation proceed regardless."); } status = UnprotectStatus.DecryptionKeyWasRevoked; } @@ -274,7 +274,7 @@ private byte[] UnprotectCore(byte[] protectedData, bool allowOperationsOnRevoked { if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Key {keyIdFromPayload:B} was revoked. Unprotect operation cannot proceed."); + _logger.LogVerbose(DataProtectionEventId.KeyRingBasedDataProtector, $"Key {keyIdFromPayload:B} was revoked. Unprotect operation cannot proceed."); } throw Error.Common_KeyRevoked(keyIdFromPayload); } diff --git a/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingProvider.cs b/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingProvider.cs index c5cff618..275cf787 100644 --- a/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingProvider.cs +++ b/src/Microsoft.AspNet.DataProtection/KeyManagement/KeyRingProvider.cs @@ -47,7 +47,7 @@ private CacheableKeyRing CreateCacheableKeyRingCore(DateTimeOffset now, IKey key if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerbose("Policy resolution states that a new key should be added to the key ring."); + _logger.LogVerbose(DataProtectionEventId.KeyRingProvider, "Policy resolution states that a new key should be added to the key ring."); } // We shouldn't call CreateKey more than once, else we risk stack diving. This code path shouldn't @@ -71,7 +71,7 @@ private CacheableKeyRing CreateCacheableKeyRingCore(DateTimeOffset now, IKey key { 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.LogError(DataProtectionEventId.KeyRingProvider, "The key ring does not contain a valid default key, and the key manager is configured with auto-generation of keys disabled."); } throw new InvalidOperationException(Resources.KeyRingProvider_NoDefaultKey_AutoGenerateDisabled); } @@ -79,7 +79,7 @@ private CacheableKeyRing CreateCacheableKeyRingCore(DateTimeOffset now, IKey key { 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.LogWarning(DataProtectionEventId.KeyRingProvider, $"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."); } return CreateCacheableKeyRingCoreStep2(now, cacheExpirationToken, keyToUse, allKeys); } @@ -111,7 +111,7 @@ private CacheableKeyRing CreateCacheableKeyRingCoreStep2(DateTimeOffset now, Can if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Using key {defaultKey.KeyId:B} as the default key."); + _logger.LogVerbose(DataProtectionEventId.KeyRingProvider, $"Using key {defaultKey.KeyId:B} as the default key."); } DateTimeOffset nextAutoRefreshTime = now + GetRefreshPeriodWithJitter(_keyManagementOptions.KeyRingRefreshPeriod); @@ -167,7 +167,7 @@ internal IKeyRing GetCurrentKeyRingCore(DateTime utcNow) if (existingCacheableKeyRing != null && _logger.IsVerboseLevelEnabled()) { - _logger.LogVerbose("Existing cached key ring is expired. Refreshing."); + _logger.LogVerbose(DataProtectionEventId.KeyRingProvider, "Existing cached key ring is expired. Refreshing."); } // It's up to us to refresh the cached keyring. @@ -184,11 +184,11 @@ internal IKeyRing GetCurrentKeyRingCore(DateTime utcNow) { if (existingCacheableKeyRing != null) { - _logger.LogError(ex, "An error occurred while refreshing the key ring. Will try again in 2 minutes."); + _logger.LogError(DataProtectionEventId.KeyRingProvider, 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.LogError(DataProtectionEventId.KeyRingProvider, ex, "An error occurred while reading the key ring."); } } diff --git a/src/Microsoft.AspNet.DataProtection/KeyManagement/XmlKeyManager.cs b/src/Microsoft.AspNet.DataProtection/KeyManagement/XmlKeyManager.cs index f913b7f6..cb90515c 100644 --- a/src/Microsoft.AspNet.DataProtection/KeyManagement/XmlKeyManager.cs +++ b/src/Microsoft.AspNet.DataProtection/KeyManagement/XmlKeyManager.cs @@ -177,7 +177,7 @@ public IReadOnlyCollection GetAllKeys() // Skip unknown elements. if (_logger.IsWarningLevelEnabled()) { - _logger.LogWarningF($"Unknown element with name '{element.Name}' found in keyring, skipping."); + _logger.LogWarning(DataProtectionEventId.XmlKeyManager, $"Unknown element with name '{element.Name}' found in keyring, skipping."); } } } @@ -194,14 +194,14 @@ public IReadOnlyCollection GetAllKeys() key.SetRevoked(); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Marked key {revokedKeyId:B} as revoked in the keyring."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Marked key {revokedKeyId:B} as revoked in the keyring."); } } else { if (_logger.IsWarningLevelEnabled()) { - _logger.LogWarningF($"Tried to process revocation of key {revokedKeyId:B}, but no such key was found in keyring. Skipping."); + _logger.LogWarning(DataProtectionEventId.XmlKeyManager, $"Tried to process revocation of key {revokedKeyId:B}, but no such key was found in keyring. Skipping."); } } } @@ -222,7 +222,7 @@ public IReadOnlyCollection GetAllKeys() key.SetRevoked(); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Marked key {key.KeyId:B} as revoked in the keyring."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Marked key {key.KeyId:B} as revoked in the keyring."); } } } @@ -251,7 +251,7 @@ private KeyBase ProcessKeyElement(XElement keyElement) if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Found key {keyId:B}."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Found key {keyId:B}."); } return new DeferredKey( @@ -285,7 +285,7 @@ private object ProcessRevocationElement(XElement revocationElement) DateTimeOffset massRevocationDate = (DateTimeOffset)revocationElement.Element(RevocationDateElementName); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Found revocation of all keys created prior to {massRevocationDate:u}."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Found revocation of all keys created prior to {massRevocationDate:u}."); } return massRevocationDate; } @@ -295,7 +295,7 @@ private object ProcessRevocationElement(XElement revocationElement) Guid keyId = XmlConvert.ToGuid(keyIdAsString); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Found revocation of key {keyId:B}."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Found revocation of key {keyId:B}."); } return keyId; } @@ -306,7 +306,7 @@ private object ProcessRevocationElement(XElement revocationElement) // revocation information. if (_logger.IsErrorLevelEnabled()) { - _logger.LogErrorF(ex, $"An exception occurred while processing the revocation element '{revocationElement}'. Cannot continue keyring processing."); + _logger.LogError(DataProtectionEventId.XmlKeyManager, ex, $"An exception occurred while processing the revocation element '{revocationElement}'. Cannot continue keyring processing."); } throw; } @@ -323,7 +323,7 @@ public void RevokeAllKeys(DateTimeOffset revocationDate, string reason = null) if (_logger.IsInformationLevelEnabled()) { - _logger.LogInformationF($"Revoking all keys as of {revocationDate:u} for reason '{reason}'."); + _logger.LogInformation(DataProtectionEventId.XmlKeyManager, $"Revoking all keys as of {revocationDate:u} for reason '{reason}'."); } var revocationElement = new XElement(RevocationElementName, @@ -352,7 +352,7 @@ private void TriggerAndResetCacheExpirationToken([CallerMemberName] string opNam { if (!suppressLogging && _logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Key cache expiration token triggered by '{opName}' operation."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Key cache expiration token triggered by '{opName}' operation."); } Interlocked.Exchange(ref _cacheExpirationTokenSource, new CancellationTokenSource())?.Cancel(); @@ -368,13 +368,13 @@ private void WriteKeyDeserializationErrorToLog(Exception error, XElement keyElem if (_logger.IsErrorLevelEnabled()) { // write sanitized element - _logger.LogErrorF(error, $"An exception occurred while processing the key element '{keyElement.WithoutChildNodes()}'."); + _logger.LogError(DataProtectionEventId.XmlKeyManager, error, $"An exception occurred while processing the key element '{keyElement.WithoutChildNodes()}'."); } if (_logger.IsDebugLevelEnabled()) { // write full element - _logger.LogDebugF(error, $"An exception occurred while processing the key element '{keyElement}'."); + _logger.LogDebug(DataProtectionEventId.XmlKeyManager, error, $"An exception occurred while processing the key element '{keyElement}'."); } } @@ -391,7 +391,7 @@ IKey IInternalXmlKeyManager.CreateNewKey(Guid keyId, DateTimeOffset creationDate if (_logger.IsInformationLevelEnabled()) { - _logger.LogInformationF($"Creating key {keyId:B} with creation date {creationDate:u}, activation date {activationDate:u}, and expiration date {expirationDate:u}."); + _logger.LogInformation(DataProtectionEventId.XmlKeyManager, $"Creating key {keyId:B} with creation date {creationDate:u}, activation date {activationDate:u}, and expiration date {expirationDate:u}."); } var newDescriptor = _authenticatedEncryptorConfiguration.CreateNewDescriptor() @@ -400,7 +400,7 @@ IKey IInternalXmlKeyManager.CreateNewKey(Guid keyId, DateTimeOffset creationDate if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Descriptor deserializer type for key {keyId:B} is '{descriptorXmlInfo.DeserializerType.AssemblyQualifiedName}'."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Descriptor deserializer type for key {keyId:B} is '{descriptorXmlInfo.DeserializerType.AssemblyQualifiedName}'."); } // build the element @@ -419,11 +419,11 @@ IKey IInternalXmlKeyManager.CreateNewKey(Guid keyId, DateTimeOffset creationDate { if (_keyEscrowSink != null) { - _logger.LogVerboseF($"Key escrow sink found. Writing key {keyId:B} to escrow."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"Key escrow sink found. Writing key {keyId:B} to escrow."); } else { - _logger.LogVerboseF($"No key escrow sink found. Not writing key {keyId:B} to escrow."); + _logger.LogVerbose(DataProtectionEventId.XmlKeyManager, $"No key escrow sink found. Not writing key {keyId:B} to escrow."); } } _keyEscrowSink?.Store(keyId, keyElement); @@ -431,7 +431,7 @@ IKey IInternalXmlKeyManager.CreateNewKey(Guid keyId, DateTimeOffset creationDate // If an XML encryptor has been configured, protect secret key material now. if (KeyEncryptor == null && _logger.IsWarningLevelEnabled()) { - _logger.LogWarningF($"No XML encryptor configured. Key {keyId:B} may be persisted to storage in unencrypted form."); + _logger.LogWarning(DataProtectionEventId.XmlKeyManager, $"No XML encryptor configured. Key {keyId:B} may be persisted to storage in unencrypted form."); } var possiblyEncryptedKeyElement = KeyEncryptor?.EncryptIfNecessary(keyElement) ?? keyElement; @@ -481,7 +481,7 @@ void IInternalXmlKeyManager.RevokeSingleKey(Guid keyId, DateTimeOffset revocatio if (_logger.IsInformationLevelEnabled()) { - _logger.LogInformationF($"Revoking key {keyId:B} at {revocationDate:u} for reason '{reason}'."); + _logger.LogInformation(DataProtectionEventId.XmlKeyManager, $"Revoking key {keyId:B} at {revocationDate:u} for reason '{reason}'."); } var revocationElement = new XElement(RevocationElementName, diff --git a/src/Microsoft.AspNet.DataProtection/LoggingExtensions.cs b/src/Microsoft.AspNet.DataProtection/LoggingExtensions.cs index 2c8a7dd3..fb49b8f8 100644 --- a/src/Microsoft.AspNet.DataProtection/LoggingExtensions.cs +++ b/src/Microsoft.AspNet.DataProtection/LoggingExtensions.cs @@ -3,6 +3,7 @@ using System; using System.Runtime.CompilerServices; +using Microsoft.AspNet.DataProtection; using Microsoft.Extensions.Logging.Internal; namespace Microsoft.Extensions.Logging @@ -69,44 +70,72 @@ private static bool IsLogLevelEnabledCore(ILogger logger, LogLevel level) return (logger != null && logger.IsEnabled(level)); } - public static void LogDebugF(this ILogger logger, FormattableString message) + public static void LogDebug(this ILogger logger, DataProtectionEventId eventId, FormattableString message) { - logger.LogDebug(message.Format, message.GetArguments()); + logger.LogDebug((int)eventId, message.Format, message.GetArguments()); } - public static void LogDebugF(this ILogger logger, Exception error, FormattableString message) + public static void LogDebug(this ILogger logger, DataProtectionEventId eventId, string message) { - logger.LogDebug(new FormattedLogValues(message.Format, message.GetArguments()), error); + logger.LogDebug((int)eventId, message); } - public static void LogError(this ILogger logger, Exception error, string message) + public static void LogDebug(this ILogger logger, DataProtectionEventId eventId, Exception error, FormattableString message) { - logger.LogError(message, error); + logger.LogDebug((int)eventId, new FormattedLogValues(message.Format, message.GetArguments()), error); } - public static void LogErrorF(this ILogger logger, Exception error, FormattableString message) + public static void LogError(this ILogger logger, DataProtectionEventId eventId, string message) { - logger.LogError(new FormattedLogValues(message.Format, message.GetArguments()), error); + logger.LogError((int)eventId, message); } - public static void LogInformationF(this ILogger logger, FormattableString message) + public static void LogError(this ILogger logger, DataProtectionEventId eventId, Exception error, string message) { - logger.LogInformation(message.Format, message.GetArguments()); + logger.LogError((int)eventId, message, error); } - public static void LogVerboseF(this ILogger logger, FormattableString message) + public static void LogError(this ILogger logger, DataProtectionEventId eventId, Exception error, FormattableString message) { - logger.LogVerbose(message.Format, message.GetArguments()); + logger.LogError((int)eventId, new FormattedLogValues(message.Format, message.GetArguments()), error); } - public static void LogWarningF(this ILogger logger, FormattableString message) + public static void LogInformation(this ILogger logger, DataProtectionEventId eventId, FormattableString message) { - logger.LogWarning(message.Format, message.GetArguments()); + logger.LogInformation((int)eventId, message.Format, message.GetArguments()); } - public static void LogWarningF(this ILogger logger, Exception error, FormattableString message) + public static void LogInformation(this ILogger logger, DataProtectionEventId eventId, string message) { - logger.LogWarning(new FormattedLogValues(message.Format, message.GetArguments()), error); + logger.LogInformation((int)eventId, message); + } + + public static void LogVerbose(this ILogger logger, DataProtectionEventId eventId, FormattableString message) + { + logger.LogVerbose((int)eventId, message.Format, message.GetArguments()); + } + public static void LogVerbose(this ILogger logger, DataProtectionEventId eventId, string message) + { + logger.LogVerbose((int)eventId, message); + } + + public static void LogWarning(this ILogger logger, DataProtectionEventId eventId, FormattableString message) + { + logger.LogWarning((int)eventId, message.Format, message.GetArguments()); + } + public static void LogWarning(this ILogger logger, DataProtectionEventId eventId, string message) + { + logger.LogWarning((int)eventId, message); + } + + public static void LogWarning(this ILogger logger, DataProtectionEventId eventId, Exception error, FormattableString message) + { + logger.LogWarning((int)eventId, new FormattedLogValues(message.Format, message.GetArguments()), error); + } + + public static void LogWarning(this ILogger logger, DataProtectionEventId eventId, Exception error, string message) + { + logger.LogWarning((int)eventId, message, error); } } } diff --git a/src/Microsoft.AspNet.DataProtection/Repositories/EphemeralXmlRepository.cs b/src/Microsoft.AspNet.DataProtection/Repositories/EphemeralXmlRepository.cs index d1baa63b..37122d21 100644 --- a/src/Microsoft.AspNet.DataProtection/Repositories/EphemeralXmlRepository.cs +++ b/src/Microsoft.AspNet.DataProtection/Repositories/EphemeralXmlRepository.cs @@ -22,7 +22,7 @@ public EphemeralXmlRepository(IServiceProvider services) var logger = services?.GetLogger(); if (logger.IsWarningLevelEnabled()) { - logger.LogWarning("Using an in-memory repository. Keys will not be persisted to storage."); + logger.LogWarning(DataProtectionEventId.EphemeralXmlRepository, "Using an in-memory repository. Keys will not be persisted to storage."); } } diff --git a/src/Microsoft.AspNet.DataProtection/Repositories/FileSystemXmlRepository.cs b/src/Microsoft.AspNet.DataProtection/Repositories/FileSystemXmlRepository.cs index 3cc94174..bbaaa8ed 100644 --- a/src/Microsoft.AspNet.DataProtection/Repositories/FileSystemXmlRepository.cs +++ b/src/Microsoft.AspNet.DataProtection/Repositories/FileSystemXmlRepository.cs @@ -187,7 +187,7 @@ private XElement ReadElementFromFile(string fullPath) { if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Reading data from file '{fullPath}'."); + _logger.LogVerbose(DataProtectionEventId.FileSystemXmlRepository, $"Reading data from file '{fullPath}'."); } using (var fileStream = File.OpenRead(fullPath)) @@ -208,7 +208,7 @@ public virtual void StoreElement(XElement element, string friendlyName) string newFriendlyName = Guid.NewGuid().ToString(); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"The name '{friendlyName}' is not a safe file name, using '{newFriendlyName}' instead."); + _logger.LogVerbose(DataProtectionEventId.FileSystemXmlRepository, $"The name '{friendlyName}' is not a safe file name, using '{newFriendlyName}' instead."); } friendlyName = newFriendlyName; } @@ -237,7 +237,7 @@ private void StoreElementCore(XElement element, string filename) // Renames are atomic operations on the file systems we support. if (_logger.IsInformationLevelEnabled()) { - _logger.LogInformationF($"Writing data to file '{finalFilename}'."); + _logger.LogInformation(DataProtectionEventId.FileSystemXmlRepository, "Writing data to file '{finalFilename}'."); } File.Move(tempFilename, finalFilename); } diff --git a/src/Microsoft.AspNet.DataProtection/Repositories/RegistryXmlRepository.cs b/src/Microsoft.AspNet.DataProtection/Repositories/RegistryXmlRepository.cs index b880a12a..60f02a01 100644 --- a/src/Microsoft.AspNet.DataProtection/Repositories/RegistryXmlRepository.cs +++ b/src/Microsoft.AspNet.DataProtection/Repositories/RegistryXmlRepository.cs @@ -142,7 +142,7 @@ private XElement ReadElementFromRegKey(RegistryKey regKey, string valueName) { if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Reading data from registry key '{regKey}', value '{valueName}'."); + _logger.LogVerbose(DataProtectionEventId.RegistryXmlRepository, $"Reading data from registry key '{regKey}', value '{valueName}'."); } string data = regKey.GetValue(valueName) as string; @@ -161,7 +161,7 @@ public virtual void StoreElement(XElement element, string friendlyName) string newFriendlyName = Guid.NewGuid().ToString(); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"The name '{friendlyName}' is not a safe registry value name, using '{newFriendlyName}' instead."); + _logger.LogVerbose(DataProtectionEventId.RegistryXmlRepository, $"The name '{friendlyName}' is not a safe registry value name, using '{newFriendlyName}' instead."); } friendlyName = newFriendlyName; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/CertificateXmlEncryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/CertificateXmlEncryptor.cs index 5cdfc505..887f3826 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/CertificateXmlEncryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/CertificateXmlEncryptor.cs @@ -151,7 +151,7 @@ private Func CreateCertFactory(string thumbprint, ICertificate { if (_logger.IsErrorLevelEnabled()) { - _logger.LogErrorF(ex, $"An exception occurred while trying to resolve certificate with thumbprint '{thumbprint}'."); + _logger.LogError(DataProtectionEventId.CertificateXmlEncryptor, ex, $"An exception occurred while trying to resolve certificate with thumbprint '{thumbprint}'."); } throw; } @@ -165,7 +165,7 @@ EncryptedData IInternalCertificateXmlEncryptor.PerformEncryption(EncryptedXml en if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Encrypting to X.509 certificate with thumbprint '{cert.Thumbprint}'."); + _logger.LogVerbose(DataProtectionEventId.CertificateXmlEncryptor, $"Encrypting to X.509 certificate with thumbprint '{cert.Thumbprint}'."); } try @@ -176,7 +176,7 @@ EncryptedData IInternalCertificateXmlEncryptor.PerformEncryption(EncryptedXml en { if (_logger.IsErrorLevelEnabled()) { - _logger.LogErrorF(ex, $"An error occurred while encrypting to X.509 certificate with thumbprint '{cert.Thumbprint}'."); + _logger.LogError(DataProtectionEventId.CertificateXmlEncryptor, ex, $"An error occurred while encrypting to X.509 certificate with thumbprint '{cert.Thumbprint}'."); } throw; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlDecryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlDecryptor.cs index d451373e..c51ee945 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlDecryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlDecryptor.cs @@ -72,7 +72,7 @@ public XElement Decrypt(XElement encryptedElement) // swallow all errors - it's just a log protectionDescriptorRule = null; } - _logger.LogVerboseF($"Decrypting secret element using Windows DPAPI-NG with protection descriptor rule '{protectionDescriptorRule}'."); + _logger.LogVerbose(DataProtectionEventId.DpapiNGXmlDecryptor, $"Decrypting secret element using Windows DPAPI-NG with protection descriptor rule '{protectionDescriptorRule}'."); } using (Secret secret = DpapiSecretSerializerHelper.UnprotectWithDpapiNG(protectedSecret)) @@ -86,7 +86,7 @@ public XElement Decrypt(XElement encryptedElement) // sensitive information. if (_logger.IsErrorLevelEnabled()) { - _logger.LogError(ex, "An exception occurred while trying to decrypt the element."); + _logger.LogError(DataProtectionEventId.DpapiNGXmlDecryptor, ex, "An exception occurred while trying to decrypt the element."); } throw; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlEncryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlEncryptor.cs index e2c6ee8e..a59c89ab 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlEncryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiNGXmlEncryptor.cs @@ -75,7 +75,7 @@ public EncryptedXmlInfo Encrypt(XElement plaintextElement) string protectionDescriptorRuleString = _protectionDescriptorHandle.GetProtectionDescriptorRuleString(); if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerboseF($"Encrypting to Windows DPAPI-NG using protection descriptor rule '{protectionDescriptorRuleString}'."); + _logger.LogVerbose(DataProtectionEventId.DpapiNGXmlEncryptor, $"Encrypting to Windows DPAPI-NG using protection descriptor rule '{protectionDescriptorRuleString}'."); } // Convert the XML element to a binary secret so that it can be run through DPAPI @@ -91,7 +91,7 @@ public EncryptedXmlInfo Encrypt(XElement plaintextElement) { if (_logger.IsErrorLevelEnabled()) { - _logger.LogError(ex, "An error occurred while encrypting to Windows DPAPI-NG."); + _logger.LogError(DataProtectionEventId.DpapiNGXmlEncryptor, ex, "An error occurred while encrypting to Windows DPAPI-NG."); } throw; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlDecryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlDecryptor.cs index ad59ab82..50e3bb5e 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlDecryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlDecryptor.cs @@ -50,7 +50,7 @@ public XElement Decrypt(XElement encryptedElement) if (_logger.IsVerboseLevelEnabled()) { - _logger.LogVerbose("Decrypting secret element using Windows DPAPI."); + _logger.LogVerbose(DataProtectionEventId.DpapiXmlDecryptor, "Decrypting secret element using Windows DPAPI."); } try @@ -72,7 +72,7 @@ public XElement Decrypt(XElement encryptedElement) // sensitive information. if (_logger.IsErrorLevelEnabled()) { - _logger.LogError(ex, "An exception occurred while trying to decrypt the element."); + _logger.LogError(DataProtectionEventId.DpapiXmlDecryptor, ex, "An exception occurred while trying to decrypt the element."); } throw; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlEncryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlEncryptor.cs index c1726eb7..2610ac13 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlEncryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/DpapiXmlEncryptor.cs @@ -65,11 +65,11 @@ public EncryptedXmlInfo Encrypt(XElement plaintextElement) { if (_protectToLocalMachine) { - _logger.LogVerbose("Encrypting to Windows DPAPI for local machine account."); + _logger.LogVerbose(DataProtectionEventId.DpapiXmlEncryptor, "Encrypting to Windows DPAPI for local machine account."); } else { - _logger.LogVerboseF($"Encrypting to Windows DPAPI for current user account ({WindowsIdentity.GetCurrent().Name})."); + _logger.LogVerbose(DataProtectionEventId.DpapiXmlEncryptor, $"Encrypting to Windows DPAPI for current user account ({WindowsIdentity.GetCurrent().Name})."); } } @@ -86,7 +86,7 @@ public EncryptedXmlInfo Encrypt(XElement plaintextElement) { if (_logger.IsErrorLevelEnabled()) { - _logger.LogError(ex, "An error occurred while encrypting to Windows DPAPI."); + _logger.LogError(DataProtectionEventId.DpapiXmlEncryptor, ex, "An error occurred while encrypting to Windows DPAPI."); } throw; } diff --git a/src/Microsoft.AspNet.DataProtection/XmlEncryption/NullXmlEncryptor.cs b/src/Microsoft.AspNet.DataProtection/XmlEncryption/NullXmlEncryptor.cs index fd3cc01f..46508b59 100644 --- a/src/Microsoft.AspNet.DataProtection/XmlEncryption/NullXmlEncryptor.cs +++ b/src/Microsoft.AspNet.DataProtection/XmlEncryption/NullXmlEncryptor.cs @@ -50,7 +50,7 @@ public EncryptedXmlInfo Encrypt(XElement plaintextElement) if (_logger.IsWarningLevelEnabled()) { - _logger.LogWarning("Encrypting using a null encryptor; secret information isn't being protected."); + _logger.LogWarning(DataProtectionEventId.NullXmlDecryptor, "Encrypting using a null encryptor; secret information isn't being protected."); } //