sync: improve logging (#3774)

Author: marksvc

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

@@ -38,6 +38,23 @@ public static string[] Pull(string repository, byte[] bundle)
     public void BackupRepository(string repository, string backupFile) =>
         RunCommand(repository, $"bundle -a --type v2 \"{backupFile}\"");
 
+    /// <summary>
+    /// Returns a graph of recent commits in the repository.
+    /// </summary>
+    public string RecentLogGraph(string repositoryPath)
+    {
+        // Include commits that will help when investigating sync problems. Ideally this would include the commit before
+        // this S/R, any local commits made at the beginning of S/R, and the current tip commit. And without flooding
+        // the logs. "date(-1)" means within 1 day from today (`hg help dates`). "merge()" means merge commits.
+        string output = RunCommand(
+            repositoryPath,
+            """log --template "{node} {date|isodate} {phase}\n" --graph --rev "date(-1) or merge() or tip" --limit 5 """
+        );
+        // Use a backslash that does not need escaped.
+        string graph = output.Replace("\\", "\u29F5");
+        return graph;
+    }
+
     /// <summary>
     /// Get the most recent revision id of the commit from the last push or pull with the PT send/receive server.
     /// </summary>

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

@@ -13,5 +13,6 @@ public interface IHgWrapper
     string GetLastPublicRevision(string repository);
     string GetRepoRevision(string repositoryPath);
     void MarkSharedChangeSetsPublic(string repository);
+    string RecentLogGraph(string repositoryPath);
     string[] GetDraftRevisions(string repositoryPath);
 }

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

@@ -208,8 +208,10 @@ SyncMetrics syncMetrics
             throw new ArgumentNullException();
         }
 
