Problems with locking and transactions

RubenS · December 1, 2010, 3:26pm

Hi,

We have recently switched to the new nightly build of SmartGWT and GWT: SC_SNAPSHOT-2010-11-29/PowerEdition Deployment (built 2010-11-29) and GWT 2.1.0. As database we use mysql Ver 14.14 Distrib 5.1.50, for Win64 (unknown). Now we are encountering some weird problem in one of our DMI methods.

In our code we have some comboboxes where you can multiselect, and we process these values in a DMI method so we can insert and remove in our manytomany-table. However this approach (that used to work) doesn’t work anymore.

This is some logging produced in my testcase:

=== 2010-12-01 16:09:35,770 [l0-6] DEBUG SQLTransaction - [builtinApplication.Customer_update] Started new transaction "1434189849"
=== 2010-12-01 16:09:35,770 [l0-6] INFO  SQLDriver - [builtinApplication.Customer_update] Executing SQL update on 'Mysql': UPDATE Customer SET cstm_name='A Lab Inc22' WHERE (Customer.cstm_pk='1')
....
....
=== 2010-12-01 16:09:35,796 [l0-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'Mysql': INSERT INTO content (cntn_fk_customer, cntn_id) VALUES (1, 'id')
=== 2010-12-01 16:10:26,798 [l0-6] INFO  SQLDriver - [builtinApplication.null] Execute of update: INSERT INTO content (cntn_fk_customer, cntn_id) VALUES (1, 'id') on db: Mysql threw exception: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction - assuming stale connection and retrying update.
...
java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
...

I guess the opened transaction locks customer (I am far from a mysql expert) and prevents the Content import to happen (they are INNODB tables and connected with a foreign key constraint). The transaction doesnt seem to be closed.

I hope my explanation wasn’t too confusing. Anyway, I have produced a small example to reproduce:

package test.client;

import com.google.gwt.core.client.EntryPoint;
import com.smartgwt.client.data.Criteria;
import com.smartgwt.client.data.DataSource;
import com.smartgwt.client.widgets.IButton;
import com.smartgwt.client.widgets.events.ClickEvent;
import com.smartgwt.client.widgets.events.ClickHandler;
import com.smartgwt.client.widgets.form.DynamicForm;
import com.smartgwt.client.widgets.layout.HLayout;

public class LockTest implements EntryPoint {
	
	public void onModuleLoad() {
		DataSource ds = DataSource.get("Customer");
		Criteria crit = new Criteria();
		crit.addCriteria("cstm_pk", 1);
		
		final DynamicForm form = new DynamicForm();
		form.setDataSource(ds);
		form.fetchData(crit);
		
		IButton save = new IButton("save");
		save.addClickHandler(new ClickHandler() {
			@Override
			public void onClick(ClickEvent event) {
				form.saveData();
			}
		});
		
		HLayout hLayout = new HLayout();
		hLayout.addMember(form);
		hLayout.addMember(save);
		hLayout.draw();
	}

}

package test.server;

import java.util.HashMap;
import java.util.Map;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;

import org.springframework.stereotype.Service;

import com.isomorphic.datasource.DSRequest;
import com.isomorphic.datasource.DSResponse;



public class DMIService {
			
	public DSResponse updateCustomer(DSRequest dsRequest, HttpServletRequest servletRequest, HttpSession session) throws Exception {
		DSResponse dsResponse = dsRequest.execute();
		Object cstmPk = dsRequest.getValues().get("cstm_pk");
		DSRequest addRequest = new DSRequest("contents", "add");
		Map<String, Object> newRecord = new HashMap<String, Object>();
		newRecord.put("cntn_id", "id");
		newRecord.put("cntn_status", 20);
		newRecord.put("cntn_fk_contenttype", 1);
		newRecord.put("cntn_fk_customer", cstmPk);	
		addRequest.setValues(newRecord);
		addRequest.setOldValues(newRecord);
		addRequest.execute();
		
		return dsResponse;
	}
	

	
}

Datasources:

<DataSource ID="contents" serverType="sql" tableName="content">
	<fields>
		<field primaryKey="true" type="sequence" name="cntn_pk" hidden="true" export="false"></field>
		<field title="integer" type="integer" name="cntn_fk_customer"></field>
		<field type="datetime" name="cntn_createdOn" canEdit="false" canFilter="true" title="" showInGrid="true" export="true"></field>
		<field type="text" length="45" name="cntn_id" required="true" exportable="true" export="true"></field>
		<field title="bar" type="text" length="45" name="cntn_barCode" showInGrid="true" canEdit="false" export="true"></field>
		<field type="integer" name="cntn_fk_location" hidden="false"></field>
		<field title="quantity" type="float" name="cntn_quantity" export="true"></field>
		<field title="unit" type="text" length="45" name="cntn_unit" export="true" ></field>
	</fields>
</DataSource>

<DataSource 
	serverType="sql"
	dbName="Mysql"
	tableName="Customer"
	ID="Customer"
>
	<fields>
		<field primaryKey="true" type="sequence" name="cstm_pk" hidden="true"></field>
		<field type="text" length="45" name="cstm_name" title="" required="true" export="true"></field>
	</fields>
	<operationBindings>
		<operationBinding operationType="update">
	        <serverObject className="test.server.DMIService" lookupStyle="new"  />  
	        <serverMethod>updateCustomer</serverMethod>  
	    </operationBinding>  
	</operationBindings>  	
</DataSource>

Isomorphic · December 1, 2010, 10:41pm

Please do not trim server logs - show at least the complete log for the failing request. By trimming, you can very easily remove critical information (as you have in this case). If you need to highlight particular lines, you could make them bold.

You mention that started happening when you upgraded - what did you upgrade from?

What is your intent for the “add” dsRequest you’re performing - do you want it to be part of the current transaction or not?

RubenS · December 1, 2010, 10:47pm

We upgraded from the nightly of 22-09. For the add operation, I don’t really care if it is in the transaction or not, I just want it to be able to complete the request

This is the complete server log:

=== 2010-12-01 23:43:55,101 [l0-1] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Over_start.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,112 [l0-3] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Over_stretch.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,114 [l0-6] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Over_end.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,387 [l0-6] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Down_start.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,391 [l0-3] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Down_stretch.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,395 [l0-1] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/button/button_Down_end.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,533 [l0-1] INFO  RequestContext - URL: '/smartgwt2/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:43:55,537 [l0-1] DEBUG XML - Parsed XML from (in memory stream): 2ms
=== 2010-12-01 23:43:55,541 [l0-1] DEBUG RPCManager - Processing 1 requests.
=== 2010-12-01 23:43:55,543 [l0-1] DEBUG RPCManager - Request #1 (DSRequest) payload: {
    criteria:{
        cstm_pk:1
    },
    values:{
        cstm_name:"A Lab Inc",
        cstm_pk:1
    },
    operationConfig:{
        dataSource:"Customer",
        operationType:"update"
    },
    componentId:"isc_DynamicForm_0",
    appID:"builtinApplication",
    operation:"Customer_update",
    oldValues:{
        cstm_name:"A Lab Inc",
        cstm_pk:1
    }
}
=== 2010-12-01 23:43:55,543 [l0-1] INFO  IDACall - Performing 1 operation(s)
=== 2010-12-01 23:43:55,560 [l0-1] DEBUG Reflection - adaptArgsAndInvoke:

 public com.isomorphic.datasource.DSResponse test.server.DMIService.updateCustomer(com.isomorphic.datasource.DSRequest,javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpSession) throws java.lang.Exception

requiredArgs: [] optionalArgs: [com.isomorphic.servlet.RequestContext, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, javax.servlet.ServletContext, javax.servlet.http.HttpSession, com.isomorphic.rpc.RPCManager, com.isomorphic.datasource.DSRequest, com.isomorphic.datasource.DataSource, java.sql.Connection, com.isomorphic.log.Logger, java.util.Map]
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: com.isomorphic.servlet.RequestContext fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpServletRequest fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpServletResponse fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.ServletContext fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpSession fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: com.isomorphic.rpc.RPCManager fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: com.isomorphic.datasource.DSRequest fulfills type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - Successfully adapted optional arg type: com.isomorphic.datasource.DSRequest to type: com.isomorphic.datasource.DSRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: com.isomorphic.servlet.RequestContext fulfills type: javax.servlet.http.HttpServletRequest
=== 2010-12-01 23:43:55,561 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpServletRequest fulfills type: javax.servlet.http.HttpServletRequest
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - Successfully adapted optional arg type: javax.servlet.http.HttpServletRequest to type: javax.servlet.http.HttpServletRequest
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - checking whether type: com.isomorphic.servlet.RequestContext fulfills type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpServletRequest fulfills type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpServletResponse fulfills type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.ServletContext fulfills type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - checking whether type: javax.servlet.http.HttpSession fulfills type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - Successfully adapted optional arg type: javax.servlet.http.HttpSession to type: javax.servlet.http.HttpSession
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - method takes: 3 args.  I've assembled: 3 args
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG Reflection - invoking method:
com.isomorphic.datasource.DSResponse test.server.DMIService.updateCustomer(com.isomorphic.datasource.DSRequest, javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpSession) throws java.lang.Exception

