[JBoss JIRA] Created: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
10:39 a.m.
If an exception occurs during one phase commit optimization the local cache changes are
still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Manik Surtani
I had been implementing infinispan clustered cache with transactions. When a rollback for
a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller from
thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
10:41 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
William Burns updated ISPN-1093:
--------------------------------
Attachment: TU_InfinispanCacheProvider.java
This is the test file. It has been reproduce when the unit test fails with
java.lang.AssertionError: expected:<valueCluster> but was:<null>
at TU_InfinispanCacheProvider.testCluster(TU_InfinispanCacheProvider.java:256)
This is because I do a loop that tries to retry a transaction but the remove call was
improperly pushed to the cache so the next time around the update was seen when it
shouldn't be.
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Fix For: 4.2.2.BETA1, 5.0.0.CR2
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
10:41 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
Manik Surtani updated ISPN-1093:
--------------------------------
Assignee: Mircea Markus (was: Manik Surtani)
Fix Version/s: 4.2.2.BETA1
5.0.0.CR2
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Fix For: 4.2.2.BETA1, 5.0.0.CR2
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
10:52 a.m.
New subject: [JBoss JIRA] Commented: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
William Burns commented on ISPN-1093:
-------------------------------------
To get the unit test in a working state you need to change the
props.put(JGroupsTransport.CONFIGURATION_FILE,
"/home/wburns/RedPrairie/trunk/moca/data/jgroups-udp.xml");
to point to the appropriate jgroups xml file. In this case I am using the one distributed
by infinispan named jgroups-udp.xml.
Also to get the test to work at all you need to run the test process with the
-Djava.net.preferIPv4Stack=true jvm argument or you can remove the
commandLine.add("-Djava.net.preferIPv4Stack=true");
line to have it use the default jvm settings.
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Fix For: 4.2.2.BETA1, 5.0.0.CR2
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
5:03 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
Mircea Markus updated ISPN-1093:
--------------------------------
Fix Version/s: 4.2.2.FINAL
5.0.0.FINAL
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Fix For: 4.2.2.BETA1, 4.2.2.FINAL, 5.0.0.CR2, 5.0.0.FINAL
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
5:46 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
Manik Surtani updated ISPN-1093:
--------------------------------
Priority: Blocker (was: Major)
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Priority: Blocker
Fix For: 4.2.2.BETA1, 4.2.2.FINAL, 5.0.0.CR2, 5.0.0.FINAL
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
7:09 a.m.
New subject: [JBoss JIRA] Updated: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
Mircea Markus updated ISPN-1093:
--------------------------------
Git Pull Request: https://github.com/infinispan/infinispan/pull/303
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Priority: Blocker
Fix For: 4.2.2.BETA1, 4.2.2.FINAL, 5.0.0.CR2, 5.0.0.FINAL
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
11:12 a.m.
New subject: [JBoss JIRA] Resolved: (ISPN-1093) If an exception occurs during one phase commit optimization the local cache changes are still applied
[
https://issues.jboss.org/browse/ISPN-1093?page=com.atlassian.jira.plugin....
]
Manik Surtani resolved ISPN-1093.
---------------------------------
Resolution: Done
If an exception occurs during one phase commit optimization the local
cache changes are still applied
-----------------------------------------------------------------------------------------------------
Key: ISPN-1093
URL: https://issues.jboss.org/browse/ISPN-1093
Project: Infinispan
Issue Type: Bug
Components: Transactions
Affects Versions: 4.2.1.FINAL
Reporter: William Burns
Assignee: Mircea Markus
Priority: Blocker
Fix For: 4.2.2.BETA1, 4.2.2.FINAL, 5.0.0.CR2, 5.0.0.FINAL
Attachments: TU_InfinispanCacheProvider.java
I had been implementing infinispan clustered cache with transactions. When a rollback
for a transaction occurs it will not push the changes to the local cache.
However I found that if a one phase commit optimization is done where infispan is the one
resource and a node in the clustered is found in a Suspect state while preparing that it
will throw a RollbackException, which is great. However the local node still pushes the
changes to the cache which then puts that local cache in an inconsistent state with the
rest of the nodes in the cluster, since they were not pushed the updates.
Here is a snippet of the trace when this occurs
1 ider T 10:18:52,698 (Transactio) [0] Committing transaction
GlobalTransaction:<wburns-53118>:6:local
1 ider T 10:18:52,698 (Transactio) [0] Doing an 1PC prepare call on the interceptor
chain
1 ider T 10:18:52,698 (Invocation) [0] Invoked with command PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} and
InvocationContext [LocalTxInvocationContext{flags=null}]
1 ider T 10:18:52,698 (CallInterc) [0] Suppressing invocation of method
handlePrepareCommand.
1 ider T 10:18:52,698 (Distributi) [0] Not performing invalidation! isL1CacheEnabled?
true numCallRecipients=2
1 ider T 10:18:52,699 (RpcManager) [0] wburns-53118 broadcasting call PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to recipient
list [wburns-38125, wburns-53118]
1 ider T 10:18:52,699 (JGroupsTra) [0] dests=[wburns-38125, wburns-53118],
command=PrepareCommand {gtx=GlobalTransaction:<wburns-53118>:6:local,
modifications=[RemoveCommand{key=key, value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'},
mode=SYNCHRONOUS, timeout=15000
1 ider T 10:18:52,701 (CommandAwa) [0] Replication task sending PrepareCommand
{gtx=GlobalTransaction:<wburns-53118>:6:local, modifications=[RemoveCommand{key=key,
value=null, flags=null}], onePhaseCommit=true,
gtx=GlobalTransaction:<wburns-53118>:6:local, cacheName='test'} to addresses
[wburns-38125, wburns-53118]
1 ider T 10:18:52,703 (JBossMarsh) [0] Start marshaller after retrieving marshaller
from thread local
1 ider T 10:18:52,703 (VersionAwa) [0] Wrote version 420
1 ider T 10:18:52,704 (JBossMarsh) [0] Stop marshaller
1 ider T 10:18:52,704 (CommandAwa) [0] real_dests=[wburns-38125]
37 ider T 10:18:52,720 (JGroupsDis) Closing joinInProgress gate
37 ider I 10:18:53,028 (JGroupsTra) Received new cluster view: [wburns-53118|2]
[wburns-53118]
1 ider T 10:18:53,032 (CommandAwa) [0] Responses: [sender=wburns-38125, retval=null,
received=false, suspected=true]
37 ider T 10:18:53,028 (Transactio) Saw 1 leavers - kicking off a lock breaking task
1 ider T 10:18:53,034 (RpcManager) [0] replication exception:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,037 (DistLockin) [0] Number of entries in context: 1
41 ider T 10:18:53,036 (Transactio) No global transactions pertain to originator(s)
[wburns-38125] who have left the cluster.
37 ider I 10:18:53,036 (Distributi) Detected a view change. Member list changed from
[wburns-53118, wburns-38125] to [wburns-53118]
41 ider T 10:18:53,038 (Transactio) Completed cleaning stale locks.
37 ider I 10:18:53,038 (Distributi) This is a LEAVE event! Node wburns-38125 has just
left
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
1 ider T 10:18:53,039 (DistLockin) [0] Releasing lock on [key] for owner
GlobalTransaction:<wburns-53118>:6:local
37 ider T 10:18:53,039 (Distributi) Added new leaver wburns-38125, leavers list is
[wburns-38125]
1 ider T 10:18:53,039 (LockManage) [0] Attempting to unlock key
1 ider E 10:18:53,039 (Invocation) [0] Execution error:
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,041 (Invocation) [0] Transaction marked for rollback as exception was
received.
1 ider T 10:18:53,041 (jta ) [0] TransactionImple.getStatus
1 ider E 10:18:53,041 (Transactio) [0] Error while processing 1PC PrepareCommand
org.infinispan.remoting.transport.jgroups.SuspectException: Suspected member:
wburns-38125
.... full stack trace removed for clarity ....
1 ider T 10:18:53,043 (jta ) [0] TransactionImple.equals
37 ider T 10:18:53,040 (Distributi) wburns-53118 is looking for a new backup to replace
leaver wburns-38125
37 ider T 10:18:53,044 (Distributi) Leaver wburns-38125 main backup wburns-53118 is
looking for another backup as well.
37 ider T 10:18:53,044 (Distributi) Nodes that need new backups are: [wburns-53118,
wburns-53118]
37 ider T 10:18:53,044 (Distributi) This node won't receive state
37 ider I 10:18:53,044 (Distributi) I wburns-53118 am participating in rehash, state
providers [wburns-53118, wburns-53118], state receivers [wburns-53118, wburns-53118]
1 ider W 10:18:53,045 (jta ) [0] ARJUNA-16039 onePhaseCommit on <
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >
(TransactionXaAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null,
isMarkedForRollback=false, transaction=TransactionImple < ac, BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.COMMITTING >, xid=<
formatId=131076, gtrid_length=29, bqual_length=28, tx_uid=0:ffff0a0302c6:ba1e:4dc805d1:16,
node_name=1, branch_uid=0:ffff0a0302c6:ba1e:4dc805d1:17, eis_name=unknown eis name >}
org.infinispan.transaction.xa.LocalTransaction@9c35300f}) failed with exception
XAException.XAER_RMERR
javax.transaction.xa.XAException
.... full stack trace removed for clarity ....
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1
1 ider T 10:18:53,046 (arjuna ) [0] BasicAction::removeChildThread () action
0:ffff0a0302c6:ba1e:4dc805d1:16 removing TSThread:1 result = true
1 ider T 10:18:53,047 (arjuna ) [0] TransactionReaper::remove ( BasicAction:
0:ffff0a0302c6:ba1e:4dc805d1:16 status: ActionStatus.ABORTED )
RollbackException encountered - ARJUNA-16053 Could not commit transaction.
1 ider T 10:18:53,047 (jta ) [0] BaseTransaction.begin
The significant line is
1 ider T 10:18:53,038 (ReadCommit) [0] Updating entry (key=key removed=true valid=false
changed=true created=false value=com.redprairie.moca.cache.Maybe@5bd6c768]
where in the ReadCommited isolation level still pushed the remove call that should have
been rolled back.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
4996
days inactive
4999
days old
infinispan-issues@lists.jboss.org
7 comments
3 participants
participants (3)
-
Manik Surtani (JIRA) -
Mircea Markus (JIRA)
-
William Burns (JIRA)