SF-3622 Definitively associate draft generation metrics

Records SF request id to help find related events.

Drafting event metrics that are associated with the same NMT draft
generation request have a 'tags.draftGenerationRequestId' written to
them with an SF-specific id. This id is transferred around by
Activity.Current.Tags, by method arguments, and looked up by finding a
BuildProjectAsync event with a Serval build id.

When SMT is used, `null` is passed for draftGenerationRequestId method
arguments.

Author: pmachapman

src/SIL.XForge.Scripture/ClientApp/src/app/event-metrics/event-metric.ts

@@ -9,6 +9,7 @@ export interface EventMetric {
   timeStamp: string;
   userId?: string;
   executionTime?: string;
+  tags?: { [key: string]: any | undefined };
 }
 
 export enum EventScope {

src/SIL.XForge.Scripture/Services/IMachineProjectService.cs

@@ -15,7 +15,8 @@ Task BuildProjectForBackgroundJobAsync(
         string curUserId,
         BuildConfig buildConfig,
         bool preTranslate,
-        CancellationToken cancellationToken
+        string? draftGenerationRequestId = null,
+        CancellationToken cancellationToken = default
     );
     Task<string> GetProjectZipAsync(string sfProjectId, Stream outputStream, CancellationToken cancellationToken);
     Task RemoveProjectAsync(string sfProjectId, bool preTranslate, CancellationToken cancellationToken);

src/SIL.XForge.Scripture/Services/MachineApiService.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Security.Cryptography;
 using System.Text;
@@ -584,6 +585,12 @@ public async Task BuildCompletedAsync(string sfProjectId, string buildId, string
     {
         try
         {
+            string? draftGenerationRequestId = await GetDraftGenerationRequestIdForBuildAsync(buildId);
+            if (!string.IsNullOrEmpty(draftGenerationRequestId))
+            {
+                Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
+            }
+
             // Retrieve the build started from the event metric. We do this as there may be multiple builds started,
             // and this ensures that only builds that want to send an email will have one sent.
             var eventMetrics = await eventMetricService.GetEventMetricsAsync(
@@ -680,8 +687,15 @@ await projectSecrets.UpdateAsync(
                 cancellationToken
             );
 
+            string buildId = translationBuild.Id;
+            string? draftGenerationRequestId = await GetDraftGenerationRequestIdForBuildAsync(buildId);
+            if (!string.IsNullOrEmpty(draftGenerationRequestId))
+            {
+                Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
+            }
+
             // Return the build id so it can be logged
-            return translationBuild.Id;
+            return buildId;
         }
         catch (ServalApiException e) when (e.StatusCode == StatusCodes.Status404NotFound)
         {
@@ -765,6 +779,13 @@ public async Task ExecuteWebhookAsync(string json, string signature)
             return;
         }
 
+        // Add the draftGenerationRequestId to associate with other events.
+        string? draftGenerationRequestId = await GetDraftGenerationRequestIdForBuildAsync(buildId);
+        if (!string.IsNullOrEmpty(draftGenerationRequestId))
+        {
+            Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
+        }
+
         // Record that the webhook was run successfully
         var arguments = new Dictionary<string, object>
         {
@@ -1800,17 +1821,23 @@ await projectSecrets.UpdateAsync(
                 );
 
                 // Notify any SignalR clients subscribed to the project
+                string? buildId = translationBuild?.Id;
                 await hubContext.NotifyBuildProgress(
                     sfProjectId,
-                    new ServalBuildState
+                    new ServalBuildState { BuildId = buildId, State = nameof(ServalData.PreTranslationsRetrieved) }
+                );
+
+                if (!string.IsNullOrEmpty(buildId))
+                {
+                    string? draftGenerationRequestId = await GetDraftGenerationRequestIdForBuildAsync(buildId);
+                    if (!string.IsNullOrEmpty(draftGenerationRequestId))
                     {
-                        BuildId = translationBuild?.Id,
-                        State = nameof(ServalData.PreTranslationsRetrieved),
+                        Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
                     }
-                );
+                }
 
                 // Return the build id
-                return translationBuild?.Id;
+                return buildId;
             }
         }
         catch (TaskCanceledException e) when (e.InnerException is not TimeoutException)
@@ -1879,6 +1906,7 @@ public async Task StartBuildAsync(string curUserId, string sfProjectId, Cancella
                     curUserId,
                     new BuildConfig { ProjectId = sfProjectId },
                     false,
+                    null,
                     CancellationToken.None
                 ),
             null,
@@ -1904,6 +1932,8 @@ public async Task StartPreTranslationBuildAsync(
         CancellationToken cancellationToken
     )
     {
+        string draftGenerationRequestId = ObjectId.GenerateNewId().ToString();
+        Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
         // Load the project from the realtime service
         await using IConnection conn = await realtimeService.ConnectAsync(curUserId);
         IDocument<SFProject> projectDoc = await conn.FetchAsync<SFProject>(buildConfig.ProjectId);
@@ -2018,7 +2048,14 @@ await projectDoc.SubmitJson0OpAsync(op =>
         //       so that the interceptor functions for BuildProjectAsync().
         jobId = backgroundJobClient.ContinueJobWith<MachineProjectService>(
             jobId,
-            r => r.BuildProjectForBackgroundJobAsync(curUserId, buildConfig, true, CancellationToken.None)
+            r =>
+                r.BuildProjectForBackgroundJobAsync(
+                    curUserId,
+                    buildConfig,
+                    true,
+                    draftGenerationRequestId,
+                    CancellationToken.None
+                )
         );
 
         // Set the pre-translation queued date and time, and hang fire job id
@@ -2586,6 +2623,29 @@ CancellationToken cancellationToken
         return project;
     }
 
+    /// <summary>
+    /// Gets the SF-specific draft generation request identifier for a build by looking up the BuildProjectAsync event.
+    /// </summary>
+    /// <param name="buildId">The Serval build identifier.</param>
+    /// <returns>The draft generation request identifier, or null if not found.</returns>
+    private async Task<string?> GetDraftGenerationRequestIdForBuildAsync(string buildId)
+    {
+        // BuildProjectAsync events serve as a record of what Serval build id corresponds to what draft generation
+        // request id.
+        const int lookupTimeframeDays = 60;
+        DateTime startDate = DateTime.UtcNow.AddDays(-lookupTimeframeDays);
+        QueryResults<EventMetric> buildProjectEvents = await eventMetricService.GetEventMetricsAsync(
+            projectId: null,
+            scopes: [EventScope.Drafting],
+            eventTypes: [nameof(MachineProjectService.BuildProjectAsync)],
+            fromDate: startDate
+        );
+        EventMetric? buildEvent = buildProjectEvents.Results.FirstOrDefault(e => e.Result?.ToString() == buildId);
+        return (buildEvent?.Tags?.TryGetValue("draftGenerationRequestId", out BsonValue? requestId) == true)
+            ? requestId?.AsString
+            : null;
+    }
+
     private async Task<string> GetTranslationIdAsync(
         string sfProjectId,
         bool preTranslate,

src/SIL.XForge.Scripture/Services/MachineProjectService.cs

@@ -106,6 +106,9 @@ public async Task<string> AddSmtProjectAsync(string sfProjectId, CancellationTok
     /// <param name="curUserId">The current user identifier.</param>
     /// <param name="buildConfig">The build configuration.</param>
     /// <param name="preTranslate">If <c>true</c> use NMT; otherwise if <c>false</c> use SMT.</param>
+    /// <param name="draftGenerationRequestId">
+    /// The draft generation request identifier (NMT only). Pass null for SMT builds.
+    /// </param>
     /// <param name="cancellationToken">The cancellation token.</param>
     /// <returns>An asynchronous task.</returns>
     /// <remarks>
@@ -115,12 +118,18 @@ public async Task BuildProjectForBackgroundJobAsync(
         string curUserId,
         BuildConfig buildConfig,
         bool preTranslate,
-        CancellationToken cancellationToken
+        string? draftGenerationRequestId = null,
+        CancellationToken cancellationToken = default
     )
     {
+        if (!string.IsNullOrEmpty(draftGenerationRequestId))
+        {
+            System.Diagnostics.Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
+        }
+
         try
         {
-            await BuildProjectAsync(curUserId, buildConfig, preTranslate, cancellationToken);
+            await BuildProjectAsync(curUserId, buildConfig, preTranslate, draftGenerationRequestId, cancellationToken);
         }
         catch (TaskCanceledException e) when (e.InnerException is not TimeoutException)
         {
@@ -598,8 +607,11 @@ await projectDoc.SubmitJson0OpAsync(op =>
     /// <param name="curUserId">The current user identifier.</param>
     /// <param name="buildConfig">The build configuration.</param>
     /// <param name="preTranslate">If <c>true</c> use NMT; otherwise if <c>false</c> use SMT.</param>
+    /// <param name="draftGenerationRequestId">
+    /// The draft generation request identifier (NMT only). Pass null for SMT builds.
+    /// </param>
     /// <param name="cancellationToken">The cancellation token.</param>
-    /// <returns>An asynchronous task.</returns>
+    /// <returns>Serval build ID</returns>
     /// <exception cref="DataNotFoundException">The project or project secret could not be found.</exception>
     /// <exception cref="InvalidDataException">The language of the source project was not specified.</exception>
     /// <remarks>
@@ -616,9 +628,15 @@ public virtual async Task<string> BuildProjectAsync(
         string curUserId,
         BuildConfig buildConfig,
         bool preTranslate,
-        CancellationToken cancellationToken
+        string? draftGenerationRequestId = null,
+        CancellationToken cancellationToken = default
     )
     {
+        if (!string.IsNullOrEmpty(draftGenerationRequestId))
+        {
+            System.Diagnostics.Activity.Current?.AddTag("draftGenerationRequestId", draftGenerationRequestId);
+        }
+
         // Load the target project secrets, so we can get the translation engine ID
         if (
             !(await projectSecrets.TryGetAsync(buildConfig.ProjectId, cancellationToken)).TryResult(

src/SIL.XForge.Scripture/Services/SyncService.cs

@@ -198,6 +198,7 @@ await projectSecrets.UpdateAsync(
                                 syncConfig.UserId,
                                 new BuildConfig { ProjectId = syncConfig.ProjectId },
                                 false,
+                                null,
                                 CancellationToken.None
                             ),
                         null,

src/SIL.XForge/EventMetrics/EventMetric.cs

@@ -36,7 +36,7 @@ public class EventMetric : IIdentifiable
     public string Id { get; set; } = string.Empty;
 
     /// <summary>
-    /// Gets or sets the event payload.
+    /// Gets or sets the event payload, which contains the arguments given to the RPC or method call being recorded.
     /// </summary>
     /// <remarks>
     /// <para>If you are querying by projectId or userId, that will be done here.</para>
@@ -73,4 +73,12 @@ public class EventMetric : IIdentifiable
     /// Gets or sets the event user identifier.
     /// </summary>
     public string? UserId { get; set; }
+
+    /// <summary>
+    /// Additional event metadata. For example, from items in an Activity Tags.
+    /// </summary>
+    /// <remarks>
+    /// <para>Keys should be normalized to lowerCamelCase.</para>
+    /// </remarks>
+    public Dictionary<string, BsonValue?>? Tags { get; set; }
 }

src/SIL.XForge/EventMetrics/EventMetricLogger.cs

@@ -56,6 +56,9 @@ public void Intercept(IInvocation invocation)
             is LogEventMetricAttribute logEventMetricAttribute
         )
         {
+            // Start an activity so additional information can be logged via tags
+            Activity activity = new Activity("log_event_metric").Start();
+
             // Invoke the method, then record its event metrics
             Task task;
             Stopwatch stopwatch = Stopwatch.StartNew();
@@ -68,21 +71,21 @@ is LogEventMetricAttribute logEventMetricAttribute
                     task = methodTask.ContinueWith(t =>
                     {
                         stopwatch.Stop();
-                        return SaveEventMetricAsync(stopwatch.Elapsed, t.Exception);
+                        return SaveEventMetricAsync(stopwatch.Elapsed, activity, t.Exception);
                     });
                 }
                 else
                 {
                     // Save the event metric in another thread after the method has executed
                     stopwatch.Stop();
-                    task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed));
+                    task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed, activity));
                 }
             }
             catch (Exception e)
             {
                 // Save the error in the event metric, as the Proceed() will have faulted
                 stopwatch.Stop();
-                task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed, e));
+                task = Task.Run(() => SaveEventMetricAsync(stopwatch.Elapsed, activity, e));
 
                 // Notify observers of the task of immediate completion
                 TaskStarted?.Invoke(task);
@@ -97,7 +100,7 @@ is LogEventMetricAttribute logEventMetricAttribute
 
             // Run as a separate task so we do not slow down the method execution
             // Unless we want the return value, in which case we will not write the metric until the method returns
-            async Task SaveEventMetricAsync(TimeSpan executionTime, Exception? exception = null)
+            async Task SaveEventMetricAsync(TimeSpan executionTime, Activity activity, Exception? exception = null)
             {
                 string methodName = invocation.Method.Name;
                 try
@@ -194,6 +197,10 @@ await eventMetricService.SaveEventMetricAsync(
                     // Just log any errors rather than throwing
                     logger.LogError(e, "Error logging event metric for {methodName}", methodName);
                 }
+                finally
+                {
+                    activity.Dispose();
+                }
             }
         }
 

src/SIL.XForge/Services/EventMetricService.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
@@ -93,6 +94,27 @@ public async Task SaveEventMetricAsync(
             payload[kvp.Key] = GetBsonValue(kvp.Value);
         }
 
+        // Collect tags from Activity.Current and all parent activities
+        // Child activity tags override parent tags with the same key
+        Dictionary<string, BsonValue?>? tags = null;
+        var collectedTags = new Dictionary<string, string?>();
+
+        // Walk up the activity chain collecting tags (child first, so child overrides parent)
+        var activity = Activity.Current;
+        while (activity is not null)
+        {
+            collectedTags = activity
+                .Tags.Where(kvp => !collectedTags.ContainsKey(kvp.Key))
+                .Union(collectedTags)
+                .ToDictionary();
+            activity = activity.Parent;
+        }
+
+        if (collectedTags.Count > 0)
+        {
+            tags = collectedTags.ToDictionary(kvp => kvp.Key, kvp => GetBsonValue(kvp.Value));
+        }
+
         // Generate the event metric
         var eventMetric = new EventMetric
         {
@@ -103,6 +125,7 @@ public async Task SaveEventMetricAsync(
             ProjectId = projectId,
             Scope = scope,
             UserId = userId,
+            Tags = tags,
         };
 
         // Do not set Result if it is null, or the document will contain "result: null"