When using Infinispan 5.3.0 (also with 6.0.0) we encountered an issue where entities are no longer found when doing an index search, after being updated.

On every update, infinispan removes the old entity, and updates the new entity, in the same transaction.
For some reason, the updates don't always happen.

We isolated the issue to WeakIdentityHashMap in TransactionalWorker.

Doing concurrent puts/gets causes get operations on the map to sometimes return null, even when there's a value.
I assume this is because the map is not concurrent or synchronized, and gets corrupted.

The following test reproduces the problem:
Each threads does a put/get/remove using the thread name as key, and the get fails frequently.
Protecting the map methods with synchronized solves the problem (see below)

import org.hibernate.search.util.impl.WeakIdentityHashMap;
import org.junit.Assert;
import org.junit.Test;

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;

public class TestMap {
protected final WeakIdentityHashMap<String, String> weakIdentityHashMap = new WeakIdentityHashMap<String, String>();

@Test
public void executeTest() throws Exception {
ExecutorService executorService = Executors.newFixedThreadPool(20);
TestWeakIdentityHashMap test = new TestWeakIdentityHashMap();
for (int i = 0; i < 20; i++) {
executorService.execute(test);
}
executorService.shutdown();
executorService.awaitTermination(10, TimeUnit.MINUTES);
}

public class TestWeakIdentityHashMap implements Runnable {

public void run() {
String name = Thread.currentThread().getName();
while(true) {
weakIdentityHashMap.put(name, name);
Assert.assertEquals(name, weakIdentityHashMap.get(name));
weakIdentityHashMap.removeValue(name);
}
}
}
}

Protected map:

protected final WeakIdentityHashMap<String, String> weakIdentityHashMap = new WeakIdentityHashMap<String, String>() {

private final Object lock = new Object();

@Override
public boolean removeValue(Object value) {
synchronized (lock) {
return super.removeValue(value);
}
}

@Override
public String get(Object key) {
synchronized (lock) {
return super.get(key);
}
}

@Override
public String put(String key, String value) {
synchronized (lock) {
return super.put(key, value);
}
}
};

Hello,
thanks for the example code I'll look into it asap.

To put this into context: you mean this problem happens when using "Infinispan Query", so to search for objects being stored in Infinispan, right?

I'm asking as we usually have only Hibernate Search questions here, the one when the query engine is used in combination with Hibernate ORM / JPA.

Hello,

I meet the same problem using only Hibernate Search. On high concurrency hibernate insert actions, sgbd work is OK but some lucene works are lost. I isolate the issue to WeakIdentityHashMap use in FullTextIndexEventListener before finding this post.

Here is the log stack per threads (builded with some aspect on HS classes) :

- thread "taskExecutor-6" behaviour is correct, on flush FullTextIndexEventListener find PostTransactionWorkQueueSynchronization mapped to current session and ask for it's completion
- thread "taskExecutor-3" behaviour is not correct, PostTransactionWorkQueueSynchronization is not finded for current transaction... lucene work is lost


15:05:18,621 (taskExecutor-6) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.AdresseNaissance-8870004
15:05:18,636 (taskExecutor-6) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.Individu-8897003
15:05:18,709 (taskExecutor-6) FullTextIndexEventListener.addSynchronization
15:05:18,711 (taskExecutor-6) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.Individu-8897003-ADD
15:05:18,792 (taskExecutor-6) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.NumeroInscriptionRepertoire-6276003
15:05:18,798 (taskExecutor-6) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.NumeroInscriptionRepertoire-6276003-ADD
15:05:18,814 (taskExecutor-6) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.Individu-8897003-COLLECTION
15:05:18,818 (taskExecutor-6) FullTextIndexEventListener.onFlush
15:05:18,824 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (taskExecutor-6) Processing Transaction's beforeCompletion() phase: org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@1039e58
15:05:18,911 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (taskExecutor-6) Processing Transaction's afterCompletion() phase for org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@1039e58. Performing work.
15:05:18,911 TRACE [org.hibernate.search.backend.impl.BatchedQueueingProcessor] (taskExecutor-6) Lucene WorkQueue to send to backends:[
AddLuceneWork: fr.dsirc.poc.poc_hs_rni.model.Individu#8897003
]

15:05:18,579 (taskExecutor-3) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.AdresseNaissance-8870005
15:05:18,612 (taskExecutor-3) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.Individu-8897004
15:05:18,708 (taskExecutor-3) FullTextIndexEventListener.addSynchronization ===> synchronisation is added
15:05:18,711 (taskExecutor-3) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.Individu-8897004-ADD
15:05:18,813 (taskExecutor-3) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.NumeroInscriptionRepertoire-6276002
15:05:18,815 (taskExecutor-3) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.NumeroInscriptionRepertoire-6276002-ADD
15:05:18,829 (taskExecutor-3) PostTransactionWorkQueueSynchronization.add class fr.dsirc.poc.poc_hs_rni.model.Individu-8897004-COLLECTION
15:05:18,830 (taskExecutor-3) FullTextIndexEventListener.onFlush
===> synchronisation not found for session. Now thread deal with another entity in an other session
15:05:18,882 (taskExecutor-3) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.AdresseNaissance-8870006
15:05:18,887 (taskExecutor-3) FullTextIndexEventListener.onPostInsert class fr.dsirc.poc.poc_hs_rni.model.Individu-8897006




Is there a ticket oppened for this bug ? A workaround ?

Hello,
I tried to verify this at the first report but I couldn't reproduce it, not even using a mocked storage to remove any possible slow-down.
I don't think there is an open issue for this, please open one on JIRA: https://hibernate.atlassian.net/browse/HSEARCH

Would you be able to contribute a test or some kind of standalone reproducer?

Hello,

Issue opened with test case - see https://hibernate.atlassian.net/browse/HSEARCH-1623.

thanks, I'm working on it.