Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-2879

App server could be stuck on shutdown when TM uses jdbc object store

    Details

      Description

      It seems that server could get stuck when TM is configured to use jdbc object store. During server shutdown, in case that jdbc connection is stopped before periodic recovery ends its work, then server is stuck and waits to recovery being finished. But recovery is just waiting for already stopped driver module and server hangs and kill -9 is needed.

      The server log then looks as pasted below.

      There was a similar issue JBEAP-1750 of the same effect but with different cause.

      2016-01-15 16:21:36,238 INFO  [org.wildfly.extension.undertow] (MSC 
      service thread 1-3) WFLYUT0019: Host default-host stopping
      2016-01-15 16:21:36,243 DEBUG 
      [org.hibernate.validator.internal.engine.ConfigurationImpl] (MSC service 
      thread 1-5) Setting custom MessageInterpolator of type 
      org.hibernate.validator.messageinterpolation.ResourceBundleMessageInterpolator
      2016-01-15 16:21:36,243 DEBUG 
      [org.hibernate.validator.internal.engine.ConfigurationImpl] (MSC service 
      thread 1-5) Setting custom TraversableResolver of type 
      org.hibernate.validator.internal.engine.resolver.DefaultTraversableResolver
      2016-01-15 16:21:36,243 DEBUG 
      [org.hibernate.validator.internal.engine.ConfigurationImpl] (MSC service 
      thread 1-5) Setting custom ParameterNameProvider of type 
      org.hibernate.validator.internal.engine.DefaultParameterNameProvider
      2016-01-15 16:21:36,280 ERROR [org.jboss.remoting.resource] (Remoting 
      "jbossts:MANAGEMENT" task-15) Close action for Channel ID 757fe114 
      (inbound) of Remoting connection 0905b5f8 to /127.0.0.1:53744 failed to 
      execute (resource may be left in an indeterminate state): 
      java.util.concurrent.RejectedExecutionException: XNIO007007: Thread is 
      terminating
          at org.xnio.nio.WorkerThread.execute(WorkerThread.java:588)
          at 
      org.jboss.remoting3.remote.RemoteConnection$RemoteWriteListener.send(RemoteConnection.java:311)
          at 
      org.jboss.remoting3.remote.RemoteConnection.send(RemoteConnection.java:122)
          at 
      org.jboss.remoting3.remote.RemoteConnectionChannel.closeReadsAndWrites(RemoteConnectionChannel.java:261)
          at 
      org.jboss.remoting3.remote.RemoteConnectionChannel.closeAction(RemoteConnectionChannel.java:534)
          at 
      org.jboss.remoting3.spi.AbstractHandleableCloseable.closeAsync(AbstractHandleableCloseable.java:372)
          at 
      org.jboss.remoting3.remote.RemoteConnectionHandler.closeAllChannels(RemoteConnectionHandler.java:437)
          at 
      org.jboss.remoting3.remote.RemoteConnectionHandler.handleConnectionClose(RemoteConnectionHandler.java:114)
          at 
      org.jboss.remoting3.remote.RemoteReadListener$1$1.run(RemoteReadListener.java:57)
          at 
      org.jboss.remoting3.EndpointImpl$TrackingExecutor$1.run(EndpointImpl.java:717)
          at 
      java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
          at 
      java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
          at java.lang.Thread.run(Thread.java:745)
      
      2016-01-15 16:21:36,295 INFO  [org.jboss.weld.deployer] (MSC service 
      thread 1-8) WFLYWELD0010: Stopping weld service for deployment 
      toolingtests.jar
      2016-01-15 16:21:36,344 INFO  [org.jboss.as.jpa] (ServerService Thread 
      Pool -- 72) WFLYJPA0011: Stopping Persistence Unit (phase 2 of 2) 
      Service 'toolingtests.jar#jbossts-crash-rec'
      2016-01-15 16:21:36,345 DEBUG 
      [org.hibernate.internal.SessionFactoryImpl] (ServerService Thread Pool 
      -- 72) HHH000031: Closing
      2016-01-15 16:21:36,348 DEBUG 
      [org.hibernate.service.internal.AbstractServiceRegistryImpl] 
      (ServerService Thread Pool -- 72) Implicitly destroying ServiceRegistry 
      on de-registration of all child ServiceRegistries
      2016-01-15 16:21:36,354 DEBUG 
      [org.hibernate.boot.registry.internal.BootstrapServiceRegistryImpl] 
      (ServerService Thread Pool -- 72) Implicitly destroying Boot-strap 
      registry on de-registration of all child ServiceRegistries
      2016-01-15 16:21:36,362 INFO 
      [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3) 
      WFLYJCA0010: Unbound data source [java:jboss/datasources/ExampleDS]
      2016-01-15 16:21:36,363 DEBUG 
      [org.hibernate.jpa.internal.EntityManagerFactoryRegistry] (ServerService 
      Thread Pool -- 72) Remove: name=toolingtests.jar#jbossts-crash-rec
      2016-01-15 16:21:36,374 INFO  [org.jboss.as.connector.deployers.jdbc] 
      (MSC service thread 1-7) WFLYJCA0019: Stopped Driver service with 
      driver-name = h2
      2016-01-15 16:21:36,374 INFO  [org.jboss.as.jpa] (ServerService Thread 
      Pool -- 72) WFLYJPA0011: Stopping Persistence Unit (phase 1 of 2) 
      Service 'toolingtests.jar#jbossts-crash-rec'
      2016-01-15 16:21:36,375 INFO  [org.wildfly.extension.messaging-activemq] 
      (MSC service thread 1-2) WFLYMSGAMQ0006: Unbound messaging object to 
      jndi name java:jboss/DefaultJMSConnectionFactory
      2016-01-15 16:21:36,377 INFO  [org.jboss.as.connector.deployment] (MSC 
      service thread 1-2) WFLYJCA0011: Unbound JCA ConnectionFactory [java:/JmsXA]
      2016-01-15 16:21:36,378 INFO 
      [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2) 
      WFLYJCA0010: Unbound data source [java:jboss/xa-datasources/CrashRecoveryDS]
      2016-01-15 16:21:36,420 INFO  [org.jboss.as.connector.deployers.jdbc] 
      (MSC service thread 1-6) WFLYJCA0019: Stopped Driver service with 
      driver-name = module_ojdbc7.jar
      2016-01-15 16:21:36,452 INFO  [org.jboss.as.clustering.infinispan] 
      (ServerService Thread Pool -- 72) WFLYCLINF0003: Stopped client-mappings 
      cache from ejb container
      2016-01-15 16:21:36,497 INFO  [org.jboss.as.server.deployment] (MSC 
      service thread 1-5) WFLYSRV0028: Stopped deployment toolingtests.jar 
      (runtime-name: toolingtests.jar) in 419ms
      2016-01-15 16:21:36,502 INFO  [org.apache.activemq.artemis.ra] 
      (ServerService Thread Pool -- 77) AMQ151003: resource adaptor stopped
      2016-01-15 16:21:36,514 INFO  [com.arjuna.ats.jbossatx] (MSC service 
      thread 1-1) ARJUNA032018: Destroying TransactionManagerService
      2016-01-15 16:21:36,518 INFO  [com.arjuna.ats.jbossatx] (MSC service 
      thread 1-6) ARJUNA032014: Stopping transaction recovery manager
      2016-01-15 16:21:36,552 DEBUG [com.arjuna.ats.arjuna] (Listener:4712) 
      Recovery listener existing 
      com.arjuna.ats.internal.arjuna.recovery.WorkerService
      2016-01-15 16:21:36,553 DEBUG [com.arjuna.ats.arjuna] (MSC service 
      thread 1-6) PeriodicRecovery: Mode <== TERMINATED
      2016-01-15 16:21:36,553 DEBUG [com.arjuna.ats.arjuna] (MSC service 
      thread 1-6) PeriodicRecovery: shutdown waiting for scan to end
      2016-01-15 16:21:36,620 INFO  [org.apache.activemq.artemis.core.server] 
      (ServerService Thread Pool -- 77) AMQ221002: Apache ActiveMQ Artemis 
      Message Broker version 1.1.0.redhat-5 
      [f31912a0-bbcb-11e5-82b2-0d8ac8338465] stopped
      2016-01-15 16:21:36,623 INFO  [org.wildfly.extension.undertow] (MSC 
      service thread 1-7) WFLYUT0008: Undertow HTTP listener default suspending
      2016-01-15 16:21:36,625 INFO  [org.wildfly.extension.undertow] (MSC 
      service thread 1-7) WFLYUT0007: Undertow HTTP listener default stopped, 
      was bound to 127.0.0.1:8080
      2016-01-15 16:21:36,628 INFO  [org.wildfly.extension.undertow] (MSC 
      service thread 1-2) WFLYUT0004: Undertow 1.3.12.Final-redhat-1 stopping
      2016-01-15 16:21:50,811 TRACE [com.arjuna.ats.arjuna] (Periodic 
      Recovery) OutputObjectState::OutputObjectState()
      2016-01-15 16:21:50,811 WARN  [com.arjuna.ats.arjuna] (Periodic 
      Recovery) ARJUNA012251: allObjUids caught exception: 
      java.lang.IllegalStateException
          at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
          at 
      org.jboss.as.naming.service.DefaultNamespaceContextSelectorService$1.getContext(DefaultNamespaceContextSelectorService.java:56)
          at 
      org.jboss.as.naming.InitialContext$DefaultInitialContext.findContext(InitialContext.java:187)
          at 
      org.jboss.as.naming.InitialContext$DefaultInitialContext.lookup(InitialContext.java:233)
          at org.jboss.as.naming.NamingContext.lookup(NamingContext.java:193)
          at org.jboss.as.naming.NamingContext.lookup(NamingContext.java:189)
          at javax.naming.InitialContext.lookup(InitialContext.java:417)
          at javax.naming.InitialContext.lookup(InitialContext.java:417)
          at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DataSourceJDBCAccess.getConnection(DataSourceJDBCAccess.java:53)
          at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.allObjUids(JDBCImple_driver.java:347)
          at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:166)
          at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.allObjUids(JDBCStore.java:122)
          at 
      com.arjuna.ats.internal.jta.recovery.arjunacore.CommitMarkableResourceRecordRecoveryModule.periodicWorkSecondPass(CommitMarkableResourceRecordRecoveryModule.java:462)
          at 
      com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793)
          at 
      com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375)
      
      2016-01-15 16:21:50,812 WARN  [com.arjuna.ats.arjuna] (Periodic 
      Recovery) Could not read data from object store
      2016-01-15 16:21:50,812 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
      2016-01-15 16:21:50,812 DEBUG [com.arjuna.ats.arjuna] (Periodic 
      Recovery) AtomicActionRecoveryModule second pass
      2016-01-15 16:21:50,812 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)
      2016-01-15 16:21:50,813 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) 
      TORecoveryModule - second pass
      2016-01-15 16:21:50,814 ERROR [stderr] (Periodic Recovery) Exception in 
      thread "Periodic Recovery" java.lang.IllegalStateException
      2016-01-15 16:21:50,815 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47)
      2016-01-15 16:21:50,815 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.as.naming.service.DefaultNamespaceContextSelectorService$1.getContext(DefaultNamespaceContextSelectorService.java:56)
      2016-01-15 16:21:50,815 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.as.naming.InitialContext$DefaultInitialContext.findContext(InitialContext.java:187)
      2016-01-15 16:21:50,816 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.as.naming.InitialContext$DefaultInitialContext.lookup(InitialContext.java:233)
      2016-01-15 16:21:50,816 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.as.naming.NamingContext.lookup(NamingContext.java:193)
      2016-01-15 16:21:50,816 ERROR [stderr] (Periodic Recovery)     at 
      org.jboss.as.naming.NamingContext.lookup(NamingContext.java:189)
      2016-01-15 16:21:50,817 ERROR [stderr] (Periodic Recovery)     at 
      javax.naming.InitialContext.lookup(InitialContext.java:417)
      2016-01-15 16:21:50,817 ERROR [stderr] (Periodic Recovery)     at 
      javax.naming.InitialContext.lookup(InitialContext.java:417)
      2016-01-15 16:21:50,817 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.accessors.DataSourceJDBCAccess.getConnection(DataSourceJDBCAccess.java:53)
      2016-01-15 16:21:50,817 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCImple_driver.currentState(JDBCImple_driver.java:250)
      2016-01-15 16:21:50,818 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.arjuna.objectstore.jdbc.JDBCStore.currentState(JDBCStore.java:138)
      2016-01-15 16:21:50,818 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.txoj.recovery.TORecoveryModule.periodicWorkSecondPass(TORecoveryModule.java:181)
      2016-01-15 16:21:50,818 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:793)
      2016-01-15 16:21:50,819 ERROR [stderr] (Periodic Recovery)     at 
      com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:375)
      2016-01-15 16:26:04,508 TRACE [com.arjuna.ats.arjuna] (Transaction 
      Reaper) ReaperThread.run ()
      2016-01-15 16:26:04,508 TRACE [com.arjuna.ats.arjuna] (Transaction 
      Reaper) TransactionReaper::check ()
      2016-01-15 16:26:04,509 TRACE [com.arjuna.ats.arjuna] (Transaction 
      Reaper) TransactionReaper::check - comparing 1452893164508
      2016-01-15 16:26:04,509 TRACE [com.arjuna.ats.arjuna] (Transaction 
      Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 
      9223370583961611298
      

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  tomjenkinson Thomas Jenkinson
                  Reporter:
                  ochaloup Ondrej Chaloupka
                  Tester:
                  Ondrej Chaloupka
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: