Reportportal: [v5]: org.postgresql.util.PSQLException: ERROR: failed to add item to index page in "path_gist_idx"

[v1-wizard]

Describe the bug

We have broken DB and get 500 errors on API calls.
Report portal java client log:

[2020-09-17T19:53:33.809Z] 19:53:33.500 [rp-io-10] ERROR - Logging context completed with error 
[2020-09-17T19:53:33.809Z] com.epam.reportportal.exception.ReportPortalException: Report Portal returned error
[2020-09-17T19:53:33.809Z] Status code: 500
[2020-09-17T19:53:33.809Z] Status message: Internal Server Error
[2020-09-17T19:53:33.809Z] Error Message: Unclassified error [could not execute statement; nested exception is org.hibernate.exception.GenericJDBCException: could not execute statement]
[2020-09-17T19:53:33.809Z] Error Type: UNCLASSIFIED_ERROR
[2020-09-17T19:53:33.809Z] 
[2020-09-17T19:53:33.809Z]  at com.epam.reportportal.service.ReportPortalErrorHandler.handleError(ReportPortalErrorHandler.java:85)
[2020-09-17T19:53:33.809Z]  at com.epam.reportportal.service.ReportPortalErrorHandler.handle(ReportPortalErrorHandler.java:61)
[2020-09-17T19:53:33.809Z]  at com.epam.reportportal.restendpoint.http.HttpClientRestEndpoint$1.subscribe(HttpClientRestEndpoint.java:526)
[2020-09-17T19:53:33.809Z]  at io.reactivex.internal.operators.maybe.MaybeCreate.subscribeActual(MaybeCreate.java:45)
[2020-09-17T19:53:33.809Z]  at io.reactivex.Maybe.subscribe(Maybe.java:4290)
[2020-09-17T19:53:33.809Z]  at io.reactivex.internal.operators.maybe.MaybeSubscribeOn$SubscribeTask.run(MaybeSubscribeOn.java:54)
[2020-09-17T19:53:33.809Z]  at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
[2020-09-17T19:53:33.809Z]  at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
[2020-09-17T19:53:33.809Z]  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[2020-09-17T19:53:33.809Z]  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[2020-09-17T19:53:33.809Z]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[2020-09-17T19:53:33.809Z]  at java.lang.Thread.run(Thread.java:748)

Report portal service-api logs:

Caused by: org.hibernate.exception.GenericJDBCException: could not execute statement
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:200)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3430)
    at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3292)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3704)
    at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:201)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604)
    at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)
    at java.base/java.util.LinkedHashMap.forEach(Unknown Source)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)
    at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:348)
    at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:102)
    at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1352)
    at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:443)
    at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3202)
    at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2370)
    at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:447)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)
    at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
    at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:534)
    ... 110 common frames omitted
Caused by: org.postgresql.util.PSQLException: ERROR: failed to add item to index page in "path_gist_idx"
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2578)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2313)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:331)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:159)
    at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:125)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197)
    ... 131 common frames omitted

Caused by: org.postgresql.util.PSQLException: ERROR: failed to add item to index page in "path_gist_idx"
  Where: SQL statement "UPDATE test_item
                SET retry_of    = new_item_id,
                    launch_id   = NULL,
                    has_retries = FALSE,
                    path        = (path_value || '.' || item_id) :: LTREE
                WHERE test_item.item_id = cur_id"
PL/pgSQL function handle_retries(bigint) line 66 at SQL statement
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2578)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2313)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:331)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:159)
    at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:109)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
    ... 154 common frames omitted



md5-60eb110a57fbad57b1ef2d09d3b0c057



2020-09-17 13:53:06.175 ERROR 6 --- [-8585-exec-4646] o.h.engine.jdbc.spi.SqlExceptionHelper   : ERROR: failed to add item to index page in "path_gist_idx"
  Where: SQL statement "UPDATE test_item
        SET retry_of    = NULL,
            has_retries = TRUE,
            launch_id   = new_item_launch_id
        WHERE item_id = new_item_id"
PL/pgSQL function handle_retries(bigint) line 47 at SQL statement



md5-5e25bed581e20b6e1c1266a5d539021e



        <dependency>
            <groupId>com.epam.reportportal</groupId>
            <artifactId>agent-java-testng</artifactId>
            <version>5.0.7</version>
        </dependency>
        <dependency>
            <groupId>com.epam.reportportal</groupId>
            <artifactId>logger-java-logback</artifactId>
            <version>5.0.3</version>
        </dependency>

[v1-wizard]

Hello, any updates? Workarounds? Could i try to restore index manually?

[Yumfriez]

@v1-wizard Probably it will help, try to drop 2 indexes from path - path_gist_idx, path_idx

Then recreate only GIST index:

CREATE INDEX path_gist_idx
ON test_item
USING gist (path);

[v1-wizard]

@Yumfriez I will try, thanks.

[v1-wizard]

Hi @Yumfriez . This is not help us. Seems like a bug in Postgres.

reportportal=# DROP INDEX path_idx;
ERROR:  index "path_idx" does not exist
reportportal=# DROP INDEX path_gist_idx;
ERROR:  index "path_gist_idx" does not exist
reportportal=# CREATE INDEX path_gist_idx ON test_item USING gist(path);
PANIC:  invalid index offnum: 37
server closed the connection unexpectedly
    This probably means the server terminated abnormally
    before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.

So I delete all our data after corruption and recreate index. Keep watching to find a root of problem.