New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Could not roll back Hibernate transaction / Unable to rollback against JDBC Connection #4302

Closed
mlamutt opened this Issue Dec 11, 2018 · 2 comments

Comments

Projects
None yet
4 participants
@mlamutt
Copy link

mlamutt commented Dec 11, 2018

Describe the bug
We have a long running job (60 minutes total, 54 minutes longest step), that was working without issues until we migrated to a mysql DB. Both steps still complete OK with status codes of 0 and then the job fails with the following error:

"Exception while executing step [2]: [org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]

15:57:09 |   |   | Exception while executing step [2]: [java.lang.RuntimeException: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]
15:57:09 |   |   | Execution failed: 7205 in project Linux: [Workflow result: , step failures: {2=Unknown: Exception while executing step [2]: [java.lang.RuntimeException: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]}, Node failures: {XXXXXXXXXXXXX=[]}, status: failed]

I have replicated the issue on multiple servers (dev and prod) connecting to different back end DBs

My Rundeck detail

  • Rundeck version: 3.0.8-20181029
  • install type: war
  • OS Name/version: Windows 2012R2
  • DB Type/version: mysql 5.7.23-23-log Percona Server release 23 rev 500fcf5

To Reproduce
Steps to reproduce the behavior:

  1. Go to a long running job
  2. Once the job succeeds on both steps the Job fails
  3. click on Log Output
  4. Scroll to bottom to view error

Expected behavior
Job successfully closes after both steps succeed.

Screenshots
If applicable, add screenshots to help explain your problem.
image

image

full error message:

  • exit 0
    Exception while executing step [2]: [org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]
    Exception while executing step [2]: [java.lang.RuntimeException: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]
    Execution failed: 7205 in project Linux: [Workflow result: , step failures: {2=Unknown: Exception while executing step [2]: [java.lang.RuntimeException: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection]}, Node failures: {XXXXXXXXXXXXXXX.net=[]}, status: failed]

Additional context
I have tried several datasource options in teh rundeck-config.properties file without any change:
dataSource.url = jdbc:mysql://servername.dev.local:3306/rundeck?autoReconnectForPools=true&useSSL=false
dataSource.username=XXXX
dataSource.password=XXXXXX
dataSource.driverClassName=com.mysql.jdbc.Driver

address timeout issues #3994

dataSource.pooled=true
dataSource.properties.removeAbandoned=true
dataSource.properties.removeAbandonedTimeout=18000
dataSource.properties.testOnBorrow=true
dataSource.properties.logAbandoned=true
dataSource.properties.maxActive=3000

Enables DB for Project configuration storage

rundeck.projectsStorageType=db

Enable DB for Key Storage

rundeck.storage.provider.1.type=db
rundeck.storage.provider.1.path=keys

Encryption for Key Storage

rundeck.storage.converter.1.type=jasypt-encryption
rundeck.storage.converter.1.path=keys
rundeck.storage.converter.1.config.password=XXXXXXXXX

This jobs had no issues when I was sing the h2 datasource, but has failed since changing to mysql.:
dataSource.url = jdbc:h2:file:C:/rundeck/server/data/grailsdb;MVCC=true

Thanks in advance for any help.

@shlomosh

This comment has been minimized.

Copy link

shlomosh commented Dec 13, 2018

I am not sure if related but on Rundeck 3.0.8 w/ MySQL. I get from time-to-time the following -

