Login failed for user '<token-identified principal>'. Token is expired.

Driver version

mssql-jdbc-11.2.1.jre11

SQL Server version

Azure SQL

Client Operating System

Linux on Azure App Service.

JAVA/JVM version

Java 11 Spring Boot 2.7.5 Hikaricp 5.0.1

Hikari configuration

datasource: url: jdbc:sqlserver://${DATABASE_SERVER_NAME}:1433;database=${DATABASE_NAME};Authentication=ActiveDirectoryMSI driverClassName: com.microsoft.sqlserver.jdbc.SQLServerDriver hikari: maximumPoolSize: 20 Note: default

Problem description

The connections to the database are acquired and work correctly for several hours. After some time, Hikari tries to create a new connection for the pool using the SQLServerDriver, and it receives an expired token as specified in the stack trace, when calling SQLServerConnection.sendFedAuthToken(...) Login failed for user '<token-identified principal>'. Token is expired. Once the App service is restarted manually, the connections are recreated. Same issue as described in #1908 by @akleemans

Error message/stack trace

2022-10-29T05:26:54.664576128Z Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '<token-identified principal>'. Token is expired. ClientConnectionId:2787d61f-5f69-476c-8df7-ce83dbb3ec57 2022-10-29T05:26:54.664580428Z at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:265) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664584428Z at com.microsoft.sqlserver.jdbc.TDSTokenHandler.onEOF(tdsparser.java:300) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664588428Z at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:133) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664592428Z at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:37) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664596628Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.sendFedAuthToken(SQLServerConnection.java:5616) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664600728Z at com.microsoft.sqlserver.jdbc.SQLServerConnection$FedAuthTokenCommand.doExecute(SQLServerConnection.java:5394) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664604828Z at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7627) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664609929Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.onFedAuthInfo(SQLServerConnection.java:5422) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664614029Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.processFedAuthInfo(SQLServerConnection.java:5302) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664618029Z at com.microsoft.sqlserver.jdbc.TDSTokenHandler.onFedAuthInfo(tdsparser.java:306) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664622029Z at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:126) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664626129Z at com.microsoft.sqlserver.jdbc.TDSParser.parse(tdsparser.java:37) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664630029Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.sendLogon(SQLServerConnection.java:6295) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664634129Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.logon(SQLServerConnection.java:4907) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664638129Z at com.microsoft.sqlserver.jdbc.SQLServerConnection$LogonCommand.doExecute(SQLServerConnection.java:4845) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664642229Z at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7627) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664646229Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3912) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664650330Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:3358) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664657530Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:2950) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664661630Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectInternal(SQLServerConnection.java:2790) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664665930Z at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:1663) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664670030Z at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:1064) ~[mssql-jdbc-11.2.1.jre11.jar!/:na] 2022-10-29T05:26:54.664674030Z at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:121) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664678130Z at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:359) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664682130Z at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:201) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664686031Z at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:470) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664689931Z at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:733) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664693831Z at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:712) ~[HikariCP-5.0.1.jar!/:na] 2022-10-29T05:26:54.664697931Z at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]

Comments

I’ve noticed that the error response contains the error Id 18456, which is not considered a transient error; hence the connection cannot be retried. Is this because the error 18456 could mean wrong credentials? but is it also used for expired token? I’ve also noticed the same issue in the .net SDK https://github.com/dotnet/SqlClient/issues/617#issuecomment-654319568