Index triggered many times for each change in the entity

Hibernate Search
1

I am running Elasticsearch 5.6 with hibernate search 5.10.3 Final, and what I’ve noticed that each update to an indexed entity causes 3 index updates… is it somehow configuration related, wrong mapping or is just a bug?
here are the logs which I can see after I activate the debug with org.hibernate.search.elasticsearch.request org.hibernate.search.fulltext_query.

10:54:29,780 DEBUG [com.company.MyEntity.data.impl.interceptor.MyEntityChangeInterceptor] (default task-1) MyEntityChangeInterceptor: try to find the differences, 'MyEntity' 
10:54:29,951 INFO  [com.company.MyEntity.data.impl.interceptor.MyEntityChangeInterceptor] (default task-1) MyEntityChangeInterceptor: entity class: MyEntity , changes found, '{owner=owner is changed from - to UserName: saif(xx)}' 
10:54:30,114 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Processing Transaction's beforeCompletion() phase: org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985
10:54:30,114 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Processing Transaction's beforeCompletion() phase: org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985
10:54:30,119 TRACE [org.hibernate.search.spi.impl.TypeHierarchy] (default task-1) Targeted indexed classes for [com.company.MyEntity.data.entities.MyEntity]: [com.company.MyEntity.data.entities.MyEntity]
10:54:30,119 TRACE [org.hibernate.search.spi.impl.TypeHierarchy] (default task-1) Targeted indexed classes for [com.company.MyEntity.data.entities.MyEntity]: [com.company.MyEntity.data.entities.MyEntity]
10:54:30,131 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Transaction's beforeCompletion() phase already been processed, ignoring: org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985
10:54:30,131 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Transaction's beforeCompletion() phase already been processed, ignoring: org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985
10:54:30,196 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Processing Transaction's afterCompletion() phase for org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985. Performing work.
10:54:30,196 TRACE [org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization] (default task-1) Processing Transaction's afterCompletion() phase for org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization@65616985. Performing work.
10:54:30,198 TRACE [org.hibernate.search.backend.impl.BatchedQueueingProcessor] (default task-1) Lucene WorkQueue to send to backends:[ 
	UpdateLuceneWork: com.company.MyEntity.data.entities.MyEntity#000000
]
10:54:30,198 TRACE [org.hibernate.search.backend.impl.BatchedQueueingProcessor] (default task-1) Lucene WorkQueue to send to backends:[ 
	UpdateLuceneWork: com.company.MyEntity.data.entities.MyEntity#000000
]
10:54:30,231 TRACE [org.hibernate.search.elasticsearch.processor.impl.ElasticsearchWorkProcessor] (Hibernate Search: Elasticsearch non-stream work orchestrator for index MyEntity-index-v2.15) Processing IndexWork[path = /MyEntity-index-v2.15/com.company.MyEntity.data.entities.MyEntity/000000, dirtiedIndexName = MyEntity-index-v2.15]
10:54:30,231 TRACE [org.hibernate.search.elasticsearch.processor.impl.ElasticsearchWorkProcessor] (Hibernate Search: Elasticsearch non-stream work orchestrator for index MyEntity-index-v2.15) Processing IndexWork[path = /MyEntity-index-v2.15/com.company.MyEntity.data.entities.MyEntity/000000, dirtiedIndexName = MyEntity-index-v2.15]
10:54:30,302 DEBUG [com.company.MyEntity.data.impl.repositories.MyEntityRepoBean] (default task-1) getting MyEntity by id=000000
10:54:30,400 TRACE [org.hibernate.search.elasticsearch.request] (Hibernate Search: Elasticsearch transport thread-3) HSEARCH400093: Executed Elasticsearch HTTP PUT request to path '/MyEntity-index-v2.15/com.company.MyEntity.data.entities.MyEntity/000000' with query parameters {} in 157ms. Response had status 200 'OK'. Request body:
10:54:30,400 TRACE [org.hibernate.search.elasticsearch.request] (Hibernate Search: Elasticsearch transport thread-3) HSEARCH400093: Executed Elasticsearch HTTP PUT request to path '/MyEntity-index-v2.15/com.company.MyEntity.data.entities.MyEntity/000000' with query parameters {} in 157ms. Response had status 200 'OK'. Request body: <
10:54:30,400 TRACE [org.hibernate.search.elasticsearch.request] (Hibernate Search: Elasticsearch transport thread-3) HSEARCH400093: Executed Elasticsearch HTTP PUT request to path '/MyEntity-index-v2.15/com.company.MyEntity.data.entities.MyEntity/000000' with query parameters {} in 157ms. Response had status 200 'OK'. Request body: <
2

There is dedicated code in Hibernate Search to avoid that: even when you change an entity multiple times in the same transaction, Hibernate Search will only execute one update.

The fact that the same operation happens three times at the exact same instant, and took exactly the same to execute, is extremely suspicious. It looks your logs are being duplicated. Could you check it’s not a problem with your logging setup? With log4j, it’s possible that you configured two (or more) appenders targeting the same file.

The easiest way to rule out a logging issue would be to put a breakpoint in PostTransactionWorkQueueSynchronization#afterCompletion. It you hit the breakpoint twice for a single transaction, there’s indeed a problem in Hibernate Search.

If there is a problem in Hibernate Search, there could be different causes:

  • Two (or more) versions of Hibernate Search in your classpath. This would be strange, but theoretically it could happen with WildFly, or any non-flat classpath scheme (I heard that you could get something like that in Tomcat, too). But this shouldn’t happen in a correct setup. Check that you didn’t deploy Hibernate Search twice by mistake?
  • A bug in Hibernate Search? That would have to be an edge case. Maybe try disabling your entity change interceptor, and see if the problem still occurs?