with arg types: com.isomorphic.datasource.DSRequest, com.isomorphic.servlet.ISCHttpServletRequest, org.mortbay.jetty.servlet.HashSessionManager$Session
=== 2010-12-01 23:43:55,562 [l0-1] DEBUG AppBase - [builtinApplication.Customer_update] No userTypes defined, allowing anyone access to all operations for this application
=== 2010-12-01 23:43:55,563 [l0-1] DEBUG AppBase - [builtinApplication.Customer_update] No public zero-argument method named '_Customer_update' found, performing generic datasource operation
=== 2010-12-01 23:43:55,563 [l0-1] INFO  SQLDataSource - [builtinApplication.Customer_update] Performing update operation with
	criteria: {cstm_pk:1}	values: {cstm_name:"A Lab Inc",cstm_pk:1}
=== 2010-12-01 23:43:55,576 [l0-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.Customer_update] Returning pooled Connection
=== 2010-12-01 23:43:55,577 [l0-1] DEBUG SQLTransaction - [builtinApplication.Customer_update] Started new transaction "2423780"
=== 2010-12-01 23:43:55,577 [l0-1] INFO  SQLDriver - [builtinApplication.Customer_update] Executing SQL update on 'Mysql': UPDATE Customer SET cstm_name='A Lab Inc' WHERE (Customer.cstm_pk='1')
=== 2010-12-01 23:43:55,597 [l0-1] DEBUG SQLDataSource - [builtinApplication.Customer_update] update operation affected 1 rows
=== 2010-12-01 23:43:55,598 [l0-1] INFO  SQLDataSource - [builtinApplication.Customer_update] primaryKeys: {cstm_pk=1}
=== 2010-12-01 23:43:55,599 [l0-1] INFO  SQLDriver - [builtinApplication.Customer_update] Executing SQL query on 'Mysql': SELECT Customer.cstm_name, Customer.cstm_pk FROM Customer WHERE (Customer.cstm_pk='1')
=== 2010-12-01 23:43:55,600 [l0-1] INFO  DSResponse - [builtinApplication.Customer_update] DSResponse: List with 1 items
=== 2010-12-01 23:43:55,601 [l0-1] DEBUG AppBase - [builtinApplication.null] No userTypes defined, allowing anyone access to all operations for this application
=== 2010-12-01 23:43:55,602 [l0-1] DEBUG AppBase - [builtinApplication.null] No public zero-argument method named '_null' found, performing generic datasource operation
=== 2010-12-01 23:43:55,602 [l0-1] INFO  SQLDataSource - [builtinApplication.null] Performing add operation with
	criteria: {}	values: {cntn_fk_contenttype:1,cntn_status:20,cntn_fk_customer:1,cntn_id:"id"}
=== 2010-12-01 23:43:55,602 [l0-1] INFO  SQLValuesClause - [builtinApplication.null] Ignored data for non-existent columns: [cntn_fk_contenttype, cntn_status]
=== 2010-12-01 23:43:55,608 [l0-1] DEBUG SQLValuesClause - [builtinApplication.null] Sequences: {cntn_pk=__default}
=== 2010-12-01 23:43:55,624 [l0-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] Returning pooled Connection
=== 2010-12-01 23:43:55,624 [l0-1] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'Mysql': INSERT INTO content (cntn_fk_customer, cntn_id) VALUES (1, 'id')
=== 2010-12-01 23:44:46,644 [l0-1] INFO  SQLDriver - [builtinApplication.null] Execute of update: INSERT INTO content (cntn_fk_customer, cntn_id) VALUES (1, 'id') on db: Mysql threw exception: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction - assuming stale connection and retrying update.
=== 2010-12-01 23:44:46,665 [l0-1] DEBUG PoolableSQLConnectionFactory - [builtinApplication.null] Returning pooled Connection
=== 2010-12-01 23:45:37,537 [l0-1] DEBUG DataSourceDMI - Invocation threw exception
java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1055)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3536)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3468)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1957)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2107)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2086)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2371)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2289)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2274)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102)
	at com.isomorphic.sql.SQLDriver.doUpdate(SQLDriver.java:458)
	at com.isomorphic.sql.SQLDriver.update(SQLDriver.java:423)
	at com.isomorphic.sql.SQLDriver.executeUpdate(SQLDriver.java:532)
	at com.isomorphic.sql.SQLDataSource.executeNativeUpdate(SQLDataSource.java:360)
	at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1335)
	at com.isomorphic.sql.SQLDataSource.execute(SQLDataSource.java:257)
	at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:721)
	at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658)
	at com.isomorphic.application.AppBase.execute(AppBase.java:491)
	at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:1418)
	at test.server.DMIService.updateCustomer(DMIService.java:29)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.isomorphic.base.Reflection.adaptArgsAndInvoke(Reflection.java:908)
	at com.isomorphic.datasource.DataSourceDMI.execute(DataSourceDMI.java:575)
	at com.isomorphic.datasource.DataSourceDMI.execute(DataSourceDMI.java:64)
	at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:1415)
	at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:173)
	at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:130)
	at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:95)
	at com.isomorphic.servlet.IDACall.doPost(IDACall.java:54)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
	at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1097)
	at com.isomorphic.servlet.CompressionFilter.doFilter(CompressionFilter.java:259)
	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1088)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:729)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.RequestLogHandler.handle(RequestLogHandler.java:49)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:324)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:505)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:843)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:647)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)
=== 2010-12-01 23:45:37,542 [l0-1] WARN  RequestContext - dsRequest.execute() failed: 
java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1055)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3536)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3468)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1957)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2107)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2086)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2371)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2289)
	at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2274)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102)
	at com.isomorphic.sql.SQLDriver.doUpdate(SQLDriver.java:458)
	at com.isomorphic.sql.SQLDriver.update(SQLDriver.java:423)
	at com.isomorphic.sql.SQLDriver.executeUpdate(SQLDriver.java:532)
	at com.isomorphic.sql.SQLDataSource.executeNativeUpdate(SQLDataSource.java:360)
	at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1335)
	at com.isomorphic.sql.SQLDataSource.execute(SQLDataSource.java:257)
	at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:721)
	at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658)
	at com.isomorphic.application.AppBase.execute(AppBase.java:491)
	at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:1418)
	at test.server.DMIService.updateCustomer(DMIService.java:29)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.isomorphic.base.Reflection.adaptArgsAndInvoke(Reflection.java:908)
	at com.isomorphic.datasource.DataSourceDMI.execute(DataSourceDMI.java:575)
	at com.isomorphic.datasource.DataSourceDMI.execute(DataSourceDMI.java:64)
	at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:1415)
	at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:173)
	at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:130)
	at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:95)
	at com.isomorphic.servlet.IDACall.doPost(IDACall.java:54)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
	at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1097)
	at com.isomorphic.servlet.CompressionFilter.doFilter(CompressionFilter.java:259)
	at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1088)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:729)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.RequestLogHandler.handle(RequestLogHandler.java:49)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:324)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:505)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:843)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:647)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:380)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:395)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:488)
