MySQL Bugs: #37458: with server 5.1, getGeneratedKeys returns them in ascending order

Bug #37458	with server 5.1, getGeneratedKeys returns them in ascending order
Submitted:	17 Jun 2008 20:12	Modified:	3 Aug 2009 18:03
Reporter:	Eric Jensen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / J	Severity:	S1 (Critical)
Version:	5.1.6	OS:	Any (only with mysql server 5.1)
Assigned to:		CPU Architecture:	Any

Description:
I recently upgraded my mysql server from 5.0.51 to 5.1.25 and have found that a bug similar to an old one I reported has again reared its ugly head. 
It used to be this only happened with rewriteBatchedStatements=true (see http://bugs.mysql.com/bug.php?id=34093), but I now have it set to false.  

The previous, correct, behavior of calling getGeneratedKeys() after an executeBatch() was to return the keys generated in order of the statements added using addBatch.  

After upgrading to mysql 5.1, however, getGeneratedKeys() returns the keys from an executeBatch() in ascending key order.  This makes it impossible to map the generated keys to the statements you ran, which effectively makes that call useless at best, and misleading at worst.  

I expected to find a different stack executing this in the 5.1 version or something, but it looks basically the same as before...hopefully the problem is in connector/j and not the server itself:

   java.lang.Thread.State: RUNNABLE
        at java.net.SocketOutputStream.socketWrite0(Native Method)
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
        - locked <0xd644a820> (a java.io.BufferedOutputStream)
        at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3227)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1917)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
        - locked <0xd644abe0> (a java.lang.Object)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2019)
        - locked <0xd644abe0> (a java.lang.Object)
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1627)
        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1082)
        - locked <0xd644abe0> (a java.lang.Object)
        at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
        at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)

How to repeat:
executeBatch() some statements that follow the
pattern:

insert into test (uniqueTextKey) values (?)
on duplicate key UPDATE autoIncId = last_insert_id( autoIncId )

then look at the output of getGeneratedKeys()

Hi Eric and thanks for spotting this. True, regression test for your original Bug#34093 fails against MySQL server 5.1.26 while, on the same box and same c/J sources, works with 5.0.64...

junit.framework.AssertionFailedError: expected:<4> but was:<1>
	at junit.framework.Assert.fail(Assert.java:47)
	at junit.framework.Assert.failNotEquals(Assert.java:282)
	at junit.framework.Assert.assertEquals(Assert.java:64)
	at junit.framework.Assert.assertEquals(Assert.java:71)
	at testsuite.BaseTestCase.assertResultSetsEqual(BaseTestCase.java:694)
	at testsuite.regression.StatementRegressionTest.testBug34093(StatementRegressionTest.java:5381)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at junit.framework.TestCase.runTest(TestCase.java:154)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at junit.framework.TestResult$1.protect(TestResult.java:106)
	at junit.framework.TestResult.runProtected(TestResult.java:124)
	at junit.framework.TestResult.run(TestResult.java:109)
	at junit.framework.TestCase.run(TestCase.java:118)
	at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
	at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

The problem is in "bigger" nonRewrittenRsKeys:
nonRewrittenRsKeys	ResultSetImpl  (id=51)	
	catalog	"test"	
	columnLabelToIndex	null	
	columnNameToIndex	null	
	columnUsed	null	
	connection	ConnectionImpl  (id=58)	
	connectionId	5	
	currentRow	-1	
	defaultTimeZone	ZoneInfo  (id=95)	
	doingUpdates	false	
	eventSink	null	
	fastDateCal	null	
	fetchDirection	1000	
	fetchSize	0	
	fields	Field[1]  (id=98)	
	firstCharOfQuery	
	fullColumnNameToIndex	null	
	gmtCalendar	null	
	hasBuiltIndexMapping	false	
	invalidRowReason	"Before start of result set"	
	isBinaryEncoded	false	
	isClosed	false	
	jdbcCompliantTruncationForReads	true	
	nextResultSet	null	
	onInsertRow	false	
	onValidRow	false	
	owningStatement	PreparedStatement  (id=102)	
	padCharsWithSpace	false	
	pointOfOrigin	null	
	profileSql	false	
	reallyResult	true	
	resultId	0	
	resultSetConcurrency	0	
	resultSetType	0	
	retainOwningStatement	false	
	rowData	RowDataStatic  (id=54)	
		index	-1	
		metadata	Field[1]  (id=98)	
		owner	ResultSetImpl  (id=51)	
		rows	ArrayList<E>  (id=64)	
			elementData	Object[11]  (id=73)	
				[0]	ByteArrayRow  (id=75)	
					internalRowData	byte[1][]  (id=85)	
						[0]	byte[1]  (id=88)	
							[0]	51	
					metadata	null	
				[1]	ByteArrayRow  (id=77)	
					internalRowData	byte[1][]  (id=81)	
						[0]	byte[1]  (id=87)	
							[0]	52	
					metadata	null	
				[2]	ByteArrayRow  (id=78)	
					internalRowData	byte[1][]  (id=84)	
						[0]	byte[1]  (id=89)	
							[0]	49	
					metadata	null	
				[3]	ByteArrayRow  (id=79)	
					internalRowData	byte[1][]  (id=86)	
						[0]	byte[1]  (id=90)	
							[0]	50	
					metadata	null	
				[4]	ByteArrayRow  (id=108)	
					internalRowData	byte[1][]  (id=127)	
						[0]	byte[1]  (id=128)	
							[0]	52	
					metadata	null	
				[5]	ByteArrayRow  (id=109)	
					internalRowData	byte[1][]  (id=129)	
						[0]	byte[1]  (id=130)	
							[0]	53	
					metadata	null	
				[6]	ByteArrayRow  (id=110)	
					internalRowData	byte[1][]  (id=131)	
						[0]	byte[1]  (id=132)	
							[0]	50	
					metadata	null	
				[7]	ByteArrayRow  (id=111)	
					internalRowData	byte[1][]  (id=133)	
						[0]	byte[1]  (id=134)	
							[0]	51	
					metadata	null	
				[8]	null	
				[9]	null	
				[10]	null	
			modCount	8	
			size	8	
	serverInfo	null	
	serverTimeZoneTz	null	
	statementUsedForFetchingRows	null	
	thisRow	null	
	updateCount	8	
	updateId	-1	
	useColumnNamesInFindColumn	false	
	useFastDateParsing	true	
	useFastIntParsing	true	
	useLegacyDatetimeCode	true	
	useStrictFloatingPoint	false	
	useUsageAdvisor	false	
	warningChain	null	
	wasNullFlag	false	
	wrapperStatement	null	

