Canceling "insert into" statement closes connection

[thomek]

Driver version

11.2.0

SQL Server version

Microsoft SQL Server 2017 (RTM-GDR) (KB4505224) - 14.0.2027.2 (X64) Jun 15 2019 00:26:19 Copyright (C) 2017 Microsoft Corporation Developer Edition (64-bit) on Windows 10 Enterprise 2016 LTSB 10.0 (Build 14393: ) (Hypervisor)

Client Operating System

OS Name Microsoft Windows 10 Enterprise 2016 LTSB
Version 10.0.14393 Build 14393
System Type x64-based PC

JAVA/JVM version

Eclipse Adoptium jdk-17.0.1.12-hotspot

Table schema

create table test_table (column_name bit)

Problem description

1. Prepare an "insert into" table Statement
2. Call Statement.executeBatch
3. Start to iterate over the statement's ResultSet
4. Cancel the statement via a concurrent thread
5. Iterating over the statement's results may now fail with an exception
6. If iterating over the results does not fail with an exception, then commit the transaction

Expected behavior

a. Either an exception in step 5. telling me that the query was canceled or
b. a successful commit of the transaction in step 6.

The behavior may depend on timing. For each run I expect to see either a. or b..

Actual behavior

I frequently get:

c. the commit in step 6. fails because the connection got closed

Error message/stack trace

These are the last lines from the console output as attached under "JDBC trace logs" when executing the test provided in "Any other details that can be helpful":

delayInMilliseconds=2, numberOfCommands=2: canceled
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.TDSParser throwUnexpectedTokenException
SEVERE: TDSReader@34 (ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e): batch completion: Encountered unexpected TDS_RETURN_VALUE (0xAC)
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.TDSReader throwInvalidTDSToken
SEVERE: TDSReader@34 (ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e) got unexpected value in TDS response at offset:18
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: *** SQLException:ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e com.microsoft.sqlserver.jdbc.SQLServerException: The TDS protocol stream is not valid. Unexpected token TDS_RETURN_VALUE (0xAC). The TDS protocol stream is not valid. Unexpected token TDS_RETURN_VALUE (0xAC).
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:3806)com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:3795)com.microsoft.sqlserver.jdbc.SQLServerConnection.throwInvalidTDSToken(SQLServerConnection.java:3785)com.microsoft.sqlserver.jdbc.TDSReader.throwInvalidTDSToken(IOBuffer.java:6707)com.microsoft.sqlserver.jdbc.TDSParser.throwUnexpectedTokenException(tdsparser.java:153)com.microsoft.sqlserver.jdbc.TDSTokenHandler.onRetValue(tdsparser.java:231)com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:93)com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:37)com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:26)com.microsoft.sqlserver.jdbc.SQLServerStatement.processExecuteResults(SQLServerStatement.java:1327)com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.processResponse(SQLServerPreparedStatement.java:2780)com.microsoft.sqlserver.jdbc.TDSCommand.close(IOBuffer.java:7697)com.microsoft.sqlserver.jdbc.SQLServerStatement.discardLastExecutionResults(SQLServerStatement.java:151)com.microsoft.sqlserver.jdbc.SQLServerStatement.closeInternal(SQLServerStatement.java:685)com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.closeInternal(SQLServerPreparedStatement.java:340)com.microsoft.sqlserver.jdbc.SQLServerStatement.close(SQLServerStatement.java:700)SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:156)SqlServerTest.main(SqlServerTest.java:69)
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed. The connection is closed.
Exception in thread "main" com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:1555)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.commit(SQLServerConnection.java:4218)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.commit(SQLServerConnection.java:4199)
	at SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:157)
	at SqlServerTest.main(SqlServerTest.java:69)

The test runs the steps in "Problem description" for different parameters in a loop.

The test prints

delayInMilliseconds=2, numberOfCommands=2: canceled

at the end of its last successful loop iteration.

In the next iteration the driver logs

Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.TDSParser throwUnexpectedTokenException
SEVERE: TDSReader@34 (ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e): batch completion: Encountered unexpected TDS_RETURN_VALUE (0xAC)
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.TDSReader throwInvalidTDSToken
SEVERE: TDSReader@34 (ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e) got unexpected value in TDS response at offset:18
Aug 12, 2022 8:52:14 AM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: *** SQLException:ConnectionID:1 ClientConnectionId: 9b4d1828-a2de-495b-84ca-39cd32b9900e com.microsoft.sqlserver.jdbc.SQLServerException: The TDS protocol stream is not valid. Unexpected token TDS_RETURN_VALUE (0xAC). The TDS protocol stream is not valid. Unexpected token TDS_RETURN_VALUE (0xAC).

I suspect this is unexpected and should not happen.

After some additional lines logged by the driver the test fails with this exception included at the end of the console output:

Exception in thread "main" com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:1555)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.commit(SQLServerConnection.java:4218)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.commit(SQLServerConnection.java:4199)
	at SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:157)
	at SqlServerTest.main(SqlServerTest.java:69)

Any other details that can be helpful

Test to reproduce the issue:

import static org.junit.Assert.assertEquals;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.logging.ConsoleHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.Logger;

import org.junit.Test;

public class SqlServerTest {

	/**
	 * Repeat a string a given number of times.
	 * 
	 * @param string
	 *            The string
	 * 
	 * @param count
	 *            Number of times to repeat {@code string}
	 * 
	 * @return The repeated string
	 */
	private static String repeat(String string, int count) {
		StringBuilder sb = new StringBuilder();
		for (int i = 0; i < count; i++) {
			sb.append(string);
		}
		return sb.toString();
	}

	/**
	 * Cancel a {@link Statement} after some delay via a concurrent thread.
	 * 
	 * @param statement
	 *            The statement to cancel
	 * 
	 * @param delayInMilliseconds
	 *            Delay to wait until canceling the statement in milliseconds
	 * 
	 * @return The thread used to cancel the statement.
	 * 
	 *             <p>
	 *             The method does not wait until the statement got canceled.
	 *             Use {@link Thread#join()} to wait until the concurrent thread has called {@link Statement#cancel()}.
	 *             </p>
	 */
	private static Thread cancelAsync(Statement statement, long delayInMilliseconds) {
		Thread thread = new Thread(() -> {
			try {
				Thread.sleep(delayInMilliseconds);
				statement.cancel();
			} catch (SQLException | InterruptedException e) {
				// does not/must not happen
				e.printStackTrace();
				throw new IllegalStateException(e);
			}
		});
		thread.start();
		return thread;
	}

	public static void main(String[] args) throws Exception {
		new SqlServerTest().test_cancelStatementWhileInsertInto();
	}

	@Test
	public void test_cancelStatementWhileInsertInto() throws Exception {
		String database = "Test";
		String user = "test";
		String password = "secret";

		Level level = Level.FINE;
		Logger logger = Logger.getLogger("com.microsoft.sqlserver.jdbc");
		for (Handler handler : logger.getParent().getHandlers()) {
			if (handler instanceof ConsoleHandler consoleHandler) {
				consoleHandler.setLevel(level);
			}
		}
		logger.setLevel(level);

		try (Connection connection =
				DriverManager.getConnection(
						"jdbc:sqlserver://localhost:1433;encrypt=true;trustServerCertificate=true;databaseName=" + database,
						user,
						password)) {
			connection.setAutoCommit(false);

			System.out.println("# Driver version");
			System.out.println(connection.getMetaData().getDriverName() + " - " + connection.getMetaData().getDriverVersion());
			System.out.println();

			System.out.println("# SQL Server version");
			try (PreparedStatement statement = connection.prepareStatement(
					"SELECT @@VERSION")) {
				try (ResultSet resultSet = statement.executeQuery()) {
					while (resultSet.next()) {
						System.out.println(resultSet.getString(1));
					}
				}
			}
			connection.commit();
			System.out.println();

			try (PreparedStatement statement = connection.prepareStatement(
					"if object_id('test_table') is not null drop table test_table")) {
				statement.execute();
			}
			connection.commit();

			try (PreparedStatement statement = connection.prepareStatement(
					"create table test_table (column_name bit)")) {
				statement.execute();
			}
			connection.commit();

			AssertionError firstAssertionError = null;
			for (long delayInMilliseconds : new long[] { 1, 2, 4, 8, 16, 32, 64, 128 }) {
				for (int numberOfCommands : new int[] { 1, 2, 4, 8, 16, 32, 64, 128, 256, 512, 1024 }) {
					int parameterCount = 512;

					try (PreparedStatement statement = connection.prepareStatement(
							"insert into test_table values (?)" + repeat(",(?)", parameterCount - 1))) {

						for (int i = 0; i < numberOfCommands; i++) {
							for (int j = 0; j < parameterCount; j++) {
								statement.setBoolean(j + 1, true);
							}
							statement.addBatch();
						}

						Thread cancelThread = cancelAsync(statement, delayInMilliseconds);
						String outcome;
						try {
							statement.executeBatch();
							outcome = "executed";
						} catch (SQLException e) {
							// this is what should happen
							assertEquals("The query was canceled.", e.getMessage());
							outcome = "canceled";
						} catch (AssertionError e) {
							// unexpected but happens frequently if Java assertions are enabled
							if (firstAssertionError == null) {
								firstAssertionError = e;
							}
							outcome = "assertion error";
						}
						cancelThread.join();

						System.out.println("delayInMilliseconds=" + delayInMilliseconds + ", numberOfCommands=" + numberOfCommands + ": " + outcome);
					}
					connection.commit();
				}
			}

			System.out.println();
			System.out.println("# Test result");
			if (firstAssertionError == null) {
				System.out.println("Success");
			} else {
				System.out.println("Failed, throwing first assertion error");
				throw firstAssertionError;
			}
		}
	}
}

JDBC trace logs

This is the console output of SqlServerTest.main with log level FINE:

SqlServerTest.main--2022-08-12.txt

[thomek]

This issue is related to #1849.

[Jeffery-Wasty]

Thanks for creating a new issue, this will help keeping track of progress much easier.

Regarding the issue, I've managed to reproduce it using the code you have provided, but am still looking into the cause.

[tkyc]

Hi @thomek, I believe I fixed the issue. I'm still in the middle of testing, but I've attached a driver version with the fix to my comment, if you or anyone is interested in testing it out.
mssql-jdbc-11.3.0-SNAPSHOT.jre17-preview.zip