Details
-
Bug
-
Resolution: Done
-
Major
-
7.0.0.ER4
-
None
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
Attachments
Issue Links
- is blocked by
-
JBEAP-3014 Upgrade Narayana to 5.2.13.Final
-
- Closed
-
-
JBTM-2609 Make JDBCStore able to handle Java EE errors interfacing with a datasource in an app server
-
- Closed
-
- is related to
-
-
- Closed
-
