HBASE-28403 Improve debugging for failures in procedure tests (#5709)

ndimiduk · ndimiduk · commit 233cebcb51c6 · 2024-03-01T11:10:06.000+01:00
We see unit test failures in Jenkins that look like this:

```
java.lang.IllegalArgumentException: run queue not empty
	at org.apache.hbase.thirdparty.com.google.common.base.Preconditions.checkArgument(Preconditions.java:143)
	at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.load(ProcedureExecutor.java:332)
	at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.init(ProcedureExecutor.java:665)
	at org.apache.hadoop.hbase.procedure2.ProcedureTestingUtility.restart(ProcedureTestingUtility.java:132)
	at org.apache.hadoop.hbase.procedure2.ProcedureTestingUtility.restart(ProcedureTestingUtility.java:100)
	at org.apache.hadoop.hbase.master.procedure.MasterProcedureTestingUtility.restartMasterProcedureExecutor(MasterProcedureTestingUtility.java:85)
	at org.apache.hadoop.hbase.master.assignment.TestRollbackSCP.testFailAndRollback(TestRollbackSCP.java:180)
```

This isn't enough information to debug the situation. The test code in question looks reasonable
enough – it clears the object for re-use between tests. However, somewhere between
stop/clear/start we miss something. Add some toString implementations and dump the objects in the
preconditions.

Signed-off-by: Duo Zhang &lt;zhangduo@apache.org&gt;
diff --git a/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/AbstractProcedureScheduler.java b/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/AbstractProcedureScheduler.java
@@ -21,6 +21,8 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.locks.Condition;
 import java.util.concurrent.locks.ReentrantLock;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.yetus.audience.InterfaceAudience;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -293,4 +295,10 @@ protected void wakePollIfNeeded(final int waitingCount) {
       schedWaitCond.signalAll();
     }
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).append("running", running)
+      .build();
+  }
 }
diff --git a/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/LockAndQueue.java b/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/LockAndQueue.java
@@ -20,6 +20,8 @@
 import java.util.function.Function;
 import java.util.function.Predicate;
 import java.util.stream.Stream;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.yetus.audience.InterfaceAudience;
 
 /**
@@ -36,8 +38,9 @@
  * NOT thread-safe. Needs external concurrency control: e.g. uses in MasterProcedureScheduler are
  * guarded by schedLock(). <br/>
  * There is no need of 'volatile' keyword for member variables because of memory synchronization
- * guarantees of locks (see 'Memory Synchronization',
- * http://docs.oracle.com/javase/8/docs/api/java/util/concurrent/locks/Lock.html) <br/>
+ * guarantees of locks (see
+ * <a href="http://docs.oracle.com/javase/8/docs/api/java/util/concurrent/locks/Lock.html">Memory
+ * Synchronization</a>) <br/>
  * We do not implement Lock interface because we need exclusive and shared locking, and also because
  * try-lock functions require procedure id. <br/>
  * We do not use ReentrantReadWriteLock directly because of its high memory overhead.
@@ -182,7 +185,7 @@ public Stream<Procedure> filterWaitingQueue(Predicate<Procedure> predicate) {
 
   @Override
   public String toString() {
-    return "exclusiveLockOwner=" + (hasExclusiveLock() ? getExclusiveLockProcIdOwner() : "NONE")
-      + ", sharedLockCount=" + getSharedLockCount() + ", waitingProcCount=" + queue.size();
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE)
+      .appendSuper(describeLockStatus()).append("waitingProcCount", queue.size()).build();
   }
 }
diff --git a/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/LockStatus.java b/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/LockStatus.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.procedure2;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.yetus.audience.InterfaceAudience;
 
 /**
@@ -68,4 +70,14 @@ default long getExclusiveLockProcIdOwner() {
    * Get the number of procedures which hold the shared lock.
    */
   int getSharedLockCount();
+
+  default String describeLockStatus() {
+    ToStringBuilder builder = new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE)
+      .append("exclusiveLock", hasExclusiveLock());
+    if (hasExclusiveLock()) {
+      builder.append("exclusiveLockProcIdOwner", getExclusiveLockProcIdOwner());
+    }
+    builder.append("sharedLockCount", getSharedLockCount());
+    return builder.build();
+  }
 }
diff --git a/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/ProcedureExecutor.java b/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/ProcedureExecutor.java
@@ -333,10 +333,11 @@ public void forceUpdate(long[] procIds) {
   }
 
   private void load(final boolean abortOnCorruption) throws IOException {
-    Preconditions.checkArgument(completed.isEmpty(), "completed not empty");
-    Preconditions.checkArgument(rollbackStack.isEmpty(), "rollback state not empty");
-    Preconditions.checkArgument(procedures.isEmpty(), "procedure map not empty");
-    Preconditions.checkArgument(scheduler.size() == 0, "run queue not empty");
+    Preconditions.checkArgument(completed.isEmpty(), "completed not empty: %s", completed);
+    Preconditions.checkArgument(rollbackStack.isEmpty(), "rollback state not empty: %s",
+      rollbackStack);
+    Preconditions.checkArgument(procedures.isEmpty(), "procedure map not empty: %s", procedures);
+    Preconditions.checkArgument(scheduler.size() == 0, "scheduler queue not empty: %s", scheduler);
 
     store.load(new ProcedureStore.ProcedureLoader() {
       @Override
diff --git a/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/SimpleProcedureScheduler.java b/hbase-procedure/src/main/java/org/apache/hadoop/hbase/procedure2/SimpleProcedureScheduler.java
@@ -19,6 +19,8 @@
 
 import java.util.Collections;
 import java.util.List;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.yetus.audience.InterfaceAudience;
 import org.apache.yetus.audience.InterfaceStability;
 
@@ -82,4 +84,10 @@ public List<LockedResource> getLocks() {
   public LockedResource getLockResource(LockedResourceType resourceType, String resourceName) {
     return null;
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .append("runnables", runnables).build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/balancer/RandomCandidateGenerator.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/balancer/RandomCandidateGenerator.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.balancer;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.yetus.audience.InterfaceAudience;
 
 @InterfaceAudience.Private
@@ -31,4 +33,10 @@ BalanceAction generate(BalancerClusterState cluster) {
 
     return pickRandomRegions(cluster, thisServer, otherServer);
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/MasterProcedureScheduler.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/MasterProcedureScheduler.java
@@ -22,6 +22,8 @@
 import java.util.List;
 import java.util.function.Function;
 import java.util.function.Supplier;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.ServerName;
 import org.apache.hadoop.hbase.TableExistsException;
 import org.apache.hadoop.hbase.TableName;
@@ -1022,4 +1024,29 @@ public String dumpLocks() throws IOException {
       schedUnlock();
     }
   }
+
+  private void serverBucketToString(ToStringBuilder builder, String queueName, Queue<?> queue) {
+    int size = queueSize(queue);
+    if (size != 0) {
+      builder.append(queueName, queue);
+    }
+  }
+
+  @Override
+  public String toString() {
+    ToStringBuilder builder =
+      new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString());
+    schedLock();
+    try {
+      for (int i = 0; i < serverBuckets.length; i++) {
+        serverBucketToString(builder, "serverBuckets[" + i + "]", serverBuckets[i]);
+      }
+      builder.append("tableMap", tableMap);
+      builder.append("peerMap", peerMap);
+      builder.append("metaMap", metaMap);
+    } finally {
+      schedUnlock();
+    }
+    return builder.build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/MetaQueue.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/MetaQueue.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.procedure;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.TableName;
 import org.apache.hadoop.hbase.procedure2.LockStatus;
 import org.apache.hadoop.hbase.procedure2.Procedure;
@@ -38,4 +40,10 @@ protected MetaQueue(LockStatus lockStatus) {
   boolean requireExclusiveLock(Procedure<?> proc) {
     return true;
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/PeerQueue.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/PeerQueue.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.procedure;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.master.procedure.PeerProcedureInterface.PeerOperationType;
 import org.apache.hadoop.hbase.procedure2.LockStatus;
 import org.apache.hadoop.hbase.procedure2.Procedure;
@@ -37,4 +39,10 @@ public boolean requireExclusiveLock(Procedure<?> proc) {
   private static boolean requirePeerExclusiveLock(PeerProcedureInterface proc) {
     return proc.getPeerOperationType() != PeerOperationType.REFRESH;
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/Queue.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/Queue.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.procedure;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.procedure2.LockStatus;
 import org.apache.hadoop.hbase.procedure2.Procedure;
 import org.apache.hadoop.hbase.procedure2.ProcedureDeque;
@@ -105,10 +107,7 @@ public int compareTo(Queue<TKey> other) {
 
   @Override
   public String toString() {
-    return String.format("%s(%s, xlock=%s sharedLock=%s size=%s)", getClass().getSimpleName(), key,
-      lockStatus.hasExclusiveLock()
-        ? "true (" + lockStatus.getExclusiveLockProcIdOwner() + ")"
-        : "false",
-      lockStatus.getSharedLockCount(), size());
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).append("key", key)
+      .append("lockStatus", lockStatus.describeLockStatus()).append("size", size()).build();
   }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/SchemaLocking.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/SchemaLocking.java
@@ -22,6 +22,9 @@
 import java.util.List;
 import java.util.Map;
 import java.util.function.Function;
+import java.util.stream.Collectors;
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.ServerName;
 import org.apache.hadoop.hbase.TableName;
 import org.apache.hadoop.hbase.master.locking.LockProcedure;
@@ -211,26 +214,19 @@ void clear() {
 
   @Override
   public String toString() {
-    return "serverLocks=" + filterUnlocked(this.serverLocks) + ", namespaceLocks="
-      + filterUnlocked(this.namespaceLocks) + ", tableLocks=" + filterUnlocked(this.tableLocks)
-      + ", regionLocks=" + filterUnlocked(this.regionLocks) + ", peerLocks="
-      + filterUnlocked(this.peerLocks) + ", metaLocks="
-      + filterUnlocked(ImmutableMap.of(TableName.META_TABLE_NAME, metaLock));
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE)
+      .append("serverLocks", filterUnlocked(serverLocks))
+      .append("namespaceLocks", filterUnlocked(namespaceLocks))
+      .append("tableLocks", filterUnlocked(tableLocks))
+      .append("regionLocks", filterUnlocked(regionLocks))
+      .append("peerLocks", filterUnlocked(peerLocks))
+      .append("metaLocks", filterUnlocked(ImmutableMap.of(TableName.META_TABLE_NAME, metaLock)))
+      .build();
+
   }
 
   private String filterUnlocked(Map<?, LockAndQueue> locks) {
-    StringBuilder sb = new StringBuilder("{");
-    int initialLength = sb.length();
-    for (Map.Entry<?, LockAndQueue> entry : locks.entrySet()) {
-      if (!entry.getValue().isLocked()) {
-        continue;
-      }
-      if (sb.length() > initialLength) {
-        sb.append(", ");
-      }
-      sb.append("{").append(entry.getKey()).append("=").append(entry.getValue()).append("}");
-    }
-    sb.append("}");
-    return sb.toString();
+    return locks.entrySet().stream().filter(val -> !val.getValue().isLocked())
+      .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue)).toString();
   }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/ServerQueue.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/ServerQueue.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.procedure;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.ServerName;
 import org.apache.hadoop.hbase.procedure2.LockStatus;
 import org.apache.hadoop.hbase.procedure2.Procedure;
@@ -46,4 +48,10 @@ public boolean requireExclusiveLock(Procedure<?> proc) {
     }
     throw new UnsupportedOperationException("unexpected type " + spi.getServerOperationType());
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .build();
+  }
 }
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/TableQueue.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/procedure/TableQueue.java
@@ -17,6 +17,8 @@
  */
 package org.apache.hadoop.hbase.master.procedure;
 
+import org.apache.commons.lang3.builder.ToStringBuilder;
+import org.apache.commons.lang3.builder.ToStringStyle;
 import org.apache.hadoop.hbase.TableName;
 import org.apache.hadoop.hbase.procedure2.LockStatus;
 import org.apache.hadoop.hbase.procedure2.Procedure;
@@ -72,4 +74,10 @@ private static boolean requireTableExclusiveLock(TableProcedureInterface proc) {
     }
     throw new UnsupportedOperationException("unexpected type " + proc.getTableOperationType());
   }
+
+  @Override
+  public String toString() {
+    return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).appendSuper(super.toString())
+      .append("namespaceLockStatus", namespaceLockStatus.describeLockStatus()).build();
+  }
 }

Original file line number	Diff line number	Diff line change
`@@ -21,6 +21,8 @@`
`21`	`21`	`import java.util.concurrent.TimeUnit;`
`22`	`22`	`import java.util.concurrent.locks.Condition;`
`23`	`23`	`import java.util.concurrent.locks.ReentrantLock;`
	`24`	`+import org.apache.commons.lang3.builder.ToStringBuilder;`
	`25`	`+import org.apache.commons.lang3.builder.ToStringStyle;`
`24`	`26`	`import org.apache.yetus.audience.InterfaceAudience;`
`25`	`27`	`import org.slf4j.Logger;`
`26`	`28`	`import org.slf4j.LoggerFactory;`
`@@ -293,4 +295,10 @@ protected void wakePollIfNeeded(final int waitingCount) {`
`293`	`295`	`schedWaitCond.signalAll();`
`294`	`296`	`}`
`295`	`297`	`}`
	`298`	`+`
	`299`	`+ @Override`
	`300`	`+ public String toString() {`
	`301`	`+ return new ToStringBuilder(this, ToStringStyle.SHORT_PREFIX_STYLE).append("running", running)`
	`302`	`+ .build();`
	`303`	`+ }`
`296`	`304`	`}`