diff --git a/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificateOperation.cs b/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificateOperation.cs index 51f8c9d08a90..13650701f630 100644 --- a/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificateOperation.cs +++ b/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificateOperation.cs @@ -2,6 +2,7 @@ // Licensed under the MIT License. using System; +using System.Diagnostics; using System.Threading; using System.Threading.Tasks; using Azure.Core; @@ -13,6 +14,9 @@ namespace Azure.Security.KeyVault.Certificates /// public class CertificateOperation : Operation { + private const string CancelledStatus = "cancelled"; + private const string CompletedStatus = "completed"; + private readonly CertificateClient _client; private bool _completed; @@ -73,7 +77,7 @@ public override KeyVaultCertificateWithPolicy Value throw new InvalidOperationException("The operation was deleted so no value is available."); } - if (Properties.Status == "cancelled") + if (Properties.Status == CancelledStatus) { throw new OperationCanceledException("The operation was canceled so no value is available."); } @@ -110,6 +114,8 @@ public override ValueTask> WaitForComple /// The raw response of the poll operation. public override Response UpdateStatus(CancellationToken cancellationToken = default) { + using var _ = new UpdateStatusActivity(this); + if (!_completed) { Response pollResponse = _client.GetPendingCertificate(Properties.Name, cancellationToken); @@ -126,7 +132,7 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa } } - if (Properties.Status == "completed") + if (Properties.Status == CompletedStatus) { Response getResponse = _client.GetCertificate(Properties.Name, cancellationToken); @@ -136,7 +142,7 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa _completed = true; } - else if (Properties.Status == "cancelled") + else if (Properties.Status == CancelledStatus) { _completed = true; } @@ -158,6 +164,8 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa /// The raw response of the poll operation. public override async ValueTask UpdateStatusAsync(CancellationToken cancellationToken = default) { + using var _ = new UpdateStatusActivity(this); + if (!_completed) { Response pollResponse = await _client.GetPendingCertificateAsync(Properties.Name, cancellationToken).ConfigureAwait(false); @@ -174,7 +182,7 @@ public override async ValueTask UpdateStatusAsync(CancellationToken ca } } - if (Properties.Status == "completed") + if (Properties.Status == CompletedStatus) { Response getResponse = await _client.GetCertificateAsync(Properties.Name, cancellationToken).ConfigureAwait(false); @@ -184,7 +192,7 @@ public override async ValueTask UpdateStatusAsync(CancellationToken ca _completed = true; } - else if (Properties.Status == "cancelled") + else if (Properties.Status == CancelledStatus) { _completed = true; } @@ -261,5 +269,36 @@ public virtual async Task DeleteAsync(CancellationToken cancellationToken = defa Properties = response; } + + private class UpdateStatusActivity : IDisposable + { + private readonly CertificateOperation _operation; + private readonly long _start; + + public UpdateStatusActivity(CertificateOperation operation) + { + _operation = operation; + + if (EventSource.IsEnabled()) + { + EventSource.BeginUpdateStatus(_operation.Properties); + + _start = Stopwatch.GetTimestamp(); + } + } + + public void Dispose() + { + if (EventSource.IsEnabled()) + { + long end = Stopwatch.GetTimestamp(); + double elapsed = (end - _start) / Stopwatch.Frequency; + + EventSource.EndUpdateStatus(_operation.Properties, elapsed); + } + } + + private static CertificatesEventSource EventSource => CertificatesEventSource.Singleton; + } } } diff --git a/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificatesEventSource.cs b/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificatesEventSource.cs new file mode 100644 index 000000000000..b6e36bbec2a6 --- /dev/null +++ b/sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificatesEventSource.cs @@ -0,0 +1,37 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System.Diagnostics.Tracing; +using Azure.Core.Diagnostics; + +namespace Azure.Security.KeyVault.Certificates +{ + [EventSource(Name = EventSourceName)] + internal sealed class CertificatesEventSource : EventSource + { + internal const int BeginUpdateStatusEvent = 1; + internal const int EndUpdateStatusEvent = 2; + + private const string EventSourceName = "Azure-Security-KeyVault-Certificates"; + private const string Deleted = "(deleted)"; + private const string NoError = "(none)"; + + private CertificatesEventSource() : base(EventSourceName, EventSourceSettings.Default, AzureEventSourceListener.TraitName, AzureEventSourceListener.TraitValue) { } + + public static CertificatesEventSource Singleton { get; } = new CertificatesEventSource(); + + [NonEvent] + public void BeginUpdateStatus(CertificateOperationProperties properties) => + BeginUpdateStatus(properties?.Id.ToString(), properties?.Status, properties?.Error?.Message); + + [Event(BeginUpdateStatusEvent, Level = EventLevel.Verbose, Message = "Updating certificate operation status: {0}, current status: {1}, error: {2}")] + public void BeginUpdateStatus(string id, string status, string error) => WriteEvent(BeginUpdateStatusEvent, id ?? Deleted, status, error ?? NoError); + + [NonEvent] + public void EndUpdateStatus(CertificateOperationProperties properties, double elapsed) => + EndUpdateStatus(properties?.Id.ToString(), properties?.Status, properties?.Error?.Message, elapsed); + + [Event(EndUpdateStatusEvent, Level = EventLevel.Verbose, Message = "Updated certificate operation status: {0}, ending status: {1}, error: {2}, elapsed: {3:00.0}s")] + public void EndUpdateStatus(string id, string status, string error, double elapsed) => WriteEvent(EndUpdateStatusEvent, id ?? Deleted, status, error ?? NoError, elapsed); + } +} diff --git a/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateClientLiveTests.cs b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateClientLiveTests.cs index b5e4d94791a6..c7d2c7e9cbc4 100644 --- a/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateClientLiveTests.cs +++ b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateClientLiveTests.cs @@ -110,7 +110,7 @@ public async Task VerifyCancelCertificateOperation() } OperationCanceledException ex = Assert.ThrowsAsync( - () => WaitForCompletion(operation), + async () => await WaitForCompletion(operation), $"Expected exception {nameof(OperationCanceledException)} not thrown. Operation status: {operation?.Properties?.Status}, error: {operation?.Properties?.Error?.Message}"); Assert.AreEqual("The operation was canceled so no value is available.", ex.Message); @@ -142,7 +142,7 @@ public async Task VerifyUnexpectedCancelCertificateOperation() } OperationCanceledException ex = Assert.ThrowsAsync( - () => WaitForCompletion(operation), + async () => await WaitForCompletion(operation), $"Expected exception {nameof(OperationCanceledException)} not thrown. Operation status: {operation?.Properties?.Status}, error: {operation?.Properties?.Error?.Message}"); Assert.AreEqual("The operation was canceled so no value is available.", ex.Message); @@ -165,7 +165,7 @@ public async Task VerifyDeleteCertificateOperation() await operation.DeleteAsync(); - InvalidOperationException ex = Assert.ThrowsAsync(() => WaitForCompletion(operation)); + InvalidOperationException ex = Assert.ThrowsAsync(async () => await WaitForCompletion(operation)); Assert.AreEqual("The operation was deleted so no value is available.", ex.Message); Assert.IsTrue(operation.HasCompleted); @@ -195,7 +195,7 @@ public async Task VerifyUnexpectedDeleteCertificateOperation() Assert.Inconclusive("The create operation completed before it could be canceled."); } - InvalidOperationException ex = Assert.ThrowsAsync(() => WaitForCompletion(operation)); + InvalidOperationException ex = Assert.ThrowsAsync(async () => await WaitForCompletion(operation)); Assert.AreEqual("The operation was deleted so no value is available.", ex.Message); Assert.IsTrue(operation.HasCompleted); diff --git a/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateOperationTests.cs b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateOperationTests.cs new file mode 100644 index 000000000000..83b339fbe15b --- /dev/null +++ b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateOperationTests.cs @@ -0,0 +1,325 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System; +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.Linq; +using System.Text.Json; +using System.Threading; +using System.Threading.Tasks; +using Azure.Core; +using Azure.Core.Pipeline; +using Azure.Core.TestFramework; +using NUnit.Framework; + +namespace Azure.Security.KeyVault.Certificates.Tests +{ + [NonParallelizable] + public class CertificateOperationTests : ClientTestBase + { + private const string VaultUri = "https://test.vault.azure.net"; + private const string CertificateId = "https://test.vault.azure.net/certificates/test-cert"; + private const string CertificateName = "test-cert"; + + private static readonly string s_policyJson = $@"{{""id"":""{CertificateId}/policy"",""issuer"":{{""name"":""Self""}}}}"; + private static readonly CertificatePolicy s_policy; + + private TestEventListener _listener; + + public CertificateOperationTests(bool isAsync) : base(isAsync) + { + } + + static CertificateOperationTests() + { + var policy = new CertificatePolicy(); + ((IJsonDeserializable)policy).ReadProperties(JsonDocument.Parse(s_policyJson).RootElement); + + s_policy = policy; + } + + [SetUp] + public void Setup() + { + _listener = new TestEventListener(); + _listener.EnableEvents(CertificatesEventSource.Singleton, EventLevel.Verbose); + } + + [TearDown] + public void TearDown() + { + _listener.Dispose(); + } + + [Test] + public async Task UpdateStatusCompleted() + { + var transport = new MockTransport(new[] + { + new MockResponse(202).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""completed""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/1"",""policy"":{s_policyJson}}}"), + }); + + CertificateClient client = CreateClient(transport); + CertificateOperation operation = await client.StartCreateCertificateAsync(CertificateName, s_policy); + + await WaitForOperationAsync(operation); + + // Begin + IEnumerable messages = _listener.EventsById(CertificatesEventSource.BeginUpdateStatusEvent); + Assert.AreEqual(1, messages.Count()); + + EventWrittenEventArgs message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("BeginUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("inProgress", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + + // End + messages = _listener.EventsById(CertificatesEventSource.EndUpdateStatusEvent); + Assert.AreEqual(1, messages.Count()); + + message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("EndUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("completed", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + } + + [Test] + public async Task UpdateStatusEventuallyCompleted() + { + var transport = new MockTransport(new[] + { + new MockResponse(202).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""completed""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/1"",""policy"":{s_policyJson}}}"), + }); + + CertificateClient client = CreateClient(transport); + CertificateOperation operation = await client.StartCreateCertificateAsync(CertificateName, s_policy); + + await WaitForOperationAsync(operation); + + // Begin + IEnumerable messages = _listener.EventsById(CertificatesEventSource.BeginUpdateStatusEvent); + Assert.AreEqual(10, messages.Count()); + + EventWrittenEventArgs message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("BeginUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("inProgress", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + + // End + messages = _listener.EventsById(CertificatesEventSource.EndUpdateStatusEvent); + Assert.AreEqual(10, messages.Count()); + + message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("EndUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("completed", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + } + + [Test] + public async Task UpdateStatusCanceled() + { + var transport = new MockTransport(new[] + { + new MockResponse(202).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""cancelled""}}"), + }); + + CertificateClient client = CreateClient(transport); + CertificateOperation operation = await client.StartCreateCertificateAsync(CertificateName, s_policy); + + Exception ex = Assert.ThrowsAsync(async () => await WaitForOperationAsync(operation)); + Assert.AreEqual("The operation was canceled so no value is available.", ex.Message); + + // Begin + IEnumerable messages = _listener.EventsById(CertificatesEventSource.BeginUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + EventWrittenEventArgs message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("BeginUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("inProgress", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + + // End + messages = _listener.EventsById(CertificatesEventSource.EndUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("EndUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("cancelled", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + } + + [Test] + public async Task UpdateStatusDeleted() + { + var transport = new MockTransport(new[] + { + new MockResponse(202).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(404), + }); + + CertificateClient client = CreateClient(transport); + CertificateOperation operation = await client.StartCreateCertificateAsync(CertificateName, s_policy); + + Exception ex = Assert.ThrowsAsync(async () => await WaitForOperationAsync(operation)); + Assert.AreEqual("The operation was deleted so no value is available.", ex.Message); + + // Begin + IEnumerable messages = _listener.EventsById(CertificatesEventSource.BeginUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + EventWrittenEventArgs message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("BeginUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("inProgress", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + + // End + messages = _listener.EventsById(CertificatesEventSource.EndUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("EndUpdateStatus", message.EventName); + Assert.AreEqual("(deleted)", message.GetProperty("id")); + Assert.AreEqual(string.Empty, message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + } + + [Test] + public async Task UpdateStatusErred() + { + var transport = new MockTransport(new[] + { + new MockResponse(202).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""inProgress""}}"), + + new MockResponse(200).WithContent($@"{{""id"":""{CertificateId}/pending"",""status"":""failed"",""error"":{{""code"":""mock failure code"",""message"":""mock failure message""}}}}"), + }); + + CertificateClient client = CreateClient(transport); + CertificateOperation operation = await client.StartCreateCertificateAsync(CertificateName, s_policy); + + Exception ex = Assert.ThrowsAsync(async () => await WaitForOperationAsync(operation)); + Assert.AreEqual("The certificate operation failed: mock failure message", ex.Message); + + // Begin + IEnumerable messages = _listener.EventsById(CertificatesEventSource.BeginUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + EventWrittenEventArgs message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("BeginUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("inProgress", message.GetProperty("status")); + Assert.AreEqual("(none)", message.GetProperty("error")); + + // End + messages = _listener.EventsById(CertificatesEventSource.EndUpdateStatusEvent); + Assert.AreEqual(5, messages.Count()); + + message = messages.Last(); + Assert.AreEqual(EventLevel.Verbose, message.Level); + Assert.AreEqual("EndUpdateStatus", message.EventName); + Assert.AreEqual($"{CertificateId}/pending", message.GetProperty("id")); + Assert.AreEqual("failed", message.GetProperty("status")); + Assert.AreEqual("mock failure message", message.GetProperty("error")); + } + + private CertificateClient CreateClient(HttpPipelineTransport transport) + { + CertificateClientOptions options = new CertificateClientOptions + { + Transport = transport, + }; + + return InstrumentClient( + new CertificateClient( + new Uri(VaultUri), + new MockCredential(), + options + )); + } + + private async ValueTask WaitForOperationAsync(CertificateOperation operation) + { + var rand = new Random(); + TimeSpan PollingInterval() => TimeSpan.FromMilliseconds(rand.Next(1, 50)); + + if (IsAsync) + { + return await operation.WaitForCompletionAsync(PollingInterval(), default); + } + else + { + while (!operation.HasCompleted) + { + operation.UpdateStatus(); + await Task.Delay(PollingInterval()); + } + + return operation.Value; + } + } + + public class MockCredential : TokenCredential + { + private readonly AccessToken _token = new AccessToken("mockToken", DateTimeOffset.UtcNow.AddHours(1)); + + public override AccessToken GetToken(TokenRequestContext requestContext, CancellationToken cancellationToken) + { + return _token; + } + + public override ValueTask GetTokenAsync(TokenRequestContext requestContext, CancellationToken cancellationToken) + { + return new ValueTask(_token); + } + } + } +} diff --git a/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/TestExtensionMethods.cs b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/TestExtensionMethods.cs index dca17100d7e3..42df51bab4ae 100644 --- a/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/TestExtensionMethods.cs +++ b/sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/TestExtensionMethods.cs @@ -3,6 +3,7 @@ using System; using System.Security.Cryptography; +using Azure.Core.TestFramework; using Azure.Security.KeyVault.Keys.Cryptography; namespace Azure.Security.KeyVault.Certificates.Tests @@ -35,5 +36,11 @@ public static class TestExtensionMethods "P-521" => 521, _ => throw new NotSupportedException($"{keyCurveName} is not supported"), }; + + public static MockResponse WithContent(this MockResponse response, string content) + { + response.SetContent(content); + return response; + } } }