Uploaded image for project: 'JBoss Transaction Manager'
  1. JBoss Transaction Manager
  2. JBTM-3618

FailedLRAIT testCannotDeleteNonFailedLRAs hanging

XMLWordPrintable

      Seen on a PR:

      The test was hanging: https://github.com/jbosstm/narayana/blob/master/rts/lra/test/basic/src/test/java/io/narayana/lra/arquillian/FailedLRAIT.java#L190

      [33m16:11:41,028 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-without-status-reporting/compensate?method=javax.ws.rs.PUT reported a failure to compensate (cause FailedToCompensate)
      [0m[33m16:11:41,028 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-without-status-reporting/compensate?method=javax.ws.rs.PUT reported a failure to compensate (cause FailedToCancel)
      [0m[0m16:11:41,127 INFO  [io.narayana.lra] (default task-1) Failed lra record (Uid: 0:ffffac11000b:a618:62b1ed7a:b1) moved to new location type: /StateManager/BasicAction/LongRunningAction/Failed
      [0m[33m16:11:41,323 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-without-status-reporting/complete?method=javax.ws.rs.PUT reported a failure to complete (cause FailedToComplete)
      [0m[33m16:11:41,323 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-without-status-reporting/complete?method=javax.ws.rs.PUT reported a failure to complete (cause FailedToClose)
      [0m[0m16:11:41,393 INFO  [io.narayana.lra] (default task-1) Failed lra record (Uid: 0:ffffac11000b:a618:62b1ed7a:b9) moved to new location type: /StateManager/BasicAction/LongRunningAction/Failed
      [0m[33m16:11:41,561 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-with-status-reporting/compensate?method=javax.ws.rs.PUT reported a failure to compensate (cause FailedToCompensate)
      [0m[33m16:11:41,562 WARN  [io.narayana.lra] (default task-1) LRAParticipantRecord: participant http://127.0.0.1:8180/FailedLRAIT/participant-with-status-reporting/compensate?method=javax.ws.rs.PUT reported a failure to compensate (cause FailedToCancel)
      [0m[0m16:11:41,631 INFO  [io.narayana.lra] (default task-1) Failed lra record (Uid: 0:ffffac11000b:a618:62b1ed7a:c1) moved to new location type: /StateManager/BasicAction/LongRunningAction/Failed
      [0m[INFO] [com.arjuna.ats.arjuna] ARJUNA012330: TransactionStatusManager process for uid a618 is ALIVE. connected to host: 127.0.0.1, port: 38002 on socket: Socket[addr=/127.0.0.1,port=38002,localport=50726]
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:7 has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:7 restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@6cf0f909
      [INFO] [io.narayana.lra] LRAParticipantRecord.doEnd status URI http://compensator.url:8080 is invalid (javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: compensator.url: Name or service not known)
      [INFO] [io.narayana.lra] RecoveringLRA.replayPhase2 for http://localhost:8080/lra-coordinator/lra-coordinator/0_ffffac11000b_a618_62b1ed7a_7 ended with status: Cancelling
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:c has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:c restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@3e4eb049
      [INFO] [io.narayana.lra] LRAParticipantRecord.doEnd(compensate) HTTP PUT at http://compensate.url:8080 failed for LRA http://localhost:8080/lra-coordinator/lra-coordinator/0_ffffac11000b_a618_62b1ed7a_c (reason: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: compensate.url: Name or service not known)
      [INFO] [io.narayana.lra] RecoveringLRA.replayPhase2 for http://localhost:8080/lra-coordinator/lra-coordinator/0_ffffac11000b_a618_62b1ed7a_c ended with status: Cancelling
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:2d has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:2d restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@28d69b63
      [INFO] [io.narayana.lra] LRAParticipantRecord.doEnd status URI http://compensator.url:8080/status is invalid (javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: compensator.url)
      [INFO] [io.narayana.lra] RecoveringLRA.replayPhase2 for http://localhost:8080/lra-coordinator/lra-coordinator/0_ffffac11000b_a618_62b1ed7a_2d ended with status: Cancelling
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:42 has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:42 restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@30a87876
      [WARNING] [io.narayana.lra] LRA025029: Cannot notify AfterLRA URL at http://after.url:8080
      java.util.concurrent.ExecutionException: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: after.url: Name or service not known
          at java.util.concurrent.CompletableFuture.reportGet (CompletableFuture.java:395)
          at java.util.concurrent.CompletableFuture.get (CompletableFuture.java:2022)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.afterLRARequest (LRAParticipantRecord.java:463)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.runPostLRAActions (LRAParticipantRecord.java:519)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.atEnd (LRAParticipantRecord.java:503)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.tryDoEnd (LRAParticipantRecord.java:288)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.doEnd (LRAParticipantRecord.java:275)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.topLevelCommit (LRAParticipantRecord.java:266)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit (BasicAction.java:2933)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit (BasicAction.java:2849)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit (BasicAction.java:1905)
          at io.narayana.lra.coordinator.internal.RecoveringLRA.tryReplayPhase2 (RecoveringLRA.java:89)
          at io.narayana.lra.coordinator.internal.RecoveringLRA.replayPhase2 (RecoveringLRA.java:58)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.doRecoverTransaction (LRARecoveryModule.java:146)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.lambda$processTransactionsStatus$0 (LRARecoveryModule.java:212)
          at java.util.ArrayList.forEach (ArrayList.java:1541)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.processTransactionsStatus (LRARecoveryModule.java:209)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.recoverTransactions (LRARecoveryModule.java:116)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.periodicWorkSecondPass (LRARecoveryModule.java:108)
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal (PeriodicRecovery.java:816)
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run (PeriodicRecovery.java:382)
      Caused by: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: after.url: Name or service not known
          at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke (ManualClosingApacheHttpClient43Engine.java:321)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke (ClientInvocation.java:494)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.lambda$executorSubmit$11 (ClientInvocation.java:856)
          at java.util.concurrent.CompletableFuture$AsyncSupply.run (CompletableFuture.java:1700)
          at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
          at java.lang.Thread.run (Thread.java:829)
      Caused by: java.net.UnknownHostException: after.url: Name or service not known
          at java.net.Inet4AddressImpl.lookupAllHostAddr (Native Method)
          at java.net.InetAddress$PlatformNameService.lookupAllHostAddr (InetAddress.java:929)
          at java.net.InetAddress.getAddressesFromNameService (InetAddress.java:1519)
          at java.net.InetAddress$NameServiceAddresses.get (InetAddress.java:848)
          at java.net.InetAddress.getAllByName0 (InetAddress.java:1509)
          at java.net.InetAddress.getAllByName (InetAddress.java:1368)
          at java.net.InetAddress.getAllByName (InetAddress.java:1302)
          at org.apache.http.impl.conn.SystemDefaultDnsResolver.resolve (SystemDefaultDnsResolver.java:45)
          at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect (DefaultHttpClientConnectionOperator.java:112)
          at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect (PoolingHttpClientConnectionManager.java:376)
          at org.apache.http.impl.execchain.MainClientExec.establishRoute (MainClientExec.java:393)
          at org.apache.http.impl.execchain.MainClientExec.execute (MainClientExec.java:236)
          at org.apache.http.impl.execchain.ProtocolExec.execute (ProtocolExec.java:186)
          at org.apache.http.impl.execchain.RetryExec.execute (RetryExec.java:89)
          at org.apache.http.impl.execchain.RedirectExec.execute (RedirectExec.java:110)
          at org.apache.http.impl.client.InternalHttpClient.doExecute (InternalHttpClient.java:185)
          at org.apache.http.impl.client.CloseableHttpClient.execute (CloseableHttpClient.java:83)
          at org.apache.http.impl.client.CloseableHttpClient.execute (CloseableHttpClient.java:56)
          at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke (ManualClosingApacheHttpClient43Engine.java:302)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke (ClientInvocation.java:494)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.lambda$executorSubmit$11 (ClientInvocation.java:856)
          at java.util.concurrent.CompletableFuture$AsyncSupply.run (CompletableFuture.java:1700)
          at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
          at java.lang.Thread.run (Thread.java:829)
      [WARNING] [io.narayana.lra] LRA025029: Cannot notify AfterLRA URL at http://after.url:8080
      java.util.concurrent.ExecutionException: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: after.url
          at java.util.concurrent.CompletableFuture.reportGet (CompletableFuture.java:395)
          at java.util.concurrent.CompletableFuture.get (CompletableFuture.java:2022)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.afterLRARequest (LRAParticipantRecord.java:463)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.runPostLRAActions (LRAParticipantRecord.java:519)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.atEnd (LRAParticipantRecord.java:503)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.tryDoEnd (LRAParticipantRecord.java:288)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.doEnd (LRAParticipantRecord.java:275)
          at io.narayana.lra.coordinator.domain.model.LRAParticipantRecord.topLevelCommit (LRAParticipantRecord.java:266)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit (BasicAction.java:2933)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit (BasicAction.java:2849)
          at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit (BasicAction.java:1905)
          at io.narayana.lra.coordinator.domain.model.LongRunningAction.runPostLRAActions (LongRunningAction.java:587)
          at io.narayana.lra.coordinator.internal.RecoveringLRA.tryReplayPhase2 (RecoveringLRA.java:91)
          at io.narayana.lra.coordinator.internal.RecoveringLRA.replayPhase2 (RecoveringLRA.java:58)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.doRecoverTransaction (LRARecoveryModule.java:146)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.lambda$processTransactionsStatus$0 (LRARecoveryModule.java:212)
          at java.util.ArrayList.forEach (ArrayList.java:1541)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.processTransactionsStatus (LRARecoveryModule.java:209)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.recoverTransactions (LRARecoveryModule.java:116)
          at io.narayana.lra.coordinator.internal.LRARecoveryModule.periodicWorkSecondPass (LRARecoveryModule.java:108)
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal (PeriodicRecovery.java:816)
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run (PeriodicRecovery.java:382)
      Caused by: javax.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.UnknownHostException: after.url
          at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke (ManualClosingApacheHttpClient43Engine.java:321)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke (ClientInvocation.java:494)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.lambda$executorSubmit$11 (ClientInvocation.java:856)
          at java.util.concurrent.CompletableFuture$AsyncSupply.run (CompletableFuture.java:1700)
          at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
          at java.lang.Thread.run (Thread.java:829)
      Caused by: java.net.UnknownHostException: after.url
          at java.net.InetAddress$CachedAddresses.get (InetAddress.java:797)
          at java.net.InetAddress.getAllByName0 (InetAddress.java:1509)
          at java.net.InetAddress.getAllByName (InetAddress.java:1368)
          at java.net.InetAddress.getAllByName (InetAddress.java:1302)
          at org.apache.http.impl.conn.SystemDefaultDnsResolver.resolve (SystemDefaultDnsResolver.java:45)
          at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect (DefaultHttpClientConnectionOperator.java:112)
          at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect (PoolingHttpClientConnectionManager.java:376)
          at org.apache.http.impl.execchain.MainClientExec.establishRoute (MainClientExec.java:393)
          at org.apache.http.impl.execchain.MainClientExec.execute (MainClientExec.java:236)
          at org.apache.http.impl.execchain.ProtocolExec.execute (ProtocolExec.java:186)
          at org.apache.http.impl.execchain.RetryExec.execute (RetryExec.java:89)
          at org.apache.http.impl.execchain.RedirectExec.execute (RedirectExec.java:110)
          at org.apache.http.impl.client.InternalHttpClient.doExecute (InternalHttpClient.java:185)
          at org.apache.http.impl.client.CloseableHttpClient.execute (CloseableHttpClient.java:83)
          at org.apache.http.impl.client.CloseableHttpClient.execute (CloseableHttpClient.java:56)
          at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke (ManualClosingApacheHttpClient43Engine.java:302)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke (ClientInvocation.java:494)
          at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.lambda$executorSubmit$11 (ClientInvocation.java:856)
          at java.util.concurrent.CompletableFuture$AsyncSupply.run (CompletableFuture.java:1700)
          at java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1128)
          at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:628)
          at java.lang.Thread.run (Thread.java:829)
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:ac has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:ac restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@1096600e
      [INFO] [io.narayana.lra] RecoveringLRA.replayPhase2 for http://localhost:8080/lra-coordinator/lra-coordinator/0_ffffac11000b_a618_62b1ed7a_ac ended with status: Cancelling
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:c9 has 1 heuristic participant(s)!
      [WARNING] [com.arjuna.ats.arjuna] Transaction 0:ffffac11000b:a618:62b1ed7a:c9 restored heuristic participant io.narayana.lra.coordinator.domain.model.LRAParticipantRecord@56950239
      

      Of note is that the TCK tests module had passed:

      [INFO] Tests run: 133, Failures: 0, Errors: 0, Skipped: 0

      And:

      [INFO] Installing /home/jenkins/workspace/btny-pulls-narayana/PROFILE/LRA/jdk/jdk11.latest/label/linux/rts/lra/test/tck/target/lra-test-tck-5.12.7.Final-SNAPSHOT-sources.jar to /home/jenkins/.m2/repository/org/jboss/narayana/rts/lra-test-tck/5.12.7.Final-SNAPSHOT/lra-test-tck-5.12.7.Final-SNAPSHOT-sources.jar

      Then it went on to the lra/test/basic tests:

      [INFO] Building LRA tests: Basic 5.12.7.Final-SNAPSHOT                  [14/15]

      Eventually having difficulty:

      [INFO] Running io.narayana.lra.arquillian.FailedLRAIT

      Interestingly

      LRA025029: Cannot notify AfterLRA URL at http://after.url:8080:

      is seen which suggests the TCK is still running which it shouldn't be but:
      1. The ObjectStore might be being reused.
      2. There were two WildFly processes running - though this might also be normal for LRA basic tests as it is normal for LRA tck tests

      I have reconfigured some jobs to archive */ObjectStore/* which was not already being archived.

              Unassigned Unassigned
              thjenkin@redhat.com Tom Jenkinson
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Created:
                Updated: