Fix thread stuck issue + addtnl logs (#368)

* Added logs to troubleshoot thread hanging issue
* CASL-258 unreleased lock fix (#358)
* Fixed array patching (#365) (#367)
* corrected patcher test expectation
* updated version
* updated changelog
---------

Co-authored-by: Pawel Mazurek <52866094+cyberhead-pl@users.noreply.github.com>

CHANGELOG.md

@@ -1,3 +1,7 @@
+## Naksha_2.1.5
+
+- Fixed thread hanging issue fixed by avoiding indefinite locking in `FibLinearProbeTable.java`
+
 ## Naksha_2.1.4
 
 - Fixes:

gradle.properties

@@ -11,4 +11,4 @@ mavenPassword=YourPassword
 # - here-naksha-lib-core/NakshaVersion (static property: latest)
 # - here-naksha-lib-psql/resources/naksha_plpgsql.sql (method: naksha_version)
 # - here-naksha-app-service/src/main/resources/swagger/openapi.yaml (info.version property)
-version=2.1.4
+version=2.1.5

here-naksha-app-service/src/main/resources/swagger/openapi.yaml

@@ -12,7 +12,7 @@ servers:
 info:
   title: "Naksha Hub-API"
   description: "Naksha Hub-API is a REST API to provide simple access to geo data."
-  version: "2.1.4"
+  version: "2.1.5"
 
 security:
   - AccessToken: [ ]

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/AbstractTask.java

@@ -613,6 +613,9 @@ private void incInstanceLevelUsage(String actorId, long limit) {
         break;
       }
       // Failed, conflict, repeat
+      log.info(
+          "Concurrency conflict while incrementing instance level threadCount from {}. Will retry...",
+          threadCount);
     }
   }
 
@@ -649,6 +652,9 @@ private void incActorLevelUsage(String actorId, long limit) {
       if (counter == null) {
         Long existing = actorUsageMap.putIfAbsent(actorId, 1L);
         if (existing != null) {
+          log.info(
+              "Concurrency conflict while initializing threadCount to 1 for actorId [{}]. Will retry...",
+              actorId);
           continue; // Repeat, conflict with other thread
         }
         return;
@@ -669,6 +675,10 @@ private void incActorLevelUsage(String actorId, long limit) {
         break;
       }
       // Failed, conflict, repeat
+      log.info(
+          "Concurrency conflict while incrementing actor level threadCount from {} for actorId [{}]. Will retry...",
+          counter,
+          actorId);
     }
   }
 
@@ -693,13 +703,20 @@ private void decActorLevelUsage(String actorId) {
           log.error("Invalid actor usage value for actor: " + actorId + " value: " + current);
         }
         if (!actorUsageMap.remove(actorId, current)) {
+          log.info(
+              "Concurrency conflict while removing actor level threadCount for actorId [{}]. Will retry...",
+              actorId);
           continue;
         }
         break;
       } else if (actorUsageMap.replace(actorId, current, current - 1)) {
         break;
       }
       // Failed, repeat, conflict with other thread
+      log.info(
+          "Concurrency conflict while decrementing actor level threadCount from {} for actorId [{}]. Will retry...",
+          current,
+          actorId);
     }
   }
 }

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/NakshaContext.java

@@ -221,6 +221,7 @@ public long startNanos() {
         return newValue;
       }
       // Conflict, two threads seem to want to update the same key the same time!
+      logger.info("Concurrency conflict while updating attachment map for key {}", valueClass);
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/storage/IStorage.java

@@ -32,13 +32,17 @@
 import org.jetbrains.annotations.ApiStatus.AvailableSince;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Storage API to gain access to storages.
  */
 @AvailableSince(NakshaVersion.v2_0_6)
 public interface IStorage extends AutoCloseable {
 
+  Logger logger = LoggerFactory.getLogger(IStorage.class);
+
   /**
    * Initializes the storage, create the transaction table, install needed scripts and extensions.
    *
@@ -191,10 +195,12 @@ default void close() {
       try {
         shutdown(null).get();
         return;
-      } catch (InterruptedException ignore) {
+      } catch (InterruptedException ie) {
+        logger.warn("Exception while shutting down IStorage. ", ie);
       } catch (Exception e) {
         throw unchecked(e);
       }
+      logger.info("Unable to shutdown IStorage. Will retry...");
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/FibMap.java

@@ -29,6 +29,8 @@
 import java.util.List;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Functional implementation of a recursive, thread safe, growing map, based upon <a
@@ -76,6 +78,8 @@ public final class FibMap {
   // See: https://developer.arm.com/documentation/100941/0101/Barriers
   //
 
+  private static final Logger log = LoggerFactory.getLogger(FibMap.class);
+
   /** The empty array used by default, so that empty maps do not consume memory. */
   public static final Object[] EMPTY = new Object[0];
 
@@ -343,6 +347,7 @@ public static boolean containsKey(@NotNull Object searchKey, Object @NotNull []
 
       if (existing_key == LOCK_OBJECT) {
         // Thread.yield();
+        log.info("Concurrency conflict while modifying a key at {}. Will retry...", i);
         continue;
       }
 
@@ -359,6 +364,7 @@ public static boolean containsKey(@NotNull Object searchKey, Object @NotNull []
 
             if (sub_key == LOCK_OBJECT) {
               // Thread.yield();
+              log.info("Concurrency conflict while modifying a sub_key at {}. Will retry...", j);
               continue;
             }
             if (ILike.equals(sub_key, key)) {
@@ -560,6 +566,7 @@ public static long count(@Nullable Object @NotNull [] array) {
 
       if (existing_key == LOCK_OBJECT) {
         // Thread.yield();
+        log.info("Concurrency conflict while modifying a key at {}. Will retry...", ki);
         continue;
       }
 
@@ -630,6 +637,7 @@ public static long count(@Nullable Object @NotNull [] array) {
             }
           }
           // Conflict: concurrent update.
+          log.info("Concurrency conflict while locking key at {}. Will retry...", ki);
           continue;
         }
         return _put(key, key_hash, expected_value, new_value, create, segment, depth + 1, intern, conflict);
@@ -656,6 +664,7 @@ public static long count(@Nullable Object @NotNull [] array) {
           }
           // Race condition, another thread modifies concurrently.
           // Thread.yield();
+          log.info("Concurrency conflict while locking key at {}. Will retry...", ki);
           continue;
         }
 
@@ -693,6 +702,7 @@ public static long count(@Nullable Object @NotNull [] array) {
             return UNDEFINED;
           }
           // Race condition, another thread modifies concurrently.
+          log.info("Concurrency conflict while locking key at {}. Will retry...", ki);
           continue;
         }
         // We need to create a new sub-array that must be initialized with the existing key, so we
@@ -710,6 +720,7 @@ public static long count(@Nullable Object @NotNull [] array) {
           return _put(key, key_hash, expected_value, new_value, true, sub_array, depth + 1, intern, conflict);
         }
         // Race condition, another thread modifies concurrently.
+        log.info("Concurrency conflict while locking key at {}. Will retry...", ki);
         continue;
       }
 
@@ -735,6 +746,7 @@ public static long count(@Nullable Object @NotNull [] array) {
         return UNDEFINED;
       }
       // Race condition, another thread modified concurrently.
+      log.info("Race condition while modifying key. Will retry...");
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/fib/FibLinearProbeTable.java

@@ -82,7 +82,7 @@ ENTRY execute(final @NotNull FibSetOp op, final @NotNull KEY key, final @NotNull
           if (raw instanceof Reference<?>) {
             Reference<?> ref = (Reference<?>) raw;
             entry = (ENTRY) ref.get();
-            if (entry == null && lock.tryLock()) {
+            if (entry == null && (lock.isHeldByCurrentThread() || lock.tryLock())) {
               locked = true;
               array[i] = null;
               SIZE.getAndAdd(fibSet, -1L);

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/fib/FibSet.java

@@ -37,6 +37,8 @@
 import org.jetbrains.annotations.ApiStatus.AvailableSince;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * A recursive, thread safe, weak/soft/strong referencing set, based upon <a
@@ -54,6 +56,8 @@
 @SuppressWarnings({"rawtypes", "unused"})
 public class FibSet<KEY, ENTRY extends FibEntry<KEY>> {
 
+  private static final Logger logger = LoggerFactory.getLogger(FibSet.class);
+
   /**
    * The empty array used by default, so that empty maps do not consume memory.
    */
@@ -452,6 +456,9 @@ ENTRY _execute(
         if (raw_entry == null) {
           if (!ARRAY.compareAndSet(array, index, ref, null)) {
             // Race condition, another thread modified the array slot.
+            logger.info(
+                "Concurrency conflict while initializing array value at index {}. Will retry...",
+                index);
             continue;
           }
           SIZE.getAndAdd(this, -1L);
@@ -487,6 +494,7 @@ ENTRY _execute(
               return (ENTRY) entry;
             }
             // Race condition, other thread updated the reference concurrently.
+            logger.info("Concurrency conflict while setting array value at index {}. Will retry...", index);
             continue;
           }
           assert op == REMOVE;
@@ -495,6 +503,7 @@ ENTRY _execute(
             return (ENTRY) entry;
           }
           // Race condition, other thread updated the reference concurrently.
+          logger.info("Concurrency conflict while nullifying array value at index {}. Will retry...", index);
           continue;
         }
 
@@ -516,6 +525,7 @@ ENTRY _execute(
             return _execute(op, key, key_hash, refType, sub_array, depth + 1);
           }
           // Race condition, another thread modified concurrently.
+          logger.info("Concurrency conflict while setting array value at index {}. Will retry...", index);
           continue;
         }
 
@@ -529,6 +539,7 @@ ENTRY _execute(
           return new_entry;
         }
         // Race condition, another thread modified concurrently.
+        logger.info("Concurrency conflict while setting array value at index {}. Will retry...", index);
         continue;
       }
 
@@ -546,6 +557,7 @@ ENTRY _execute(
         return new_entry;
       }
       // Race condition, another thread modified concurrently.
+      logger.info("Concurrency conflict while initializing array value at index {}. Will retry...", index);
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/json/JsonFieldBool.java

@@ -23,9 +23,13 @@
 import java.nio.ByteOrder;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public final class JsonFieldBool<OBJECT> extends JsonField<OBJECT, Boolean> {
 
+  private static final Logger logger = LoggerFactory.getLogger(JsonFieldBool.class);
+
   JsonFieldBool(
       @NotNull JsonClass<OBJECT> jsonClass,
       @NotNull Field javaField,
@@ -94,6 +98,7 @@ public boolean _compareAndSwap(@NotNull OBJECT object, Boolean expected, Boolean
         return true;
       }
       // We need to loop, because possibly some code modified bytes we're not interested in.
+      logger.info("Concurrency conflict while setting value at offset {}. Will retry...", offset);
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/json/JsonFieldByte.java

@@ -23,9 +23,13 @@
 import java.nio.ByteOrder;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public final class JsonFieldByte<OBJECT> extends JsonField<OBJECT, Byte> {
 
+  private static final Logger logger = LoggerFactory.getLogger(JsonFieldByte.class);
+
   JsonFieldByte(
       @NotNull JsonClass<OBJECT> jsonClass,
       @NotNull Field javaField,
@@ -100,6 +104,7 @@ public boolean _compareAndSwap(@NotNull OBJECT object, Byte expected, Byte value
         return true;
       }
       // We need to loop, because possibly some code modified bytes we're not interested in.
+      logger.info("Concurrency conflict while setting value at offset {}. Will retry...", offset);
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/json/JsonFieldChar.java

@@ -23,9 +23,13 @@
 import java.nio.ByteOrder;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public final class JsonFieldChar<OBJECT> extends JsonField<OBJECT, Character> {
 
+  private static final Logger logger = LoggerFactory.getLogger(JsonFieldChar.class);
+
   JsonFieldChar(
       @NotNull JsonClass<OBJECT> jsonClass,
       @NotNull Field javaField,
@@ -101,6 +105,7 @@ public boolean _compareAndSwap(@NotNull OBJECT object, Character expected, Chara
         return true;
       }
       // We need to loop, because possibly some code modified bytes we're not interested in.
+      logger.info("Concurrency conflict while setting value at offset {}. Will retry...", offset);
     }
   }
 

here-naksha-lib-core/src/main/java/com/here/naksha/lib/core/util/json/JsonFieldShort.java

@@ -23,9 +23,13 @@
 import java.nio.ByteOrder;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public final class JsonFieldShort<OBJECT> extends JsonField<OBJECT, Short> {
 
+  private static final Logger logger = LoggerFactory.getLogger(JsonFieldShort.class);
+
   JsonFieldShort(
       @NotNull JsonClass<OBJECT> jsonClass,
       @NotNull Field javaField,
@@ -102,6 +106,7 @@ public boolean _compareAndSwap(@NotNull OBJECT object, Short expected, Short val
         return true;
       }
       // We need to loop, because possibly some code modified bytes we're not interested in.
+      logger.info("Concurrency conflict while setting value at offset {}. Will retry...", offset);
     }
   }