Lesson Learned #375: Playing with Hikari Connection Pooling Logging

Some Time ago, I wrote an article where you could find information about error message "Connection is not available, request timed out after ." Lesson Learned #168: Connection is not available error message using Hikari connection pooling - Microsoft Community Hub . Now, I would like to expand more details about this, enabling the logging.

 

The first thing using the library logback

 

The main library that contains the Logback classes is called "logback-classic." Logback consists of several modules, but "logback-classic" is the main module that provides the logging framework implementation.

 

You can find more information and the official documentation of Logback at the following link:

• Logback Official Website: http://logback.qos.ch/

On that website, you will find detailed information about Logback, including guides, documentation, examples, and configuration references. There are also configuration examples available to help you set up Logback according to your needs.

 

In addition to "logback-classic," Logback also provides other modules:

• "logback-core": This module contains basic classes and utilities used by "logback-classic." However, most of the time, you only need to add "logback-classic" to your project since "logback-classic" already includes the necessary dependencies from "logback-core."
• "logback-access": This module provides integration with servlet containers and allows logging within the context of web requests.

Remember that you can obtain the Logback library, including all its modules, through dependency management tools like Maven or Gradle, or by downloading the JAR files directly from the official website.

I added this library in the dependecies of my Java Project: 

 

 

    </dependency>
        <dependency>
            <groupId>com.microsoft.sqlserver</groupId>
            <artifactId>mssql-jdbc</artifactId>
            <version>8.4.1.jre8</version>
        </dependency>
        <dependency>
          <groupId>com.microsoft.azure</groupId>
          <artifactId>adal4j</artifactId>
          <version>1.6.5</version>
        </dependency>
           <dependency>
            <groupId>com.zaxxer</groupId>
            <artifactId>HikariCP</artifactId>
            <version>4.0.3</version>
        </dependency>
         <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.6</version>
         </dependency>			
  </dependencies>

 

 

I created a file called logback.xml that contains the information that I would like to have in my environment.

 

 

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
  
  <appender name="STDOUT" class="com.zaxxer.hikari.HikariConfig" level="INFO">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
  
    <appender name="STDOUT" class="com.zaxxer.hikari.pool.HikariPool" level="INFO">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

 

 

With this information, we could start our logging and debugging our Java code. Every time that we connect to the database, Hikari log reported the following text: 

 

Connecting to Database [DotNetExample-ConnectionPooling connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Added connection ConnectionID:444 ClientConnectionId: XYZ-8877-4a58-b69b-161b161f82a9

 

The ClientConnectionId is a unique identifier assigned to each client connection established with Azure SQL Database or Azure SQL Managed Instance. This identifier is generated by the Azure connection management system to track and monitor individual connections. The ClientConnectionId is useful in various scenarios such as tracing and diagnosing connection issues, analyzing logs, and monitoring performance. When receiving a specific ClientConnectionId, you can use it to search for related logs and metrics for that particular connection in diagnostic logs and Azure monitoring tools.

 

Connection Pooling 

 

In our first test, we are going to reach the maximum available connections in the connection pooling, for this reason, we configure 10 connections and for every connection, we got the following message: [DotNetExample-ConnectionPooling connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Added connection ConnectionID:11 ClientConnectionId: xyz-ad66-4d91-b763-44e4fa2c729a

 

In this important, because having enable the Hikari log we could see that we reached the maximum number of available connections But, [main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Timeout failure stats (total=10, active=10, idle=0, waiting=0)
Error connecting to .. DotNetExample-ConnectionPooling - Connection is not available, request timed out after 2069ms.
java.sql.SQLTransientConnectionException: DotNetExample-ConnectionPooling - Connection is not available, request timed out after 2069ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
at testconnectionms.ClsRetryLogicHikari.HazUnaConexionConReintentos(ClsRetryLogicHikari.java:35)
at testconnectionms.ErrorClientHikari.LoadData(ErrorClientHikari.java:51)
at testconnectionms.Main.main(Main.java:31)

 

When we are using a Redirect connection policy and the port ranges are closed, we faced the following error message:

 

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: The TCP/IP connection to the host hostname.tr11327.northeurope1-a.worker.database.windows.net (redirected from servername.database.windows.net), port 11029 has failed. Error: "Permission denied: connect. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".

Other error may be: [main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host hostname.tr11327.northeurope1-a.worker.database.windows.net (redirected from servername.database.windows.net), port 11029 has failed. Error: "Permission denied: connect. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:234)
at com.microsoft.sqlserver.jdbc.SQLServerException.ConvertConnectExceptionToSQLServerException(SQLServerException.java:285)
at com.microsoft.sqlserver.jdbc.SocketFinder.findSocket(IOBuffer.java:2462)
at com.microsoft.sqlserver.jdbc.TDSChannel.open(IOBuffer.java:668)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:2695)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:2362)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectInternal(SQLServerConnection.java:2213)

 

If the port 1433 is closed: 

 

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: The TCP/IP connection to the host eeo1c8uk2i.database.windows.net, port 1433 has failed. Error: "Permission denied: connect. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".

 

Other common scenario, could be when the connection is closed at network level, in this case we may face the following error message:

 

[main] WARN com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to validate connection ConnectionID:6 ClientConnectionId: XYZ-7a67-4017-bb9b-1dbc82ca172d (The connection is closed.). Possibly consider using a shorter maxLifetime value. 
[DotNetExample-ConnectionPooling connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Closing connection ConnectionID:6 ClientConnectionId: XYZ-7a67-4017-bb9b-1dbc82ca172d: (connection is dead)
01:31:17.416 [DotNetExample-ConnectionPooling connection closer] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Fill pool skipped, pool is at sufficient level.
01:31:17.803 [DotNetExample-ConnectionPooling connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Added connection ConnectionID:7 ClientConnectionId: XYZ-c0dd-4555-8bc6-42283d17ab30

 

Incorrect DatabaseName:

 

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: Cannot open database "dbName" requested by the login. The login failed. ClientConnectionId:XYZ-0819-4ed6-963e-75389acbf38d
01:34:34.241 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source com.microsoft.sqlserver.jdbc.SQLServerException: Cannot open database "dbName " requested by the login. The login failed. ClientConnectionId:XYZ-0819-4ed6-963e-75389acbf38d

 

Incorrect ServerName or doesn't exists:

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: The TCP/IP connection to the host SERVERNAME.database.windows.net, port 1433 has failed. Error: "servername.database.windows.net. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
01:36:56.176 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host eeo1c8uk223.database.windows.net, port 1433 has failed. Error: "servername.database.windows.net. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".

 

Incorrect UserName

 

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: Login failed for user 'UserName'. ClientConnectionId:XYZ-e3be-4c6a-9382-3707a835f22f
01:38:28.147 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user 'UserName'. ClientConnectionId:XYZ-e3be-4c6a-9382-3707a835f22f

 

Incorrect Password

 

[main] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to create/setup connection: Login failed for user 'UserName'. ClientConnectionId:XYZ-ec45-4a39-ab9a-39b6ce4f4e01
[main] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user 'UserName'. ClientConnectionId:XYZ-ec45-4a39-ab9a-39b6ce4f4e01
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:262)
at com.microsoft.sqlserver.jdbc.TDSTokenHandler.onEOF(tdsparser.java:283)
at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:129)
at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:37)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.sendLogon(SQLServerConnection.java:5233)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.logon(SQLServerConnection.java:3988)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.access$000(SQLServerConnection.java:85)

 

Any issue with connectivity

 

[main] WARN com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Failed to validate connection ConnectionID:3 ClientConnectionId: XYZ-83fe-4247-9a1a-cf8fbb051770 (The connection is closed.). Possibly consider using a shorter maxLifetime value.
01:41:50.337 [DotNetExample-ConnectionPooling connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - DotNetExample-ConnectionPooling - Closing connection ConnectionID:3 ClientConnectionId: XYZ-83fe-4247-9a1a-cf8fbb051770: (connection is dead)
01:41:50.338 [DotNetExample-ConnectionPooling connection closer] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Fill pool skipped, pool is at sufficient level.
01:41:50.731 [DotNetExample-ConnectionPooling connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Added connection ConnectionID:4 ClientConnectionId: XYZ-2d0b-4201-9abf-4cc3d909b278

 

Finally, if we reach any SLO threshold:

 

[DotNetExample-ConnectionPooling connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - DotNetExample-ConnectionPooling - Cannot acquire connection from data source
com.microsoft.sqlserver.jdbc.SQLServerException: Resource ID : 2. The session limit for the database is 900 and has been reached. See 'https://docs.microsoft.com/azure/azure-sql/database/resource-limits-logical-server' for assistance. ClientConnectionId:XYZ-2ad9-4302-baca-d31014eb6eba
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:262)