Merged PR 722185: Revert "Merged PR 718998: Revert "Merged PR 717355: Send ETW events on symbol...

Merge the BSI change back in.

Related work items: #2060729

Author: Oleksii Kononenko

Public/Src/Tools/SymbolDaemon/SymbolDaemon.cs

@@ -15,8 +15,9 @@
 using BuildXL.Ipc.ExternalApi;
 using BuildXL.Ipc.Interfaces;
 using BuildXL.Storage;
-using BuildXL.Utilities.Core;
+using BuildXL.Tracing.CloudBuild;
 using BuildXL.Utilities.CLI;
+using BuildXL.Utilities.Core;
 using BuildXL.Utilities.Core.Tasks;
 using Microsoft.VisualStudio.Services.Common;
 using Microsoft.VisualStudio.Services.Symbol.App.Core.Tracing;
@@ -160,7 +161,7 @@ public sealed class SymbolDaemon : ServicePipDaemon.FinalizedByCreatorServicePip
             IsRequired = false,
             DefaultValue = true,
         });
-        
+
         internal static readonly StrOption PersonalAccessTokenEnv = RegisterSymbolConfigOption(new StrOption("PersonalAccessTokenEnv")
         {
             ShortName = "patenv",
@@ -730,20 +731,11 @@ internal static void EnsureCommandsInitialized()
         /// </summary>
         protected override async Task<IIpcResult> DoCreateAsync(string name = null)
         {
-            // TODO(olkonone): add logging
-            Request createRequestResult;
-
-            try
-            {
-                createRequestResult = await InternalCreateAsync();
-            }
-            catch (Exception e)
-            {
-                return new IpcResult(IpcResultStatus.GenericError, e.DemystifyToString());
-            }
+            var dropCreationEvent = await HandleResultAndSendSymbolEtwEventAsync(InternalCreateAsync());
 
-            // get and return RequestId ?
-            return IpcResult.Success(I($"Symbol request '{RequestName}' created (assigned request ID: '{createRequestResult.Id}')."));
+            return dropCreationEvent.Succeeded
+                ? IpcResult.Success(I($"Symbol request '{RequestName}' created (url: '{dropCreationEvent.DropUrl}')."))
+                : new IpcResult(IpcResultStatus.GenericError, dropCreationEvent.ErrorMessage);
         }
 
         /// <summary>
@@ -777,19 +769,11 @@ private async Task<IIpcResult> AddSymbolFileAsync(SymbolFile file)
         /// </summary>
         protected override async Task<IIpcResult> DoFinalizeAsync()
         {
-            // TODO(olkonone): add logging
-            Request finalizeRequestResult;
-
-            try
-            {
-                finalizeRequestResult = await InternalFinalizeAsync();
-            }
-            catch (Exception e)
-            {
-                return new IpcResult(IpcResultStatus.GenericError, e.DemystifyToString());
-            }
+            var dropFinalizationEvent = await HandleResultAndSendSymbolEtwEventAsync(InternalFinalizeAsync());
 
-            return IpcResult.Success(I($"Symbol request '{RequestName}' finalized; the request expires on '{finalizeRequestResult.ExpirationDate}'."));
+            return dropFinalizationEvent.Succeeded
+               ? IpcResult.Success(I($"Symbol request '{RequestName}' finalized."))
+               : new IpcResult(IpcResultStatus.GenericError, dropFinalizationEvent.ErrorMessage);
         }
 
         /// <nodoc />
@@ -805,25 +789,42 @@ public override void Dispose()
             base.Dispose();
         }
 
-        private async Task<Request> InternalCreateAsync()
+        private async Task<DropCreationEvent> InternalCreateAsync()
         {
             var symbolClient = await m_symbolServiceClientTask;
             var result = await symbolClient.CreateAsync();
 
             Contract.Assert(result.Status == RequestStatus.Created);
 
-            return result;
+            var serializedResult = SymbolRequesToString(result);
+            m_logger.Info($"CreateAsync completed:{Environment.NewLine}{serializedResult}");
+
+            return new DropCreationEvent()
+            {
+                Succeeded = true,
+                DropUrl = result.Url.ToString(),
+                // For Symbols, expiration is set during finalization, so we are using a value we will be assigning later.
+                DropExpirationInDays = (int)SymbolConfig.Retention.TotalDays,
+                AdditionalInformation = serializedResult
+            };
         }
 
-        private async Task<Request> InternalFinalizeAsync()
+        private async Task<DropFinalizationEvent> InternalFinalizeAsync()
         {
             var symbolClient = await m_symbolServiceClientTask;
             var result = await symbolClient.FinalizeAsync();
 
             Contract.Assert(result.Status == RequestStatus.Sealed);
             Contract.Assert(result.ExpirationDate.HasValue);
 
-            return result;
+            var serializedResult = SymbolRequesToString(result);
+            m_logger.Info($"FinalizeAsync completed:{Environment.NewLine}{serializedResult}");
+
+            return new DropFinalizationEvent()
+            {
+                Succeeded = true,
+                DropUrl = result.Url.ToString(),
+            };
         }
 
         private async Task ReportStatisticsAsync()
@@ -870,5 +871,46 @@ private async Task ReportStatisticsAsync()
                 m_logger.Warning("No stats recorded by symbol client of type " + symbolClient.GetType().Name);
             }
         }