while rewrittenRsKeys remains the same between versions:
rewrittenRsKeys	ResultSetImpl  (id=92)	
	catalog	"test"	
	columnLabelToIndex	null	
	columnNameToIndex	null	
	columnUsed	null	
	connection	ConnectionImpl  (id=91)	
	connectionId	6	
	currentRow	-1	
	defaultTimeZone	ZoneInfo  (id=113)	
	doingUpdates	false	
	eventSink	null	
	fastDateCal	null	
	fetchDirection	1000	
	fetchSize	0	
	fields	Field[1]  (id=114)	
	firstCharOfQuery	
	fullColumnNameToIndex	null	
	gmtCalendar	null	
	hasBuiltIndexMapping	false	
	invalidRowReason	"Before start of result set"	
	isBinaryEncoded	false	
	isClosed	false	
	jdbcCompliantTruncationForReads	true	
	nextResultSet	null	
	onInsertRow	false	
	onValidRow	false	
	owningStatement	PreparedStatement  (id=115)	
	padCharsWithSpace	false	
	pointOfOrigin	null	
	profileSql	false	
	reallyResult	true	
	resultId	0	
	resultSetConcurrency	0	
	resultSetType	0	
	retainOwningStatement	false	
	rowData	RowDataStatic  (id=116)	
		index	-1	
		metadata	Field[1]  (id=114)	
		owner	ResultSetImpl  (id=92)	
		rows	ArrayList<E>  (id=117)	
			elementData	Object[4]  (id=118)	
				[0]	ByteArrayRow  (id=119)	
					internalRowData	byte[1][]  (id=123)	
						[0]	byte[1]  (id=124)	
							[0]	51	
					metadata	null	
				[1]	ByteArrayRow  (id=120)	
					internalRowData	byte[1][]  (id=125)	
						[0]	byte[1]  (id=126)	
							[0]	49	
					metadata	null	
				[2]	ByteArrayRow  (id=121)	
				[3]	ByteArrayRow  (id=122)	
			modCount	4	
			size	4	
	serverInfo	null	
	serverTimeZoneTz	null	
	statementUsedForFetchingRows	null	
	thisRow	null	
	updateCount	4	
	updateId	-1	
	useColumnNamesInFindColumn	false	
	useFastDateParsing	true	
	useFastIntParsing	true	
	useLegacyDatetimeCode	true	
	useStrictFloatingPoint	false	
	useUsageAdvisor	false	
	warningChain	null	
	wasNullFlag	false	
	wrapperStatement	null

This is more complex than it looks. It seems prior to 5.1, the server returned "normal" update counts for "ON DUPLICATE KEY UPDATE", and now it returns *2*. This confuses the JDBC driver's code for creating the result set for getGeneratedKeys(), because it also has to support statements of the form "INSERT INTO ... VALUES (...), (....), (...)...", which will also have an update count > 1.

The server only returns the "first" generated key for a statement, the rest have to be "computed" (more like "divined" in the case of REPLACE, and now it seems for "ON DUPLICATE KEY UPDATE", so to make this work we'll have to scan the statement for "ON DUPLICATE KEY UPDATE" clauses.

Now that 5.1 is GA, this could become a fairly widespread issue.

any update on this?  now that 5.1 is GA should this be critical?  it does indeed result in invalid results.

Eric,
Can you elaborate on what stack you expected to see, and how you obtained it? I'm not sure of the relevance here. Regarding the bug, I have run the attached test program without a problem. Can you review this test to see if it differs from your situation? Also, have you tried the recently released Connector/J 5.1.8?

Thanks,
Jess

Test:
int ids[] = {13, 1, 8};
createTable("testBug37458", "(id int not null auto_increment, primary key (id))");
stmt.executeUpdate("insert into testBug37458 values (1), (8), (13)");
pstmt = conn.prepareStatement("insert into testBug37458 values (?) on duplicate key update id = last_insert_id(id)", PreparedStatement.RETURN_GENERATED_KEYS);
for(int i = 0; i < ids.length; ++i) {
	pstmt.setInt(1, ids[i]);
	pstmt.addBatch();
}
pstmt.executeBatch();
ResultSet keys = pstmt.getGeneratedKeys();
for(int i = 0; i < ids.length; ++i) {
	assertTrue(keys.next());
	assertEquals(ids[i], keys.getInt(1));
	System.out.println("Key " + (i+1) + " = " + keys.getInt(1));
}

your test appears to cover the situation i was describing, so maybe it is fixed.  my particular use case is inserting into a unique key string value to get back the autogenerated id for it, but i'm not sure if there's a particular bug with that or not.  there was a test case that covered this and was failing on 5.1, is this still true?

[18 Jun 2008 8:54] Tonci Grgin
Hi Eric and thanks for spotting this. True, regression test for your original Bug#34093
fails against MySQL server 5.1.26 while, on the same box and same c/J sources, works with
5.0.64...

Eric,
All tests are passing. I will add this new test to prevent a regression and close this bug report. Feel free to re-open it if you still have an issue.