More debug info on controller lock warnings

3 files changed, 18 insertions, 24 deletions

diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
index 05294a5435b..469b8d1355c 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/Lock.java
@@ -9,9 +9,11 @@ import com.yahoo.vespa.curator.stats.ThreadLockStats;
 import org.apache.curator.framework.recipes.locks.InterProcessLock;
 
 import java.time.Duration;
+import java.time.Instant;
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
+import java.util.function.Consumer;
 
 /**
  * A cluster-wide re-entrant mutex which is released on (the last symmetric) close.
@@ -23,9 +25,11 @@ import java.util.concurrent.TimeUnit;
  */
 public class Lock implements Mutex {
 
+    // TODO(hakon): Remove once debugging is done
     private final Object monitor = new Object();
     private long nextSequenceNumber = 0;
     private final Map<Long, Long> reentriesByThreadId = new HashMap<>();
+    private final Instant created = Instant.now();
 
     private final InterProcessLock mutex;
     private final String lockPath;
@@ -62,13 +66,8 @@ public class Lock implements Mutex {
         invoke(+1L, threadLockStats::lockAcquired);
     }
 
-    @FunctionalInterface
-    private interface TriConsumer {
-        void accept(String lockId, long reentryCountDiff, Map<Long, Long> reentriesByThreadId);
-    }
-
     // TODO(hakon): Remove once debugging is unnecessary
-    private void invoke(long reentryCountDiff, TriConsumer consumer) {
+    private void invoke(long reentryCountDiff, Consumer<String> consumer) {
         long threadId = Thread.currentThread().getId();
         final long sequenceNumber;
         final Map<Long, Long> reentriesByThreadIdCopy;
@@ -86,8 +85,10 @@ public class Lock implements Mutex {
             reentriesByThreadIdCopy = Map.copyOf(reentriesByThreadId);
         }
 
-        String lockId = Integer.toHexString(System.identityHashCode(this));
-        consumer.accept(lockId, sequenceNumber, reentriesByThreadIdCopy);
+        String debug = "thread " + threadId + " " + lockPath + "@" + created + " 0x" +
+                       Integer.toHexString(System.identityHashCode(this))  + " #" + sequenceNumber +
+                       ", reentries by thread ID = " + reentriesByThreadIdCopy;
+        consumer.accept(debug);
     }
 
     @Override
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java
index ecb344dedb9..a37034b7547 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/LockStats.java
@@ -64,33 +64,28 @@ public class LockStats {
     }
 
     /** Must be invoked only after the first and non-reentry acquisition of the lock. */
-    void notifyOfThreadHoldingLock(Thread currentThread, String lockPath, String lockId,
-                                   long sequenceNumber, Map<Long, Long> reentriesByThreadId) {
+    void notifyOfThreadHoldingLock(Thread currentThread, String lockPath, String debug) {
         Thread oldThread = lockPathsHeld.put(lockPath, currentThread);
         if (oldThread != null) {
             getLockMetrics(lockPath).incrementAcquireWithoutReleaseCount();
             logger.warning("Thread " + currentThread.getName() + " reports it has the lock on " +
                            lockPath + ", but thread " + oldThread.getName() +
-                           " has not reported it released the lock. " + lockId + "#" + sequenceNumber +
-                           ", reentries by thread ID = " + reentriesByThreadId);
+                           " has not reported it released the lock. " + debug);
         }
     }
 
     /** Must be invoked only before the last and non-reentry release of the lock. */
-    void notifyOfThreadReleasingLock(Thread currentThread, String lockPath, String lockId,
-                                     long sequenceNumber, Map<Long, Long> reentriesByThreadId) {
+    void notifyOfThreadReleasingLock(Thread currentThread, String lockPath, String debug) {
         Thread oldThread = lockPathsHeld.remove(lockPath);
         if (oldThread == null) {
             getLockMetrics(lockPath).incrementNakedReleaseCount();
             logger.warning("Thread " + currentThread.getName() + " is releasing the lock " + lockPath +
-                           ", but nobody owns that lock. " + lockId + "#" + sequenceNumber +
-                           ", reentries by thread ID = " + reentriesByThreadId);
+                           ", but nobody owns that lock. " + debug);
         } else if (oldThread != currentThread) {
             getLockMetrics(lockPath).incrementForeignReleaseCount();
             logger.warning("Thread " + currentThread.getName() +
                            " is releasing the lock " + lockPath + ", but it was owned by thread " +
-                           oldThread.getName() + ". " + lockId + "#" + sequenceNumber +
-                           ", reentries by thread ID = " + reentriesByThreadId);
+                           oldThread.getName() + ". " + debug);
         }
     }
 
diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
index 7f8eafdcf7f..beda7eaa142 100644
--- a/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
+++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/stats/ThreadLockStats.java
@@ -98,7 +98,7 @@ public class ThreadLockStats {
     }
 
     /** Mutable method (see class doc) */
-    public void lockAcquired(String lockId, long sequenceNumber, Map<Long, Long> reentriesByThreadId) {
+    public void lockAcquired(String debug) {
         withLastLockAttempt(lockAttempt -> {
             // Note on the order of lockAcquired() vs notifyOfThreadHoldingLock(): When the latter is
             // invoked, other threads may query e.g. isAcquired() on the lockAttempt, which would
@@ -107,20 +107,18 @@ public class ThreadLockStats {
             lockAttempt.lockAcquired();
 
             if (!lockAttempt.isReentry()) {
-                LockStats.getGlobal().notifyOfThreadHoldingLock(thread, lockAttempt.getLockPath(),
-                                                                lockId, sequenceNumber, reentriesByThreadId);
+                LockStats.getGlobal().notifyOfThreadHoldingLock(thread, lockAttempt.getLockPath(), debug);
             }
         });
     }
 
     /** Mutable method (see class doc) */
-    public void preRelease(String lockId, long sequenceNumber, Map<Long, Long> reentriesByThreadId) {
+    public void preRelease(String debug) {
         withLastLockAttempt(lockAttempt -> {
             // Note on the order of these two statement: Same concerns apply here as in lockAcquired().
 
             if (!lockAttempt.isReentry()) {
-                LockStats.getGlobal().notifyOfThreadReleasingLock(thread, lockAttempt.getLockPath(),
-                                                                  lockId, sequenceNumber, reentriesByThreadId);
+                LockStats.getGlobal().notifyOfThreadReleasingLock(thread, lockAttempt.getLockPath(), debug);
             }
 
             lockAttempt.preRelease();