[BUG] azure-identity-extentions - WorkloadIdentityCredential with JDBC lag in response

[grabskimm]

Describe the bug
Our application setup with Java/Maven built with docker runs on AKS alongside Azure managed PostgreSQL Flexiable server. The application connects to PostgreSQL datababase via JDBC URL which until now included the complete URL with username & password. We have now setup service connector with workload identity as describe here, which in turn allows us to pass the JDBC URL without a password relying on AzurePostgresqlAuthenticationPlugin / azure-identity-extentions.

Previouslly with username/password auth the query for a single row would return a response within 500 milliseconds, the same query now takes up to 30 seconds. We suspect the logs below to cause the delay in returning the expected token.

Exception or Stack Trace

25/01/15 17:30:06 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:12 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:12 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:18 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:18 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:19 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:24 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:24 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:25 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:25 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:30 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:30 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:31 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:36 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token
25/01/15 17:30:36 INFO ChainedTokenCredential: Azure Identity => Attempted credential EnvironmentCredential is unavailable.
25/01/15 17:30:42 INFO ChainedTokenCredential: Azure Identity => Attempted credential WorkloadIdentityCredential returns a token

To Reproduce

1. Setup AKS cluster
2. Setup Azure PostgreSQL
3. Setup service connector with workload identity as describe here.
4. Connect to Postgres database via JDBC

Code Snippet
No code changes other than passing a new format of the full connection string now including the pluginName.

String url = System.getenv("AZURE_POSTGRESQL_CONNECTIONSTRING");
String pluginName = "com.azure.identity.extensions.jdbc.postgresql.AzurePostgresqlAuthenticationPlugin";  
Connection connection = DriverManager.getConnection(url + "&authenticationPluginClassName=" + pluginName);

Updated complete JDBC URL

jdbc:postgresql://HOSTNAME.postgres.database.azure.com:5432/postgres?sslmode=require&user=USERNAME&authenticationPluginClassName=com.azure.identity.extensions.jdbc.postgresql.AzurePostgresqlAuthenticationPlugin

Expected behavior
The expected behavior is returning a query within 500 milliseconds, instead the query time for a single row takes up close to 30 second.

Screenshots
If applicable, add screenshots to help explain your problem.

Setup (please complete the following information):

• OS: AKS / Ubuntu Linux
• IDE: N/A
• Library/Libraries: azure-identity-extentions:1.2.0, azure-identity:1.15.0 PostgreSQL:42.3.6
• Java version: 21.0.5, Apache Maven 3.8.7
• App Server/Environment: Azure AKS
• Frameworks: Java / Scala

If you suspect a dependency version mismatch (e.g. you see NoClassDefFoundError, NoSuchMethodError or similar), please check out Troubleshoot dependency version conflict article first. If it doesn't provide solution for the problem, please provide:

• verbose dependency tree (mvn dependency:tree -Dverbose)
• exception message, full stack trace, and any available logs

Additional context
Add any other context about the problem here.

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

• Bug Description Added
• Repro Steps Added
• Setup information Added

[github-actions]

@billwert @g2vinay

[github-actions]

Thank you for your feedback. Tagging and routing to the team member best able to assist.

[grabskimm]

@billwert @g2vinay Here are additional error logs regarding this error

25/01/28 16:58:08 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:09 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:10 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:14 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:14 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:14 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:15 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:16 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:17 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:20 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:20 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:20 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:21 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:22 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:24 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:27 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:27 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:27 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:28 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:28 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:29 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:30 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:30 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:31 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:33 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:33 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:33 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:34 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:34 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:34 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:34 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:34 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:35 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:35 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:36 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:37 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:40 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:40 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:40 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:40 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:40 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:40 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:40 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:41 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:43 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:46 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:46 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:46 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:46 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:47 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:49 ERROR IgniteConnector: Exception while inserting into SPARKQUERYLOGS query logs table : java.lang.NullPointerException
25/01/28 16:58:49 ERROR IgniteConnector: null
25/01/28 16:58:49 ERROR SparkQueryLogListener: Failed to insert into SXT SPARKQUERYLOG table for jobGroupID 
25/01/28 16:58:49 ERROR IgniteConnector: Exception while inserting into SXTQUERYLOGS query logs table : java.lang.NullPointerException
25/01/28 16:58:49 ERROR IgniteConnector: null
25/01/28 16:58:49 ERROR SparkQueryLogListener: Failed to insert into SXT ignite table for jobGroupID 
25/01/28 16:58:49 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:52 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:52 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:52 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:52 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:53 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:55 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:58 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:58 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:58:58 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:58 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:58:59 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:01 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:04 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:04 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:59:04 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:05 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:05 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:07 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:10 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:10 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:59:10 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:11 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:12 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:14 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:17 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:17 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:59:17 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:17 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:18 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:20 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:23 ERROR NettyAsyncHttpClient: io.netty.channel.StacklessClosedChannelException
25/01/28 16:59:23 ERROR RetryPolicy: {"az.sdk.message":"Retry attempts have been exhausted.","exception":"io.netty.channel.StacklessClosedChannelException","tryCount":3}
25/01/28 16:59:23 ERROR RetryPolicy: io.netty.channel.StacklessClosedChannelException

[billwert]

@saragluna Can you ptal?