=== 2010-12-01 23:45:37,543 [l0-1] DEBUG RPCManager - Content type for RPC transaction: text/plain; charset=UTF-8
=== 2010-12-01 23:45:37,544 [l0-1] DEBUG SQLTransaction - Rolling back transaction "2423780"
=== 2010-12-01 23:45:37,577 [l0-1] DEBUG SQLTransaction - Ending transaction "2423780"
=== 2010-12-01 23:45:37,579 [l0-1] DEBUG RPCManager - non-DMI response, dropExtraFields: false
=== 2010-12-01 23:45:37,580 [l0-1] INFO  Compression - /smartgwt2/sc/IDACall: 160 -> 147 bytes
=== 2010-12-01 23:45:37,607 [l0-1] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/Dialog/warn.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header
=== 2010-12-01 23:45:37,660 [l0-1] INFO  RequestContext - URL: '/smartgwt2/sc/skins/Enterprise/images/headerIcons/close.png', User-Agent: 'Mozilla/5.0 (Windows; U; Windows NT 6.1; nl; rv:1.9.2.12) Gecko/20101026 Firefox/3.6.12': Moz (Gecko) with Accept-Encoding header

Isomorphic · December 2, 2010, 5:51pm

Can you tell us exactly what the foreign key constraint between those two tables is? Also, is there anything else going on behind the scenes here (like triggers)?

RubenS · December 2, 2010, 6:26pm

We have some triggers in our database however they aren’t related to these tables. After I dropped the triggers i still had the issues. These are the two table definitions:

CREATE TABLE IF NOT EXISTS `Content` (
  `cntn_pk` INT(11) UNSIGNED NOT NULL AUTO_INCREMENT ,
  `cntn_fk_location` INT(11) UNSIGNED NULL DEFAULT NULL ,
  `cntn_id` VARCHAR(45) NULL DEFAULT NULL ,
  `cntn_barCode` VARCHAR(45) NULL DEFAULT NULL ,
  `cntn_status` INT(3) NOT NULL DEFAULT 10 ,
  `cntn_position_row` INT(11) NULL DEFAULT 0,
  `cntn_position_column` INT(11) NULL DEFAULT 0,
  `cntn_quantity` FLOAT NULL DEFAULT NULL ,
  `cntn_unit` VARCHAR(45) NULL DEFAULT NULL ,
  `cntn_fk_contentType` INT(11) UNSIGNED DEFAULT NULL ,
  `cntn_fk_originalContent` INT(11) unsigned DEFAULT NULL,
  `cntn_fk_source` INT(11) unsigned DEFAULT NULL,
  `cntn_fk_disease` INT(11) unsigned DEFAULT NULL,
  `cntn_fk_customer` INT(11) unsigned DEFAULT NULL,
  `cntn_fk_user` INT(11) unsigned DEFAULT NULL,
  `cntn_fk_group` INT(11) unsigned NULL,
  `cntn_createdBy` VARCHAR(100) NULL ,
  `cntn_modifiedBy` VARCHAR(100) NULL ,
  `cntn_createdOn` TIMESTAMP NULL DEFAULT CURRENT_TIMESTAMP ,
  `cntn_modifiedOn` TIMESTAMP NULL DEFAULT NULL ,
  PRIMARY KEY (`cntn_pk`) ,
  UNIQUE KEY `cntn_barCode` (`cntn_barCode`),
  KEY `cntn_fk_contentType` (`cntn_fk_contentType`),
  KEY `cntn_fk_location` (`cntn_fk_location`),
  KEY `cntn_fk_originalContent` (`cntn_fk_originalContent`),
  KEY `cntn_fk_source` (`cntn_fk_source`),
  KEY `cntn_fk_disease` (`cntn_fk_disease`),
  KEY `cntn_fk_customer` (`cntn_fk_customer`),
  KEY `cntn_fk_user` (`cntn_fk_user`),
  KEY `cntn_fk_group` (`cntn_fk_group`),
  INDEX `cntn_id`(`cntn_id`), 
  -- Content -> Source : Restricted
  CONSTRAINT `cntn_fk_source` FOREIGN KEY (`cntn_fk_source`) REFERENCES `source` (`sorc_pk`),
  -- Content -> Disease : Restricted
  CONSTRAINT `cntn_fk_disease` FOREIGN KEY (`cntn_fk_disease`) REFERENCES `disease` (`diss_pk`),
  -- Content -> Customer : Restricted
  CONSTRAINT `cntn_fk_customer` FOREIGN KEY (`cntn_fk_customer`) REFERENCES `customer` (`cstm_pk`),
  -- Content -> User : Restricted
  CONSTRAINT `cntn_fk_user` FOREIGN KEY (`cntn_fk_user`) REFERENCES `user` (`user_pk`),
  CONSTRAINT `cntn_fk_group` FOREIGN KEY (`cntn_fk_group`) REFERENCES `Groups` (`grps_pk`),
  -- Content -> ContentType : Restricted
  CONSTRAINT `cntn_fk_contentType` FOREIGN KEY (`cntn_fk_contentType`) REFERENCES `contenttype` (`cntp_pk`),
  -- Content -> Content : Cascade
  CONSTRAINT `cntn_fk_originalContent` FOREIGN KEY (`cntn_fk_originalContent`) REFERENCES `content` (`cntn_pk`) ON DELETE SET NULL ON UPDATE SET NULL,
  -- Content -> Location : Restricted
  CONSTRAINT `cntn_fk_location` FOREIGN KEY (`cntn_fk_location`) REFERENCES `location` (`lctn_pk`)
) ENGINE=InnoDB AUTO_INCREMENT=20000 DEFAULT CHARSET=latin1;


CREATE TABLE IF NOT EXISTS `Customer` (
  `cstm_pk` INT(11) UNSIGNED NOT NULL AUTO_INCREMENT,
  `cstm_number` INT(11) unsigned NOT NULL,
  `cstm_name` varchar(45) NOT NULL,
  `cstm_description` TEXT DEFAULT NULL,
  `cstm_address` varchar(100) DEFAULT NULL,
  `cstm_city` varchar(45) DEFAULT NULL,
  `cstm_zip` varchar(45) DEFAULT NULL,
  `cstm_country` varchar(45) DEFAULT NULL,
  `cstm_email` varchar(100) DEFAULT NULL,
  `cstm_createdBy` VARCHAR(100) NULL ,
  `cstm_modifiedBy` VARCHAR(100) NULL ,
  `cstm_createdOn` TIMESTAMP NULL DEFAULT CURRENT_TIMESTAMP ,
  `cstm_modifiedOn` TIMESTAMP NULL DEFAULT NULL ,  
  PRIMARY KEY (`cstm_pk`),
  INDEX `cstm_name`(`cstm_name`)
  ) ENGINE=InnoDB DEFAULT CHARSET=latin1;

Isomorphic · December 3, 2010, 11:27am

Actually, the problem here is more straightforward than it looks at first glance. Our automatic transaction support (which is enabled by default for all updates) works by caching a database connection on the RPCManager for use by all autoJoining operations. In this case, your manual DSRequest is not setting up the RPCManager, so the operation cannot join the transaction - it has no access to the connection being used and has to be run via a separate database connection. However, the original update of Customer is part of a transaction that has not yet been committed and so is still holding a lock on the row that needs to be checked for a foreign key constraint.

The fix for this is to copy the RPCManager to your server-side DSRequest:

addRequest.setRPCManager(dsRequest.getRPCManager());

Alternatively, if you aren’t interested in having support for transactions, add this line to your server.properties file:

autoJoinTransactions: NONE

RubenS · December 3, 2010, 11:49am

Thanks a lot, this works perfectly

Sytematic · December 14, 2010, 11:19am

I got a related question/problem, however I cannot pass on the RPCManager.

After the req.execute(); I am doing some separate queries, using the Spring Framework (ie. using jdbcTemplate), which has its own mysql connection bean specified.

I am using the latest nightly build (14-12-2010) of the Power edition. I didn’t have this problem with the 2.3 release of the Power edition (but that one has another bug that is fixed in the latest nightly, as it appears).

How can I close the connection of the RPCManager? Is that the way to go anyway? Rewriting it to let it make use of an extra DSRequest is not really something I wanna try rightaway. Hopefully there is a simpler solution, comparable to the first one above.

*** EDIT ***
On second thought, I went for the solution of making an extra DSRequest, reducing the amount of hardcoded queries. Better code anyway…

Isomorphic · December 14, 2010, 10:29pm

Yes, a second DSRequest is definitely a better solution. However note that APIs on SQLTransaction would allow you to either get the current SQL Connection object to have your customized SQL execute in the current transaction (a sample for this is being added soon) OR manually end the transaction early.