Improve logging of why a project or ref is not replicated

Add more debug logs to indicate the cases where a project or
ref does not replicated.

For failure to read the project cache, log at warning level.

Also fix logging of the "scheduling replication ..." info log, which
was emitted before the check which could cause the replication to not
be scheduled. Move it to after the check, and add an additional debug
log of "NOT replicating ..." for the case where the check fails.

Change-Id: I13f5649cfe7e42fc672989efe8d77b47b0472023
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/Destination.java b/src/main/java/com/googlesource/gerrit/plugins/replication/Destination.java
index 746d2ca..cbd5887 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/Destination.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/Destination.java
@@ -261,9 +261,12 @@
 
   private boolean shouldReplicate(ProjectState state, CurrentUser user)
       throws PermissionBackendException {
+    String name = state.getProject().getName();
     if (!config.replicateHiddenProjects()
         && state.getProject().getState()
             == com.google.gerrit.extensions.client.ProjectState.HIDDEN) {
+      repLog.atFine().log(
+          "Project %s is hidden and replication of hidden projects is disabled", name);
       return false;
     }
 
@@ -276,6 +279,9 @@
       permissionBackend.user(user).project(state.getNameKey()).check(permissionToCheck);
       return true;
     } catch (AuthException e) {
+      repLog.atFine().log(
+          "Project %s is not visible to current user %s",
+          name, user.getUserName().orElse("unknown"));
       return false;
     }
   }
@@ -292,15 +298,20 @@
                   try {
                     projectState = projectCache.checkedGet(project);
                   } catch (IOException e) {
+                    repLog.atWarning().withCause(e).log(
+                        "Error reading project %s from cache", project);
                     return false;
                   }
                   if (projectState == null) {
+                    repLog.atFine().log("Project %s does not exist", project);
                     throw new NoSuchProjectException(project);
                   }
                   if (!projectState.statePermitsRead()) {
+                    repLog.atFine().log("Project %s does not permit read", project);
                     return false;
                   }
                   if (!shouldReplicate(projectState, userProvider.get())) {
+                    repLog.atFine().log("Project %s should not be replicated", project);
                     return false;
                   }
                   if (PushOne.ALL_REFS.equals(ref)) {
@@ -313,6 +324,9 @@
                         .ref(ref)
                         .check(RefPermission.READ);
                   } catch (AuthException e) {
+                    repLog.atFine().log(
+                        "Ref %s on project %s is not visible to calling user",
+                        ref, project, userProvider.get().getUserName().orElse("unknown"));
                     return false;
                   }
                   return true;
@@ -363,10 +377,11 @@
 
   void schedule(
       Project.NameKey project, String ref, URIish uri, ReplicationState state, boolean now) {
-    repLog.atInfo().log("scheduling replication %s:%s => %s", project, ref, uri);
     if (!shouldReplicate(project, ref, state)) {
+      repLog.atFine().log("Not scheduling replication %s:%s => %s", project, ref, uri);
       return;
     }
+    repLog.atInfo().log("scheduling replication %s:%s => %s", project, ref, uri);
 
     if (!config.replicatePermissions()) {
       PushOne e;
@@ -575,6 +590,7 @@
 
   boolean wouldPushProject(Project.NameKey project) {
     if (!shouldReplicate(project)) {
+      repLog.atFine().log("Skipping replication of project %s", project.get());
       return false;
     }
 
@@ -584,7 +600,12 @@
       return true;
     }
 
-    return (new ReplicationFilter(projects)).matches(project);
+    boolean matches = (new ReplicationFilter(projects)).matches(project);
+    if (!matches) {
+      repLog.atFine().log(
+          "Skipping replication of project %s; does not match filter", project.get());
+    }
+    return matches;
   }
 
   boolean isSingleProjectMatch() {
@@ -607,6 +628,7 @@
 
   boolean wouldPushRef(String ref) {
     if (!config.replicatePermissions() && RefNames.REFS_CONFIG.equals(ref)) {
+      repLog.atFine().log("NOT pushing ref %s; meta ref", ref);
       return false;
     }
     for (RefSpec s : config.getRemoteConfig().getPushRefSpecs()) {
@@ -614,6 +636,7 @@
         return true;
       }
     }
+    repLog.atFine().log("NOT pushing ref %s; does not match push ref specs", ref);
     return false;
   }
 
diff --git a/src/main/java/com/googlesource/gerrit/plugins/replication/ReplicationQueue.java b/src/main/java/com/googlesource/gerrit/plugins/replication/ReplicationQueue.java
index 4a59d70..2783584 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/replication/ReplicationQueue.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/replication/ReplicationQueue.java
@@ -184,6 +184,8 @@
             new ReplicateRefUpdate(project.get(), refName, uri, cfg.getRemoteConfigName()));
         cfg.schedule(project, refName, uri, state);
       }
+    } else {
+      repLog.atFine().log("Skipping ref %s on project %s", refName, project.get());
     }
 
     if (withoutState) {