2018-12-12 08:19:54.039  WARN --- [l-9865-thread-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 1205, SQLState: 40001
2018-12-12 08:19:54.039 ERROR --- [l-9865-thread-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : Lock wait timeout exceeded; try restarting transaction
2018-12-12 08:19:54.039 ERROR --- [l-9865-thread-1] rundeck.services.ExecutionService        : Caught ConcurrencyFailureException, will retry updateScheduledExecStatistics for jobref
2018-12-12 08:20:43.864 ERROR --- [eduler_Worker-2] rundeck.services.ExecutionUtilService    : Execution failed: 130726 in project bxx: [Workflow result: , step failures: {3=Unknown: Exception while executing step [3]:      [java.lang.RuntimeException: org.springframework.dao.CannotAcquireLockException: Hibernate operation: could not execute statement; SQL [n/a]; Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction]}, flow control: Continue, status: failed]
@shields478

This comment has been minimized.

Copy link

shields478 commented Jan 9, 2019

I am also seeing a similar error when running a job that consists of 2 Job Reference steps. The error does not always occur when the job runs long. The log output below was from a job where the 2 steps finished successfully in less than 2 minutes. The job continued to run for another ~30 minutes before failing with the Failed dispatching to node XXX: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection error.
When the jobs that are referenced are run individually, there is no error.

Rundeck detail
Rundeck version: 3.0.9
Install type: war
OS: Centos 7.5
DB: MS SQL

These logs begin from when the workflow step finished:

1: Workflow step finished, result: Dispatch successful (1 nodes) [workflow] Finish step: 1,NodeDispatch OperationSuccess: operation succeeded: StepSuccess{stepNum=1, stepResultCapture=StepResultCapture{stepResult=Dispatch successful (1 nodes), stepSuccess=true, statusString='null', controlBehavior=Dispatch successful (1 nodes), resultData=MultiDataContextImpl(map={ContextView(node:XXX)=BaseDataContext{{exec={exitCode=0}}}, ContextView(step:1, node:XXX)=BaseDataContext{{exec={exitCode=0}}}}, base=null)}, newState=DataState{state={step.label.Deploy01.state=success, step.1.completed=true, step.label.Deploy01.completed=true, step.any.state.success=true, before.step.1=false, step.1.state=success, after.step.1=true}}} WillProcessStateChange: saw state changes: {step.label.Deploy01.state=success, step.1.completed=true, step.label.Deploy01.completed=true, step.any.state.success=true, before.step.1=false, step.1.state=success, after.step.1=true} Update conditional state: {step.label.Deploy01.state=success, step.1.completed=true, step.label.Deploy01.completed=true, step.any.state.success=true, before.step.1=false, step.1.state=success, after.step.1=true} Update conditional state: {step.1.start=true} DidProcessStateChange: applied state changes and rules (changed? true): StateLogger{state=DataState{state={job.url=XXX, job.id=0ccf8551-9d57-462e-948e-1aa74a37b6f7, job.loglevel=DEBUG, step.any.state.success=true, node.os-name=, after.step.1=true, workflow.state=started, job.retryInitialExecId=0, node.hostname=XXX, node.os-family=Unknown OS, job.user.name=XXX, node.tags=XXX, node.description=, node.username=, job.name=Deploy01, step.1.state=success, job.successOnEmptyNodeFilter=false, job.executionType=user, job.filter=name: XXX, step.1.completed=true, step.label.Deploy01.completed=true, job.wasRetry=false, job.project=XXX, before.step.1=false, step.1.start=true, option.revision=64593f26aedd57122f, job.username=XXX, node.os-arch=, job.retryAttempt=0, step.label.Deploy01.state=success, job.group=XXX, node.os-version=, workflow.keepgoing=false, job.execid=105889, node.name=XXX, job.serverUrl=XXX, job.threadcount=3}}} LoopProgress: Pending(0) => run(0), skip(0), remain(0) EndOfChanges: No more state changes expected, finishing workflow. WillShutdown: Workflow engine shutting down Complete: Workflow complete: [Step{stepNum=1, label='Deploy01'}: StepSuccess{stepNum=1, stepResultCapture=StepResultCapture{stepResult=Dispatch successful (1 nodes), stepSuccess=true, statusString='null', controlBehavior=Dispatch successful (1 nodes), resultData=MultiDataContextImpl(map={ContextView(node:XXX)=BaseDataContext{{exec={exitCode=0}}}, ContextView(step:1, node:XXX)=BaseDataContext{{exec={exitCode=0}}}}, base=null)}, newState=DataState{state={step.label.Deploy01.state=success, step.1.completed=true, step.label.Deploy01.completed=true, step.any.state.success=true, before.step.1=false, step.1.state=success, after.step.1=true}}}]

[workflow] Finish execution: node-first: [Workflow result: , Node failures: {XXX=[]}, status: succeeded]
[workflow] finishExecuteNodeStep(XXX): NodeDispatch: Unknown: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection
Failed dispatching to node XXX: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection

Failed dispatching to node XXX: com.dtolabs.rundeck.core.execution.workflow.steps.node.NodeStepException: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection at com.dtolabs.rundeck.core.execution.ExecutionServiceImpl.executeNodeStep(ExecutionServiceImpl.java:220) at com.dtolabs.rundeck.core.execution.dispatch.SequentialNodeDispatcher.dispatch(SequentialNodeDispatcher.java:130) at com.dtolabs.rundeck.core.execution.dispatch.SequentialNodeDispatcher.dispatch(SequentialNodeDispatcher.java:61) at com.dtolabs.rundeck.core.execution.ExecutionServiceImpl.dispatchToNodesWith(ExecutionServiceImpl.java:262) at com.dtolabs.rundeck.core.execution.ExecutionServiceImpl.dispatchToNodes(ExecutionServiceImpl.java:233) at com.dtolabs.rundeck.core.execution.workflow.steps.NodeDispatchStepExecutor.executeWorkflowStep(NodeDispatchStepExecutor.java:65) at com.dtolabs.rundeck.core.execution.ExecutionServiceImpl.executeStep(ExecutionServiceImpl.java:111) at com.dtolabs.rundeck.core.execution.workflow.BaseWorkflowExecutor.executeWFItem(BaseWorkflowExecutor.java:291) at com.dtolabs.rundeck.core.execution.workflow.BaseWorkflowExecutor.executeWorkflowStep(BaseWorkflowExecutor.java:687) at com.dtolabs.rundeck.core.execution.workflow.engine.StepCallable.apply(StepCallable.java:71) at com.dtolabs.rundeck.core.execution.workflow.engine.StepOperation.apply(StepOperation.java:73) at com.dtolabs.rundeck.core.execution.workflow.engine.StepOperation.apply(StepOperation.java:31) at com.dtolabs.rundeck.core.rules.WorkflowEngineOperationsProcessor.lambda$processRunnableOperations$1(WorkflowEngineOperationsProcessor.java:222) at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125) at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:57) at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: org.springframework.transaction.TransactionSystemException: Could not roll back Hibernate transaction; nested exception is org.hibernate.TransactionException: Unable to rollback against JDBC Connection at org.springframework.orm.hibernate5.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:611) at org.grails.orm.hibernate.GrailsHibernateTransactionManager.doRollback(GrailsHibernateTransactionManager.groovy:83) at org.springframework.transaction.support.AbstractPlatformTransactionManager.doRollbackOnCommitException(AbstractPlatformTransactionManager.java:904) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:793) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:734) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:150) at grails.gorm.transactions.GrailsTransactionTemplate.execute(GrailsTransactionTemplate.groovy:91) at rundeck.services.ExecutionService.executeNodeStep(ExecutionService.groovy) at com.dtolabs.rundeck.core.execution.ExecutionServiceImpl.executeNodeStep(ExecutionServiceImpl.java:206) ... 18 more Caused by: org.hibernate.TransactionException: Unable to rollback against JDBC Connection at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.rollback(AbstractLogicalConnectionImplementor.java:120) at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.rollback(JdbcResourceLocalTransactionCoordinatorImpl.java:250) at org.hibernate.engine.transaction.internal.TransactionImpl.rollback(TransactionImpl.java:89) at org.springframework.orm.hibernate5.HibernateTransactionManager.doRollback(HibernateTransactionManager.java:608) ... 26 more Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed. at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:228) at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:1007) at com.microsoft.sqlserver.jdbc.SQLServerConnection.rollback(SQLServerConnection.java:2933) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.interceptor.ConnectionState.invoke(ConnectionState.java:152) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:40) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79) at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81) at com.sun.proxy.$Proxy66.rollback(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.invoke(LazyConnectionDataSourceProxy.java:376) at com.sun.proxy.$Proxy68.rollback(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:240) at com.sun.proxy.$Proxy68.rollback(Unknown Source) at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.rollback(AbstractLogicalConnectionImplementor.java:115) ... 29 more

This was referenced Jan 9, 2019

gschueler added a commit that referenced this issue Jan 14, 2019

Merge pull request #4388 from rundeck/fix/jobref-stats-3-0-11
Fix #4302 deadlock and allow disabling jobref stats

@gschueler gschueler added this to the 3.0.12 milestone Jan 14, 2019

@gschueler gschueler closed this Jan 14, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment