From 4e30d020cac03bb7f44b7960076a93b5dc5d62f4 Mon Sep 17 00:00:00 2001
From: Ben McIlwain <mcilwain@google.com>
Date: Thu, 1 Jul 2021 18:21:17 -0400
Subject: [PATCH] Set payload response in happy path of
 ReplayCommitLogsToSqlAction (#1229)

* Set payload response in happy path of ReplayCommitLogsToSqlAction

I suspect this may be the reason the logs are missing on the happy path (when it
runs successfully), but are visible on the exception paths (which do set the
payload response). I don't think App Engine likes it when a Web request
terminates without a response.

This also adds more logging and error handling.
---
 .../backup/ReplayCommitLogsToSqlAction.java   | 22 ++++++++++++++++---
 .../ReplayCommitLogsToSqlActionTest.java      |  2 ++
 2 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/core/src/main/java/google/registry/backup/ReplayCommitLogsToSqlAction.java b/core/src/main/java/google/registry/backup/ReplayCommitLogsToSqlAction.java
index c64dae3c4..108d9ca77 100644
--- a/core/src/main/java/google/registry/backup/ReplayCommitLogsToSqlAction.java
+++ b/core/src/main/java/google/registry/backup/ReplayCommitLogsToSqlAction.java
@@ -109,7 +109,14 @@ public class ReplayCommitLogsToSqlAction implements Runnable {
     try {
       replayFiles();
       response.setStatus(HttpServletResponse.SC_OK);
-      logger.atInfo().log("ReplayCommitLogsToSqlAction completed successfully.");
+      String message = "ReplayCommitLogsToSqlAction completed successfully.";
+      response.setPayload(message);
+      logger.atInfo().log(message);
+    } catch (Throwable t) {
+      String message = "Errored out replaying files.";
+      logger.atSevere().withCause(t).log(message);
+      response.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
+      response.setPayload(message);
     } finally {
       lock.ifPresent(Lock::release);
     }
@@ -139,21 +146,30 @@ public class ReplayCommitLogsToSqlAction implements Runnable {
   }
 
   private void processFile(GcsFileMetadata metadata) {
+    logger.atInfo().log(
+        "Processing commit log file %s of size %d B.",
+        metadata.getFilename(), metadata.getLength());
     try (InputStream input =
         Channels.newInputStream(
             gcsService.openPrefetchingReadChannel(metadata.getFilename(), 0, BLOCK_SIZE))) {
       // Load and process the Datastore transactions one at a time
       ImmutableList<ImmutableList<VersionedEntity>> allTransactions =
           CommitLogImports.loadEntitiesByTransaction(input);
+      logger.atInfo().log(
+          "Replaying %d transactions from commit log file %s.",
+          allTransactions.size(), metadata.getFilename());
       allTransactions.forEach(this::replayTransaction);
       // if we succeeded, set the last-seen time
       DateTime checkpoint =
           DateTime.parse(
               metadata.getFilename().getObjectName().substring(DIFF_FILE_PREFIX.length()));
       SqlReplayCheckpoint.set(checkpoint);
-      logger.atInfo().log("Replayed %d transactions from commit log file.", allTransactions.size());
+      logger.atInfo().log(
+          "Replayed %d transactions from commit log file %s.",
+          allTransactions.size(), metadata.getFilename());
     } catch (IOException e) {
-      throw new RuntimeException(e);
+      throw new RuntimeException(
+          "Errored out while replaying commit log file " + metadata.getFilename(), e);
     }
   }
 
diff --git a/core/src/test/java/google/registry/backup/ReplayCommitLogsToSqlActionTest.java b/core/src/test/java/google/registry/backup/ReplayCommitLogsToSqlActionTest.java
index cea01ff7e..6561455bf 100644
--- a/core/src/test/java/google/registry/backup/ReplayCommitLogsToSqlActionTest.java
+++ b/core/src/test/java/google/registry/backup/ReplayCommitLogsToSqlActionTest.java
@@ -494,6 +494,8 @@ public class ReplayCommitLogsToSqlActionTest {
   private void runAndAssertSuccess(DateTime expectedCheckpointTime) {
     action.run();
     assertThat(response.getStatus()).isEqualTo(SC_OK);
+    assertThat(response.getPayload())
+        .isEqualTo("ReplayCommitLogsToSqlAction completed successfully.");
     assertThat(jpaTm().transact(SqlReplayCheckpoint::get)).isEqualTo(expectedCheckpointTime);
   }