13 Replies Latest reply on Feb 6, 2017 3:09 AM by ochaloup

    Transactions from @Remote annotated EJB sometimes not commited

    hans.christian.goranson

      I have a problem with a transaction not being committed and the db connections not being released in my web application which runs with Wildfly 10.1 and uses Narayana and IronJacamar together with a postgres db.

      This causes the connection pool to run out of connection after a while. The issue started to occur after we updated Wildfly from 9 to 10.

       

      I'm not sure if this is a Narayana related issue or not but I would like to understand some transaction related things I see in the logs

       

      The scenario is that I have different EJBs packaged in different ear files which communicates with eachother using JNDI lookup. Each ear has its own persistence context but uses the same datasource and database.

      I start a transaction from a @Local annotated EJB bean (lets call it CrmEJB) in crm.ear, this calls a @Remote anotated bean (lets call it PriceEJB) in price.ear.

      The transaction scope is default (REQUIRED) everywhere so I expect (I'm not sure if this is a correct assumption) the transaction to be propagated from CrmBean to PriceEJB.

      For this scenario, all queries to the database are SELECT queries (so it is just database reads)

       

      The problem is that around every fifth time, the PriceEJB aquires a new connection from the connection pool, and begins a new transaction but never commits. So that connection will never never be put back into the pool.

       

      After enabling some TRACE logs for arjuna and compare a successful scenario with a failure scenario, I can see that for failure cases, two different versions of the class TransactionImple is used, where one is from the subordinate folder

      The CrmBean which starts the transaction uses the class

      /narayana/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/TransactionImple.java

      while the PriceBean uses the class

      /narayana/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/subordinate/jca/TransactionImple.java

       

      When I enabled JTS in the configuration, I do not experience the problem anymore and everything works fine, but I'm not sure if this has any side effects

       

      My questions are:

      - Can the different classes of TransactionImple have something to do with the problem?  if so some hints what could be wrong and maybe some tips where to continue the investigation (I'm not particularly familiar with Narayana and transactions so any background information is welcome)

      - shall I have JTS enabled for ear to ear communication within the same app server with @Remote annotated EJB?

       

      I can see some different behaviour of the PriceEJB, sometimes it is running as a separate thread and sometime it is the same thread running as CrmBean.

      I also had successful cases where the TransactionImple comes both from the arjunacore folder and subordinate folder

      For both failure and success cases, I can see this in the log: "SubordinationManager.setTxType(JTA)"

       

      My configuration looks like this (if have tried to set interleaving and tracking to true without any differences):

      XA datasourceTransactionsJCA

      <xa-datasource jndi-name="java:jboss/datasources/postgres-crm-ds" pool-name="postgres-crm-ds" statistics-enabled="true"  >

          <driver>postgresql-9.4.1212.jar</driver>

          <xa-datasource-property name="ServerName">...</xa-datasource-property>

          <xa-datasource-property name="PortNumber">...</xa-datasource-property>

          <xa-datasource-property name="DatabaseName">...</xa-datasource-property>

       

          <xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class>

          <xa-pool>

               <min-pool-size>1</min-pool-size>

               <max-pool-size>400</max-pool-size>

          </xa-pool>

          <timeout>

                  <idle-timeout-minutes>5</idle-timeout-minutes>

          </timeout>

          <security>

               <user-name>...</user-name>

               <password>...</password>

          </security>

      </xa-datasource>

      <subsystem xmlns="urn:jboss:domain:transactions:3.0">

          <core-environment>

              <process-id>

                  <uuid/>

              </process-id>

          </core-environment>

          <recovery-environment socket-binding="txn-recovery-environment" status-socket-binding="txn-status-manager"/>

          <coordinator-environment default-timeout="300" enable-statistics="true"/>

          <!-- Enabling JTS here seems to solve the problem-->

          <!--jts/-->

      </subsystem>

      <subsystem xmlns="urn:jboss:domain:jca:4.0">

          <archive-validation enabled="true" fail-on-error="true" fail-on-warn="false"/>

          <bean-validation enabled="true"/>

          <default-workmanager>

              <short-running-threads>

                  <core-threads count="50"/>

                  <queue-length count="50"/>

                  <max-threads count="50"/>

                  <keepalive-time time="10" unit="seconds"/>

              </short-running-threads>

              <long-running-threads>

                  <core-threads count="50"/>

                  <queue-length count="50"/>

                  <max-threads count="50"/>

                  <keepalive-time time="10" unit="seconds"/>

              </long-running-threads>

          </default-workmanager>

          <cached-connection-manager/>

      </subsystem>

       

       

      ---

      Here are some log example for the failure case:

      // CrmBean aquires a connection from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will be put back to the pool.

      13:21:33,761 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 129) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@73e03c

      5c[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@594c1ffb connection handles=0 lastReturned=1484745693690 lastValidated=1484745693642 lastCheckedOut=1484745693761 trackByTx=false pool=org.jboss.jca.core

      .connectionmanager.pool.strategy.OnePool@2e93c6bc mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@277beead[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@396fea6a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnectio

      n@594c1ffb pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:74c8ec99:587f6b90:2c status: ActionS

      tatus.RUNNING >

       

      // PriceBean aquires a connection from the pool and I can see that the "TransactionImple < jca-subordinate" is in the log. This connection will never be put back to the pool

      13:21:34,652 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-87) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7c56eb55[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6128d8d7 connection handles=0 lastReturned=1484745693661 lastValidated=1484745635169 lastCheckedOut=1484745694652 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2e93c6bc mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@277beead[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@d2533cb[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6128d8d7 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < jca-subordinate, BasicAction: 0:ffff0af6c016:74c8ec99:587f6b90:36 status: ActionStatus.RUNNING >

       

      EDIT: below is the successful case - not failure

      Here are some log example for the success case:

      // CrmBean aquires a connection from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will b eput back to the pool.

      13:31:11,495 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 78) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e7c430

      0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a connection handles=0 lastReturned=1484746271484 lastValidated=1484746269735 lastCheckedOut=1484746271495 trackByTx=false pool=org.jboss.jca.core.

      connectionmanager.pool.strategy.OnePool@51760712 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@146717d1[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@137df56c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection

      @5400fe1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionSt

      atus.RUNNING >

       

      // PriceBean reuses the connetion that was aquired by the CrmBean from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will be put back to the pool

      13:31:11,510 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [tx-3] (ServerService Thread Pool -- 78) Previous connection tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e7c4300[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a connection handles=1 lastReturned=1484746271484 lastValidated=1484746269735 lastCheckedOut=1484746271495 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@51760712 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@146717d1[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@137df56c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=TransactionSynchronization@1874016840{tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true cancel=false}] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionStatus.RUNNING >

      13:31:11,510 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] [tx-3] (ServerService Thread Pool -- 78) [TxConnectionListener@6e7c4300] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@51118944 [size=2] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@5cb3a3f3, org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@51118944])

       

      Best regards

      Hans-Christian

        • 1. Re: Transactions from @Remote annotated EJB sometimes not commited
          tomjenkinson

          Hi Hans-Christian,

           

          I will move this to WildFly as it seems to be affected by the EJB remoting code so you will get more input.

           

          The reason that JTS works is because transaction propagation over JTS/CORBA is quite differently handled. Note that the JTS case might even not be working, unless you did the injection with corba addresses?:

          jboss-eap-quickstarts/CustomerManagerEJB.java at 7.1.x-develop · jboss-developer/jboss-eap-quickstarts · GitHub

           

          For the EJB remoting case I would definitely expect the two different classes, cases where that didn't happen are likely an error.

           

          I want to check two things with you.

           

          1. Your original post mentions PriceBean using "/narayana/ArjunaJTS/jtax/classes/com/arjuna/ats/internal/jta/transaction/jts/subordinate/jca/TransactionImple.java" (note jts package) but your current post does not - is that correct?

          2. Your post has two examples for failure cases, but the second one has a connection put in the pool.

           

          Are you able to share a full log for a failure with me?

           

          Thanks,

          Tom

          • 2. Re: Transactions from @Remote annotated EJB sometimes not commited
            hans.christian.goranson

            Thanks for the reply.

             

            For the questions:

            1. I made a mistake when I searched in the code for "TransactionImple < jca-subordinate" and landend in the ArjunaJTS version of TransactionImple and I was confused that both JTA and JTS was used. Later I realized that the same is printed from the class TransactionImple in the ArjunaJTA both comes from the ArjunaJTA module

            2. I can see that I made a second mistake, sorry about that, the title for second example should be successful case

             

            Also, we do not use corba addresses. I gave it a try due to that I thought that sometimes the TransactionImple from ArjunaJTS was used.

             

            If it is fine for you I can share some logs per mail with a successful and failure cases

             

            BR

            Hans-Christian

            • 3. Re: Transactions from @Remote annotated EJB sometimes not commited
              tomjenkinson

              Sure, no problem to share the logs by email. You can get my email address from github: https://github.com/tomjenkinson

              • 4. Re: Transactions from @Remote annotated EJB sometimes not commited
                tomjenkinson

                Hi Hans-Christian,

                 

                I have slimmed the logs you provided by email a little and can see a discrepancy in two of the cases.  It would help if you can share server-failure-thread_change and server-success-threadchange logs publicly as Stefano (maeste) from JCA and David (dmlloyd from EJB) might have some good input as it looks like it might be related to silent prepare calls when TX is not fully imported: https://issues.jboss.org/browse/WFLY-7196

                 

                Thanks,

                Tom

                • 5. Re: Transactions from @Remote annotated EJB sometimes not commited
                  hans.christian.goranson

                  I have added two log examples: server-failure-thread_change.log and server-success-threadchange.log in the attache logs.zip. Below is a small summary of the two logs

                   

                  The logic in this piece of code is that we loop over 13 currencies and for each currency we call first a @Local EJB, which calls a new @Local EJV wich calls a @Remote EJB in a separate ear in the same application server.

                   

                  === Failure case (server-failure-thread_change.log) ===

                  // First, the connection 73e03c5c is taken out from the pool when entering the first @Local EJB

                  13:21:33,761 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 129) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@73e03c5c...

                   

                  // Later on, the connection 7c56eb55 is aquired from the pool when entering the @Remote EJB (in a separate thread)

                  13:04:30,287 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-82) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e94df70...

                   

                  //The connection 7c56eb55 is never return to the pool

                   

                  // When iterating through the next currency and the @remote EJB is called, a new connection is aquired from the pool with id

                  13:21:35,719 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-111) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@520ecd7a...

                   

                  // This is the repeated until all 13 currencies has been iterated and there are 13 connections in the pool which never will be returned

                  // The first connection (73e03c5c) is returned to the pool

                  13:21:42,540 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 129) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@73e03c5c

                   

                  // The pool with the first "leaked" connection . The statistics says "StartCount: 29" and "  CommitCount: 16"

                  13:21:42,572 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 129) getConnection(null, WrappedConnectionRequestInfo@7e42d8c1[userName=crm])

                  Method: getConnection(null, WrappedConnectionRequestInfo@7e42d8c1[userName=crm])

                    Subject: null

                    CRI: 7e42d8c1

                  ManagedConnectionPool:

                    Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool

                    Object: 277beead

                  ManagedConnectionFactory:

                    Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF

                    Object: 2adcc580

                  ConnectionManager:

                    Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl

                    Object: 2d369919

                  Pool:

                    Name: postgres-crm-ds

                    Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool

                    Object: 2e93c6bc

                    FIFO: false

                  PoolConfiguration:

                    MinSize: 1

                    InitialSize: 1

                    MaxSize: 400

                    BlockingTimeout: 30000

                    IdleTimeoutMinutes: 5

                    ValidateOnMatch: false

                    BackgroundValidation: false

                    BackgroundValidationMillis: 0

                    StrictMin: false

                    UseFastFail: false

                    Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer

                  Available (1):

                    73e03c5c (NORMAL) (Returned: 1484745702540) (Validated: 1484745693642) (Pool: 32)

                  InUse (13):

                    7c56eb55 (NORMAL) (CheckedOut: 1484745694652) (Validated: 1484745635169) (Usage: 7920)

                    520ecd7a (NORMAL) (CheckedOut: 1484745695719) (Validated: 1484745695719) (Usage: 6853)

                    e351b23 (NORMAL) (CheckedOut: 1484745696428) (Validated: 1484745696428) (Usage: 6144)

                    605cdf41 (NORMAL) (CheckedOut: 1484745696984) (Validated: 1484745696984) (Usage: 5588)

                    d41cdfc (NORMAL) (CheckedOut: 1484745697621) (Validated: 1484745697621) (Usage: 4951)

                    4e011821 (NORMAL) (CheckedOut: 1484745698226) (Validated: 1484745698226) (Usage: 4346)

                    24a5508f (NORMAL) (CheckedOut: 1484745698833) (Validated: 1484745698833) (Usage: 3739)

                    7c5148bc (NORMAL) (CheckedOut: 1484745699392) (Validated: 1484745699392) (Usage: 3180)

                    44ef5059 (NORMAL) (CheckedOut: 1484745700067) (Validated: 1484745700067) (Usage: 2505)

                    5f06f4c0 (NORMAL) (CheckedOut: 1484745700612) (Validated: 1484745700612) (Usage: 1960)

                    2bbbb53b (NORMAL) (CheckedOut: 1484745701128) (Validated: 1484745701128) (Usage: 1444)

                    6c5cd7b8 (NORMAL) (CheckedOut: 1484745701579) (Validated: 1484745701579) (Usage: 993)

                    53ecf26c (NORMAL) (CheckedOut: 1484745702102) (Validated: 1484745702102) (Usage: 470)

                  Statistics:

                    ActiveCount: 14

                    AvailableCount: 387

                    AverageBlockingTime: 1

                    AverageCreationTime: 83

                    AverageGetTime: 63

                    AveragePoolTime: 3299

                    AverageUsageTime: 682

                    BlockingFailureCount: 0

                    CreatedCount: 14

                    DestroyedCount: 0

                    IdleCount: 1

                    InUseCount: 13

                    MaxCreationTime: 988

                    MaxGetTime: 1043

                    MaxPoolTime: 29443

                    MaxUsageTime: 1911

                    MaxUsedCount: 14

                    MaxWaitTime: 1

                    TimedOut: 0

                    TotalBlockingTime: 2

                    TotalCreationTime: 1171

                    TotalGetTime: 1271

                    TotalPoolTime: 56094

                    TotalUsageTime: 12282

                    WaitCount: 0

                  XAResource:

                    CommitCount: 16

                    CommitTotalTime: 53

                    CommitAverageTime: 3

                    CommitMaxTime: 23

                    EndCount: 16

                    EndTotalTime: 0

                    EndAverageTime: 0

                    EndMaxTime: 0

                    ForgetCount: 0

                    ForgetTotalTime: 0

                    ForgetAverageTime: 0

                    ForgetMaxTime: 0

                    PrepareCount: 13

                    PrepareTotalTime: 22

                    PrepareAverageTime: 1

                    PrepareMaxTime: 6

                    RecoverCount: 0

                    RecoverTotalTime: 0

                    RecoverAverageTime: 0

                    RecoverMaxTime: 0

                    RollbackCount: 0

                    RollbackTotalTime: 0

                    RollbackAverageTime: 0

                    RollbackMaxTime: 0

                    StartCount: 29

                    StartTotalTime: 1

                    StartAverageTime: 0

                    StartMaxTime: 1

                   

                  === Success case (server-success-threadchange.log) ===

                  // For the first currency

                  // First, the connection 24df623d is taken out from the pool when entering the first @Local EJB

                  13:04:29,458 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 141) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@24df623d[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5d0aaa1a connection handles=0 lastReturned=1484744669419 lastValidated=1484744612662 lastCheckedOut=1484744669383 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163ec013 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@2cb8d805[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@5274e3ac[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5d0aaa1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null]

                   

                  // Later on, the connection 6e94df70 is aquired from the pool when entering the @Remote EJB (in a separate thread)

                  13:04:30,287 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-82) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e94df70[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@7455f601 connection handles=0 lastReturned=1484744669462 lastValidated=1484744669412 lastCheckedOut=1484744670287 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163ec013 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@2cb8d805[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@feeaadc[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@7455f601 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < jca-subordinate, BasicAction: 0:ffff0af6c016:665763b3:587f6791:36 status: ActionStatus.RUNNING >

                   

                  // The connection 6e94df70 is returned to the pool

                  13:04:31,426 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-108) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e94df70[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@7455f601 connection handles=0 lastReturned=1484744671426 lastValidated=1484744669412 lastCheckedOut=1484744670287 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163ec013 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@2cb8d805[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@feeaadc[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@7455f601 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null]

                   

                  // The connection 24df623d is returned to the pool

                  13:04:31,432 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 141) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@24df623d[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5d0aaa1a connection handles=0 lastReturned=1484744671432 lastValidated=1484744612662 lastCheckedOut=1484744669458 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@163ec013 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@2cb8d805[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@5274e3ac[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5d0aaa1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null]

                   

                  // This above pattern is repeated for the next 12 currencies

                   

                  // After all currencies has been iterated, the pool looks like this. The statistics says: "StartCount: 29" and "  CommitCount: 29"

                  13:04:37,731 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 141) getConnection(null, WrappedConnectionRequestInfo@2dfa2d40[userName=crm])

                  Method: getConnection(null, WrappedConnectionRequestInfo@2dfa2d40[userName=crm])

                    Subject: null

                    CRI: 2dfa2d40

                  ManagedConnectionPool:

                    Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool

                    Object: 2cb8d805

                  ManagedConnectionFactory:

                    Class: org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$WildFlyXaMCF

                    Object: 1f1cceb1

                  ConnectionManager:

                    Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl

                    Object: 63f0703f

                  Pool:

                    Name: postgres-crm-ds

                    Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool

                    Object: 163ec013

                    FIFO: false

                  PoolConfiguration:

                    MinSize: 1

                    InitialSize: 1

                    MaxSize: 400

                    BlockingTimeout: 30000

                    IdleTimeoutMinutes: 5

                    ValidateOnMatch: false

                    BackgroundValidation: false

                    BackgroundValidationMillis: 0

                    StrictMin: false

                    UseFastFail: false

                    Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer

                  Available (2):

                    6e94df70 (NORMAL) (Returned: 1484744677690) (Validated: 1484744669412) (Pool: 41)

                    24df623d (NORMAL) (Returned: 1484744677694) (Validated: 1484744612662) (Pool: 37)

                  InUse (0):

                  Statistics:

                    ActiveCount: 2

                    AvailableCount: 400

                    AverageBlockingTime: 0

                    AverageCreationTime: 365

                    AverageGetTime: 60

                    AveragePoolTime: 1821

                    AverageUsageTime: 660

                    BlockingFailureCount: 0

                    CreatedCount: 2

                    DestroyedCount: 0

                    IdleCount: 2

                    InUseCount: 0

                    MaxCreationTime: 715

                    MaxGetTime: 736

                    MaxPoolTime: 30299

                    MaxUsageTime: 3038

                    MaxUsedCount: 2

                    MaxWaitTime: 0

                    TimedOut: 0

                    TotalBlockingTime: 0

                    TotalCreationTime: 731

                    TotalGetTime: 786

                    TotalPoolTime: 52828

                    TotalUsageTime: 20469

                    WaitCount: 0

                  XAResource:

                    CommitCount: 29

                    CommitTotalTime: 31

                    CommitAverageTime: 1

                    CommitMaxTime: 5

                    EndCount: 29

                    EndTotalTime: 2

                    EndAverageTime: 0

                    EndMaxTime: 1

                    ForgetCount: 0

                    ForgetTotalTime: 0

                    ForgetAverageTime: 0

                    ForgetMaxTime: 0

                    PrepareCount: 26

                    PrepareTotalTime: 39

                    PrepareAverageTime: 1

                    PrepareMaxTime: 8

                    RecoverCount: 0

                    RecoverTotalTime: 0

                    RecoverAverageTime: 0

                    RecoverMaxTime: 0

                    RollbackCount: 0

                    RollbackTotalTime: 0

                    RollbackAverageTime: 0

                    RollbackMaxTime: 0

                    StartCount: 29

                    StartTotalTime: 1

                    StartAverageTime: 0

                    StartMaxTime: 1

                  • 6. Re: Transactions from @Remote annotated EJB sometimes not commited
                    tomjenkinson

                    I can see from the logs that one of the atomic actions that is not committed (and so holds on to the connection via XAResourceWrapperImpl@d2533cb):

                    0:ffff0af6c016:74c8ec99:587f6b90:36

                     

                    I can see the equivalent that passes is:

                    0:ffff0af6c016:665763b3:587f6791:36

                     

                    Basically this subordinate jca action is not told to prepare or commit, this does seem reminiscent of:

                    https://issues.jboss.org/browse/WFLY-7196

                     

                    What do you think flavia.rainone ?

                    • 7. Re: Transactions from @Remote annotated EJB sometimes not commited
                      flavia.rainone

                      Yes, it looks like it could be related to that bug.

                       

                      Is there a way I can get a reproducer of this?

                      • 8. Re: Transactions from @Remote annotated EJB sometimes not commited
                        hans.christian.goranson

                        Hi Flavia,

                         

                        Unfortunately not from my side. I can sometimes reproduce the issue in our environment but we have a rather big and old legacy application with a lot of modules.

                        I tried to reproduce the issue by building an smaller application that performing the same scenario and that could be deployed on a "clean" Wildfly but without any success.

                        • 9. Re: Transactions from @Remote annotated EJB sometimes not commited
                          tomjenkinson

                          You could try the CORBA addresses/JTS mode to workaround the issue.

                          • 10. Re: Transactions from @Remote annotated EJB sometimes not commited
                            tomjenkinson

                            flavia.rainone - what is happening with WFLY-7196 The outcome of xa_commit call on non exiting transaction is silently ignored by kurobako · Pull Request #9448 …  is there something hidden in the PR that is incorrect? Perhaps hans.christian.goranson could test with your PR to see if it resolves the issue?

                            • 11. Re: Transactions from @Remote annotated EJB sometimes not commited
                              ochaloup

                              Hi Hans-Christian,

                               

                              I spend a while to investigate what could be happening in your case but unfortunately I'm not able to hit the issue. I created a simple reproducer (ear ejb calls ear ejb) but there is not usage of subordinate transaction in my case.

                               

                              Three is one interesting point at your comment

                              // Later on, the connection 6e94df70 is aquired from the pool when entering the @Remote EJB (in a separate thread)

                              My understanding is that ejb in-vm calls (ejb calls inside of the app container even when happening over different ears) when they're not asynchronous should happen at the same thread. I'm not 100% sure with that but at least my reproducer confirms that.

                              May I ask how do you process the ejb lookup to the remote ejb? What is jndi lookup name that you use?

                               

                              Thanks

                              Ondra

                              • 12. Re: Transactions from @Remote annotated EJB sometimes not commited
                                hans.christian.goranson

                                Hi Ondra,

                                 

                                My @Remote annotated EJB is looks something like this (no @Asynchronous annotation used):

                                 

                                @Stateless
                                public class ProductPriceFacadeEJB extends BasePriceSessionBean implements ProductPriceFacadeRemote, ProductPriceFacade {

                                ...

                                @Override
                                public CurrencyPriceData findProductUnitPrice(int productNumber, String currencyCode, int amount)

                                   throws ProductNotFoundException, ProductPriceNotFoundException {

                                  OneProduct productEntity = OneProductFinderUtil.findProductByNumber(getEntityManager(), productNumber);
                                  return findProductUnitPrice(productEntity, currencyCode, amount);
                                }

                                ...

                                }

                                and the interface:

                                @Remote
                                public interface ProductPriceFacadeRemote extends BaseProductPriceFacade{}

                                 

                                The JNDI lookup is using the ejb namespace (Remote JNDI Reference - WildFly 10 - Project Documentation Editor ), eg:

                                  ejb:price/price-ejb-impl/ProductPriceFacadeEJB!com.price.ejb.session.ProductPriceFacadeRemote

                                 

                                BR

                                Hans-Christian

                                • 13. Re: Transactions from @Remote annotated EJB sometimes not commited
                                  ochaloup

                                  I see. Do you think you could change the JNDI name lookup from remote EJB one to local JNDI lookup (https://docs.jboss.org/author/display/WFLY10/JNDI+Reference)?

                                   

                                  In my case is for example change from

                                  ejb:test-ear/test-jar//JPAClientBean!org.jboss.test.JPAClientBeanRemote

                                  to

                                  java:global/test-ear/test-jar/JPAClientBean!org.jboss.test.JPAClientBeanRemote

                                   

                                  Two points that I have in my mind here

                                  • if you use remote EJB lookup there is no certainty that it will work with <jts/>. For JTS to work you should use OpenJDK IIOP lookup (which means using EJB2.x style of beans with Home interfaces etc.)
                                  • when you use remote EJB for a server to server communication you should define remote server to server connection. It means you should configure remote-outbound-connection (https://docs.jboss.org/author/display/WFLY10/EJB+invocations+from+a+remote+server+instance). From my experience, if you don't do so there is a risk that recovery manager won't work correctly.
                                    I'm not sure how you define connection info for the ejb:/ lookup, e.g. in my case when I used scoped context [1] for connection definition not all interceptors on a server to server remote EJB call was introduced and recovery procedures were not added to process. Of course, it could be a trouble later in case of failure.

                                   

                                  Still, I'm curious why I'm not able to hit the trouble with the JCA pool lock. But it's just an interest I hope that using java:global/ lookup could fix the issue.

                                   

                                  [1]

                                  System.setProperty("org.jboss.ejb.client.view.annotation.scan.enabled", "true");  // without this, CompressionHint for requests won't work
                                  Properties env = new Properties();
                                  env.put(Context.URL_PKG_PREFIXES, "org.jboss.ejb.client.naming");
                                  env.put("org.jboss.ejb.client.scoped.context", "true");
                                  env.put("endpoint.name", "client-endpoint");
                                  env.put("remote.connections", "main");
                                  env.put("remote.connection.main.host", "127.0.0.1");
                                  env.put("remote.connection.main.protocol", "http-remoting");
                                  env.put("remote.connection.main.port", Integer.toString(8080));
                                  env.put("remote.connection.main.connect.options.org.xnio.Options.SASL_POLICY_NOANONYMOUS", "false");
                                  env.put("remote.connection.main.connect.options.org.xnio.Options.SSL_STARTTLS", "true");
                                  env.put("remote.connection.main.connect.options.org.xnio.Options.SASL_POLICY_NOPLAINTEXT", "true");
                                  env.put("remote.connection.main.connect.options.org.xnio.Options.SSL_ENABLED", "false");
                                  env.put("remote.connection.main.username", "user1");
                                  env.put("remote.connection.main.password", "password1");
                                  env.put("remote.connection.main.connect.options.org.xnio.Options.SASL_DISALLOWED_MECHANISMS", "JBOSS-LOCAL-USER");
                                  final Context context = new InitialContext(env);
                                  String jndiLookupString = "ejb:" + deploymentName + "/" + deploymentName + "//" + JPAClientBean.class.getSimpleName() + "!" + JPAClientBeanRemote.class.getName();