[DMS-382] TraceId logging fixes (#352)

Co-authored-by: Robert Hunter Jr <[email protected]>
Ed-Fi-Alliance-OSS · Nov 20, 2024 · d7e9319 · d7e9319
1 parent 246a6c4
commit d7e9319
Show file tree

Hide file tree

Showing 41 changed files with 299 additions and 208 deletions.
diff --git a/src/dms/.vscode/settings.json b/src/dms/.vscode/settings.json
@@ -73,4 +73,8 @@
             "css", "json", "xml", "config", "plaintext", "markdown", "batch"
         ]
     },
+    "cSpell.words": [
+        "Retryable",
+        "sszzz"
+    ],
 }
diff --git a/...backend/EdFi.DataManagementService.Backend.OpenSearch/OpenSearchQueryHandlerRepository.cs b/...backend/EdFi.DataManagementService.Backend.OpenSearch/OpenSearchQueryHandlerRepository.cs
@@ -19,7 +19,7 @@ public async Task<QueryResult> QueryDocuments(IQueryRequest queryRequest)
     {
         logger.LogDebug(
             "Entering OpenSearchQueryHandlerRepository.QueryDocuments - {TraceId}",
-            queryRequest.TraceId
+            queryRequest.TraceId.Value
         );
 
         try
@@ -30,7 +30,7 @@ public async Task<QueryResult> QueryDocuments(IQueryRequest queryRequest)
         }
         catch (Exception ex)
         {
-            logger.LogCritical(ex, "Uncaught QueryDocuments failure - {TraceId}", queryRequest.TraceId);
+            logger.LogCritical(ex, "Uncaught QueryDocuments failure - {TraceId}", queryRequest.TraceId.Value);
             return new QueryResult.UnknownFailure("Unknown Failure");
         }
     }

diff --git a/src/dms/backend/EdFi.DataManagementService.Backend.OpenSearch/QueryOpenSearch.cs b/src/dms/backend/EdFi.DataManagementService.Backend.OpenSearch/QueryOpenSearch.cs
@@ -72,7 +72,7 @@ public static async Task<QueryResult> QueryDocuments(
         ILogger logger
     )
     {
-        logger.LogDebug("Entering QueryOpenSearch.Query - {TraceId}", queryRequest.TraceId);
+        logger.LogDebug("Entering QueryOpenSearch.Query - {TraceId}", queryRequest.TraceId.Value);
 
         try
         {
@@ -91,36 +91,38 @@ ILogger logger
                             ["match_phrase"] = new JsonObject
                             {
                                 [$@"edfidoc.{QueryFieldFrom(queryElement.DocumentPaths[0])}"] =
-                                    queryElement.Value
-                            }
+                                    queryElement.Value,
+                            },
                         }
                     );
                 }
                 else
                 {
                     // If more than one document path, it's an OR
-                    JsonObject[] possibleTerms = queryElement.DocumentPaths.Select(
-                        documentPath => new JsonObject
+                    JsonObject[] possibleTerms = queryElement
+                        .DocumentPaths.Select(documentPath => new JsonObject
                         {
                             ["match_phrase"] = new JsonObject
                             {
-                                [$@"edfidoc.{QueryFieldFrom(documentPath)}"] = queryElement.Value
-                            }
-                        }
-                    ).ToArray();
+                                [$@"edfidoc.{QueryFieldFrom(documentPath)}"] = queryElement.Value,
+                            },
+                        })
+                        .ToArray();
 
-                    terms.Add(new JsonObject
-                    {
-                        ["bool"] = new JsonObject { ["should"] = new JsonArray(possibleTerms) }
-                    });
+                    terms.Add(
+                        new JsonObject
+                        {
+                            ["bool"] = new JsonObject { ["should"] = new JsonArray(possibleTerms) },
+                        }
+                    );
                 }
             }
 
             JsonObject query =
                 new()
                 {
                     ["query"] = new JsonObject { ["bool"] = new JsonObject { ["must"] = terms } },
-                    ["sort"] = SortDirective()
+                    ["sort"] = SortDirective(),
                 };
 
             // Add in PaginationParameters if any
@@ -159,7 +161,7 @@ ILogger logger
         }
         catch (Exception ex)
         {
-            logger.LogCritical(ex, "Uncaught Query failure - {TraceId}", queryRequest.TraceId);
+            logger.LogCritical(ex, "Uncaught Query failure - {TraceId}", queryRequest.TraceId.Value);
             return new QueryResult.UnknownFailure("Unknown Failure");
         }
     }