+
+        private async Task<T> HandleResultAndSendSymbolEtwEventAsync<T>(Task<T> task) where T : DropOperationBaseEvent
+        {
+            var sw = Stopwatch.StartNew();
+            T dropEvent;
+            try
+            {
+                dropEvent = await task;
+            }
+            catch (Exception e)
+            {
+                dropEvent = Activator.CreateInstance<T>();
+                dropEvent.Succeeded = false;
+                dropEvent.ErrorMessage = e.DemystifyToString();
+                // For symbols, url is something that is only defined for successful operations
+                // (it's based on a requestId which is not available until successful execution of 'symbol create').
+                dropEvent.DropUrl = null;
+            }
+
+            // common properties: execution time, drop type
+            dropEvent.ElapsedTimeTicks = sw.ElapsedTicks;
+            dropEvent.DropType = "SymbolIndex";
+
+            // send event
+            m_etwLogger.Log(dropEvent);
+
+            return dropEvent;
+        }
+
+        private static string SymbolRequesToString(Request request)
+        {
+            try
+            {
+                return request.ToJson();
+            }
+            catch (Exception e)
+            {
+                // The value is only used for debugging, so it's not a big deal if we fail to create the string.
+                return $"Failed to serialized Request. Exception: {e}";
+            }
+        }
     }
 }

Public/Src/Tools/SymbolDaemon/VsoSymbolClient.cs

@@ -11,17 +11,13 @@
 using BuildXL.Ipc.Common;
 using BuildXL.Ipc.ExternalApi;
 using BuildXL.Ipc.Interfaces;
-using BuildXL.Utilities.Core;
 using BuildXL.Utilities.Authentication;
-using BuildXL.Utilities.Collections;
-using BuildXL.Utilities.ParallelAlgorithms;
+using BuildXL.Utilities.Core;
 using BuildXL.Utilities.Core.Tasks;
-using BuildXL.Utilities.Tracing;
-using Microsoft.IdentityModel.Clients.ActiveDirectory;
+using BuildXL.Utilities.ParallelAlgorithms;
 using Microsoft.VisualStudio.Services.BlobStore.Common;
 using Microsoft.VisualStudio.Services.Common;
 using Microsoft.VisualStudio.Services.Content.Common;
-using Microsoft.VisualStudio.Services.Content.Common.Authentication;
 using Microsoft.VisualStudio.Services.Content.Common.Tracing;
 using Microsoft.VisualStudio.Services.Symbol.App.Core;
 using Microsoft.VisualStudio.Services.Symbol.App.Core.Telemetry;
@@ -471,7 +467,7 @@ public async Task<Request> FinalizeAsync(CancellationToken token)
                 var result = await m_symbolClient.FinalizeRequestAsync(
                     RequestId,
                     ComputeExpirationDate(m_config.Retention),
-                    // isUpdateOperation == true => request will be marked as 'Sealed', 
+                    // isUpdateOperation != true => request will be marked as 'Sealed', 
                     // i.e., no more DebugEntries could be added to it 
                     isUpdateOperation: false,
                     token);