1 Reply Latest reply on Feb 21, 2012 9:18 AM by Jesper Pedersen

    Install phase error due to IllegalStateException.

    Jeremy Whiting Expert

      Hi,

      I have a JEE 5 specification application. Deployed without problem and running fine during a benchmark run. During a run I needed to shutdown AS7. This is a typical server crash scenario.

       

      I am seeing a problem with the INSTALL phase of the application when starting up AS7. The application deployment configuration uses XA aware datasources and JMS connection factories.

      There were global transactions in flight during the benchmark run. As you would exect there are durable action store records for crash recovery which is great. But the application is prevented from completing the INSTALL phase when AS7 is started again.

       

      I am using a Postgresql database and I am aware the XAResource not serializable and the consequences of that. See: https://community.jboss.org/wiki/TxNonSerializableXAResource

       

      For this crash scenario my expectation is the application should INSTALL successfully and be available to service requests. Despite the fact an XAResource could not be found for the RecoveryManager to terminate the transaction. The lack of the serializable XAResource shouldn't (I think) prevent normal operation resuming when the application server starts again.

       

      There are several components in AS7 at play here. The JCA cached connection manager and TS deployment integration. They both are expecting to work with an InjectedValue (XAResource) but the state of the object is illegal. Probably because it cannot be deserialized.

       

      This is the INSTALL error when I start up AS7.1 Final

       

       

      11:25:43,789 ERROR [org.jboss.as.txn] (MSC service thread 1-2) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException

          at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)

          at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:43)

          at org.jboss.as.webservices.deployers.AspectDeploymentProcessor.deploy(AspectDeploymentProcessor.java:85) [jboss-as-webservices-server-integration-7.1.0.Final.jar:7.1.0.Final]

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:113)

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811)

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746)

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.6.0_24]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.6.0_24]

          at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]

       

      11:25:43,794 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-2) MSC00001: Failed to start service jboss.deployment.subunit."specj.ear"."supplier.war".INSTALL: org.jboss.msc.service.StartException in service jboss.deployment.subunit."specj.ear"."supplier.war".INSTALL: Failed to process phase INSTALL of subdeployment "supplier.war" of deployment "specj.ear"

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:119) [jboss-as-server-7.1.0.Final.jar:7.1.0.Final]

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.6.0_24]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.6.0_24]

          at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]

      Caused by: java.lang.IllegalStateException

          at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction.teardown(CachedConnectionManagerSetupProcessor.java:83)

          at org.jboss.as.webservices.deployers.AspectDeploymentProcessor.deploy(AspectDeploymentProcessor.java:85)

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:113) [jboss-as-server-7.1.0.Final.jar:7.1.0.Final]

          ... 5 more

       

      11:25:44,298 ERROR [org.jboss.as.txn] (MSC service thread 1-1) JBAS010151: Unable to get transaction state: java.lang.IllegalStateException

          at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)

          at org.jboss.as.txn.deployment.TransactionRollbackSetupAction.teardown(TransactionRollbackSetupAction.java:43)

          at org.jboss.as.webservices.deployers.AspectDeploymentProcessor.deploy(AspectDeploymentProcessor.java:85) [jboss-as-webservices-server-integration-7.1.0.Final.jar:7.1.0.Final]

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:113)

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811)

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746)

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.6.0_24]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.6.0_24]

          at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]

       

      11:25:44,337 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC00001: Failed to start service jboss.deployment.subunit."specj.ear"."specj.jar".INSTALL: org.jboss.msc.service.StartException in service jboss.deployment.subunit."specj.ear"."specj.jar".INSTALL: Failed to process phase INSTALL of subdeployment "specj.jar" of deployment "specj.ear"

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:119) [jboss-as-server-7.1.0.Final.jar:7.1.0.Final]

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [rt.jar:1.6.0_24]

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) [rt.jar:1.6.0_24]

          at java.lang.Thread.run(Thread.java:679) [rt.jar:1.6.0_24]

      Caused by: java.lang.IllegalStateException

          at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]

          at org.jboss.as.connector.deployers.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction.teardown(CachedConnectionManagerSetupProcessor.java:83)

          at org.jboss.as.webservices.deployers.AspectDeploymentProcessor.deploy(AspectDeploymentProcessor.java:85)

          at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:113) [jboss-as-server-7.1.0.Final.jar:7.1.0.Final]

          ... 5 more

       

       

      At the end of server startup this is the summary provided by AS7

       

       

      JBAS014777:   Services which failed to start:      service jboss.deployment.subunit."specj.ear"."specj.jar".INSTALL: org.jboss.msc.service.StartException in service jboss.deployment.subunit."specj.ear"."specj.jar".INSTALL: Failed to process phase INSTALL of subdeployment "specj.jar" of deployment "specj.ear"

            service jboss.deployment.subunit."emulator.ear"."emulator.war".INSTALL: org.jboss.msc.service.StartException in service jboss.deployment.subunit."emulator.ear"."emulator.war".INSTALL: Failed to process phase INSTALL of subdeployment "emulator.war" of deployment "emulator.ear"

            service jboss.deployment.subunit."specj.ear"."supplier.war".INSTALL: org.jboss.msc.service.StartException in service jboss.deployment.subunit."specj.ear"."supplier.war".INSTALL: Failed to process phase INSTALL of subdeployment "supplier.war" of deployment "specj.ear"

       

      After a while I see a few of these which is the Recovery Manager attepting to terminate the transaction. I am not concerned about these. I can simple restart the benchmark run.

       

       

      11:28:09,473 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5c0, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5cc, subordinatenodename=null, eis_name=java:/jdbc/SPECjSupplierDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjSupplierDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@29db197 >

      11:28:09,565 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5ff, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:617, subordinatenodename=null, eis_name=java:/jdbc/SPECjSupplierDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjSupplierDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3ef631d8 >

      11:28:09,657 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:2be, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:2e9, subordinatenodename=null, eis_name=java:/jdbc/SPECjSupplierDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjSupplierDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@15427c33 >

      11:28:09,750 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5ec, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5f5, subordinatenodename=null, eis_name=java:/jdbc/SPECjOrderDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjOrderDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@19285e7b >

      11:28:09,826 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:4d3, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:5e2, subordinatenodename=null, eis_name=java:/jdbc/SPECjMfgDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjMfgDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@2952ea24 >

      11:28:09,893 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:6e6, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:6f1, subordinatenodename=null, eis_name=java:/jdbc/SPECjOrderDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjOrderDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@289f6ae >

      11:28:09,969 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:202, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:210, subordinatenodename=null, eis_name=java:/jdbc/SPECjMfgDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjMfgDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3b8e2477 >

      11:28:10,044 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:303, node_name=1, branch_uid=0:ffff0a441042:7bb9ff29:4f40cd8c:30e, subordinatenodename=null, eis_name=java:/jdbc/SPECjOrderDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: PostgreSQL/9.1.2, jndiName: java:/jdbc/SPECjOrderDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@70fc1f2c >

       

      Do you think my expectation state above is unrealistic or is this an issue that needs to be raised as a JIRA ?

       

      Regards,

      Jeremy