search

snowdrop / narayana-spring-boot

Narayana Spring Boot autoconfiguration and starter
Apache License 2.0
46 stars 43 forks source link

Is this expected behavior for 2 XA databases? #159

Closed rinaldodev closed 1 month ago

rinaldodev commented 2 months ago

I have set up a reproducer that uses 2 PostgreSQL databases enlisted in a XA transaction. It is a modified version of narayana-spring-boot-sample-2pc. One of the databases has a UNIQUE column while the other doesn't. The reproducer is available here: https://github.com/rinaldodev/narayana-spring-boot/tree/2ds-2pc-test.

I see a behavior that I'm not sure if it's expected:

  1. PREPARE is called for db1 (non-unique), works fine (TwoPhaseOutcome.PREPARE_OK)
  2. PREPARE is called for db2 (unique), db returns constraint violation as expected (TwoPhaseOutcome.PREPARE_NOTOK)
  3. ROLLBACK PREPARED is called for db1, works fines (TwoPhaseOutcome.FINISH_OK)
  4. ROLLBACK PREPARED is called for db2, but fails because the prepared transaction doesn't exist (TwoPhaseOutcome.HEURISTIC_HAZARD)

Is step 4 expected to occur?

Steps to run the example:

  1. podman run --rm --name db1 -e POSTGRES_PASSWORD=password -p 5432:5432 docker.io/library/postgres:latest -c max_prepared_transactions=10
  2. podman run --rm --name db2 -e POSTGRES_PASSWORD=password -p 5433:5432 docker.io/library/postgres:latest -c max_prepared_transactions=10
  3. cd narayana-spring-boot-samples/narayana-spring-boot-sample-2pc
  4. mvn spring-boot:run -Ddisable.checks > out.log
  5. leave it running for a while (around 30 seconds used to be enough in my tests)

Trace logs are enabled so I suggest output to a file.

Here are some relevant parts from the log:

Executor ---> Attempting to create a user named Richard
XAResource 6fc88644: preparing transaction xid = < formatId=131077 ...
PREPARE TRANSACTION '131077_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUDE=_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUQAAAAAAAAAA'
BasicAction::doPrepare() result for action-id (0:ffff0a057e34:ac09:66ce254f:50) on record id: (0:ffff0a057e34:ac09:66ce254f:52) is (TwoPhaseOutcome.PREPARE_OK) node id: (1)
XAResource 7defacb6: preparing transaction xid = < formatId=131077 ...
PREPARE TRANSACTION '131077_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUDE=_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAVAAAAAAAAAAA'
BasicAction::doPrepare() result for action-id (0:ffff0a057e34:ac09:66ce254f:50) on record id: (0:ffff0a057e34:ac09:66ce254f:55) is (TwoPhaseOutcome.PREPARE_NOTOK) node id: (1)
ARJUNA012073: BasicAction.End() - prepare phase of action-id 0:ffff0a057e34:ac09:66ce254f:50 failed.
XAResource 6fc88644: rolling back xid = < formatId=131077 ...
ROLLBACK PREPARED '131077_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUDE=_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUQAAAAAAAAAA'
BasicAction::doAbort() result for action-id (0:ffff0a057e34:ac09:66ce254f:50) on record id: (0:ffff0a057e34:ac09:66ce254f:52) is (TwoPhaseOutcome.FINISH_OK) node id: (1)
ROLLBACK PREPARED '131077_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUDE=_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAVAAAAAAAAAAA'
ERROR: prepared transaction with identifier "131077_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAUDE=_AAAAAAAAAAAAAP//CgV+NAAArAlmziVPAAAAVAAAAAAAAAAA" does not exist
ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a057e34:ac09:66ce254f:50, node_name=1, branch_uid=0:ffff0a057e34:ac09:66ce254f:54, subordinatenodename=null, eis_name=unknown eis name > (org.postgresql.xa.PGXAConnection@7defacb6) failed with exception code XAException.XAER_RMERR
ARJUNA012089: Top-level abort of action 0:ffff0a057e34:ac09:66ce254f:50 received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD
BasicAction::End() result for action-id (0:ffff0a057e34:ac09:66ce254f:50) is (TwoPhaseOutcome.HEURISTIC_HAZARD) node id: (1)
rinaldodev commented 2 months ago

@marcosgopen

marcosgopen commented 2 months ago

Thanks @rinaldodev for your reproducer. As expected the db2 throws the exception 'ERROR: duplicate key value violates unique constraint "users_name_key"'. So the second prepare fails and the transaction is rolled back. And I can see that the rollback throws "XAException.XAER_RMERR" because the prepared transaction does not exist. I need to check if this is the expected behaviour. cc @graben

graben commented 2 months ago

@rinaldodev: Could you please look at what happens if you use Agroal DataSource instead of the Narayana unpooled one.

rinaldodev commented 2 months ago

@rinaldodev: Could you please look at what happens if you use Agroal DataSource instead of the Narayana unpooled one.

My original tests were with Agroal, that's when I saw it happening. I removed it from this reproducer just to reduce the scope. My original test is here: https://github.com/apache/camel-spring-boot-examples/pull/141

I can augment this one with Agroal if you believe it's necessary.

jmfinelli commented 2 months ago

Hi @rinaldodev, I think you bumped into JBTM-3843. There is an upstream PR (on hold) to fix this issue and a PR to fix/discuss how pgjdbc handles rollback invocations when there has been a constraint violation during the prepare phase. We'll keep you posted

rinaldodev commented 2 months ago

Hi @rinaldodev, I think you bumped into JBTM-3843. There is an upstream PR (on hold) to fix this issue and a PR to fix/discuss how pgjdbc handles rollback invocations when there has been a constraint violation during the prepare phase. We'll keep you posted

Thanks a lot. I'll follow this issue.

graben commented 2 months ago

@rinaldodev: Could you please look at what happens if you use Agroal DataSource instead of the Narayana unpooled one.

My original tests were with Agroal, that's when I saw it happening. I removed it from this reproducer just to reduce the scope. My original test is here: https://github.com/apache/camel-spring-boot-examples/pull/141

I can augment this one with Agroal if you believe it's necessary.

I think it's not necessary at the moment. Let's wait for the Narayana patch to be committed.

graben commented 1 month ago

@rinaldodev Narayana patch has been merged. You might be able to retest with a snapshot.

jmfinelli commented 1 month ago

Thanks @graben! You were quicker than me sharing the news :-D

rinaldodev commented 1 month ago

Thanks, I'll take a look.

graben commented 1 month ago

@rinaldodev: Any news on this issue? Can it be closed regarding Narayana > 7.0.2?

jmfinelli commented 1 month ago

@graben: I had a quick look, it seems that @rinaldodev's reproducer is now failing for something different than HEURISTIC_HAZARD (log attached) so I suppose the latest snapshot from Narayana's main fixed the initial issue.

out.log

rinaldodev commented 1 month ago

I'm getting a different error that seems related to the log implementation that arjuna is trying to use. I've rebased this example but the I get the same error.

Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'narayanaPropertiesInitializer' defined in class path resource [dev/snowdrop/boot/narayana/autoconfigure/NarayanaAutoConfiguration.class]: java.lang.reflect.InvocationTargetException
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1806) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:600) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:522) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:337) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:335) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:313) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:313) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.config.DependencyDescriptor.resolveCandidate(DependencyDescriptor.java:254) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1443) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:1353) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.ConstructorResolver.resolveAutowiredArgument(ConstructorResolver.java:904) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:782) ~[spring-beans-6.1.13.jar:6.1.13]
    ... 60 common frames omitted
Caused by: java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
    at com.arjuna.common.internal.util.propertyservice.BeanPopulator.getNamedInstance(BeanPopulator.java:75) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    at com.arjuna.common.internal.util.propertyservice.BeanPopulator.getDefaultInstance(BeanPopulator.java:38) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    at dev.snowdrop.boot.narayana.core.properties.NarayanaPropertiesInitializer.getPopulator(NarayanaPropertiesInitializer.java:151) ~[narayana-spring-boot-core-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
    at dev.snowdrop.boot.narayana.core.properties.NarayanaPropertiesInitializer.setXARecoveryNodes(NarayanaPropertiesInitializer.java:95) ~[narayana-spring-boot-core-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
    at dev.snowdrop.boot.narayana.core.properties.NarayanaPropertiesInitializer.afterPropertiesSet(NarayanaPropertiesInitializer.java:53) ~[narayana-spring-boot-core-3.3.0-SNAPSHOT.jar:3.3.0-SNAPSHOT]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1853) ~[spring-beans-6.1.13.jar:6.1.13]
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1802) ~[spring-beans-6.1.13.jar:6.1.13]
    ... 75 common frames omitted
Caused by: java.lang.reflect.InvocationTargetException: null
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
    at java.base/java.lang.reflect.Method.invoke(Method.java:569) ~[na:na]
    at com.arjuna.common.internal.util.propertyservice.BeanPopulator.handleGroupProperty(BeanPopulator.java:273) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    at com.arjuna.common.internal.util.propertyservice.BeanPopulator.configureFromProperties(BeanPopulator.java:155) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    at com.arjuna.common.internal.util.propertyservice.BeanPopulator.getNamedInstance(BeanPopulator.java:72) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    ... 81 common frames omitted
Caused by: java.lang.ExceptionInInitializerError: null
    at com.arjuna.ats.jta.common.JTAEnvironmentBean.setXaRecoveryNodes(JTAEnvironmentBean.java:357) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    ... 88 common frames omitted
Caused by: java.lang.IllegalArgumentException: Invalid logger interface com.arjuna.ats.jta.logging.jtaI18NLogger (implementation not found in jdk.internal.loader.ClassLoaders$AppClassLoader@2cdf8d8a)
    at org.jboss.logging.Logger.doGetMessageLogger(Logger.java:2573) ~[jboss-logging-3.5.3.Final.jar:3.5.3.Final]
    at org.jboss.logging.Logger.getMessageLogger(Logger.java:2532) ~[jboss-logging-3.5.3.Final.jar:3.5.3.Final]
    at org.jboss.logging.Logger.getMessageLogger(Logger.java:2518) ~[jboss-logging-3.5.3.Final.jar:3.5.3.Final]
    at com.arjuna.ats.jta.logging.jtaLogger.<clinit>(jtaLogger.java:16) ~[narayana-jta-7.0.3.Final-SNAPSHOT.jar:7.0.3.Final-SNAPSHOT (revision: 3acf8)]
    ... 89 common frames omitted
graben commented 1 month ago

Following your steps to reproduce does not lead to an exception like this.

rinaldodev commented 1 month ago

Following your steps to reproduce does not lead to an exception like this.

As suggested, I've built 7.0.3.Final-SNAPSHOT locally with ./build.sh -DskipTests and replaced the version in the narayana.version property.

After doing that, that's the error I'm getting. When using 7.0.2-Final, I get the original error.

If there are other changes that are needed to run with the SNAPSHOT version, please let me know.

graben commented 1 month ago

If still compiling against NSB 3.2 you still might get Narayana 7.0.2. Add both Narayana dependencies from parent pom. That's what I did.

jmfinelli commented 1 month ago

Hi @rinaldodev, I tried your reproducer again but I cannot reproduce the error you're getting. I'll list the steps I executed to clairfy what I did:

rinaldodev commented 1 month ago

Thanks a lot, @jmfinelli. I believe this can be closed now.