-        void traceListener(string message) => syncMetrics.Log.Add($"{DateTime.UtcNow:u} Trace: {message}");
-        void alertListener(string message) => syncMetrics.Log.Add($"{DateTime.UtcNow:u} {message}");
+        // Note that SyncMetricsLog does not call _logger.Log, to not recurse into the trace listener.
+        void SyncMetricsLog(string message) => syncMetrics?.Log.Add($"{DateTime.UtcNow:u} SR: {message}");
+        void traceListener(string message) => SyncMetricsLog($"Trace {message}");
+        void alertListener(string message) => SyncMetricsLog($"Alert {message}");
         LambdaTraceListener listener = new LambdaTraceListener(traceListener);
         try
         {
@@ -259,7 +261,9 @@ SyncMetrics syncMetrics
             if (TryGetProject(userSecret, sendReceiveRepository, projectsMetadata, out ParatextProject ptProject))
             {
                 if (!projectGuids.Contains(paratextId))
-                    _logger.LogWarning($"The project with PT ID {paratextId} did not have a full name available.");
+                {
+                    SyncMetricsLog($"The project with PT ID {paratextId} did not have a full name available.");
+                }
             }
             else
             {
@@ -340,28 +344,37 @@ SyncMetrics syncMetrics
                     throw new InvalidOperationException("User does not have permission to share changes.");
                 }
 
-                // TODO report results
+                void SyncMetricsLogCommitGraph()
+                {
+                    string graph = _hgHelper.RecentLogGraph(scrText.Directory);
+                    SyncMetricsLog($"Commit graph:");
+                    Linq.Enumerable.ForEach(Extensions.StringExtensions.SplitLines(graph), SyncMetricsLog);
+                }
+
                 List<SharedProject> sharedPtProjectsToSr = [sharedProj];
                 List<SendReceiveResult> results = Enumerable.Empty<SendReceiveResult>().ToList();
                 bool success = false;
-                bool noErrors = SharingLogicWrapper.HandleErrors(() =>
-                    success = SharingLogicWrapper.ShareChanges(
-                        sharedPtProjectsToSr,
-                        source.AsInternetSharedRepositorySource(),
-                        out results,
-                        sharedPtProjectsToSr
-                    )
-                );
-                if (results == null)
+                bool noErrors = false;
+                try
                 {
-                    _logger.LogWarning($"SendReceive results are unexpectedly null.");
+                    noErrors = SharingLogicWrapper.HandleErrors(() =>
+                        success = SharingLogicWrapper.ShareChanges(
+                            sharedPtProjectsToSr,
+                            source.AsInternetSharedRepositorySource(),
+                            out results,
+                            sharedPtProjectsToSr
+                        )
+                    );
                 }
-                if (results != null && results.Any(r => r == null))
+                catch
                 {
-                    _logger.LogWarning($"SendReceive results unexpectedly contained a null result.");
+                    SyncMetricsLogCommitGraph();
+                    throw;
                 }
+
                 string srResultDescriptions = ExplainSRResults(results);
-                _logger.LogInformation($"SendReceive results: {srResultDescriptions}");
+                SyncMetricsLog(srResultDescriptions);
+                SyncMetricsLogCommitGraph();
                 if (
                     !noErrors
                     || !success
@@ -650,17 +663,33 @@ public async Task<string> GetResourcePermissionAsync(string paratextId, string s
 
     private static string ExplainSRResults(IEnumerable<SendReceiveResult>? srResults)
     {
-        return string.Join(
-            ";",
-            srResults?.Select(
-                (SendReceiveResult r) =>
-                    $"SR result: {r.Result}, "
-                    + $"Revisions sent: {string.Join(",", r.RevisionsSent ?? Enumerable.Empty<string>())}, "
-                    + $"Revisions received: {string.Join(",", r.RevisionsReceived ?? Enumerable.Empty<string>())}, "
-                    + $"Failure message: {r.FailureMessage}."
-            )
-                ?? []
-        );
+        if (srResults == null)
+        {
+            return $"SendReceive results are unexpectedly null.";
+        }
+
+        return $"SendReceive results ({srResults.Count()}):\n"
+            + string.Join("\n", srResults.Select(ExplainOneSRResult));
+    }
+
+    private static string ExplainOneSRResult(SendReceiveResult? srResult)
+    {
+        if (srResult == null)
+        {
+            return $"SendReceive result is null.";
+        }
+        string revisionsSent =
+            srResult.RevisionsSent == null
+                ? "(null)"
+                : $"({srResult.RevisionsSent.Length}) " + string.Join(", ", srResult.RevisionsSent);
+        string revisionsReceived =
+            srResult.RevisionsReceived == null
+                ? "(null)"
+                : $"({srResult.RevisionsReceived.Length}) " + string.Join(", ", srResult.RevisionsReceived);
+        return $"SR Result: {srResult.Result}\n"
+            + $"  Revisions sent: {revisionsSent}\n"
+            + $"  Revisions received: {revisionsReceived}\n"
+            + $"  Failure message: {srResult.FailureMessage ?? "(null)"}";
     }
 
     /// <summary>

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

@@ -171,11 +171,13 @@ CancellationToken token
                 _syncMetrics.RepositoryBackupCreated = canRollbackParatext;
                 if (canRollbackParatext)
                 {
-                    Log($"RunAsync: There wasn't already a local PT repo backup, so we made one.");
+                    LogMetric($"RunAsync: There wasn't already a local PT repo backup, so we made one.");
                 }
                 else
                 {
-                    Log($"RunAsync: There wasn't already a local PT repo backup, so we tried to make one but failed.");
+                    LogMetric(
+                        $"RunAsync: There wasn't already a local PT repo backup, so we tried to make one but failed."
+                    );
                 }
             }
 
@@ -184,17 +186,17 @@ CancellationToken token
 
             if (_paratextService.IsResource(targetParatextId))
             {
-                Log($"This is a resource, so not considering hg repo revisions.");
+                LogMetric($"This is a resource, so not considering hg repo revisions.");
             }
             else if (_projectDoc.Data.Sync.SyncedToRepositoryVersion == null)
             {
-                Log(
+                LogMetric(
                     $"The SF DB SyncedToRepositoryVersion is null. Maybe this project is being Connected, or has not synced successfully since we started tracking this information."
                 );
             }
             else
             {
-                Log(
+                LogMetric(
                     $"Setting hg repo to last imported hg repo rev of {_projectDoc.Data.Sync.SyncedToRepositoryVersion}."
                 );
                 _paratextService.SetRepoToRevision(
@@ -295,7 +297,7 @@ await GetAndUpdateParatextBooksAndNotes(
             // delete all data for removed books
             if (targetBooksToDelete.Count > 0)
             {
-                Log(
+                LogMetric(
                     $"RunAsync: Going to delete texts and questions,comments,answers for {targetBooksToDelete.Count} books."
                 );
                 // delete target books
@@ -889,7 +891,7 @@ private async Task PreflightAuthenticationReportAsync()
     {
         bool canAuthToRegistry = await _paratextService.CanUserAuthenticateToPTRegistryAsync(_userSecret);
         bool canAuthToArchives = await _paratextService.CanUserAuthenticateToPTArchivesAsync(_userSecret.Id);
-        Log($"User can authenticate to PT Registry: {canAuthToRegistry}, to PT Archives: {canAuthToArchives}.");
+        LogMetric($"User can authenticate to PT Registry: {canAuthToRegistry}, to PT Archives: {canAuthToArchives}.");
     }
 
     private async Task UpdateDocsAsync(
@@ -1688,11 +1690,11 @@ private async Task CompleteSync(bool successful, bool canRollbackParatext, Cance
         await NotifySyncProgress(SyncPhase.Phase9, 60.0);
         if (token.IsCancellationRequested)
         {
-            Log($"CompleteSync: There was a cancellation request.");
+            LogMetric($"CompleteSync: There was a cancellation request.");
         }
         if (_projectDoc == null || _projectSecret == null)
         {
-            Log("CompleteSync: _projectDoc or _projectSecret are null. Rolling back SF DB transaction.");
+            LogMetric("CompleteSync: _projectDoc or _projectSecret are null. Rolling back SF DB transaction.");
             _conn.RollbackTransaction();
             return;
         }
@@ -1738,7 +1740,7 @@ private async Task CompleteSync(bool successful, bool canRollbackParatext, Cance
                     _syncMetrics.RepositoryRestoredFromBackup = restoreSucceeded;
                 }
             }
-            Log(
+            LogMetric(
                 $"CompleteSync: Sync was not successful. {(restoreSucceeded ? "Rolled back" : "Failed to roll back")} local PT repo."
             );
             if (!restoreSucceeded)
@@ -1757,15 +1759,15 @@ await _projectDoc.SubmitJson0OpAsync(op =>
 
             if (successful)
             {
-                Log($"CompleteSync: Successfully synchronized to PT repo commit id '{repoVersion}'.");
+                LogMetric($"CompleteSync: Successfully synchronized to PT repo commit id '{repoVersion}'.");
                 op.Set(pd => pd.Sync.DateLastSuccessfulSync, DateTime.UtcNow);
                 op.Set(pd => pd.Sync.SyncedToRepositoryVersion, repoVersion);
                 // If the sync was successful, then the last sync error code should be cleared
                 op.Unset(pd => pd.Sync.LastSyncErrorCode);
             }
             else
             {
-                Log(
+                LogMetric(
                     $"CompleteSync: Failed to synchronize. PT repo latest shared version is '{repoVersion}'. SF DB project SyncedToRepositoryVersion is '{_projectDoc.Data.Sync.SyncedToRepositoryVersion}'."
                 );
             }
@@ -2061,7 +2063,7 @@ private void ReportRepoRevs(string prefix = "")
             $"DB Sync.SyncedToRepositoryVersion: {_projectDoc.Data.Sync.SyncedToRepositoryVersion}, DB Sync.DataInSync: {_projectDoc.Data.Sync.DataInSync}.";
         if (_paratextService.IsResource(projectPTId))
         {
-            Log($"{prefix}In-sync info: Is resource. {dbInfo}");
+            LogMetric($"{prefix}In-sync info: Is resource. {dbInfo}");
         }
         else if (!_paratextService.LocalProjectDirExists(projectPTId))
         {
@@ -2071,7 +2073,7 @@ private void ReportRepoRevs(string prefix = "")
         {
             string repoRev = _paratextService.GetRepoRevision(_userSecret, projectPTId);
             string sharedRev = _paratextService.GetLatestSharedVersion(_userSecret, projectPTId);
-            Log(
+            LogMetric(
                 $"{prefix}In-sync info: Local hg repo current rev: {repoRev}, Latest shared rev: {sharedRev}, {dbInfo}"
             );
         }
@@ -2197,5 +2199,5 @@ private void Log(string message, string? projectSFId = null, string? userId = nu
         _syncMetrics?.Log.Add($"{DateTime.UtcNow:u} {message}");
     }
 
-    private void LogMetric(string message) => Log(message);
+    private void LogMetric(string message) => _syncMetrics?.Log.Add($"{DateTime.UtcNow:u} {message}");
 }