Uploaded image for project: 'Hibernate Search'
  1. HSEARCH-2636

Be more resilient to the absence of id in the _source

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.6.1.Final
    • Component/s: None
    • Labels:
      None

      Description

      I have upgraded the application from 5.6.0.Beta3 to 5.6.1.Final without reindexing. The index structure was generated by 5.6.0.Beta3 but read by 5.6.1.Final.

      I received the following exception

      java.lang.NullPointerException
      	at org.hibernate.search.query.hibernate.impl.EntityInfoLoadKey.hashCode(EntityInfoLoadKey.java:47)
      	at java.util.HashMap.hash(HashMap.java:338)
      	at java.util.HashMap.put(HashMap.java:611)
      	at org.hibernate.search.query.hibernate.impl.QueryLoader.executeLoad(QueryLoader.java:82)
      	at org.hibernate.search.query.hibernate.impl.AbstractLoader.load(AbstractLoader.java:58)
      	at org.hibernate.search.query.hibernate.impl.FullTextQueryImpl.list(FullTextQueryImpl.java:199)
      	at org.hibernate.search.jpa.impl.FullTextQueryImpl.getResultList(FullTextQueryImpl.java:157)
      	at org.hibernate.demos.HibernateSearchWithDbIT.lambda$queryOnSingleField$1(HibernateSearchWithDbIT.java:110)
      	at org.hibernate.demos.HibernateSearchWithDbIT$$Lambda$16/1653153736.accept(Unknown Source)
      	at org.hibernate.demos.TestBase.inTransaction(TestBase.java:21)
      	at org.hibernate.demos.HibernateSearchWithDbIT.queryOnSingleField(HibernateSearchWithDbIT.java:103)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:497)
      	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
      	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
      	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
      	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
      	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
      	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
      	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
      	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
      	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
      	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
      	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
      	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
      	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:117)
      	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:42)
      	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:262)
      	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:84)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:497)
      	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
      
      [2017-03-13 14:47:55,445][INFO ][org.hibernate.jpa.internal.util.LogHelper] HHH000204: Processing PersistenceUnitInfo [
      	name: videoGamePu
      	...]
      [2017-03-13 14:47:55,536][INFO ][org.hibernate.Version    ] HHH000412: Hibernate Core {5.1.3.Final}
      [2017-03-13 14:47:55,537][INFO ][org.hibernate.cfg.Environment] HHH000206: hibernate.properties not found
      [2017-03-13 14:47:55,538][INFO ][org.hibernate.cfg.Environment] HHH000021: Bytecode provider name : javassist
      [2017-03-13 14:47:55,577][INFO ][org.hibernate.annotations.common.Version] HCANN000001: Hibernate Commons Annotations {5.0.1.Final}
      [2017-03-13 14:47:55,768][WARN ][org.hibernate.orm.connections.pooling] HHH10001002: Using Hibernate built-in connection pool (not for production use!)
      [2017-03-13 14:47:55,769][INFO ][org.hibernate.orm.connections.pooling] HHH10001005: using driver [null] at URL [jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1]
      [2017-03-13 14:47:55,769][INFO ][org.hibernate.orm.connections.pooling] HHH10001001: Connection properties: {user=sa}
      [2017-03-13 14:47:55,769][INFO ][org.hibernate.orm.connections.pooling] HHH10001003: Autocommit mode: false
      [2017-03-13 14:47:55,772][INFO ][org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl] HHH000115: Hibernate connection pool size: 20 (min=1)
      [2017-03-13 14:47:55,936][INFO ][org.hibernate.dialect.Dialect] HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
      [2017-03-13 14:47:56,307][INFO ][org.hibernate.search.engine.Version] HSEARCH000034: Hibernate Search 5.6.0.Final
      [2017-03-13 14:47:56,443][INFO ][org.hibernate.orm.connections.access] HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@71984c3] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
      [2017-03-13 14:47:56,446][INFO ][org.hibernate.orm.connections.access] HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@1bc715b8] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
      [2017-03-13 14:47:56,464][INFO ][org.hibernate.tool.schema.internal.SchemaCreatorImpl] HHH000476: Executing import script 'org.hibernate.tool.schema.internal.exec.ScriptSourceInputNonExistentImpl@2c104774'
      [2017-03-13 14:47:56,765][INFO ][io.searchbox.client.AbstractJestClient] Setting server pool to a list of 1 servers: [http://127.0.0.1:9200]
      [2017-03-13 14:47:56,766][INFO ][io.searchbox.client.JestClientFactory] Using multi thread/connection supporting pooling connection manager
      [2017-03-13 14:47:56,837][INFO ][io.searchbox.client.JestClientFactory] Using custom GSON instance
      [2017-03-13 14:47:56,838][INFO ][io.searchbox.client.JestClientFactory] Node Discovery disabled...
      [2017-03-13 14:47:56,838][INFO ][io.searchbox.client.JestClientFactory] Idle connection reaping disabled...
      [2017-03-13 14:47:57,191][ERROR][org.hibernate.search.exception.impl.LogErrorHandler] HSEARCH000058: Exception occurred org.hibernate.search.elasticsearch.client.impl.BulkRequestFailedException: HSEARCH400008: Elasticsearch request failed.
       Request:
      ========
      Operation: Bulk
      URI:/_bulk?refresh=true
      Data:
      {"index":{"_id":"4","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"4","title":"Revenge of the Samurai","description":"The Samurai is mad and takes revenge","rating":8,"tags":["action","real-time","anime"],"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Luigi"},{"nickName":"Dash"}]}
      {"index":{"_id":"5","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"5","title":"Tanaka\u0027s return","description":"The famous Samurai Tanaka returns","rating":10,"tags":["action","round-based"],"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Frank"},{"nickName":"Dash"},{"nickName":"Luigi"}]}
      {"index":{"_id":"6","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"6","title":"Ninja Castle","description":"7 Ninjas live in a castle","rating":5,"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Frank"}]}
      
      Response:
      =========
      Status: 200
      Error message: One or more of the items in the Bulk request failed, check BulkResult.getItems() for more information.
      Cluster name: null
      Cluster status: null
      
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 4
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 5
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 6
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      
      Subsequent failures:
      	Entity org.hibernate.demos.hswithes.model.VideoGame  Id 4  Work Type  org.hibernate.search.backend.AddLuceneWork
      	Entity org.hibernate.demos.hswithes.model.VideoGame  Id 5  Work Type  org.hibernate.search.backend.AddLuceneWork
      	Entity org.hibernate.demos.hswithes.model.VideoGame  Id 6  Work Type  org.hibernate.search.backend.AddLuceneWork
      
      org.hibernate.search.elasticsearch.client.impl.BulkRequestFailedException: HSEARCH400008: Elasticsearch request failed.
       Request:
      ========
      Operation: Bulk
      URI:/_bulk?refresh=true
      Data:
      {"index":{"_id":"4","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"4","title":"Revenge of the Samurai","description":"The Samurai is mad and takes revenge","rating":8,"tags":["action","real-time","anime"],"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Luigi"},{"nickName":"Dash"}]}
      {"index":{"_id":"5","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"5","title":"Tanaka\u0027s return","description":"The famous Samurai Tanaka returns","rating":10,"tags":["action","round-based"],"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Frank"},{"nickName":"Dash"},{"nickName":"Luigi"}]}
      {"index":{"_id":"6","_index":"org.hibernate.demos.hswithes.model.videogame","_type":"org.hibernate.demos.hswithes.model.VideoGame"}}
      {"id":"6","title":"Ninja Castle","description":"7 Ninjas live in a castle","rating":5,"publisher":{"name":"Samurai Games, Inc."},"characters":[{"nickName":"Frank"}]}
      
      Response:
      =========
      Status: 200
      Error message: One or more of the items in the Bulk request failed, check BulkResult.getItems() for more information.
      Cluster name: null
      Cluster status: null
      
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 4
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 5
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      Operation: index
        Index: org.hibernate.demos.hswithes.model.videogame
        Type: org.hibernate.demos.hswithes.model.VideoGame
        Id: 6
        Status: 400
        Error: {"type":"strict_dynamic_mapping_exception","reason":"mapping set to strict, dynamic introduction of [id] within [org.hibernate.demos.hswithes.model.VideoGame] is not allowed"}
      
      	at org.hibernate.search.elasticsearch.client.impl.JestClient.executeBulkRequest(JestClient.java:225)
      	at org.hibernate.search.elasticsearch.client.impl.BulkRequest.execute(BulkRequest.java:61)
      	at org.hibernate.search.elasticsearch.client.impl.BackendRequestProcessor.doExecute(BackendRequestProcessor.java:106)
      	at org.hibernate.search.elasticsearch.client.impl.BackendRequestProcessor.executeSync(BackendRequestProcessor.java:76)
      	at org.hibernate.search.elasticsearch.impl.ElasticsearchIndexManager.performOperations(ElasticsearchIndexManager.java:424)
      	at org.hibernate.search.backend.impl.LocalBackendQueueProcessor.applyWork(LocalBackendQueueProcessor.java:38)
      	at org.hibernate.search.backend.impl.WorkQueuePerIndexSplitter.commitOperations(WorkQueuePerIndexSplitter.java:46)
      	at org.hibernate.search.backend.impl.BatchedQueueingProcessor.performWorks(BatchedQueueingProcessor.java:83)
      	at org.hibernate.search.backend.impl.PostTransactionWorkQueueSynchronization.afterCompletion(PostTransactionWorkQueueSynchronization.java:76)
      	at org.hibernate.search.backend.impl.EventSourceTransactionContext$DelegateToSynchronizationOnAfterTx.doAfterTransactionCompletion(EventSourceTransactionContext.java:187)
      	at org.hibernate.engine.spi.ActionQueue$AfterTransactionCompletionProcessQueue.afterTransactionCompletion(ActionQueue.java:957)
      	at org.hibernate.engine.spi.ActionQueue.afterTransactionCompletion(ActionQueue.java:491)
      	at org.hibernate.internal.SessionImpl.afterTransactionCompletion(SessionImpl.java:2369)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterTransactionCompletion(JdbcCoordinatorImpl.java:497)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.afterCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:167)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$200(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:233)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:65)
      	at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:61)
      	at org.hibernate.demos.TestBase.inTransaction(TestBase.java:22)
      	at org.hibernate.demos.HibernateSearchWithDbIT.setUpTestData(HibernateSearchWithDbIT.java:43)
      	at org.hibernate.demos.HibernateSearchWithDbIT.setUpEmf(HibernateSearchWithDbIT.java:37)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:497)
      	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
      	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
      	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
      	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
      	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
      	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:117)
      	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:42)
      	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:262)
      	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:84)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:497)
      	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
      
      Process finished with exit code 255
      

      The root cause is that the _source includes the id in 5.6.0.Final and uses it to retrieve the entity id whereas the 5.6.0.Beta3 did not include it and was expecting the id from the index structure proper.

      I wonder a few things:

      • should we have thrown the inner exception of the bulk operations instead of swallowing (strict mapping error).
      • should we catch any EntityInfo with a null id early on during query and raise a more meaningful exception? That one is a rhetorical question, of course we should.
      • should we be more lenient toward older mappings and fallback to reading id the old fashion way?

        Attachments

          Activity

            People

            • Assignee:
              yrodiere Yoann Rodière
              Reporter:
              emmanuel Emmanuel Bernard
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: