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

  • Thread starter Thread starter Jose_Manuel_Jurado
  • Start date Start date
J

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:





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.



Code: 
[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...
 
Back
Top