Lesson Learned #503: Lessons Learned Using JDBC Logging with Microsoft JDBC Driver for SQL Server

This post has been republished via RSS; it originally appeared at: Azure Database Support Blog articles.

A few days ago, our customer encountered connectivity issues while using HikariCP in their Java application. To troubleshoot the problem, we enabled detailed logging for the Microsoft JDBC Driver for SQL Server. This logging gave me a lot of information and details, following I would like to share my lessons learned here.

 

To capture detailed logs, we configured the Java logging framework to record the operations of the JDBC driver at a fine-grained level. 

 

To enable the logging I included these instrucctions in the code:

 

 

import java.util.logging.*; public static void main(String[] args) throws Exception{ Logger globalLogger1 = Logger.getLogger(Logger.GLOBAL_LOGGER_NAME); globalLogger1.setLevel(Level.FINE); Logger rootLogger1 = Logger.getLogger(""); rootLogger1.setLevel(Level.FINE); // Set the root logger level // Create a custom formatter Formatter customFormatter = new Formatter() { @Override public String format(LogRecord record) { return String.format("[%1$tF %1$tT] [%2$s] %3$s %n", record.getMillis(), record.getLevel().getName(), record.getMessage()); } }; // Remove all existing handlers // Create a new console handler ConsoleHandler consoleHandler = new ConsoleHandler(); consoleHandler.setLevel(Level.FINE); // Set the level for console handler consoleHandler.setFormatter(customFormatter); //consoleHandler.setFormatter(new SimpleFormatter()); // Set the formatter // Add the new handler to the root logger rootLogger1.addHandler(consoleHandler); // Set specific log levels for SQL Server JDBC driver Logger sqlLogger = Logger.getLogger("com.microsoft.sqlserver.jdbc"); sqlLogger.setLevel(Level.FINE); Logger sqlDataSourceLogger = Logger.getLogger("com.microsoft.sqlserver.jdbc.SQLServerDataSource"); sqlDataSourceLogger.setLevel(Level.FINE); }

 

 

Basically, after enabling this information we could see the following details (as an example):

 

  • ConnectionID.
  • Redirection (depending on connection policy).
  • Login Timeout. 

 

[2024-06-18 10:27:21] [FINE] ConnectionID:1 created by (SQLServerDataSource:1) [2024-06-18 10:27:21] [FINE] ConnectionID:1 This attempt server name: servername.database.windows.net port: 1433 InstanceName: null useParallel: false [2024-06-18 10:27:21] [FINE] ConnectionID:1 This attempt endtime: 1718699261215 [2024-06-18 10:27:21] [FINE] ConnectionID:1 This attempt No: 0 [2024-06-18 10:27:21] [FINE] ConnectionID:1 Connecting with server: servername.database.windows.net port: 1433 Timeout slice: 19934 Timeout Full: 20 [2024-06-18 10:27:21] [FINE] ConnectionID:1 ClientConnectionId: 80f77dcf-5d20-47bc-be53-025868ac76e6 Server returned major version:12 [2024-06-18 10:27:22] [FINE] ConnectionID:1 This attempt server name: aabeaXXX.trXXXX.northeurope1-a.worker.database.windows.net port: 11002 InstanceName: null useParallel: false [2024-06-18 10:27:22] [FINE] ConnectionID:1 This attempt endtime: 1718699261215 [2024-06-18 10:27:22] [FINE] ConnectionID:1 This attempt No: 1 [2024-06-18 10:27:22] [FINE] ConnectionID:1 Connecting with server: aabeaXXX.trXXXX.northeurope1-a.worker.database.windows.net port: 11002 Timeout slice: 19074 Timeout Full: 20 [2024-06-18 10:27:22] [FINE] ConnectionID:1 ClientConnectionId: 0bb41f4c-dcac-4a32-9e04-8f9395055527 Server returned major version:12 [2024-06-18 10:27:22] [FINE] SQLServerStatement:1 created by (ConnectionID:1 ClientConnectionId: 0bb41f4c-dcac-4a32-9e04-8f9395055527) [2024-06-18 10:27:22] [FINE] SQLServerStatement:1 Executing (not server cursor) select 1 [2024-06-18 10:27:23] [FINE] SQLServerResultSet:1 created by (SQLServerStatement:1) [2024-06-18 10:27:23] [FINE] SQLServerStatement:2 created by (ConnectionID:1 ClientConnectionId: 0bb41f4c-dcac-4a32-9e04-8f9395055527) [2024-06-18 10:27:23] [FINE] SQLServerStatement:2 Executing (not server cursor) SELECT 1 [2024-06-18 10:27:23] [FINE] ConnectionID:2 created by (SQLServerDataSource:1) [2024-06-18 10:27:23] [FINE] sp_executesql SQL: SELECT 1 AS ID: calling sp_executesql: SQL:SELECT 1 AS ID [2024-06-18 10:27:23] [FINE] ConnectionID:2 ClientConnectionId: 3161a9ac-f8f4-4eab-bf80-999f48859d26 Server returned major version:12 [2024-06-18 10:27:23] [FINE] SQLServerResultSet:3 created by (sp_executesql SQL: SELECT 1 AS ID)

 

 

By enabling and analyzing these logs, we were able to quickly pinpoint the connectivity issue and understand the redirections being taken by the JDBC driver. 

 

For more information on downloading and using the Microsoft JDBC Driver for SQL Server, you can visit the official documentation.

 

 

Leave a Reply

Your email address will not be published. Required fields are marked *

*

This site uses Akismet to reduce spam. Learn how your comment data is processed.