lockTimeout doesn't work if applications run on Azure environment

[nanahoshi]

Driver version

12.2.0.jre11

SQL Server version

Microsoft SQL Azure (RTM) - 12.0.2000.8
Mar 8 2023 17:58:50
Copyright (C) 2022 Microsoft Corporation

Client Operating System

Ubuntu 18.04 LTS
Ubuntu 20.04 LTS

JAVA/JVM version

openjdk version "11.0.18" 2023-01-17 LTS
OpenJDK Runtime Environment Microsoft-7208460 (build 11.0.18+10-LTS)
OpenJDK 64-Bit Server VM Microsoft-7208460 (build 11.0.18+10-LTS, mixed mode)

Table schema

N/A

Problem description

The behaviour of 'lockTimeout' is NOT the same on 'from within Azure' and 'from outside Azure'.

From within Azure / connection policy = redirect
ref: https://learn.microsoft.com/en-us/azure/azure-sql/database/connectivity-architecture?view=azuresql#connectivity-from-within-azure

The 'lockTimeout' is ignored.

Outside Azure / connection policy = proxy
ref: https://learn.microsoft.com/en-us/azure/azure-sql/database/connectivity-architecture?view=azuresql#connectivity-from-outside-of-azure

The 'lockTimeout' is applied.

We use the below connection string on both sides.

jdbc:sqlserver://<dummy>.database.windows.net:1433;database=<dummy>;encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;user=<dummy>;password=<dummy>;lockTimeout=5000;

I'm not sure if the other options are applied or not.

Expected behavior

Even if the connection policy is redirect mode, JDBC shall send a packet set lock_timeout 5000.
below query returns '5000'

SELECT @@LOCK_TIMEOUT AS [Lock Timeout]

Actual behavior

If the connection policy is redirect mode, JDBC doesn't send the packet set lock_timeout 5000.
below query returns '-1'

SELECT @@LOCK_TIMEOUT AS [Lock Timeout]

Error message/stack trace

N/A

Any other details that can be helpful

I tested it with simple class

package jp.example;

import java.io.IOException;
import java.io.InputStream;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;

import org.apache.commons.cli.CommandLine;
import org.apache.commons.cli.CommandLineParser;
import org.apache.commons.cli.DefaultParser;
import org.apache.commons.cli.HelpFormatter;
import org.apache.commons.cli.Option;
import org.apache.commons.cli.Options;

public class SimpleJDBCTestMain {
	private static Logger log = Logger.getLogger(SimpleJDBCTestMain.class.getName());
	public static void main(String[] args) {

		try( InputStream in = SimpleJDBCTestMain.class.getClassLoader().getResourceAsStream("logging.properties") ){
			if(in == null) {
				log.log(Level.WARNING, "logging.properties is not exists");
			}
			LogManager.getLogManager().readConfiguration( in );
		} catch (Exception e) {
			e.printStackTrace();
            return;
		}
		
		Options options = new Options();
		options.addOption(new Option("u", "user", true, "user name"));
		options.addOption(new Option("p", "password", true, "password"));
		CommandLine cmd;
		try {
			CommandLineParser parser = new DefaultParser();
			cmd = parser.parse(options, args);
		}catch(Exception e) {
			System.out.println(e.getMessage());
			HelpFormatter formatter = new HelpFormatter();
			formatter.printHelp("Usage", options);
			return;
		}
        
		// Main Logic
		String connectionUrl = "jdbc:sqlserver://<dummy>.database.windows.net:1433;database=<dummy>;encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;";
		connectionUrl += "user=" + cmd.getOptionValue("user") + ";";
		connectionUrl += "password="+cmd.getOptionValue("password") + ";";
		connectionUrl += "lockTimeout=50000;";
		
		try( Connection con = DriverManager.getConnection(connectionUrl)){
			log.log(Level.INFO ,"Database Connected: "+ con.getSchema());
			Statement statement = con.createStatement();
            // check if lock_timeout is setted
			String sql = "SELECT @@LOCK_TIMEOUT AS [Lock Timeout]";
			ResultSet resultset = statement.executeQuery(sql);
			while (resultset.next()) {
				log.info("Lock_Timeout: " + resultset.getString(1));
			}
			
		} catch (SQLException e) {
			e.printStackTrace();
            return;
		}
	}

}

JDBC trace logs

Provide the JDBC driver trace logs. Instructions can be found here: https://docs.microsoft.com/sql/connect/jdbc/tracing-driver-operation

[Jeffery-Wasty]

Hi @nanahoshi,

Thank you for bringing this to our attention. We'll take a look into this to see what changes are needed.

[nanahoshi]

@Jeffery-Wasty
Thank you for your investigation. I have attached the masked jdbc debug log.
It seems that there is no packet for 'set lock_timeout' on withinAzure.log.

withinAzure.log
outsideAzure.log

In contrast, the following logs are output in outsideAzure.log.

[2023-04-13 11:38:37] [FINEST ] /<dummy>:56462 SPID:470 TDSWriter@61d47554 (ConnectionID:1) sending packet (76 bytes)
01 01 00 4C 01 D6 01 00 16 00 00 00 12 00 00 00   ...L............
02 00 00 00 00 00 00 00 00 00 01 00 00 00 20 00   .............. .
73 00 65 00 74 00 20 00 6C 00 6F 00 63 00 6B 00   s.e.t. .l.o.c.k.
5F 00 74 00 69 00 6D 00 65 00 6F 00 75 00 74 00   _.t.i.m.e.o.u.t.
20 00 35 00 30 00 30 00 30 00 30 00                .5.0.0.0.0. 

[Jeffery-Wasty]

Looking over what we have, we explicitly check for if we have been routed before sending lockTimeout. The logic being: if we got routed in the current attempt, the server closes the connection. In that case, we shouldn't be sending any further commands to the server.

So, the current behavior is intentional. We'll need to discuss this to see if we still want to address lockTimeout, even in the case of a redirect.

[nanahoshi]

Hi @Jeffery-Wasty
I understand that this is intentional behavior. But I guess the behavior creates a bug using Azure (redirect mode is the default).

I try to control the current bug with HikariCP's connectionInitSql (set lock_timeout 5000), but I would be happy to control it on the JDBC side.

[nanahoshi]

I'm sorry that I took a miss operation and re-open it.