Add more logging for the apply object REST-API

Introduce a lot more logging when the invocation
of the apply object REST-API fails, so that the
Gerrit admin can have more insights on the cause of
the failures.

Change-Id: I923896be72375df70a84cdd23d86e25635c88477
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/ReplicationQueue.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/ReplicationQueue.java
index cfe01e2..0ce125d 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/ReplicationQueue.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/ReplicationQueue.java
@@ -15,6 +15,7 @@
 package com.googlesource.gerrit.plugins.replication.pull;
 
 import com.google.auto.value.AutoValue;
+import com.google.common.base.Stopwatch;
 import com.google.common.collect.Queues;
 import com.google.gerrit.entities.Project;
 import com.google.gerrit.entities.Project.NameKey;
@@ -245,6 +246,12 @@
 
     try {
       Optional<RevisionData> revisionData = revisionReader.read(project, objectId, refName);
+      repLog.info(
+          "RevisionData is {} for {}:{}",
+          revisionData.map(RevisionData::toString).orElse("ABSENT"),
+          project,
+          refName);
+
       if (revisionData.isPresent()) {
         return ((source) ->
             callSendObject(source, project, refName, isDelete, revisionData.get(), state));
@@ -274,27 +281,56 @@
         try {
           URIish uri = new URIish(apiUrl);
           FetchApiClient fetchClient = fetchClientFactory.create(source);
-
+          repLog.info(
+              "Pull replication REST API apply object to {} for {}:{} - {}",
+              apiUrl,
+              project,
+              refName,
+              revision);
+          Stopwatch apiTimer = Stopwatch.createStarted();
           HttpResult result = fetchClient.callSendObject(project, refName, isDelete, revision, uri);
+          repLog.info(
+              "Pull replication REST API apply object to {} COMPLETED for {}:{} - {}, HTTP Result:"
+                  + " {} - time:{} ms",
+              apiUrl,
+              project,
+              refName,
+              revision,
+              result,
+              apiTimer.elapsed(TimeUnit.MILLISECONDS));
+
           if (isProjectMissing(result, project) && source.isCreateMissingRepositories()) {
             result = initProject(project, uri, fetchClient, result);
+            repLog.info("Missing project {} created, HTTP Result:{}", project, result);
           }
+
           if (!result.isSuccessful()) {
-            repLog.warn(
-                String.format(
-                    "Pull replication rest api apply object call failed. Endpoint url: %s, reason:%s",
-                    apiUrl, result.getMessage().orElse("unknown")));
             if (result.isParentObjectMissing()) {
               throw new MissingParentObjectException(
                   project, refName, source.getRemoteConfigName());
             }
           }
         } catch (URISyntaxException e) {
+          repLog.warn(
+              "Pull replication REST API apply object to {} *FAILED* for {}:{} - {}",
+              apiUrl,
+              project,
+              refName,
+              revision,
+              e);
           stateLog.error(String.format("Cannot parse pull replication api url:%s", apiUrl), state);
         } catch (IOException e) {
+          repLog.warn(
+              "Pull replication REST API apply object to {} *FAILED* for {}:{} - {}",
+              apiUrl,
+              project,
+              refName,
+              revision,
+              e);
           stateLog.error(
               String.format(
-                  "Exception during the pull replication fetch rest api call. Endpoint url:%s, message:%s",
+                  "Exception during the pull replication fetch rest api call. Endpoint url:%s,"
+                      + " message:%s",
                   apiUrl, e.getMessage()),
               e,
               state);
@@ -326,7 +362,8 @@
         } catch (Exception e) {
           stateLog.error(
               String.format(
-                  "Exception during the pull replication fetch rest api call. Endpoint url:%s, message:%s",
+                  "Exception during the pull replication fetch rest api call. Endpoint url:%s,"
+                      + " message:%s",
                   apiUrl, e.getMessage()),
               e,
               state);
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectAction.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectAction.java
index f83cadb..442f585 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectAction.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectAction.java
@@ -14,6 +14,8 @@
 
 package com.googlesource.gerrit.plugins.replication.pull.api;
 
+import static com.googlesource.gerrit.plugins.replication.pull.PullReplicationLogger.repLog;
+
 import com.google.common.base.Strings;
 import com.google.gerrit.extensions.restapi.AuthException;
 import com.google.gerrit.extensions.restapi.BadRequestException;
@@ -60,25 +62,68 @@
         throw new BadRequestException("Ref-update refname cannot be null or empty");
       }
 
+      repLog.info(
+          "Apply object API from {} for {}:{} - {}",
+          resource.getNameKey(),
+          input.getLabel(),
+          input.getRefName(),
+          input.getRevisionData());
+
       if (Objects.isNull(input.getRevisionData())) {
         deleteRefCommand.deleteRef(resource.getNameKey(), input.getRefName(), input.getLabel());
+        repLog.info(
+            "Apply object API - REF DELETED - from {} for {}:{} - {}",
+            resource.getNameKey(),
+            input.getLabel(),
+            input.getRefName(),
+            input.getRevisionData());
         return Response.created(input);
       }
 
       try {
         input.validate();
       } catch (IllegalArgumentException e) {
-        throw new BadRequestException("Ref-update with invalid input: " + e.getMessage(), e);
+        BadRequestException bre =
+            new BadRequestException("Ref-update with invalid input: " + e.getMessage(), e);
+        repLog.error(
+            "Apply object API *FAILED* from {} for {}:{} - {}",
+            input.getLabel(),
+            resource.getNameKey(),
+            input.getRefName(),
+            input.getRevisionData(),
+            bre);
+        throw bre;
       }
 
       command.applyObject(
           resource.getNameKey(), input.getRefName(), input.getRevisionData(), input.getLabel());
       return Response.created(input);
     } catch (MissingParentObjectException e) {
+      repLog.error(
+          "Apply object API *FAILED* from {} for {}:{} - {}",
+          input.getLabel(),
+          resource.getNameKey(),
+          input.getRefName(),
+          input.getRevisionData(),
+          e);
       throw new ResourceConflictException(e.getMessage(), e);
     } catch (NumberFormatException | IOException e) {
+      repLog.error(
+          "Apply object API *FAILED* from {} for {}:{} - {}",
+          input.getLabel(),
+          resource.getNameKey(),
+          input.getRefName(),
+          input.getRevisionData(),
+          e);
       throw RestApiException.wrap(e.getMessage(), e);
     } catch (RefUpdateException e) {
+      repLog.error(
+          "Apply object API *FAILED* from {} for {}:{} - {}",
+          input.getLabel(),
+          resource.getNameKey(),
+          input.getRefName(),
+          input.getRevisionData(),
+          e);
       throw new UnprocessableEntityException(e.getMessage());
     }
   }
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectCommand.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectCommand.java
index 276aa16..ff231d8 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectCommand.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/ApplyObjectCommand.java
@@ -73,7 +73,7 @@
       Project.NameKey name, String refName, RevisionData revisionData, String sourceLabel)
       throws IOException, RefUpdateException, MissingParentObjectException {
 
-    repLog.info("Apply object from {} for project {}, ref name {}", sourceLabel, name, refName);
+    repLog.info("Apply object from {} for {}:{} - {}", sourceLabel, name, refName, revisionData);
     Timer1.Context<String> context = metrics.start(sourceLabel);
     RefUpdateState refUpdateState = applyObject.apply(name, new RefSpec(refName), revisionData);
     long elapsed = NANOSECONDS.toMillis(context.stop());
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionData.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionData.java
index bcd4e05..9c33d07 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionData.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionData.java
@@ -43,4 +43,15 @@
   public List<RevisionObjectData> getBlobs() {
     return blobs;
   }
+
+  @Override
+  public String toString() {
+    return "{"
+        + (commitObject != null ? "commitObject=" + commitObject : "")
+        + " "
+        + (treeObject != null ? "treeObject=" + treeObject : "")
+        + " "
+        + (blobs != null && !blobs.isEmpty() ? "blobs=" + blobs : "")
+        + "}";
+  }
 }
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionObjectData.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionObjectData.java
index 02ba06c..0962717 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionObjectData.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/api/data/RevisionObjectData.java
@@ -15,6 +15,7 @@
 package com.googlesource.gerrit.plugins.replication.pull.api.data;
 
 import java.util.Base64;
+import org.eclipse.jgit.lib.Constants;
 
 public class RevisionObjectData {
   private final Integer type;
@@ -32,4 +33,18 @@
   public byte[] getContent() {
     return Base64.getDecoder().decode(content);
   }
+
+  @Override
+  public String toString() {
+    switch (type) {
+      case Constants.OBJ_BLOB:
+        return "BLOB";
+      case Constants.OBJ_COMMIT:
+        return "COMMIT";
+      case Constants.OBJ_TREE:
+        return "TREE";
+      default:
+        return "type:" + type;
+    }
+  }
 }
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/client/HttpResult.java b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/client/HttpResult.java
index bd164df..3efcacf 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/pull/client/HttpResult.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/pull/client/HttpResult.java
@@ -47,4 +47,11 @@
   public boolean isParentObjectMissing() {
     return responseCode == SC_CONFLICT;
   }
+
+  @Override
+  public String toString() {
+    return isSuccessful()
+        ? "OK"
+        : "FAILED" + ", status=" + responseCode + message.map(s -> " '" + s + "'").orElse("");
+  }
 }