Skip to content

Assertion fails when canceling "insert into" statement #1849

@thomek

Description

@thomek

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

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)

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions