Fix Hibernate cache random failures #694

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/CaffeineCache.java

@@ -5,6 +5,7 @@
 import com.github.benmanes.caffeine.cache.Expiry;
 import org.jboss.logging.Logger;
 
+import java.time.Duration;
 import java.util.Map;
 import java.util.function.BiFunction;
 import java.util.function.Consumer;
@@ -19,7 +20,7 @@ final class CaffeineCache implements InternalCache {
     private final String cacheName;
 
     public CaffeineCache(String cacheName, InternalCacheConfig config, TimeService timeService) {
-        long maxIdle = config != null ? config.maxIdle : -1;
+        Duration maxIdle = config != null ? config.maxIdle : null;
         long maxSize = config != null ? config.maxSize : -1;
 
         this.cacheName = cacheName;
@@ -129,10 +130,13 @@ public void invalidateAll() {
     // e.g. regions would then need to aggregate counts for all data accesses for that region.
     private static final class CacheExpiryPolicy implements Expiry {
 
-        private final long maxIdle;
+        private final long maxIdleNanos;
 
-        public CacheExpiryPolicy(long maxIdle) {
-            this.maxIdle = maxIdle;
+        public CacheExpiryPolicy(Duration maxIdle) {
+            if (maxIdle == null)
+                this.maxIdleNanos = -1;
+            else
+                this.maxIdleNanos = maxIdle.toNanos();
         }
 
         @Override
@@ -144,18 +148,18 @@ private long calculateExpiration(Object value, long currentTime) {
             if (value instanceof VersionedEntry) {
                 // Deal with versioned entry expirations
                 final VersionedEntry versioned = (VersionedEntry) value;
-                if (maxIdle > 0) {
-                    final long idleDeadline = currentTime + maxIdle;
-                    final long versionedLifespan = versioned.getLifespan();
+                if (maxIdleNanos > 0) {
+                    final long idleDeadline = currentTime + maxIdleNanos;
+                    final long versionedLifespan = versioned.getLifespanNanos();
                     log.tracef("Expire after create, either idle deadline %d (ns) or versioned entry lifespan %d (ns)", idleDeadline, versionedLifespan);
                     return Math.min(idleDeadline, versionedLifespan);
                 }
 
-                return versioned.getLifespan();
+                return versioned.getLifespanNanos();
             }
 
-            if (maxIdle > 0)
-                return maxIdle;
+            if (maxIdleNanos > 0)
+                return maxIdleNanos;
 
             return Long.MAX_VALUE;
         }
@@ -167,8 +171,8 @@ public long expireAfterUpdate(Object key, Object value, long currentTime, long c
 
         @Override
         public long expireAfterRead(Object key, Object value, long currentTime, long currentDuration) {
-            if (maxIdle > 0) {
-                return maxIdle;
+            if (maxIdleNanos > 0) {
+                return maxIdleNanos;
             }
 
             return Long.MAX_VALUE;

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/DomainDataRegionImpl.java

@@ -190,7 +190,7 @@ private void runInvalidation() {
                 break;
             case VERSIONED_ENTRIES:
                 // no need to use this as a function - simply override all
-                VersionedEntry evict = new VersionedEntry(regionFactory.nextTimestamp(), PutFromLoadValidator.EXPIRATION_PERIOD);
+                VersionedEntry evict = new VersionedEntry(regionFactory.nextTimestamp(), VersionedEntry.TOMBSTONE_LIFESPAN);
                 removeEntries(entry -> cache.put(entry.getKey(), evict));
                 break;
         }

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InfinispanRegionFactory.java

@@ -14,6 +14,7 @@
 import org.hibernate.internal.util.config.ConfigurationHelper;
 import org.jboss.logging.Logger;
 
+import java.time.Duration;
 import java.util.*;
 import java.util.concurrent.TimeUnit;
 
@@ -70,8 +71,7 @@ public void start(SessionFactoryOptions settings, Map configValues) {
                         if (key.contains(SIZE_SUFFIX)) {
                             cacheConfig.setMaxSize(Long.parseLong(value));
                         } else if (key.contains(MAX_IDLE_SUFFIX)) {
-                            final long nanosIdle = TimeUnit.SECONDS.toNanos(Long.parseLong(value));
-                            cacheConfig.setMaxIdle(nanosIdle);
+                            cacheConfig.setMaxIdle(Duration.ofSeconds(Long.parseLong(value)));
                         }
 
                         return cacheConfig;

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/InternalCacheConfig.java

@@ -1,15 +1,17 @@
 package org.infinispan.protean.hibernate.cache;
 
+import java.time.Duration;
+
 final class InternalCacheConfig {
 
     long maxSize = -1;
-    long maxIdle = -1;
+    Duration maxIdle; // in seconds
 
     void setMaxSize(long maxSize) {
         this.maxSize = maxSize;
     }
 
-    void setMaxIdle(long maxIdle) {
+    void setMaxIdle(Duration maxIdle) {
         this.maxIdle = maxIdle;
     }
 

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/PutFromLoadValidator.java

@@ -78,9 +78,11 @@ public final class PutFromLoadValidator {
     private static final boolean trace = log.isTraceEnabled();
 
     /**
-     * Period (in nanoseconds) after which ongoing invalidation is removed.
+     * Period (in milliseconds) after which ongoing invalidation is removed.
+     * Needs to be milliseconds because it will be compared with {@link RegionFactory#nextTimestamp()},
+     * and that method is expected to return milliseconds.
      */
-    public static final long EXPIRATION_PERIOD = 60_000_000;
+    private static final long EXPIRATION_PERIOD = Duration.ofSeconds(60).toMillis();
 
     /**
      * Registry of expected, future, isPutValid calls. If a key+owner is registered in this map, it
@@ -120,7 +122,7 @@ public PutFromLoadValidator(InternalCache cache, String regionName, RegionFactor
         this.nextTimestamp = regionFactory::nextTimestamp;
 
         this.pendingPuts = Caffeine.newBuilder()
-                .expireAfterAccess(Duration.ofNanos(EXPIRATION_PERIOD))
+                .expireAfterAccess(Duration.ofMillis(EXPIRATION_PERIOD))
                 .build();
     }
 

independent-projects/infinispan-hibernate-cache-protean/src/main/java/org/infinispan/protean/hibernate/cache/VersionedEntry.java

@@ -4,6 +4,7 @@
 import org.hibernate.cache.spi.entry.StructuredCacheEntry;
 import org.jboss.logging.Logger;
 
+import java.time.Duration;
 import java.util.Comparator;
 import java.util.Map;
 import java.util.function.BiFunction;
@@ -14,12 +15,14 @@ final class VersionedEntry {
     private static final Logger log = Logger.getLogger(VersionedEntry.class);
     private static final boolean trace = log.isTraceEnabled();
 
+    public static final Duration TOMBSTONE_LIFESPAN = Duration.ofSeconds(60);
+
     static final ExcludeEmptyFilter EXCLUDE_EMPTY_VERSIONED_ENTRY = new ExcludeEmptyFilter();
 
     private final Object value;
     private final Object version;
     private final long timestamp;
-    private long lifespan = Long.MAX_VALUE; // nanoseconds
+    private Duration lifespan = Duration.ofSeconds(Long.MAX_VALUE);
 
     VersionedEntry(Object value, Object version, long timestamp) {
         this.value = value;
@@ -31,7 +34,7 @@ final class VersionedEntry {
         this(null, null, timestamp);
     }
 
-    VersionedEntry(long timestamp, long lifespan) {
+    VersionedEntry(long timestamp, Duration lifespan) {
         this(null, null, timestamp);
         this.lifespan = lifespan;
     }
@@ -44,8 +47,8 @@ long getTimestamp() {
         return timestamp;
     }
 
-    long getLifespan() {
-        return lifespan;
+    long getLifespanNanos() {
+        return lifespan.toNanos();
     }
 
     Object getValue() {
@@ -69,7 +72,7 @@ public Object apply(Object key, Object oldValue) {
             }
             if (entry.version == null) {
                 // eviction or post-commit removal: we'll store it with given timestamp
-                entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD;
+                entry.lifespan = TOMBSTONE_LIFESPAN;
                 return entry;
             }
 
@@ -105,15 +108,15 @@ public Object apply(Object key, Object oldValue) {
                     }
                 }
                 if (versionComparator == null) {
-                    entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD;
+                    entry.lifespan = TOMBSTONE_LIFESPAN;
                     return new VersionedEntry(null, null, entry.timestamp);
                 } else {
                     int compareResult = versionComparator.compare(entry.version, oldVersion);
                     if (trace) {
                         log.tracef("Comparing %s and %s -> %d (using %s)", entry.version, oldVersion, compareResult, versionComparator);
                     }
                     if (entry.value == null && compareResult >= 0) {
-                        entry.lifespan = PutFromLoadValidator.EXPIRATION_PERIOD;
+                        entry.lifespan = TOMBSTONE_LIFESPAN;
                         return entry;
                     } else if (compareResult > 0) {
                         return entry.value instanceof CacheEntry ? entry.value : entry;

integration-tests/infinispan-cache-jpa/src/main/java/org/jboss/shamrock/example/infinispancachejpa/InfinispanCacheJPAFunctionalityTestEndpoint.java

@@ -12,8 +12,11 @@
 
 import java.io.IOException;
 import java.io.PrintWriter;
+import java.time.Duration;
 import java.util.*;
 import java.util.concurrent.TimeUnit;
+import java.util.function.BiFunction;
+import java.util.function.Supplier;
 
 import javax.persistence.EntityManager;
 import javax.persistence.EntityManagerFactory;
@@ -392,24 +395,6 @@ private static void findByIdItems(EntityManager em, String[] expectedDesc) {
 
     private static void testMaxSize(EntityManagerFactory emf) {
         addItemBeyondMaxSize(emf);
-        queryItemEvicted(emf);
-    }
-
-    private static void queryItemEvicted(EntityManagerFactory emf) {
-        Statistics stats = getStatistics(emf);
-
-        EntityManager em = emf.createEntityManager();
-        EntityTransaction transaction = em.getTransaction();
-        transaction.begin();
-        final Item i1 = em.find(Item.class, 1L);
-        final String expectedDesc = "Infinispan T-shirt";
-        if (!i1.getDescription().equals(expectedDesc))
-            throw new RuntimeException("Incorrect description: " + i1.getDescription() + ", expected: " + expectedDesc);
-
-        transaction.commit();
-        em.close();
-
-        assertRegionStats(new Counts(1, 0, 1, 3), Item.class.getName(), stats);
     }
 
     private static void addItemBeyondMaxSize(EntityManagerFactory emf) {
@@ -423,7 +408,7 @@ private static void addItemBeyondMaxSize(EntityManagerFactory emf) {
         transaction.commit();
         em.close();
 
-        assertRegionStats(new Counts(1, 0, 0, 3), Item.class.getName(), stats);
+        assertRegionStatsEventually(new Counts(1, 0, 0, 3), Item.class.getName(), stats);
     }
 
     private static void testQuery(EntityManagerFactory entityManagerFactory) {
@@ -746,13 +731,53 @@ private static void assertRegionStats(Counts expected, String region, Statistics
     }
 
     private static void assertCountEquals(Counts expected, Counts actual, String msg) {
-        //FIXME this is currently failing often on CI, needs to be investigated.
-        //Seems to fail more often in native mode.
-        // - https://github.com/jbossas/protean-shamrock/issues/694
-        /*if (!expected.equals(actual))
+        if (!expected.equals(actual))
             throw new RuntimeException(
                     "[" + msg + "] expected " + expected + " second level cache count, instead got: " + actual
-            );*/
+        );
+    }
+
+    private static void assertRegionStatsEventually(Counts expected, String region, Statistics stats) {
+        eventually(() -> {
+            final CacheRegionStatistics cacheStats = stats.getDomainDataRegionStatistics(region);
+            final Counts actual = new Counts(
+                    cacheStats.getPutCount()
+                    , cacheStats.getHitCount()
+                    , cacheStats.getMissCount()
+                    , cacheStats.getElementCountInMemory()
+            );
+            if (!expected.equals(actual)) {
+                return new RuntimeException(
+                        "[" + region + "] expected " + expected + " second level cache count, instead got: " + actual
+                );
+            }
+
+            return null;
+        });
+    }
+
+    static void eventually(Supplier<RuntimeException> condition) {
+        eventually(Duration.ofSeconds(10).toMillis(), Duration.ofMillis(500).toMillis(), TimeUnit.MILLISECONDS, condition);
+    }
+
+    static void eventually(long timeout, long pollInterval, TimeUnit unit, Supplier<RuntimeException> condition) {
+        if (pollInterval <= 0) {
+            throw new IllegalArgumentException("Check interval must be positive");
+        }
+        try {
+            long expectedEndTime = System.nanoTime() + TimeUnit.NANOSECONDS.convert(timeout, unit);
+            long sleepMillis = TimeUnit.MILLISECONDS.convert(pollInterval, unit);
+            while (expectedEndTime - System.nanoTime() > 0) {
+                if (condition.get() == null) return;
+                Thread.sleep(sleepMillis);
+            }
+
+            final RuntimeException exception = condition.get();
+            if (exception != null)
+                throw exception;
+        } catch (Exception e) {
+            throw new RuntimeException("Unexpected!", e);
+        }
     }
 
     static final class Counts {