Open captainsafia opened 1 month ago
cc: @amcasey The stacktrace (ref) for this particular failure includes some exceptions coming from data protection. Any thoughts on what might be going on here?
2024-06-24T13:02:36.3558701Z [xUnit.net 00:03:34.25] | [0.053s] Microsoft.AspNetCore.DataProtection.TypeForwardingActivator Debug: Forwarded activator type request from Microsoft.AspNetCore.DataProtection.XmlEncryption.EncryptedXmlDecryptor, Microsoft.AspNetCore.DataProtection, Version=42.42.42.42, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.XmlEncryption.EncryptedXmlDecryptor, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
2024-06-24T13:02:36.3561605Z [xUnit.net 00:03:34.25] | [0.055s] Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager Error: An exception occurred while processing the key element '<key id="a9f047bd-ba17-4a81-8318-c1f58c959944" version="1" />'.
2024-06-24T13:02:36.3563080Z [xUnit.net 00:03:34.25] | System.Security.Cryptography.CryptographicException: Unable to retrieve the decryption key.
2024-06-24T13:02:36.3564489Z [xUnit.net 00:03:34.25] | at System.Security.Cryptography.Xml.EncryptedXml.GetDecryptionKey(EncryptedData encryptedData, String symmetricAlgorithmUri)
2024-06-24T13:02:36.3565906Z [xUnit.net 00:03:34.25] | at System.Security.Cryptography.Xml.EncryptedXml.DecryptDocument()
2024-06-24T13:02:36.3567429Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.XmlEncryption.XmlEncryptionExtensions.DecryptElement(XElement element, IActivator activator) in /_/src/DataProtection/DataProtection/src/XmlEncryption/XmlEncryptionExtensions.cs:line 22
2024-06-24T13:02:36.3568915Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager.Microsoft.AspNetCore.DataProtection.KeyManagement.Internal.IInternalXmlKeyManager.DeserializeDescriptorFromKeyElement(XElement keyElement) in /_/src/DataProtection/DataProtection/src/KeyManagement/XmlKeyManager.cs:line 484
2024-06-24T13:02:36.3570300Z [xUnit.net 00:03:34.25] | [0.056s] Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver Debug: Key {a9f047bd-ba17-4a81-8318-c1f58c959944} method CreateEncryptor failed. Retrying.
2024-06-24T13:02:36.3571756Z [xUnit.net 00:03:34.25] | System.Security.Cryptography.CryptographicException: Unable to retrieve the decryption key.
2024-06-24T13:02:36.3573165Z [xUnit.net 00:03:34.25] | at System.Security.Cryptography.Xml.EncryptedXml.GetDecryptionKey(EncryptedData encryptedData, String symmetricAlgorithmUri)
2024-06-24T13:02:36.3574544Z [xUnit.net 00:03:34.25] | at System.Security.Cryptography.Xml.EncryptedXml.DecryptDocument()
2024-06-24T13:02:36.3575967Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.XmlEncryption.XmlEncryptionExtensions.DecryptElement(XElement element, IActivator activator) in /_/src/DataProtection/DataProtection/src/XmlEncryption/XmlEncryptionExtensions.cs:line 22
2024-06-24T13:02:36.3577467Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager.Microsoft.AspNetCore.DataProtection.KeyManagement.Internal.IInternalXmlKeyManager.DeserializeDescriptorFromKeyElement(XElement keyElement) in /_/src/DataProtection/DataProtection/src/KeyManagement/XmlKeyManager.cs:line 484
2024-06-24T13:02:36.3578839Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager.Microsoft.AspNetCore.DataProtection.KeyManagement.Internal.IInternalXmlKeyManager.DeserializeDescriptorFromKeyElement(XElement keyElement) in /_/src/DataProtection/DataProtection/src/KeyManagement/XmlKeyManager.cs:line 498
2024-06-24T13:02:36.3580284Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.Key.get_Descriptor() in /_/src/DataProtection/DataProtection/src/KeyManagement/Key.cs:line 133
2024-06-24T13:02:36.3581705Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.Key.get_Descriptor() in /_/src/DataProtection/DataProtection/src/KeyManagement/Key.cs:line 161
2024-06-24T13:02:36.3583090Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.Key.CreateEncryptor() in /_/src/DataProtection/DataProtection/src/KeyManagement/Key.cs:line 185
2024-06-24T13:02:36.3584543Z [xUnit.net 00:03:34.25] | at Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver.CanCreateAuthenticatedEncryptor(IKey key, Int32& retriesRemaining) in /_/src/DataProtection/DataProtection/src/KeyManagement/DefaultKeyResolver.cs:line 100
It looks like this particular test was unquarantined in https://github.com/dotnet/aspnetcore/commit/2b5d2b36a04f3a4a9bb20bbca38617d1cd6a3a1a two weeks ago. It seems like this merge was premature based on the comment here.
It looks like this issue goes back as far as 6 years ago from https://github.com/dotnet/aspnetcore/issues/4907. However, the fact that the stacktrace above comes from the recently modified data protection layer has me suspicious.
Let's keep this open as the most recent issue tracking this problem.
The stacktrace (ref) for this particular failure includes some exceptions coming from data protection. Any thoughts on what might be going on here?
Very likely unrelated. That's just an exception that's thrown on startup when the keys on disk aren't valid. See the logs directly after show the app using a new key and starting just fine:
2024-06-24T13:02:36.4708970Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver Warning: Key {a9f047bd-ba17-4a81-8318-c1f58c959944} is ineligible to be the default key because its CreateEncryptor method failed after the maximum number of retries.
2024-06-24T13:02:36.4710580Z [xUnit.net 00:03:34.34] | System.Security.Cryptography.CryptographicException: Unable to retrieve the decryption key.
2024-06-24T13:02:36.4712241Z [xUnit.net 00:03:34.34] | at Microsoft.AspNetCore.DataProtection.KeyManagement.Key.get_Descriptor() in /_/src/DataProtection/DataProtection/src/KeyManagement/Key.cs:line 143
2024-06-24T13:02:36.4713708Z [xUnit.net 00:03:34.34] | at Microsoft.AspNetCore.DataProtection.KeyManagement.Key.CreateEncryptor() in /_/src/DataProtection/DataProtection/src/KeyManagement/Key.cs:line 185
2024-06-24T13:02:36.4715397Z [xUnit.net 00:03:34.34] | at Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver.CanCreateAuthenticatedEncryptor(IKey key, Int32& retriesRemaining) in /_/src/DataProtection/DataProtection/src/KeyManagement/DefaultKeyResolver.cs:line 100
2024-06-24T13:02:36.4717375Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngCbcAuthenticatedEncryptorFactory Debug: Opening CNG algorithm 'AES' from provider '(null)' with chaining mode CBC.
2024-06-24T13:02:36.4719284Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngCbcAuthenticatedEncryptorFactory Debug: Opening CNG algorithm 'SHA256' from provider '(null)' with HMAC.
2024-06-24T13:02:36.4720971Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver Debug: Repository contains no viable default key. Caller should generate a key with immediate activation.
2024-06-24T13:02:36.4722822Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider Debug: Using key {fc21f037-0048-4040-82ea-b56ab6637257} as the default key.
2024-06-24T13:02:36.4724619Z [xUnit.net 00:03:34.34] | [4.231s] Microsoft.AspNetCore.DataProtection.Internal.DataProtectionHostedService Debug: Key ring with default key {fc21f037-0048-4040-82ea-b56ab6637257} was loaded during application startup.
2024-06-24T13:02:36.4726417Z [xUnit.net 00:03:34.34] | [4.232s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Hosting started
2024-06-24T13:02:36.4728037Z [xUnit.net 00:03:34.34] | [4.232s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly HtmlGenerationWebSite
2024-06-24T13:02:36.4729594Z [xUnit.net 00:03:34.34] | [4.243s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request starting HTTP/1.1 GET http://localhost/CacheTagHelper_VaryByCulture?culture=fr-Fr&correlationId=10 - - -
It also seems like this is the one test in MVC.FunctionalTests that actually has logs:
Very likely unrelated. That's just an exception that's thrown on startup when the keys on disk aren't valid. See the logs directly after show the app using a new key and starting just fine:
Sounds right. The retry is a little questionable, but I don't believe we had a good way to distinguish this from the AKV-unreachable case and a local retry should be cheap.
I can't immediately recall why a key on disk could be invalid like that but it's also not hugely surprising.
Failing Test(s)
Error Message
Logs
Build