Add EventSource for CertificateOperation

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

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
     /// </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 +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<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 +132,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 +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
         /// <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 +182,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 +192,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 +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;
+        }
     }
 }

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);
+    }
+}

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);