1014283 – csprocessor push fails with ClientResponseFailure

Bug 1014283 - csprocessor push fails with ClientResponseFailure

Summary: csprocessor push fails with ClientResponseFailure

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	PressGang CCMS
Classification:	Community
Component:	CSProcessor
Sub Component:
Version:	1.1
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	---
Target Release:	---
Assignee:	pressgang-ccms-dev
QA Contact:
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1013825
TreeView+	depends on / blocked

Reported:	2013-10-01 15:49 UTC by Stephen Gordon
Modified:	2014-02-23 23:40 UTC (History)
CC List:	2 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2014-02-23 23:40:25 UTC

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Comment 2 Matthew Casperson 2013-10-01 21:16:08 UTC

There appears to have been an issue with transactions on the server.

00:52:30,607 INFO  [org.jboss.pressgang.ccms.contentspec.processor.CustomContentSpecProcessor] (http--0.0.0.0-8180-21) Starting first validation pass...
00:52:30,966 INFO  [org.jboss.pressgang.ccms.contentspec.processor.CustomContentSpecProcessor] (http--0.0.0.0-8180-21) Starting second validation pass...
00:54:48,900 INFO  [org.jboss.pressgang.ccms.contentspec.processor.CustomContentSpecProcessor] (http--0.0.0.0-8180-21) Starting bug link validation pass...
00:54:51,093 INFO  [org.jboss.pressgang.ccms.contentspec.processor.ContentSpecProcessor] (http--0.0.0.0-8180-21) The Content Specification is valid.
00:54:51,094 INFO  [org.jboss.pressgang.ccms.contentspec.processor.CustomContentSpecProcessor] (http--0.0.0.0-8180-21) Saving the Content Specification to the server...
00:56:06,373 INFO  [org.jboss.pressgang.ccms.contentspec.processor.ContentSpecProcessor] (http--0.0.0.0-8180-21) The Content Specification saved successfully.
00:57:30,517 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a400e22:-263959d8:5248862f:3a12 in state  RUN
00:57:30,544 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff0a400e22:-263959d8:5248862f:3a12 invoked while multiple threads active within it.
00:57:30,579 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff0a400e22:-263959d8:5248862f:3a12 aborting with 1 threads active!
00:57:31,021 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a400e22:-263959d8:5248862f:3a12 in state  CANCEL
00:57:31,528 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a400e22:-263959d8:5248862f:3a12 in state  CANCEL_INTERRUPTED
00:57:31,533 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffff0a400e22:-263959d8:5248862f:3a12 -- worker marked as zombie and TX scheduled for mark-as-rollback
00:57:31,538 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffff0a400e22:-263959d8:5248862f:3a12 as rollback only
00:57:37,724 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (http--0.0.0.0-8180-21) SQL Error: 0, SQLState: null
00:57:37,725 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (http--0.0.0.0-8180-21) javax.resource.ResourceException: IJ000460: Error checking for a transaction
00:57:37,754 WARN  [com.arjuna.ats.arjuna] (http--0.0.0.0-8180-21) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0a400e22:-263959d8:5248862f:3a13, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@63702960 >: org.hibernate.exception.GenericJDBCException: Could not open connection
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:52) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:304) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at com.sun.proxy.$Proxy122.prepareStatement(Unknown Source)
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:144) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:127) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.getBatchStatement(BatchingBatch.java:69) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2827) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3290) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:80) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:272) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:264) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:186) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:326) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:59) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1053) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1108) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.strategy.ValidityAuditStrategy.perform(ValidityAuditStrategy.java:76) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.work.AbstractAuditWorkUnit.perform(AbstractAuditWorkUnit.java:76) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.AuditProcess.executeInSession(AuditProcess.java:115) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.AuditProcess.doBeforeTransactionCompletion(AuditProcess.java:154) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue$BeforeTransactionCompletionProcessQueue.beforeTransactionCompletion(ActionQueue.java:566) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.beforeTransactionCompletion(ActionQueue.java:218) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:510) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:113) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:53) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:273)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:93)
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117)
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.createOrUpdateJSONContentSpecFromString(BaseRESTv1.java:1233) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.createOrUpdateJSONContentSpecFromString(BaseRESTv1.java:1143) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.updateJSONContentSpecFromString(BaseRESTv1.java:1079) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.RESTv1.updateJSONTextContentSpec(RESTv1.java:2587) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.RESTv1$Proxy$_$$_WeldClientProxy.updateJSONTextContentSpec(RESTv1$Proxy$_$$_WeldClientProxy.java) [classes:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
	at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:155) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.2.Final.jar:]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:1.0.0.Final]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.weld.servlet.ConversationPropagationFilter.doFilter(ConversationPropagationFilter.java:62) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:206) [javamelody-core-1.44.0.jar:1.44.0]
	at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:179) [javamelody-core-1.44.0.jar:1.44.0]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.pressgang.ccms.server.servlet.filter.GZIPCompressionFilter.doFilter(GZIPCompressionFilter.java:85) [classes:]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.1.1.Final.jar:7.1.1.Final]
	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.13.Final.jar:]
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.13.Final.jar:]
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.13.Final.jar:]
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]
	at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:137)
	at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:67) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	... 79 more
