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

[Guest Jose_Manuel_Jurado]

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.

 

Continue reading...