Be more resilient to the absence of id in the _source

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

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 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?

Environment

None

Status

Assignee

Yoann Rodière

Reporter

Emmanuel Bernard

Labels

None

Suitable for new contributors

None

Feedback Requested

None

Fix versions

Affects versions

5.6.1.Final

Priority

Major