Caused by: javax.resource.ResourceException: IJ000460: Error checking for a transaction
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:362)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:464)
	at sun.reflect.GeneratedMethodAccessor53.invoke(Unknown Source) [:1.7.0_25]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
	at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
	at net.bull.javamelody.JdbcWrapper$ConnectionManagerInvocationHandler.invoke(JdbcWrapper.java:226) [javamelody-core-1.44.0.jar:1.44.0]
	at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:271) [javamelody-core-1.44.0.jar:1.44.0]
	at com.sun.proxy.$Proxy103.allocateConnection(Unknown Source)
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
	... 82 more
Caused by: javax.resource.ResourceException: IJ000459: Transaction is not active: tx=TransactionImple < ac, BasicAction: 0:ffff0a400e22:-263959d8:5248862f:3a12 status: ActionStatus.ABORTED >
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:352)
	... 90 more

00:57:37,904 WARN  [com.arjuna.ats.arjuna] (http--0.0.0.0-8180-21) ARJUNA012077: Abort called on already aborted atomic action 0:ffff0a400e22:-263959d8:5248862f:3a12
00:57:37,918 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012113: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] missed interrupt when cancelling TX 0:ffff0a400e22:-263959d8:5248862f:3a12 -- exiting as zombie (zombie count decremented to 0)
00:57:37,918 ERROR [org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1] (http--0.0.0.0-8180-21) Failed to process REST request: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1177)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117)
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.createOrUpdateJSONContentSpecFromString(BaseRESTv1.java:1233) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.createOrUpdateJSONContentSpecFromString(BaseRESTv1.java:1143) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.base.BaseRESTv1.updateJSONContentSpecFromString(BaseRESTv1.java:1079) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.RESTv1.updateJSONTextContentSpec(RESTv1.java:2587) [classes:]
	at org.jboss.pressgang.ccms.server.rest.v1.RESTv1$Proxy$_$$_WeldClientProxy.updateJSONTextContentSpec(RESTv1$Proxy$_$$_WeldClientProxy.java) [classes:]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_25]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_25]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
	at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:155) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.2.Final.jar:]
	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.2.Final.jar:]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:1.0.0.Final]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.weld.servlet.ConversationPropagationFilter.doFilter(ConversationPropagationFilter.java:62) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:206) [javamelody-core-1.44.0.jar:1.44.0]
	at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:179) [javamelody-core-1.44.0.jar:1.44.0]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.pressgang.ccms.server.servlet.filter.GZIPCompressionFilter.doFilter(GZIPCompressionFilter.java:85) [classes:]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.13.Final.jar:]
	at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.1.1.Final.jar:7.1.1.Final]
	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.13.Final.jar:]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.13.Final.jar:]
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.13.Final.jar:]
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.13.Final.jar:]
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]
	at java.lang.Thread.run(Thread.java:724) [rt.jar:1.7.0_25]
Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:52) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:304) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at com.sun.proxy.$Proxy122.prepareStatement(Unknown Source)
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.buildBatchStatement(AbstractBatchImpl.java:144) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.getBatchStatement(AbstractBatchImpl.java:127) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.getBatchStatement(BatchingBatch.java:69) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2827) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3290) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:80) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:272) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:264) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:186) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:326) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:59) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1053) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1108) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.strategy.ValidityAuditStrategy.perform(ValidityAuditStrategy.java:76) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.work.AbstractAuditWorkUnit.perform(AbstractAuditWorkUnit.java:76) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.AuditProcess.executeInSession(AuditProcess.java:115) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.envers.synchronization.AuditProcess.doBeforeTransactionCompletion(AuditProcess.java:154) [hibernate-envers-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue$BeforeTransactionCompletionProcessQueue.beforeTransactionCompletion(ActionQueue.java:566) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.spi.ActionQueue.beforeTransactionCompletion(ActionQueue.java:218) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:510) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:113) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion(RegisteredSynchronization.java:53) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:273)
	at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:93)
	at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:164)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1165)
	... 46 more
Caused by: java.sql.SQLException: javax.resource.ResourceException: IJ000460: Error checking for a transaction
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:137)
	at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:67) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:276) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
	... 79 more
