Wrong result of 'insert into' caused by large string in batches

[thomek]

Driver version: 6.2.0

I create a table and insert five rows.

The resulting table in SQL Server contains five rows, but the third row is missing while the fourth row is duplicated.

The table has two columns, int and nvarchar(max), and I insert each row in a separate batch.
The rows look like these:

0,a
1,b
2,ccc...
3,d
4,e

'ccc...' means a string which consists of 4001 characters.

Selecting the rows of the table returns this result:
0,a
1,b
2,ccc...
4,e
4,e

If I create the table with a primary index on the first column, then inserting the rows leads to a primary key violation.

Here is the code to reproduce the issue.

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.Statement;
import java.util.LinkedHashMap;
import java.util.Map;

public class BatchesWithLargeStringTest {

	public static void main(String[] args) throws Exception {
		try (Connection connection = DriverManager.getConnection("jdbc:sqlserver://localhost:1433;databaseName=DATABASE", "user", "password")) {
			connection.setAutoCommit(false);

			// create a table with two columns
			boolean createPrimaryKey = false;
			try (Statement createStatement = connection.createStatement()) {
				createStatement.execute("if object_id('TEST_TABLE', 'U') is not null\ndrop table TEST_TABLE;");
				if (createPrimaryKey) {
					createStatement.execute("create table TEST_TABLE ( ID int, DATA nvarchar(max), primary key (ID) );");
				} else {
					createStatement.execute("create table TEST_TABLE ( ID int, DATA nvarchar(max) );");
				}
			}
			connection.commit();

			// build a String with 4001 characters
			StringBuilder stringBuilder = new StringBuilder();
			for (int i = 0; i < 4001; i++) {
				stringBuilder.append('c');
			}
			String largeString = stringBuilder.toString();

			// insert five rows into the table; use a batch for each row
			try (PreparedStatement statement = connection.prepareStatement("insert into TEST_TABLE values (?,?)")) {
				// 0,a
				statement.setInt(1, 0);
				statement.setNString(2, "a");
				statement.addBatch();

				// 1,b
				statement.setInt(1, 1);
				statement.setNString(2, "b");
				statement.addBatch();

				// 2,ccc...
				statement.setInt(1, 2);
				statement.setNString(2, largeString);
				statement.addBatch();

				// 3,d
				statement.setInt(1, 3);
				statement.setNString(2, "d");
				statement.addBatch();

				// 4,e
				statement.setInt(1, 4);
				statement.setNString(2, "e");
				statement.addBatch();

				statement.executeBatch();
			}
			connection.commit();

			// check the data in the table
			Map<Integer, String> selectedValues = new LinkedHashMap<>();
			try (PreparedStatement statement = connection.prepareStatement("select * from TEST_TABLE;")) {
				try (ResultSet resultSet = statement.executeQuery()) {
					while (resultSet.next()) {
						int id = resultSet.getInt(1);
						String data = resultSet.getNString(2);

						System.out.println(id + "=" + data);

						if (selectedValues.containsKey(id)) {
							throw new IllegalStateException("Found duplicate id: " + id);
						}
						selectedValues.put(id, data);
					}
				}
			}
		}
	}
}

[jubax]

Note: The error neither occurs with 6.1.0 nor with 6.1.7.

[jubax]

Workaround: turn off prepared statement pooling (SQLServerConnection.setStatementPoolingCacheSize(0)).

Note: The JDBC data type of batches number 1, 2, 4, 5 is NVARCHAR(4000) and the data type of batch number 3 is NVARCHAR(max).

[nsidhaye]

Thanks @jubax for workaround

[jubax]

Note that I do not know much about the internals of the driver, so we need official confirmation if this is a valid workaround.

As this error is pretty severe I would also like to know if we should instead switch back to the last official driver version?

[AfsanehR-zz]

Hi @jubax . Thanks for raising this issue and providing the repro code. This is a valuable finding!
We are in the process of releasing a hotfix soon, so in the meantime we would suggest to use the last official version for now.
Apologies for any inconvenience this might have!

[ajlam]

@thomek @jubax , we released 6.2.1 and rolled back the caching changes. Still working on the hotfix and hope to have that out soon.

[thomek]

Thank you very much for the fast 6.2.1 release and for the efforts for a hotfix!

[AfsanehR-zz]

@thomek Would appreciate if you could test pr #393 and test if it fixes the issue you raised? Thanks!

[ajlam]

Hi @thomek , we're hoping to merge PR #393 back to dev, but would really appreciate if you could help test if before we do. Thanks!

[thomek]

Hi @ajlam

I have checked out and build pr #393 (I got 4 test errors, might be related to my German system environment).

I have set up a test with the original data which triggered the issue in our application.
I verified that it fails with the 6.2.0 release and started the test with the pr #393 build again.

The test was still running when I left the office - which is a good sign, since it failed after half an hour with the 6.2.0 release.
I will report back tomorrow, I hope that is sufficient for you.

Thanks

[thomek]

This is the current state: The test is still running on my developer laptop.

I need to stop it on my laptop, but I will execute the test with 6.2.1 on one of our servers which is supposed to finish within an hour once it has been started.
Afterwards I will try with pr #393 .

[thomek]

With 6.2.1 the test finished within an hour on the server as expected.

I replaced the driver aftwards and restarted the test.
It has not finished after an hour with pr #393 and it looks like it is actively 'hanging' at some point with a very high network traffic (~900 Mbps) between the application and the SQL Server.

I may investigate a bit further, but most likely not today.

Here is a thread dump:

java.lang.Thread.State: RUNNABLE at com.microsoft.sqlserver.jdbc.Parameter$GetTypeDefinitionOp.execute(Parameter.java:893) at com.microsoft.sqlserver.jdbc.DTV.executeOp(dtv.java:1631) at com.microsoft.sqlserver.jdbc.Parameter.getTypeDefinition(Parameter.java:1146) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.buildParamTypeDefinitions(SQLServerPreparedStatement.java:355) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.buildPreparedStrings(SQLServerPreparedStatement.java:311) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatementBatch(SQLServerPreparedStatement.java:2564) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.doExecute(SQLServerPreparedStatement.java:2519) at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7153) at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:2688) - locked <0x00000004e74eb6e0> (a java.lang.Object) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:224) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:204) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeBatch(SQLServerPreparedStatement.java:2430)

[AfsanehR-zz]

Thanks @thomek for the valuable update. We will be investigating this. We appreciate if you could later provide other updates or scenarios that causes this issue.

[AfsanehR-zz]

@thomek Also would appreciate it if you could test with the dev branch which does not have the changes in the pr #393 . and see if the hanging issue exists there as well. Thanks! 👍

[thomek]

I'm trying to create some short test which is independet of our application and the original data.
It looks like this is not that easy.
Since my time is restricted, I sadly cannot promise a result...

So, at least this is what I'm observing:
The application is 'hanging' in an infinite loop in SQLServerPreparedStatement.doExecutePreparedStatementBatch.
The following condition in line 2616 evaluates to false:

if (doPrepExec(tdsWriter, batchParam, hasNewTypeDefinitions, hasExistingTypeDefinitions) || numBatchesPrepared == numBatches) { ... }

Due to that, numBatchesExecuted is never increased.

[thomek]

Below is an example to trigger the infinite loop with pr #393 which is similar to the original one.

For the moment I cannot spend more time on this issue, thank you for taking care about it!
I assume that you will close the issue yourself once you have a fix for it - not sure if this is the usual workflow.

`import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.Statement;

public class BatchesWithLargeStringTest {

public static void main(String[] args) throws Exception {
	try (Connection connection = DriverManager.getConnection("jdbc:sqlserver://localhost:1433;databaseName=DATABASE", "user", "password")) {
		connection.setAutoCommit(false);

		// create a table with two columns
		try (Statement createStatement = connection.createStatement()) {
			createStatement.execute("if object_id('TEST_TABLE', 'U') is not null\ndrop table TEST_TABLE;");
			createStatement.execute("create table TEST_TABLE ( ID int, DATA nvarchar(max) );");
		}
		connection.commit();

		// build a String with 4001 characters
		StringBuilder stringBuilder = new StringBuilder();
		for (int i = 0; i < 4001; i++) {
			stringBuilder.append('x');
		}
		String largeString = stringBuilder.toString();

		// insert five rows into the table; use a batch for each row
		try (PreparedStatement statement = connection.prepareStatement("insert into TEST_TABLE values (?,?), (?,?);")) {
			// 0,a
			// 1,b
			statement.setInt(1, 0);
			statement.setNString(2, "a");
			statement.setInt(3, 1);
			statement.setNString(4, "b");
			System.out.println("add batch (0,a), (1,b)");
			statement.addBatch();

			// 2,c
			// 3,d
			statement.setInt(1, 2);
			statement.setNString(2, "c");
			statement.setInt(3, 3);
			statement.setNString(4, "d");
			System.out.println("add batch (2,c), (3,d)");
			statement.addBatch();

			// 4,xxx...
			// 5,f
			statement.setInt(1, 4);
			statement.setNString(2, largeString);
			statement.setInt(3, 5);
			statement.setNString(4, "f");
			System.out.println("add batch (4,xxx...), (5,f)");
			statement.addBatch();

			// 6,g
			// 7,h
			statement.setInt(1, 6);
			statement.setNString(2, "g");
			statement.setInt(3, 7);
			statement.setNString(4, "h");
			System.out.println("add batch (6,g), (7,h)");
			statement.addBatch();

			// 8,i
			// 9,xxx...
			statement.setInt(1, 8);
			statement.setNString(2, "i");
			statement.setInt(3, 9);
			statement.setNString(4, largeString);
			System.out.println("add batch (8,i), (9,xxx...)");
			statement.addBatch();

			statement.executeBatch();
		}
		connection.commit();
	}
}

}`

[AfsanehR-zz]

@thomek Thank you so much for providing the repro. we are working on this.

[AfsanehR-zz]

Thanks @thomek . I updated the pull request that will solve the issue. This way the exception "cannot find prepared statement handle x" will not happen and the application won't hang in the infinite loop. Would appreciate it If you could confirm if this is working. Thanks again for your help with this!

[thomek]

I just successfully tested the updated pr #393 in our application with the original data.
Thank very much @v-afrafi !

[AfsanehR-zz]

@thomek great to hear that! Thanks again for helping us testing this pr 👍

[AfsanehR-zz]

Closing this as fixed by pr #393