[infinispan-issues] [Red Hat JIRA] (ISPN-12738) Improve logging of transaction errors

Improve logging of transaction errors ------------------------------------- Key: ISPN-12738 URL: https://issues.redhat.com/browse/ISPN-12738 Project: Infinispan Issue Type: Bug Components: Core Affects Versions: 12.0.1.Final Reporter: Dan Berindei Assignee: Dan Berindei Priority: Major Fix For: 12.1.0.Final When {{useSynchronization=true}} and a prepare command fails, 3 ERROR and 3 WARN messages are logged: {noformat} 10:49:45,394 ERROR (jgroups-7,Test-NodeD:[]) [InvocationContextInterceptor] ISPN000136: Error executing command PrepareCommand on Cache 'defaultcache', writing keys [] org.infinispan.commons.CacheListenerException: ISPN000280: Caught exception [java.lang.IllegalArgumentException] while invoking method [public void org.infinispan.notifications.cachelistener.ListenerExceptionWithSynchronizationTest$ErrorInducingListener.entryCreated(org.infinispan.notifications.cachelistener.event.CacheEntryEvent) throws java.lang.Exception] on listener instance: org.infinispan.notifications.cachelistener.ListenerExceptionWithSynchronizationTest$ErrorInducingListener@17a626ea 10:49:45,399 WARN (jgroups-7,Test-NodeD:[]) [CLUSTER] ISPN000071: Caught exception when handling command PrepareCommand {modifications=[PutKeyValueCommand{key=k0-testPostOpExceptionListenerOnCreate, value=v0-testPostOpExceptionListenerOnCreate, flags=[], commandInvocationId=CommandInvocation:local:0, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1, maxIdle=-1}, successful=true, topologyId=17}], onePhaseCommit=true, retried=false, gtx=GlobalTransaction{id=1, addr=Test-NodeA, remote=true, xid=null, internalId=-1}, cacheName='defaultcache', topologyId=17} org.infinispan.commons.CacheListenerException: ISPN000280: Caught exception [java.lang.IllegalArgumentException] while invoking method [public void org.infinispan.notifications.cachelistener.ListenerExceptionWithSynchronizationTest$ErrorInducingListener.entryCreated(org.infinispan.notifications.cachelistener.event.CacheEntryEvent) throws java.lang.Exception] on listener instance: org.infinispan.notifications.cachelistener.ListenerExceptionWithSynchronizationTest$ErrorInducingListener@17a626ea 10:49:45,405 ERROR (jgroups-5,Test-NodeA:[]) [InvocationContextInterceptor] ISPN000136: Error executing command PrepareCommand on Cache 'defaultcache', writing keys [k0-testPostOpExceptionListenerOnCreate] org.infinispan.remoting.RemoteException: ISPN000217: Received exception from Test-NodeD, see cause for remote stack trace 10:49:45,406 ERROR (jgroups-5,Test-NodeA:[]) [TransactionCoordinator] ISPN000097: Error while processing a prepare in a single-phase transaction org.infinispan.remoting.RemoteException: ISPN000217: Received exception from Test-NodeD, see cause for remote stack trace 10:49:48,466 WARN (testng-Test:[]) [jta] ARJUNA016029: SynchronizationImple.afterCompletion - failed for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=[Test-NodeE, Test-NodeD], isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=17, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@1} org.infinispan.transaction.synchronization.SynchronizationAdapter@20 with exception java.util.concurrent.CompletionException: org.infinispan.commons.CacheException: Could not commit. 10:49:48,468 WARN (testng-Test:[]) [arjuna] ARJUNA012127: TwoPhaseCoordinator.afterCompletion - returned failure for SynchronizationImple< 0:ffff7f000001:9b93:602cd8a5:1, SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=[Test-NodeE, Test-NodeD], isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=17, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@1} org.infinispan.transaction.synchronization.SynchronizationAdapter@20 > ~[classes/:?] {noformat} Two of the messages are from Arjuna, but the contents are still determined by {{SynchronizationAdapter.toString()}}, and we could even eliminate them by catching the exception in {{SynchronizationAdapter.afterCompletion()}}. None of the ERROR messages include the global transaction id, and the InvocationContextInterceptor ERROR message on the remote node doesn't even include the affected keys. Instead we get trace-level details about the modifications in the transaction, and the identity hash codes of various internal objects. Other transaction configurations need to be checked as well: XA vs. NON_XA, 1PC vs. 2PC.