[JIRA] (HSEARCH-4915) Errors returned by OpenSearch/ElasticSearch not handled correctly
by Andreas Lanz (JIRA)
Andreas Lanz ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) *created* an issue
Hibernate Search ( https://hibernate.atlassian.net/browse/HSEARCH?atlOrigin=eyJpIjoiYzZmYjUz... ) / Bug ( https://hibernate.atlassian.net/browse/HSEARCH-4915?atlOrigin=eyJpIjoiYzZ... ) HSEARCH-4915 ( https://hibernate.atlassian.net/browse/HSEARCH-4915?atlOrigin=eyJpIjoiYzZ... ) Errors returned by OpenSearch/ElasticSearch not handled correctly ( https://hibernate.atlassian.net/browse/HSEARCH-4915?atlOrigin=eyJpIjoiYzZ... )
Issue Type: Bug Affects Versions: 6.1.5.Final Assignee: Unassigned Components: backend-elasticsearch Created: 10/Aug/2023 06:41 AM Priority: Major Reporter: Andreas Lanz ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... )
Hello,
the last few days we’ve been digging into an issue where one of our queries send to OpenSearch did not return the expected results. After some digging we found out that when pasting the query into the OpenSearch dashboard we’re getting an error from OpenSearch about “too_many_nested_clauses: Query contains too many nested clauses; maxClauseCount is set to 1024”.
Turning on tracing in of requests in Hibernate Search we can see that OpenSearch is returning the same error here too. However, this error does not seem to be processed by Hibernate Search and the query returns normally just without any results. Here are some relevant parts from the Response:
org.hibernate.search.elasticsearch.request: HSEARCH400093: Executed Elasticsearch HTTP POST request to 'http://opensearch:9200' with path '/my-index1-read,my-index2-read/_search', query parameters {size = 10000, scroll = 30s, track_total_hits = true } and 1 objects in payload in 932ms.Response had status 200 'OK'.Request body: < {"query": long query....}> .Response body:
< {
"_scroll_id": "FG...\u003d\u003d",
"took": 927,
"timed_out": false,
"_shards": {
"total": 2,
"successful": 1,
"skipped": 0,
"failed": 1,
"failures": [{
"shard": 0,
"index": "my-index1-000001",
"node": "...",
"reason": {
"type": "too_many_nested_clauses",
"reason": "too_many_nested_clauses: Query contains too many nested clauses; maxClauseCount is set to 1024"
}
}
]
},
"hits": {
"total": {
"value": 0,
"relation": "eq"
},
"hits": []
}
}
>
As you can see from the log one of the shards failed executing the query because it’s too complex.
I would have expected Hibernate Search to throw an exception in such case so the system is aware that something went wrong with the query. However browsing the code I could not find any place where the _shards part of the response is actually evaluated.
( https://hibernate.atlassian.net/browse/HSEARCH-4915#add-comment?atlOrigin... ) Add Comment ( https://hibernate.atlassian.net/browse/HSEARCH-4915#add-comment?atlOrigin... )
Get Jira notifications on your phone! Download the Jira Cloud app for Android ( https://play.google.com/store/apps/details?id=com.atlassian.android.jira.... ) or iOS ( https://itunes.apple.com/app/apple-store/id1006972087?pt=696495&ct=EmailN... ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100234- sha1:6fcbbaf )
1 year, 3 months
[JIRA] (HSEARCH-4914) Fix flaky test with CockroachDB
by Yoann Rodière (JIRA)
Yoann Rodière ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) *created* an issue
Hibernate Search ( https://hibernate.atlassian.net/browse/HSEARCH?atlOrigin=eyJpIjoiNTVmMzJj... ) / Task ( https://hibernate.atlassian.net/browse/HSEARCH-4914?atlOrigin=eyJpIjoiNTV... ) HSEARCH-4914 ( https://hibernate.atlassian.net/browse/HSEARCH-4914?atlOrigin=eyJpIjoiNTV... ) Fix flaky test with CockroachDB ( https://hibernate.atlassian.net/browse/HSEARCH-4914?atlOrigin=eyJpIjoiNTV... )
Issue Type: Task Assignee: Unassigned Components: integration Created: 10/Aug/2023 06:17 AM Fix Versions: 7.0-backlog Priority: Major Reporter: Yoann Rodière ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... )
See https://ci.hibernate.org/job/hibernate-search/job/main/773/testReport/jun...
OutboxPollingAutomaticIndexingConcurrencyIT(coord-outbox-default-database-cockroachdb).noDeadlock fails from time to time on CockroachDB, and perhaps others (see build history).
12:57:58,307 (Hibernate Search - Outbox event processor - 0) WARN SqlExceptionHelper:145 - SQL Error: 0, SQLState: 40001
12:57:58,307 (Hibernate Search - Outbox event processor - 0) WARN SqlExceptionHelper:145 - SQL Error: 0, SQLState: 40001
12:57:58,308 (Hibernate Search - Outbox event processor - 0) ERROR SqlExceptionHelper:150 - ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.273288260,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.273288260,0, global=1691672278.373288260,0)`; observed timestamps: [{1 1691672278.273288260,0}]: "sql txn" meta={id=a54f448c key=/Min pri=0.01276615 epo=0 ts=1691672278.273288260,0 min=1691672278.273288260,0 seq=0} lock=false stat=PENDING rts=1691672278.273288260,0 wto=false gul=1691672278.373288260,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...
12:57:58,308 (Hibernate Search - Outbox event processor - 0) ERROR SqlExceptionHelper:150 - ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.272971291,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.272971291,0, global=1691672278.372971291,0)`; observed timestamps: [{1 1691672278.272971291,0}]: "sql txn" meta={id=63c1df7e key=/Min pri=0.04480141 epo=0 ts=1691672278.272971291,0 min=1691672278.272971291,0 seq=0} lock=false stat=PENDING rts=1691672278.272971291,0 wto=false gul=1691672278.372971291,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...
12:57:58,310 (Hibernate Search - Outbox event processor - 0) ERROR LogFailureHandler:33 - HSEARCH000058: Exception occurred jakarta.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.272971291,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.272971291,0, global=1691672278.372971291,0)`; observed timestamps: [{1 1691672278.272971291,0}]: "sql txn" meta={id=63c1df7e key=/Min pri=0.04480141 epo=0 ts=1691672278.272971291,0 min=1691672278.272971291,0 seq=0} lock=false stat=PENDING rts=1691672278.272971291,0 wto=false gul=1691672278.372971291,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
Failing operation:
Executing task 'Outbox event processor'
jakarta.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.272971291,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.272971291,0, global=1691672278.372971291,0)`; observed timestamps: [{1 1691672278.272971291,0}]: "sql txn" meta={id=63c1df7e key=/Min pri=0.04480141 epo=0 ts=1691672278.272971291,0 min=1691672278.272971291,0 seq=0} lock=false stat=PENDING rts=1691672278.272971291,0 wto=false gul=1691672278.372971291,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:252) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:99) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:438) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.DefaultOutboxEventFinder.findOutboxEvents(DefaultOutboxEventFinder.java:66) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.lambda$work$0(OutboxPollingEventProcessor.java:278) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.common.spi.TransactionHelper.inTransaction(TransactionHelper.java:55) ~[hibernate-search-mapper-orm-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.work(OutboxPollingEventProcessor.java:270) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) [hibernate-search-engine-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.272971291,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.272971291,0, global=1691672278.372971291,0)`; observed timestamps: [{1 1691672278.272971291,0}]: "sql txn" meta={id=63c1df7e key=/Min pri=0.04480141 epo=0 ts=1691672278.272971291,0 min=1691672278.272971291,0 seq=0} lock=false stat=PENDING rts=1691672278.272971291,0 wto=false gul=1691672278.372971291,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:108) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:58) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:108) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:94) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:258) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:164) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:218) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:98) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:200) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:109) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:305) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:246) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:509) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
... 11 more
Caused by: org.postgresql.util.PSQLException: ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.272971291,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.272971291,0, global=1691672278.372971291,0)`; observed timestamps: [{1 1691672278.272971291,0}]: "sql txn" meta={id=63c1df7e key=/Min pri=0.04480141 epo=0 ts=1691672278.272971291,0 min=1691672278.272971291,0 seq=0} lock=false stat=PENDING rts=1691672278.272971291,0 wto=false gul=1691672278.372971291,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2713) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2401) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:134) ~[postgresql-42.6.0.jar:42.6.0]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:240) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:164) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:218) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:98) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:200) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:109) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:305) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:246) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:509) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
... 11 more
12:57:58,310 (Hibernate Search - Outbox event processor - 0) ERROR LogFailureHandler:33 - HSEARCH000058: Exception occurred jakarta.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.273288260,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.273288260,0, global=1691672278.373288260,0)`; observed timestamps: [{1 1691672278.273288260,0}]: "sql txn" meta={id=a54f448c key=/Min pri=0.01276615 epo=0 ts=1691672278.273288260,0 min=1691672278.273288260,0 seq=0} lock=false stat=PENDING rts=1691672278.273288260,0 wto=false gul=1691672278.373288260,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
Failing operation:
Executing task 'Outbox event processor'
jakarta.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.273288260,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.273288260,0, global=1691672278.373288260,0)`; observed timestamps: [{1 1691672278.273288260,0}]: "sql txn" meta={id=a54f448c key=/Min pri=0.01276615 epo=0 ts=1691672278.273288260,0 min=1691672278.273288260,0 seq=0} lock=false stat=PENDING rts=1691672278.273288260,0 wto=false gul=1691672278.373288260,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:252) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:99) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:438) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.DefaultOutboxEventFinder.findOutboxEvents(DefaultOutboxEventFinder.java:66) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.lambda$work$0(OutboxPollingEventProcessor.java:278) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.common.spi.TransactionHelper.inTransaction(TransactionHelper.java:55) ~[hibernate-search-mapper-orm-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.mapper.orm.coordination.outboxpolling.event.impl.OutboxPollingEventProcessor$Worker.work(OutboxPollingEventProcessor.java:270) ~[hibernate-search-mapper-orm-coordination-outbox-polling-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at org.hibernate.search.engine.backend.orchestration.spi.SingletonTask$RunnableWrapper.run(SingletonTask.java:199) [hibernate-search-engine-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.hibernate.exception.LockAcquisitionException: JDBC exception executing SQL [select oe1_0.id,oe1_0.entityId,oe1_0.entityIdHash,oe1_0.entityName,oe1_0.payload,oe1_0.processAfter,oe1_0.retries,oe1_0.status from HSEARCH_OUTBOX_EVENT oe1_0 where (oe1_0.entityIdHash between ? and ?) and ((oe1_0.processAfter<?) and (oe1_0.status=?)) order by oe1_0.processAfter limit ?] [ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.273288260,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.273288260,0, global=1691672278.373288260,0)`; observed timestamps: [{1 1691672278.273288260,0}]: "sql txn" meta={id=a54f448c key=/Min pri=0.01276615 epo=0 ts=1691672278.273288260,0 min=1691672278.273288260,0 seq=0} lock=false stat=PENDING rts=1691672278.273288260,0 wto=false gul=1691672278.373288260,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...] [n/a]
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:108) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:58) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:108) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:94) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:258) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:164) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:218) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:98) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:200) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:109) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:305) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:246) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:509) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
... 11 more
Caused by: org.postgresql.util.PSQLException: ERROR: restart transaction: TransactionRetryWithProtoRefreshError: ReadWithinUncertaintyIntervalError: read at time 1691672278.273288260,0 encountered previous write with future timestamp 1691672278.273288260,1 (local=1691672278.272719274,0) within uncertainty interval `t <= (local=1691672278.273288260,0, global=1691672278.373288260,0)`; observed timestamps: [{1 1691672278.273288260,0}]: "sql txn" meta={id=a54f448c key=/Min pri=0.01276615 epo=0 ts=1691672278.273288260,0 min=1691672278.273288260,0 seq=0} lock=false stat=PENDING rts=1691672278.273288260,0 wto=false gul=1691672278.373288260,0
Hint: See: https://www.cockroachlabs.com/docs/v23.1/transaction-retry-error-referenc...
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2713) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2401) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190) ~[postgresql-42.6.0.jar:42.6.0]
at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:134) ~[postgresql-42.6.0.jar:42.6.0]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.executeQuery(DeferredResultSetAccess.java:240) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.DeferredResultSetAccess.getResultSet(DeferredResultSetAccess.java:164) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.advanceNext(JdbcValuesResultSetImpl.java:218) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.JdbcValuesResultSetImpl.processNext(JdbcValuesResultSetImpl.java:98) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.jdbc.internal.AbstractJdbcValues.next(AbstractJdbcValues.java:19) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.internal.RowProcessingStateStandardImpl.next(RowProcessingStateStandardImpl.java:66) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:200) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:361) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:168) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:93) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$0(ConcreteSqmSelectQueryPlan.java:109) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:305) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:246) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.sqm.internal.QuerySqmImpl.doList(QuerySqmImpl.java:509) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:427) ~[hibernate-core-6.3.0.CR1.jar:6.3.0.CR1]
... 11 more
( https://hibernate.atlassian.net/browse/HSEARCH-4914#add-comment?atlOrigin... ) Add Comment ( https://hibernate.atlassian.net/browse/HSEARCH-4914#add-comment?atlOrigin... )
Get Jira notifications on your phone! Download the Jira Cloud app for Android ( https://play.google.com/store/apps/details?id=com.atlassian.android.jira.... ) or iOS ( https://itunes.apple.com/app/apple-store/id1006972087?pt=696495&ct=EmailN... ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100234- sha1:6fcbbaf )
1 year, 3 months