diff --git a/...dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/DeleteDocumentById.cs b/...dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/DeleteDocumentById.cs
@@ -28,7 +28,7 @@ public async Task<DeleteResult> DeleteById(
         NpgsqlTransaction transaction
     )
     {
-        _logger.LogDebug("Entering DeleteDocumentById.DeleteById - {TraceId}", deleteRequest.TraceId);
+        _logger.LogDebug("Entering DeleteDocumentById.DeleteById - {TraceId}", deleteRequest.TraceId.Value);
         var documentPartitionKey = PartitionKeyFor(deleteRequest.DocumentUuid);
 
         try
@@ -51,27 +51,35 @@ NpgsqlTransaction transaction
                 case 0:
                     _logger.LogInformation(
                         "Failure: Record to delete does not exist - {TraceId}",
-                        deleteRequest.TraceId
+                        deleteRequest.TraceId.Value
                     );
                     return new DeleteResult.DeleteFailureNotExists();
                 default:
                     _logger.LogError(
                         "DeleteDocumentById rows affected was '{RowsAffected}' for {DocumentUuid} - {TraceId}",
                         rowsAffectedOnDocumentDelete,
                         deleteRequest.DocumentUuid,
-                        deleteRequest.TraceId
+                        deleteRequest.TraceId.Value
                     );
                     return new DeleteResult.UnknownFailure("Unknown Failure");
             }
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.SerializationFailure)
         {
-            _logger.LogDebug(pe, "Transaction conflict on DeleteById - {TraceId}", deleteRequest.TraceId);
+            _logger.LogDebug(
+                pe,
+                "Transaction conflict on DeleteById - {TraceId}",
+                deleteRequest.TraceId.Value
+            );
             return new DeleteResult.DeleteFailureWriteConflict();
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.DeadlockDetected)
         {
-            _logger.LogDebug(pe, "Transaction deadlock on DeleteById - {TraceId}", deleteRequest.TraceId);
+            _logger.LogDebug(
+                pe,
+                "Transaction deadlock on DeleteById - {TraceId}",
+                deleteRequest.TraceId.Value
+            );
             return new DeleteResult.DeleteFailureWriteConflict();
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.ForeignKeyViolation)
@@ -86,12 +94,12 @@ NpgsqlTransaction transaction
                 transaction,
                 deleteRequest.TraceId
             );
-            _logger.LogDebug(pe, "Foreign key violation on Delete - {TraceId}", deleteRequest.TraceId);
+            _logger.LogDebug(pe, "Foreign key violation on Delete - {TraceId}", deleteRequest.TraceId.Value);
             return new DeleteResult.DeleteFailureReference(referencingDocumentNames.ToArray());
         }
         catch (Exception ex)
         {
-            _logger.LogError(ex, "DeleteById failure - {TraceId}", deleteRequest.TraceId);
+            _logger.LogError(ex, "DeleteById failure - {TraceId}", deleteRequest.TraceId.Value);
             return new DeleteResult.UnknownFailure("Unknown Failure");
         }
     }

diff --git a/src/dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/GetDocumentById.cs b/src/dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/GetDocumentById.cs
@@ -35,7 +35,7 @@ public async Task<GetResult> GetById(
         NpgsqlTransaction transaction
     )
     {
-        _logger.LogDebug("Entering GetDocumentById.GetById - {TraceId}", getRequest.TraceId);
+        _logger.LogDebug("Entering GetDocumentById.GetById - {TraceId}", getRequest.TraceId.Value);
 
         try
         {
@@ -62,12 +62,12 @@ NpgsqlTransaction transaction
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.DeadlockDetected)
         {
-            _logger.LogDebug(pe, "Transaction deadlock on query - {TraceId}", getRequest.TraceId);
+            _logger.LogDebug(pe, "Transaction deadlock on query - {TraceId}", getRequest.TraceId.Value);
             return new GetResult.GetFailureRetryable();
         }
         catch (Exception ex)
         {
-            _logger.LogError(ex, "GetDocumentById failure - {TraceId}", getRequest.TraceId);
+            _logger.LogError(ex, "GetDocumentById failure - {TraceId}", getRequest.TraceId.Value);
             return new GetResult.UnknownFailure("Unknown Failure");
         }
     }

diff --git a/src/dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/QueryDocument.cs b/src/dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/QueryDocument.cs
@@ -26,7 +26,7 @@ public async Task<QueryResult> QueryDocuments(
         NpgsqlTransaction transaction
     )
     {
-        _logger.LogDebug("Entering QueryDocument.QueryDocuments - {TraceId}", queryRequest.TraceId);
+        _logger.LogDebug("Entering QueryDocument.QueryDocuments - {TraceId}", queryRequest.TraceId.Value);
         try
         {
             string resourceName = queryRequest.ResourceInfo.ResourceName.Value;
@@ -51,16 +51,16 @@ await _sqlAction.GetAllDocumentsByResourceName(
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.DeadlockDetected)
         {
-            _logger.LogDebug(
-                pe,
-                "Transaction deadlock on query - {TraceId}",
-                queryRequest.TraceId
-            );
+            _logger.LogDebug(pe, "Transaction deadlock on query - {TraceId}", queryRequest.TraceId.Value);
             return new QueryResult.QueryFailureRetryable();
         }
         catch (Exception ex)
         {
-            _logger.LogError(ex, "QueryDocument.QueryDocuments failure - {TraceId}", queryRequest.TraceId);
+            _logger.LogError(
+                ex,
+                "QueryDocument.QueryDocuments failure - {TraceId}",
+                queryRequest.TraceId.Value
+            );
             return new QueryResult.UnknownFailure("Unknown Failure");
         }
     }

diff --git a/...dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/UpdateDocumentById.cs b/...dms/backend/EdFi.DataManagementService.Backend.Postgresql/Operation/UpdateDocumentById.cs
@@ -68,7 +68,7 @@ public async Task<UpdateResult> UpdateById(
         TraceId traceId
     )
     {
-        _logger.LogDebug("Entering UpdateDocumentById.UpdateById - {TraceId}", updateRequest.TraceId);
+        _logger.LogDebug("Entering UpdateDocumentById.UpdateById - {TraceId}", updateRequest.TraceId.Value);
         var documentPartitionKey = PartitionKeyFor(updateRequest.DocumentUuid);
 
         DocumentReferenceIds documentReferenceIds = DocumentReferenceIdsFrom(
@@ -103,7 +103,7 @@ TraceId traceId
                 if (updateRequest.ResourceInfo.AllowIdentityUpdates)
                 {
                     // Identity update is allowed
-                    _logger.LogInformation("Updating Identity - {TraceId}", updateRequest.TraceId);
+                    _logger.LogInformation("Updating Identity - {TraceId}", updateRequest.TraceId.Value);
 
                     int aliasRowsAffected = await _sqlAction.UpdateAliasReferentialIdByDocumentUuid(
                         PartitionKeyFor(updateRequest.DocumentInfo.ReferentialId).Value,
@@ -119,7 +119,7 @@ TraceId traceId
                     {
                         _logger.LogInformation(
                             "Failure: Alias record to update does not exist - {TraceId}",
-                            updateRequest.TraceId
+                            updateRequest.TraceId.Value
                         );
                         return new UpdateResult.UpdateFailureNotExists();
                     }
@@ -129,7 +129,7 @@ TraceId traceId
                     // Identity update not allowed
                     _logger.LogInformation(
                         "Failure: Identity does not match on update - {TraceId}",
-                        updateRequest.TraceId
+                        updateRequest.TraceId.Value
                     );
                     return new UpdateResult.UpdateFailureImmutableIdentity(
                         $"Identifying values for the {updateRequest.ResourceInfo.ResourceName.Value} resource cannot be changed. Delete and recreate the resource item instead."
@@ -193,7 +193,7 @@ TraceId traceId
                         {
                             _logger.LogDebug(
                                 "Foreign key violation on Update - {TraceId}",
-                                updateRequest.TraceId
+                                updateRequest.TraceId.Value
                             );
                             return ReportReferenceFailure(updateRequest.DocumentInfo, invalidReferentialIds);
                         }
@@ -281,32 +281,44 @@ await _sqlAction.UpdateDocumentEdfiDoc(
                 case 0:
                     _logger.LogInformation(
                         "Failure: Record to update does not exist - {TraceId}",
-                        updateRequest.TraceId
+                        updateRequest.TraceId.Value
                     );
                     return new UpdateResult.UpdateFailureNotExists();
                 default:
                     _logger.LogCritical(
                         "UpdateDocumentById rows affected was '{RowsAffected}' for {DocumentUuid} - Should never happen - {TraceId}",
                         rowsAffected,
                         updateRequest.DocumentUuid,
-                        updateRequest.TraceId
+                        updateRequest.TraceId.Value
                     );
                     return new UpdateResult.UnknownFailure("Unknown Failure");
             }
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.SerializationFailure)
         {
-            _logger.LogDebug(pe, "Transaction conflict on UpdateById - {TraceId}", updateRequest.TraceId);
+            _logger.LogDebug(
+                pe,
+                "Transaction conflict on UpdateById - {TraceId}",
+                updateRequest.TraceId.Value
+            );
             return new UpdateResult.UpdateFailureWriteConflict();
         }
         catch (PostgresException pe) when (pe.SqlState == PostgresErrorCodes.DeadlockDetected)
         {
-            _logger.LogDebug(pe, "Transaction deadlock on UpdateById - {TraceId}", updateRequest.TraceId);
+            _logger.LogDebug(
+                pe,
+                "Transaction deadlock on UpdateById - {TraceId}",
+                updateRequest.TraceId.Value
+            );
             return new UpdateResult.UpdateFailureWriteConflict();
         }
         catch (Exception ex)
         {
-            _logger.LogError(ex, "Failure on Documents table update - {TraceId}", updateRequest.TraceId);
+            _logger.LogError(
+                ex,
+                "Failure on Documents table update - {TraceId}",
+                updateRequest.TraceId.Value
+            );
             return new UpdateResult.UnknownFailure("Update failure");
         }
     }