Caused by: javax.resource.ResourceException: IJ000460: Error checking for a transaction
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:362)
	at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:464)
	at sun.reflect.GeneratedMethodAccessor53.invoke(Unknown Source) [:1.7.0_25]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_25]
	at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_25]
	at net.bull.javamelody.JdbcWrapper$ConnectionManagerInvocationHandler.invoke(JdbcWrapper.java:226) [javamelody-core-1.44.0.jar:1.44.0]
	at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:271) [javamelody-core-1.44.0.jar:1.44.0]
	at com.sun.proxy.$Proxy103.allocateConnection(Unknown Source)
	at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:129)
	... 82 more
Caused by: javax.resource.ResourceException: IJ000459: Transaction is not active: tx=TransactionImple < ac, BasicAction: 0:ffff0a400e22:-263959d8:5248862f:3a12 status: ActionStatus.ABORTED >
	at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:352)
	... 90 more

Comment 3 Matthew Casperson 2013-10-01 21:16:59 UTC

Rebooted server and tested an edit to a large spec. Is working ok now.

Comment 4 Matthew Casperson 2013-10-01 21:35:00 UTC

Specs are taking a while to process through:

steveg> Saving to the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> Waiting for a response from the server...
8<steveg> ^CWaiting for a response from the server...
8<steveg> WARN:  Line 0: The Content Specification has revision topics which can't have tags added, so the tags will be ignored for those topics.
8<steveg>        ->  [RHOS 4.0, Writer = Unknown]
8<steveg> INFO:  The Content Specification is valid.
8<steveg> INFO:  The Content Specification saved successfully.
8<steveg> Content Specification ID: 15807
8<steveg> Revision: 542381

Comment 5 Matthew Casperson 2013-10-01 21:56:13 UTC

From the looks of the log, it took over 5 minutes to process the spec. This is possibly due to other background processes running at the same time. This caused a transaction timeout, which then prevented any changes from being saved.

I have increased the timeout and added a connection validation checker to the server config.

Comment 6 Lee Newson 2013-10-01 22:51:27 UTC

There is no reason why that spec should take that long to process as far as I can see (it only has about 400 nodes), so there is likely something wrong in the processing.

Also updating just those values will make no difference to the reason a 502 error is being returned, as that is caused by the HTTP timeout which is currently set at 3 mins (note the 18 waiting messages in the first comment). In saying that though it will help to mitigate the Transaction reaper activating.

Comment 7 Matthew Casperson 2013-10-02 23:19:29 UTC

This may have been related to an issue that came up this morning with JavaMelody. The full explaination is documented at http://stackoverflow.com/questions/19147762/javamelody-crashing-the-server-with-thousands-of-rrd-files/19147763#19147763, but the short story is that JavaMelody needs some special configuration when used to monitor a REST API.

We have disabled JavaMelody for now on the production server, with an eye to aggregating the files (currently in testing on the dev server). We'll see if this has any impact on the performance issues and timeouts.

Comment 8 Matthew Casperson 2013-10-02 23:30:01 UTC

Added the settings

    <context-param>
        <param-name>javamelody.http-transform-pattern</param-name>
        <param-value>(?&lt;=/rest/).*</param-value>
    </context-param>

    <context-param>
        <param-name>javamelody.sql-transform-pattern</param-name>
        <param-value>.*</param-value>
    </context-param>

This results in 32 files being created in /tmp/javamelody after a couple of topic and spec edits. 

Prior to that, just booting the REST server resulted in over 100 files being created, and that number quickly grew to over 1000.

I'll do some more testing on the dev server to make sure these settings don't have any other side effects, but it looks like they will fix the problem.

Comment 9 Matthew Casperson 2013-10-03 05:05:11 UTC

Ok, we're still having problems with JavaMelody disabled. So this looks like an issue with open file limits, like in https://community.jboss.org/thread/213611?start=0&tstart=0.

The open file limit has been increased to 4096.

Comment 10 Lee Newson 2013-10-03 06:43:02 UTC

The cause of exceeding the file limit was the way the REST API version was being retrieved. The version was being retrieved from a value set in mainfest.mf at compile time and then added as a HTTP Header to all responses during runtime. The problem here is that it was doing this for every request and due to a bug where the InputStream that opened the manifest.mf was not being closed, a lot of file handles were being left open until the Garbage collector ran.

As such I've done two things to fix that issue. The first is to ensure that the InputStream is closed and the second is to cache the version so that it doesn't have to keep being looked up all the time.

Comment 11 Matthew Casperson 2013-10-08 03:19:30 UTC

Hours apply to 2013-10-01

Comment 14 Lee Newson 2014-02-23 23:40:25 UTC

Marking as closed as this should have been fixed some time ago. If the issue arises again please reopen this bug.

Note You need to log in before you can comment on or make changes to this bug.