crdb_internal.force_retry example is out of date

[MariuszCwikla]

I was trying test transaction retry as per https://www.cockroachlabs.com/docs/v22.2/build-a-java-app-with-cockroachdb-hibernate?filters=local but it looks like the example is not working any more.

I am changing the flag private static final boolean FORCE_RETRY = true; and running ./gradlew run:

Exception in thread "main" javax.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: could not execute statement
        at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:277)
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:98)
        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
        at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1621)
        at com.cockroachlabs.Sample.lambda$forceRetryLogic$2(Sample.java:106)
        at com.cockroachlabs.Sample.runTransaction(Sample.java:161)
        at com.cockroachlabs.Sample.main(Sample.java:209)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
        at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:120)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)        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.engine.query.spi.NativeSQLQueryPlan.performExecuteUpdate(NativeSQLQueryPlan.java:107)
        at org.hibernate.internal.SessionImpl.executeNativeUpdate(SessionImpl.java:1509)
        at org.hibernate.query.internal.NativeQueryImpl.doExecuteUpdate(NativeQueryImpl.java:295)
        at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1612)
        ... 3 more
Caused by: org.postgresql.util.PSQLException: ERROR: restart transaction: crdb_internal.force_retry(): TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
  Hint: See: https://www.cockroachlabs.com/docs/v20.2/transaction-retry-error-reference.html
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
        at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197)

Looks like changing

catch (JDBCException e) {

in runTransaction to:

            } catch (PersistenceException pe) {
            	JDBCException e;
            	if (pe instanceof JDBCException) {
            		e = (JDBCException) pe;
            	} else if (pe.getCause() instanceof JDBCException) {
            		e = (JDBCException) pe.getCause();
            	} else { 
            		throw pe;
            	}

and in JDBCException to PersistenceException in another method seem to fix the problem.

[rmloveland]

Hi @MariuszCwikla thanks for filing this issue. I've also filed an issue in our internal Jira to make sure this gets prioritized and looked at by the Docs team

I was able to reproduce as follows (with FORCE_RETRY = true):

JAVA_HOME=/Library/Java/JavaVirtualMachines/temurin-8.jdk/Contents/Home ./gradlew run 
> Task :compileJava
> Task :processResources UP-TO-DATE
> Task :classes

> Task :run
Feb 01, 2023 11:30:23 AM org.hibernate.Version logVersion
INFO: HHH000412: Hibernate ORM core version 5.4.23.Final
Feb 01, 2023 11:30:24 AM org.hibernate.annotations.common.reflection.java.JavaReflectionManager <clinit>
INFO: HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
Feb 01, 2023 11:30:24 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl configure
WARN: HHH10001002: Using Hibernate built-in connection pool (not for production use!)
Feb 01, 2023 11:30:24 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH10001005: using driver [org.postgresql.Driver] at URL [jdbc:postgresql://localhost:26257/defaultdb?sslmode=disable]
Feb 01, 2023 11:30:24 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH10001001: Connection properties: {ApplicationName=docs_simplecrud_hibernate, user=root, password=****}
Feb 01, 2023 11:30:24 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl buildCreator
INFO: HHH10001003: Autocommit mode: false
Feb 01, 2023 11:30:24 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PooledConnections <init>
INFO: HHH000115: Hibernate connection pool size: 20 (min=1)
Feb 01, 2023 11:30:24 AM org.hibernate.dialect.Dialect <init>
INFO: HHH000400: Using dialect: org.hibernate.dialect.CockroachDB201Dialect
Hibernate: 
    
    drop table if exists accounts cascade
Feb 01, 2023 11:30:25 AM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection
INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@3a71c100] 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.
Hibernate: 
    
    create table accounts (
       id int8 not null,
        balance numeric(19, 2),
        primary key (id)
    )
Feb 01, 2023 11:30:25 AM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection
INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@49ef32e0] 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.
Feb 01, 2023 11:30:25 AM org.hibernate.engine.transaction.jta.platform.internal.JtaPlatformInitiator initiateService
INFO: HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
APP: About to test retry logic in 'runTransaction'
APP: BEGIN;
Hibernate: 
    SELECT
        now()
APP: testRetryLogic: BEFORE EXCEPTION
Hibernate: 
    SELECT
        crdb_internal.force_retry('1s')
Feb 01, 2023 11:30:25 AM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 0, SQLState: 40001
Feb 01, 2023 11:30:25 AM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
ERROR: ERROR: restart transaction: crdb_internal.force_retry(): TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
  Hint: See: https://www.cockroachlabs.com/docs/v22.2/transaction-retry-error-reference.html
Feb 01, 2023 11:30:25 AM org.hibernate.tool.schema.internal.SchemaDropperImpl$DelayedDropActionImpl perform
INFO: HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down'
Hibernate: 
    
    drop table if exists accounts cascade
Feb 01, 2023 11:30:25 AM org.hibernate.resource.transaction.backend.jdbc.internal.DdlTransactionIsolatorNonJtaImpl getIsolatedConnection
INFO: HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@42cc13a0] 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.
Feb 01, 2023 11:30:25 AM org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl$PoolState stop
INFO: HHH10001008: Cleaning up connection pool [jdbc:postgresql://localhost:26257/defaultdb?sslmode=disable]
Exception in thread "main" javax.persistence.OptimisticLockException: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:277)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:98)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
	at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1621)
	at com.cockroachlabs.Sample.lambda$forceRetryLogic$2(Sample.java:106)
	at com.cockroachlabs.Sample.runTransaction(Sample.java:161)
	at com.cockroachlabs.Sample.main(Sample.java:209)
Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement
	at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:120)
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
	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.engine.query.spi.NativeSQLQueryPlan.performExecuteUpdate(NativeSQLQueryPlan.java:107)
	at org.hibernate.internal.SessionImpl.executeNativeUpdate(SessionImpl.java:1509)
	at org.hibernate.query.internal.NativeQueryImpl.doExecuteUpdate(NativeQueryImpl.java:295)
	at org.hibernate.query.internal.AbstractProducedQuery.executeUpdate(AbstractProducedQuery.java:1612)
	... 3 more
Caused by: org.postgresql.util.PSQLException: ERROR: restart transaction: crdb_internal.force_retry(): TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry()
  Hint: See: https://www.cockroachlabs.com/docs/v22.2/transaction-retry-error-reference.html
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2553)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2285)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:130)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197)
	... 7 more

> Task :run FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':run'.
> Process 'command '/Library/Java/JavaVirtualMachines/temurin-8.jdk/Contents/Home/bin/java'' finished with non-zero exit value 1

* Try:
Run with --stacktrace option to get the stack trace. Run with --info or --debug option to get more log output. Run with --scan to get full insights.

* Get more help at https://help.gradle.org

BUILD FAILED in 3s
3 actionable tasks: 2 executed, 1 up-to-date