Resolve a few flaky Key Vault tests (#19612)

* Wait longer for deleted keys

* Fix net5.0 tests on OSX

* Add EventSource for CertificateOperation

Added more logging to better diagnose how #17718 is happening.

* Always get start time from stopwatch

...in case the event source is initially disabled, but enabled in the middle (elapsed time would be very long).

* Fix broken test on OSX

* More fixes for OSX

* Resolve PR feedback

* Re-enable some tests and increasing polling interval

* Ignore VerifyECDecoderPrime256v1Imported on OSX

sdk/keyvault/Azure.Security.KeyVault.Certificates/src/CertificateOperation.cs

@@ -13,6 +13,9 @@ namespace Azure.Security.KeyVault.Certificates
     /// </summary>
     public class CertificateOperation : Operation<KeyVaultCertificateWithPolicy>
     {
+        private const string CancelledStatus = "cancelled";
+        private const string CompletedStatus = "completed";
+
         private readonly CertificateClient _client;
 
         private bool _completed;
@@ -73,7 +76,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 +113,8 @@ public override ValueTask<Response<KeyVaultCertificateWithPolicy>> WaitForComple
         /// <returns>The raw response of the poll operation.</returns>
         public override Response UpdateStatus(CancellationToken cancellationToken = default)
         {
+            using var _ = new UpdateStatusActivity(this);
+
             if (!_completed)
             {
                 Response<CertificateOperationProperties> pollResponse = _client.GetPendingCertificate(Properties.Name, cancellationToken);
@@ -126,7 +131,7 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa
                 }
             }
 
-            if (Properties.Status == "completed")
+            if (Properties.Status == CompletedStatus)
             {
                 Response<KeyVaultCertificateWithPolicy> getResponse = _client.GetCertificate(Properties.Name, cancellationToken);
 
@@ -136,7 +141,7 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa
 
                 _completed = true;
             }
-            else if (Properties.Status == "cancelled")
+            else if (Properties.Status == CancelledStatus)
             {
                 _completed = true;
             }
@@ -158,6 +163,8 @@ public override Response UpdateStatus(CancellationToken cancellationToken = defa
         /// <returns>The raw response of the poll operation.</returns>
         public override async ValueTask<Response> UpdateStatusAsync(CancellationToken cancellationToken = default)
         {
+            using var _ = new UpdateStatusActivity(this);
+
             if (!_completed)
             {
                 Response<CertificateOperationProperties> pollResponse = await _client.GetPendingCertificateAsync(Properties.Name, cancellationToken).ConfigureAwait(false);
@@ -174,7 +181,7 @@ public override async ValueTask<Response> UpdateStatusAsync(CancellationToken ca
                 }
             }
 
-            if (Properties.Status == "completed")
+            if (Properties.Status == CompletedStatus)
             {
                 Response<KeyVaultCertificateWithPolicy> getResponse = await _client.GetCertificateAsync(Properties.Name, cancellationToken).ConfigureAwait(false);
 
@@ -184,7 +191,7 @@ public override async ValueTask<Response> UpdateStatusAsync(CancellationToken ca
 
                 _completed = true;
             }
-            else if (Properties.Status == "cancelled")
+            else if (Properties.Status == CancelledStatus)
             {
                 _completed = true;
             }
@@ -261,5 +268,24 @@ public virtual async Task DeleteAsync(CancellationToken cancellationToken = defa
 
             Properties = response;
         }
+
+        private class UpdateStatusActivity : IDisposable
+        {
+            private readonly CertificateOperation _operation;
+
+            public UpdateStatusActivity(CertificateOperation operation)
+            {
+                _operation = operation;
+
+                EventSource.BeginUpdateStatus(_operation.Properties);
+            }
+
+            public void Dispose()
+            {
+                EventSource.EndUpdateStatus(_operation.Properties);
+            }
+
+            private static CertificatesEventSource EventSource => CertificatesEventSource.Singleton;
+        }
     }
 }

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) =>
+            EndUpdateStatus(properties?.Id.ToString(), properties?.Status, properties?.Error?.Message);
+
+        [Event(EndUpdateStatusEvent, Level = EventLevel.Verbose, Message = "Updated certificate operation status: {0}, ending status: {1}, error: {2}")]
+        public void EndUpdateStatus(string id, string status, string error) => WriteEvent(EndUpdateStatusEvent, id ?? Deleted, status, error ?? NoError);
+    }
+}

sdk/keyvault/Azure.Security.KeyVault.Certificates/tests/CertificateClientLiveTests.cs

@@ -110,7 +110,7 @@ public async Task VerifyCancelCertificateOperation()
             }
 
             OperationCanceledException ex = Assert.ThrowsAsync<OperationCanceledException>(
-                () => 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<OperationCanceledException>(
-                () => 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<InvalidOperationException>(() => WaitForCompletion(operation));
+            InvalidOperationException ex = Assert.ThrowsAsync<InvalidOperationException>(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<InvalidOperationException>(() => WaitForCompletion(operation));
+            InvalidOperationException ex = Assert.ThrowsAsync<InvalidOperationException>(async () => await WaitForCompletion(operation));
             Assert.AreEqual("The operation was deleted so no value is available.", ex.Message);
 
             Assert.IsTrue(operation.HasCompleted);
@@ -228,8 +228,8 @@ public async Task VerifyCertificateOperationError()
 
                 RegisterForCleanup(certName);
 
-                using CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromMinutes(1));
-                TimeSpan pollingInterval = TimeSpan.FromSeconds((Mode == RecordedTestMode.Playback) ? 0 : 1);
+                using CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromMinutes(2));
+                TimeSpan pollingInterval = TimeSpan.FromSeconds((Mode == RecordedTestMode.Playback) ? 0 : 2);
 
                 while (!operation.HasCompleted)
                 {
@@ -321,8 +321,8 @@ public async Task VerifyGetCertificateCompletedSubsequently()
             CertificateOperation operation = new CertificateOperation(Client, certName);
 
             // Need to call the real async wait method or the sync version of this test fails because it's using the instrumented Client directly.
-            using CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromMinutes(1));
-            TimeSpan pollingInterval = TimeSpan.FromSeconds((Mode == RecordedTestMode.Playback) ? 0 : 1);
+            using CancellationTokenSource cts = new CancellationTokenSource(TimeSpan.FromMinutes(2));
+            TimeSpan pollingInterval = TimeSpan.FromSeconds((Mode == RecordedTestMode.Playback) ? 0 : 2);
 
             await operation.WaitForCompletionAsync(pollingInterval, cts.Token);