Publish not working because Lock wait timeout

Hi,

We are facing a very annoying problem very strange for us, and it is happening in the worst moment, when we are deploying for a close release.
The problem is publishing an App from flowable-modeler, it is not able, it is failing because a “Lock timeout on ACT_DE_MODEL”.

this is the Log detail.

ESC[36mbpm |ESC[0m 12:45:20,365 [http-nio-8080-exec-7] DEBUG org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator - Translating SQLException with SQL state ‘40001’, error code ‘1205’, message [Lock wait timeout exceeded; try restarting transaction]; SQL was [] for task [
ESC[36mbpm |ESC[0m ### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
ESC[36mbpm |ESC[0m ### The error may involve org.flowable.app.domain.editor.Model.updateModel-Inline
ESC[36mbpm |ESC[0m ### The error occurred while setting parameters
ESC[36mbpm |ESC[0m ### SQL: update ACT_DE_MODEL SET name = ?, model_key = ?, description = ?, model_comment = ?, created = ?, created_by = ?, last_updated = ?, last_updated_by = ?, version = ?, model_editor_json = ?, model_type = ?, thumbnail = ? where id = ?
ESC[36mbpm |ESC[0m ### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

thanks a lot,

Toni

The ACT_DE_MODEL table is used by the modeler app for persisting the model.
A “lock timeout” typically means something else is locking the table (or row) and this one loses.
Is this happening consistently? Is there a way you can connect to the database and see the current locks? Maybe something is hogging the table for some reason.

Yes it is happening always, no way to Publish any app.
But I have realized that the first time I publish I get not error description, only a red Toast and the second time maybe it is when the lock is generated.

I have connected to the database an see a “in_use” over the table.

MySQL [(none)]> show open tables where in_use>0;
±---------±-------------±-------±------------+
| Database | Table | In_use | Name_locked |
±---------±-------------±-------±------------+
| flowable | ACT_DE_MODEL | 1 | 0 |
±---------±-------------±-------±------------+
1 row in set (0.00 sec)

com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction
ESC[36mbpm |ESC[0m at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
ESC[36mbpm |ESC[0m at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
ESC[36mbpm |ESC[0m at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
ESC[36mbpm |ESC[0m at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.Util.getInstance(Util.java:408)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:951)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
ESC[36mbpm |ESC[0m at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
ESC[36mbpm |ESC[0m at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.execute(NewProxyPreparedStatement.java:67)
ESC[36mbpm |ESC[0m at sun.reflect.GeneratedMethodAccessor810.invoke(Unknown Source)
ESC[36mbpm |ESC[0m at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
ESC[36mbpm |ESC[0m at java.lang.reflect.Method.invoke(Method.java:498)
ESC[36mbpm |ESC[0m at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59)
ESC[36mbpm |ESC[0m at com.sun.proxy.$Proxy221.execute(Unknown Source)
ESC[36mbpm |ESC[0m at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
ESC[36mbpm |ESC[0m at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
ESC[36mbpm |ESC[0m at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
ESC[36mbpm |ESC[0m at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
ESC[36mbpm |ESC[0m at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
ESC[36mbpm |ESC[0m at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
ESC[36mbpm |ESC[0m at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ESC[36mbpm |ESC[0m at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
ESC[36mbpm |ESC[0m at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
ESC[36mbpm |ESC[0m at java.lang.reflect.Method.invoke(Method.java:498)
ESC[36mbpm |ESC[0m at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:434)
ESC[36mbpm |ESC[0m at com.sun.proxy.$Proxy257.update(Unknown Source)
ESC[36mbpm |ESC[0m at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:295)
ESC[36mbpm |ESC[0m at org.flowable.app.repository.editor.ModelRepositoryImpl.save(ModelRepositoryImpl.java:89)

Hi Toni,

And there’s no exception in the log when you try and deploy the first time (and it fails)?

Cheers
Paul.

Hi Paul,

No I can get see any log despite log4j.properties for flowable-rest/-task/-modeler/-idm are with

log4j.rootLogger=DEBUG, stdout

thks,
Toni

I have realized thath this EndPoint using by Publish is not working.
It is giving a 504 GATEWAY_TIMEOUT error when issuing,

curl -X POST
https://host/flowable-task/process-api/repository/deployments?deploymentKey=Test&deploymentName=Test
-H ‘authorization: Basic YWRtaW46ZGphZG1pbg==’
-H ‘content-type: multipart/form-data; boundary=----WebKitFormBoundary7MA4YWxkTrZu0gW’

Some questions:

  • Can you access the flowable-task UI on that same url (not through REST)?
  • Does a simple GET work on that same url, like GET /process-api/repository/deployments?
  • Did you set deployment url property for the modeler (deployment.api.url) to the correct endpoint? However, given that you’re saying curl gives you a 504 there seems to be something wrong in that setup.

Hi Joram,

  • Flowable-Task webapp is returning the App with the Top Bar (Flowable and User …) but not any TaskDetail because there aren’t. So it seems to me it is working.
  • “GET /process-api/repository/deployments” is also throwing 504 Error.

Update: It gives this error if a Publish operation is tried before, if not it works.
{
“data”: [
{
“id”: “1”,
“name”: “SpringAutoDeployment”,
“deploymentTime”: “2018-03-04T07:49:04.360Z”,
“category”: null,
“url”: “https://host/flowable-task/process-api/repository/deployments/1”,
“tenantId”: “”
}
],
“total”: 1,
“start”: 0,
“sort”: “id”,
“order”: “asc”,
“size”: 1
}

  • We have setup “deployment.api.url” though /lib/flowable-ui-app.properties this way:

    “deployment.api.url=$deployment_api_url”

    where “echo $deployment_api_url” return this value:

    http://localhost:8080/flowable-task/process-api

We do this way because we are running Flowable within a Docker started by a docker-compose.

Question:

Could it be related with the fact is is behind a AWS Elastic Load Balancer connected to the Docker.
ELB is serving on http://host and flowable is configured on http://internal_ip:8080 ?

Hi all,

The problem is solved.
It was been produced for a too small connection pool size for flowable.
It was set with a minimum of 1 and maximum of 4 connections what it is not enough for the Publish action.
Incresing it has do the trick.

Many thanks @yvo, for finding the problem !

Toni