ShardingSphere Narayana XA 事务不回滚问题定位

问题背景

用户反馈，在使用 ShardingSphere + Narayana 执行 XA 事务时，发生报错：java.sql.SQLException: javax.transaction.RollbackException: TransactionImple.enlistResource - ARJUNA016064: The transaction is in an invalid state!。
这个报错的含义简单来说就是这个事务已经在其他地方被标记成只可回滚了，不能再进行后续其他的操作。报错信息如下：

Caused by: java.sql.SQLException: javax.transaction.RollbackException: TransactionImple.enlistResource - ARJUNA016064: The transaction is in an invalid state!at org.apache.shardingsphere.transaction.xa.XAShardingSphereTransactionManager.getConnection(XAShardingSphereTransactionManager.java:101)at org.apache.shardingsphere.transaction.ConnectionTransaction.getConnection(ConnectionTransaction.java:102)at org.apache.shardingsphere.driver.jdbc.core.connection.DriverDatabaseConnectionManager.createConnection(DriverDatabaseConnectionManager
.java:416)at org.apache.shardingsphere.driver.jdbc.core.connection.DriverDatabaseConnectionManager.createConnections(DriverDatabaseConnectionManage
r.java:383)at org.apache.shardingsphere.driver.jdbc.core.connection.DriverDatabaseConnectionManager.getConnections(DriverDatabaseConnectionManager.j
ava:357)at org.apache.shardingsphere.driver.jdbc.core.connection.DriverDatabaseConnectionManager.getConnections(DriverDatabaseConnectionManager.j
ava:338)at org.apache.shardingsphere.infra.executor.sql.prepare.driver.DriverExecutionPrepareEngine.group(DriverExecutionPrepareEngine.java:89)at org.apache.shardingsphere.infra.executor.sql.prepare.AbstractExecutionPrepareEngine.prepare(AbstractExecutionPrepareEngine.java:73)at org.apache.shardingsphere.infra.executor.sql.prepare.AbstractExecutionPrepareEngine.prepare(AbstractExecutionPrepareEngine.java:61)at org.apache.shardingsphere.driver.jdbc.core.statement.ShardingSpherePreparedStatement.createExecutionGroupContext(ShardingSpherePrepare
dStatement.java:764)at org.apache.shardingsphere.driver.jdbc.core.statement.ShardingSpherePreparedStatement.useDriverToExecute(ShardingSpherePreparedStatement.java:717)at org.apache.shardingsphere.driver.jdbc.core.statement.ShardingSpherePreparedStatement.executeWithExecutionContexts(ShardingSpherePreparedStatement.java:658)at org.apache.shardingsphere.driver.jdbc.core.statement.ShardingSpherePreparedStatement.execute(ShardingSpherePreparedStatement.java:631)at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:44)at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:69)at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

问题分析

观察日志里有调用 setRollbackOnly 方法的日志，通过查看 setRollbackOnly 方法的调用链路，再结合报错是在 getConnection 时报的，那么调用 setRollbackOnly 方法应该发生在getConnection之前，极有可能是 enlistResource 地方报的。
![[img-20240123115238.png]]

通过查看 enlistResource 方法的逻辑，注释里写的是 xa start 语句没执行成功时会调用 markRollbackOnly 标识事务只可回滚。
![[img-20240123115315.png]]

开启 narayana trace 日志。
[[sf-xa-log.log]]
看日志 43 行
发现 enlistResource 操作前后有一个可疑日志。

-- xid unset
[2024-01-23 11:10:08,001] [com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord],[<init>],[XNIO-1 task-1],[INFO],[202401231110026b2ab483e6ae4d43bd055383c3d57d30-0],[],[XAResourceRecord.XAResourceRecord ( ARJUNA016100: Xid unset, org.apache.shardingsphere.transaction.xa.spi.SingleXAResource@5c6c9ab9 ), record id=0:ffff0acf077d:837d:65af2e0d:4]|[TID:323d025cef50474aa2ffdd4dc341a97a.316543.17059794010875173]|-- set rollback only
[2024-01-23 11:10:08,357],[eciqs-core],[com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple],[setRollbackOnly],[XNIO-1 task-1],[INFO],[202401231110026b2ab483e6ae4d43bd055383c3d57d30-0],[],[TransactionImple.setRollbackOnly]|[TID:323d025cef50474aa2ffdd4dc341a97a.316543.17059794010875173]|-- 后续自动执行回滚操作日志
[2024-01-23 11:10:09,081],[eciqs-core],[com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction],[rollback],[XNIO-1 task-1],[INFO],[202401231110026b2ab483e6ae4d43bd055383c3d57d30-0],[],[BaseTransaction.rollback]|[TID:323d025cef50474aa2ffdd4dc341a97a.316543.17059794010875173]|[2024-01-23 11:10:09,081],[eciqs-core],[com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple],[rollbackAndDisassociate],[XNIO-1 task-1],[INFO],[202401231110026b2ab483e6ae4d43bd055383c3d57d30-0],[],[TransactionImple.rollbackAndDisassociate]|[TID:323d025cef50474aa2ffdd4dc341a97a.316543.17059794010875173]|[2024-01-23 11:10:09,081],[eciqs-core],[com.arjuna.ats.arjuna.coordinator.BasicAction],[Abort],[XNIO-1 task-1],[INFO],[202401231110026b2ab483e6ae4d43bd055383c3d57d30-0],[],[BasicAction::Abort() for action-id 0:ffff0acf077d:837d:65af2e0d:2]|[TID:323d025cef50474aa2ffdd4dc341a97a.316543.17059794010875173]|

日志显示的是 ARJUNA016100: Xid unset,正常日志应该如下：

2024-01-23 11:48:33.341 [main] TRACE com.arjuna.ats.jta - XAResourceRecord.XAResourceRecord ( < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:90ab:65af3711:2, node_name=1, branch_uid=0:ffff7f000101:90ab:65af3711:3, subordinatenodename=null, eis_name=0 >, com.zc.transaction.xa.SingleXACtrlResource@1fc793c2 ), record id=0:ffff7f000101:90ab:65af3711:4

ARJUNA016100: Xid unset

后续分析为什么会出现ARJUNA016100: Xid unset 异常。
搜索 ARJUNA016100 错误码，是在 xidImple.toString 里调用的。

原因，比如一个 xa 事务涉及两个 xa resources,在执行第一个 resource enlist 时候，由于 xid 有问题，start xid 在 mysql 上执行失败了，然后 Naryana 自己调用 com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple#setRollbackOnly 方法将当前全局事务状态设置为 ActionStatus.ABORT_ONLY 状态。
那么当事务内第二个 xa resource 执行 enlist resource 操作时，由于当前事务已经标记为只回滚，所以执行报错。也就是最开始日志里报的错：java.sql.SQLException: javax.transaction.RollbackException: TransactionImple.enlistResource - ARJUNA016064: The transaction is in an invalid state!
相关代码如下：

public boolean enlistResource(XAResource xaRes, Object[] params)  throws RollbackException, IllegalStateException,  jakarta.transaction.SystemException  
{  // ...int status = getStatus();  switch (status)  {    // jakarta.transaction.Status.STATUS_MARKED_ROLLBACK 对应上面的 ActionStatus.ABORT_ONLY 状态，报错 invalid。case jakarta.transaction.Status.STATUS_MARKED_ROLLBACK:  throw new RollbackException(  "TransactionImple.enlistResource - " + jtaLogger.i18NLogger.get_transaction_arjunacore_invalidstate() );  case jakarta.transaction.Status.STATUS_ACTIVE:  break;  default:  throw new IllegalStateException( jtaLogger.i18NLogger.get_transaction_arjunacore_inactive() );  }

当出现报错后，后续 narayana 会自动执行回滚操作，参考 narayana 日志。

XID 为空原因

为什么 xid 会为空。
这个 xid 为空的报错是在 com.arjuna.ats.jta.xa.XidImple#toString 方法中报的，实际上是 com.arjuna.ats.jta.xa.XidImple#_theXid 为空导致。
在 XidImple 所有构造方法中打断点，看创建 xid 过程，哪里导致 _theXid 属性为空。

public XidImple(Uid id, boolean branch, Integer eisName) {  try {  // 可以看到如果创建 _theXid 失败，则捕获了异常_theXid = XATxConverter.getXid(id, branch, eisName);  } catch (Exception e) {  _theXid = null;  jtaLogger.i18NLogger.warn_cant_create_xid_of_branch(id, branch, eisName, e);  // abort or throw exception?  }  hashCode = getHash(_theXid);  
}

后续 debug 看日常信息，发现 xid 为 null,异常信息里有 ARJUNA016111: The node identifier cannot be null 信息，这个明显是没有读取到 jbossts.xml 配置文件导致的报错。

后续通过修改 Transaction Rule, 尝试刷新配置，发现错误依然存在。Debug 发现没有读取到 jbossts.xml 配置文件导致。

使用 arthas 查看应用里 ShardingSphere-JDBC 的 TransactionRule 属性正常，说明 Rule 正常刷新。
但是 arthas 查看 ObjectStoreEnvironmentBean 里的 jdbc 属性为空，说明没有读取到 jbossts.xml 配置文件。

sc -d *TransactionRule
vmtool --action getInstances -c 368239c8 --className org.apache.shardingsphere.transaction.rule.TransactionRule --limit 10 -x 2sc -d *ObjectStoreEnvironmentBean
vmtool --action getInstances -c 368239c8 --className com.arjuna.ats.arjuna.common.ObjectStoreEnvironmentBean --limit 10 -x 2