mssql-jdbc: Assertion fails when canceling "insert into" statement

Driver version

9.4.1, 10.2.1

SQL Server version

Microsoft SQL Server 2017 (RTM-GDR) (KB4505224) - 14.0.2027.2 (X64) Jun 15 2019 00:26:19 Copyright © 2017 Microsoft Corporation Developer Edition (64-bit) on Windows 10 Enterprise 2016 LTSB 10.0 <X64> (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

I insert into a table and cancel the statement while it is executing its batch via a concurrent thread.

With Java assertions enabled the thread executing the statement fails frequently with an AssertionError.

Expected behavior

The thread executing the statement should fail with an exception like this:

com.microsoft.sqlserver.jdbc.SQLServerException: The query was canceled.
	at com.microsoft.sqlserver.jdbc.TDSCommand.checkForInterrupt(IOBuffer.java:7605)
	at com.microsoft.sqlserver.jdbc.TDSWriter.writePacket(IOBuffer.java:4219)
	at com.microsoft.sqlserver.jdbc.TDSWriter.endMessage(IOBuffer.java:3269)
	at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:7779)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatementBatch(SQLServerPreparedStatement.java:2816)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.doExecute(SQLServerPreparedStatement.java:2694)
	at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7417)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3488)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:262)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeBatch(SQLServerPreparedStatement.java:2092)
	at SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:123)
	...

Actual behavior

I frequently get

java.lang.AssertionError
	at com.microsoft.sqlserver.jdbc.TDSCommand.onAttentionAck(IOBuffer.java:7716)
	at com.microsoft.sqlserver.jdbc.StreamDone.setFromTDS(StreamDone.java:159)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement$1NextResult.onDone(SQLServerStatement.java:1472)
	at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:96)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1658)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatementBatch(SQLServerPreparedStatement.java:2830)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.doExecute(SQLServerPreparedStatement.java:2694)
	at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7417)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3488)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:262)
	at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeBatch(SQLServerPreparedStatement.java:2092)
	at SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:123)
	...

Error message/stack trace

See above.

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.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);

			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();

			int numberOfCommands = 4;
			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();
				}

				// execute the statement but cancel it after about 20 milliseconds -
				// you may need to try which delay works for you to reproduce the issue
				long delayInMilliseconds = 20;
				Thread cancelThread = cancelAsync(statement, delayInMilliseconds);
				boolean success = false;
				try {
					statement.executeBatch();
					success = true;
				} catch (SQLException e) {
					// this is what should happen
					assertEquals("The query was canceled.", e.getMessage());
				} catch (AssertionError e) {
					// unexpected but happens frequently if Java assertions are enabled
					throw e;
				}
				assertEquals("The statement completed without interruption. This may happen if the chosen delay is too long.", false, success);
				cancelThread.join();
			}
			connection.commit();
		}
	}
}

JDBC trace logs

With log level FINE enabled. Please note that I have shortend the output regarding the parameter list by using ellipsis.

Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.Util parseUrl
FINE: Property:serverName Value:localhost
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.Util parseUrl
FINE: Property:portNumber Value:1433
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.Util parseUrl
FINE: Property:encrypt Value:true
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.Util parseUrl
FINE: Property:trustServerCertificate Value:true
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.Util parseUrl
FINE: Property:databaseName Value:Test
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection <init>
FINE: ConnectionID:1 created by (SQLServerDriver:1)
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt server name: localhost port: 1433 InstanceName: null useParallel: false
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt endtime: 1655899063673
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection login
FINE: ConnectionID:1 This attempt No: 0
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection connectHelper
FINE: ConnectionID:1 Connecting with server: localhost port: 1433 Timeout slice: 1850 Timeout Full: 15
Jun 22, 2022 1:57:41 PM com.microsoft.sqlserver.jdbc.SQLServerConnection Prelogin
FINE: ConnectionID:1 ClientConnectionId: df4b14e5-8985-4487-a848-0c8553a60520 Server returned major version:14
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerStatement <init>
FINE: SQLServerPreparedStatement:1 created by (ConnectionID:1 ClientConnectionId: df4b14e5-8985-4487-a848-0c8553a60520)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement buildExecSQLParams
FINE: SQLServerPreparedStatement:1: calling sp_executesql: SQL:if object_id('test_table') is not null drop table test_table
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerStatement <init>
FINE: SQLServerPreparedStatement:2 created by (ConnectionID:1 ClientConnectionId: df4b14e5-8985-4487-a848-0c8553a60520)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement buildExecSQLParams
FINE: SQLServerPreparedStatement:2: calling sp_executesql: SQL:create table test_table (column_name bit)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerStatement <init>
FINE: SQLServerPreparedStatement:3 created by (ConnectionID:1 ClientConnectionId: df4b14e5-8985-4487-a848-0c8553a60520)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement buildExecSQLParams
FINE: SQLServerPreparedStatement:3: calling sp_executesql: SQL:insert into test_table values (@P0),...,(@P511)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.TDSWriter sendAttention
FINE: TDSWriter@60dcc9fe (ConnectionID:1): sending attention...
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: The query was canceled. The query was canceled.
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerException logException
FINE: com.microsoft.sqlserver.jdbc.TDSCommand.checkForInterrupt(IOBuffer.java:7605)com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:95)com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1658)com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatementBatch(SQLServerPreparedStatement.java:2830)com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.doExecute(SQLServerPreparedStatement.java:2694)com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7417)com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3488)com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:262)com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:237)com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeBatch(SQLServerPreparedStatement.java:2092)SqlServerTest.test_cancelStatementWhileInsertInto(SqlServerTest.java:116)java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)java.base/java.lang.reflect.Method.invoke(Method.java:568)org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)org.junit.runners.ParentRunner.run(ParentRunner.java:413)org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:93)org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:40)org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:529)org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:756)org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:452)org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:210)
Jun 22, 2022 1:57:42 PM com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement buildPrepExecParams
FINE: SQLServerPreparedStatement:3: calling sp_prepexec: PreparedHandle:0, SQL:insert into test_table values (@P0),...,(@P511)

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 15 (7 by maintainers)

Most upvoted comments

Sure, @Jeffery-Wasty, this is the new issue: #1896.

+1
thomek on Aug 12, 2022
Read more comments on GitHub
← mssql-jdbc: Arithmetic operations with decimals return incorrect results
mssql-jdbc: [Azure] Failed to validate the server name in a certificate during Secure Sockets Layer (SSL) initialization →