Throw exception on first connection instead of retry for incorrect password #483

ajlam · 2017-09-08T20:42:38Z

Filing on behalf of a comment left on JDBC docs

Driver version or jar name

JDBC Driver 3.0

SQL Server version

N/A

Client operating system

N/A

Java/JVM version

N/A

Table schema

N/A

Problem description

The issue is that when the SQLServerConnection class fails to make a connection on an incorrect password, we would require the SQL Server driver to throw an exception and abort the connection attempt instead of a looping retry on the same credentials. This will allow the Hikari pool to create a new connection with a new password.

Is there a way that we can SQL Server driver to throw an exception on the first connection exception instead of retrying for the duration of the set timeout? This would allow the connection pool to manage retrying connections. We were unable to find any settings for the jdbc connection string to achieve this.

We checked the latest version but there isn't a solution to this problem yet. https://github.com/Microsoft/mssql-jdbc/blob/master/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java

MightyPen · 2017-09-08T20:57:21Z

The customer brought this concern to Andrea and I, after the customer read the following documentation article:
https://docs.microsoft.com/sql/connect/jdbc/microsoft-jdbc-driver-for-sql-server

cheenamalhotra · 2017-09-12T18:34:11Z

Hi Sandeep Chinnari,

I tried to replicate your issue while trying to attempt connecting to SQL Server with incorrect password. I tested with driver versions 3.0 and latest 6.3.2 preview version, I was not able to replicate the issue. Driver does not seem to re-attempt establishing connection, if wrong credentials are provided. Neither does it make retry attempts, nor does it wait till timeout occurs to throw the Exception.

I would like to help you resolve this issue, if you can provide us repro code which can be helpful to reproduce the issue on our end. Also provide details on SQL Server version, connection properties, application configurations (e.g. connection pooling) which may be helpful to trace the issue.

sandeepchinnari · 2017-09-15T14:26:58Z

SQL Server versions tried - SQL 2012 Enterprise edition ,SQL 2008 R2 Enterprise edition
Client operating system - Linux 2.6.32
Java/JVM version - Java 8

sandeepchinnari · 2017-09-15T18:01:18Z

Our app is a spring boot app running on Tomcat and using Hikari CP.

ajlam · 2017-09-15T18:14:41Z

Thanks @sandeepchinnari, do you potentially have some code you could share with us to reproduce your issue?

ajlam · 2017-09-21T20:25:14Z

@sandeepchinnari, we're following up on this investigation. Do you have any code you could share to reproduce the issue?

sandeepchinnari · 2017-09-22T18:56:23Z

Sorry for the delayed response, we’ve had some trouble reproducing this as well. Below is the output of what it looks like when it happens, followed by the code run against a locked account to achieve it. Specifically, look for the messages “ConnectionID:1 This attempt No: ”

2017-09-22 13:45:16.702 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.705 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.707 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.708 DEBUG 2633 --- [ 2017-09-22 13:45:16.709 DEBUG 2633 --- [ 2017-09-22 13:45:16.709 DEBUG 2633 --- [ 2017-09-22 13:45:16.709 DEBUG 2633 --- [ 2017-09-22 13:45:16.709 DEBUG 2633 --- [ 2017-09-22 13:45:16.710 INFO 2633 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - configuration:
main] com.zaxxer.hikari.HikariConfig : allowPoolSuspension.............false
main] com.zaxxer.hikari.HikariConfig : autoCommit......................true
main] com.zaxxer.hikari.HikariConfig : catalog.........................null
main] com.zaxxer.hikari.HikariConfig : connectionInitSql...............null
main] com.zaxxer.hikari.HikariConfig : connectionTestQuery............."SELECT 1"
main] com.zaxxer.hikari.HikariConfig : connectionTimeout...............30000
main] com.zaxxer.hikari.HikariConfig : dataSource......................com.[xxx].security.cyberark.CyberArkDataSourceAdapter@18317edc
main] com.zaxxer.hikari.HikariConfig : dataSourceClassName.............null
main] com.zaxxer.hikari.HikariConfig : dataSourceJNDI..................null
main] com.zaxxer.hikari.HikariConfig : dataSourceProperties............{password=}
main] com.zaxxer.hikari.HikariConfig : driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"
main] com.zaxxer.hikari.HikariConfig : healthCheckProperties...........{}
main] com.zaxxer.hikari.HikariConfig : healthCheckRegistry.............null
main] com.zaxxer.hikari.HikariConfig : idleTimeout.....................600000
main] com.zaxxer.hikari.HikariConfig : initializationFailFast..........true
main] com.zaxxer.hikari.HikariConfig : isolateInternalQueries..........false
main] com.zaxxer.hikari.HikariConfig : jdbc4ConnectionTest.............false
main] com.zaxxer.hikari.HikariConfig : jdbcUrl........................."jdbc:sqlserver://[removed server]:[removed port];DatabaseName=[removed db name];socketTimeout=30000"
main] com.zaxxer.hikari.HikariConfig : leakDetectionThreshold..........0
main] com.zaxxer.hikari.HikariConfig : maxLifetime.....................1800000
main] com.zaxxer.hikari.HikariConfig : maximumPoolSize.................1
main] com.zaxxer.hikari.HikariConfig : metricRegistry..................null
main] com.zaxxer.hikari.HikariConfig : metricsTrackerFactory...........null
main] com.zaxxer.hikari.HikariConfig : minimumIdle.....................1
main] com.zaxxer.hikari.HikariConfig : password........................
main] com.zaxxer.hikari.HikariConfig : poolName........................"HikariPool-1"
main] com.zaxxer.hikari.HikariConfig : readOnly........................false
main] com.zaxxer.hikari.HikariConfig : registerMbeans..................false
main] com.zaxxer.hikari.HikariConfig : scheduledExecutorService........null
main] com.zaxxer.hikari.HikariConfig : threadFactory...................null
main] com.zaxxer.hikari.HikariConfig : transactionIsolation............null
main] com.zaxxer.hikari.HikariConfig : username........................"[removed]"
main] com.zaxxer.hikari.HikariConfig : validationTimeout...............5000
main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Started.

** Password retrieved: [xxx]
2017-09-22 13:45:17.040 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerDataSource : Property : serverName Value:[removed server]
2017-09-22 13:45:17.040 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerDataSource : Property : portNumber Value:[removed port]
2017-09-22 13:45:17.040 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerDataSource : Property:databaseNameValue:[removed db name]
2017-09-22 13:45:17.054 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 created by (SQLServerDataSource:1)
2017-09-22 13:45:17.057 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:17.057 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102319456
2017-09-22 13:45:17.057 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 0
2017-09-22 13:45:17.058 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 2398 Timeout Full: 30
2017-09-22 13:45:17.075 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:17.173 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:17.174 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:17.174 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102319574
2017-09-22 13:45:17.174 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 1
2017-09-22 13:45:17.174 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 2400 Timeout Full: 30
2017-09-22 13:45:17.184 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:17.207 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:17.208 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 sleeping milisec: 100
2017-09-22 13:45:17.308 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:17.308 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102322108
2017-09-22 13:45:17.308 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 2
2017-09-22 13:45:17.308 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 4800 Timeout Full: 30
2017-09-22 13:45:17.319 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:17.342 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:17.342 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:17.342 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102322142
2017-09-22 13:45:17.342 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 3
2017-09-22 13:45:17.342 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 4800 Timeout Full: 30
2017-09-22 13:45:17.352 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:17.375 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:17.376 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 sleeping milisec: 200
2017-09-22 13:45:17.576 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2

...
...
...

2017-09-22 13:45:45.800 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:45.801 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 sleeping milisec: 1000
2017-09-22 13:45:46.801 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:46.801 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102347056
2017-09-22 13:45:46.801 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 60
2017-09-22 13:45:46.801 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 255 Timeout Full: 30
2017-09-22 13:45:46.812 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:46.833 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:46.833 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt server name: [removed server] port: [removed port] InstanceName: null
2017-09-22 13:45:46.833 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 This attempt endtime: 1506102347056
2017-09-22 13:45:46.833 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 ## This attempt No: 61
2017-09-22 13:45:46.833 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Connecting with server: [removed server] port: [removed port] Timeout slice: 223 Timeout Full: 30
2017-09-22 13:45:46.844 DEBUG 2633 --- [ main] c.m.s.j.internals.SQLServerConnection : ConnectionID:1 Server returned major version:11
2017-09-22 13:45:46.865 DEBUG 2633 --- [ main] c.m.s.jdbc.internals.SQLServerException : *** SQLException: com.microsoft.sqlserver.jdbc.SQLServerException: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it. Msg 18486, Level 14, State 1, Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.
2017-09-22 13:45:46.866 WARN 2633 --- [ main] ationConfigEmbeddedWebApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dataSource' defined in class path resource [com/[xxx]/[xxx]/[xxx]/pwtest/config/JpaConfig.class]: Bean instantiation via factory method failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [javax.sql.DataSource]: Factory method 'dataSource' threw exception; nested exception is com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: Login failed for user '[removed]' because the account is currently locked out. The system administrator can unlock it.

And the code that we used is as follows:

        SQLServerDataSource ds = new SQLServerDataSource();
        ds.setURL(conf.getJdbcUrl());
        // Create CyberArkDataSourceAdapter
        
        CyberArkDataSourceAdapter cadsAdapter = new CyberArkDataSourceAdapter();
        cadsAdapter.setTargetDataSource(ds);
        cadsAdapter.setAppID(epvApplicationName);
        cadsAdapter.setSafe(epvSafeName);
        cadsAdapter.setObject(epvObjectName);
        cadsAdapter.setUsername(this.getUsername());
        this.setDataSource(cadsAdapter);
        
        HikariDataSource hik = new HikariDataSource(conf);
        return hik;

sandeepchinnari · 2017-10-03T20:56:38Z

Any update on this Andrea?

cheenamalhotra · 2017-10-03T21:12:10Z

Hi @sandeepchinnari Thanks for detailed logs.. We are on it - will update you soon !

cheenamalhotra · 2017-10-05T00:10:18Z

Hi @sandeepchinnari I used exactly same settings for Hikari Pool as above, but unfortunately I am not able to reproduce the issue. I created a simple Maven Application and ConnectionID:1 This attempt No: 0 is the only attempt I could see.

Looking at the logs, I think reconnect is related to the below message:

2017-09-22 13:45:46.866 WARN 2633 --- [ main] ationConfigEmbeddedWebApplicationContext : Exception encountered during context initialization - cancelling refresh attempt:

Would like to know more to help you resolve issue:

Is it Spring Application you are using?
Can you verify your application context configuration settings if there is a possible reconnect attempt happening in connection?

cheenamalhotra · 2017-10-05T00:25:26Z

Also, I would like to know does this issue occur in any kind of exception, eg invalid user, incorrect password or just locked user account.

sandeepchinnari · 2017-10-06T16:58:34Z

sandeepchinnari commented 21 days ago
Our app is a spring boot app running on Tomcat and using Hikari CP.

We don't have any reconnect setting setup. That's why we were wondering if you could help us figure why are there so many re-attempts.
The account has locked out after 5 unsuccessful attempts.

cheenamalhotra · 2017-10-06T21:59:22Z

Hi @sandeepchinnari I think this issue is occurring only on older SQL Server versions (2008 and 2012), due to error code '18486' on 'Locked User Account'. It seems like this error code does not get returned in later versions of SQL Server.

I've created a PR #522 to fix the issue, can you test your code with changes from this PR to make sure this fix works for you?

cheenamalhotra · 2017-11-21T22:21:34Z

Hi @sandeepchinnari the PR is merged and changes are reflected in the latest preview release v6.3.5. Request you to test them and let us know if your issue is resolved.

cheenamalhotra self-assigned this Sep 12, 2017

cheenamalhotra added the Under Review Used for pull requests under review label Oct 3, 2017

cheenamalhotra mentioned this issue Oct 6, 2017

Throw exception for "Account Locked" SQL Exception 18486 #522

Merged

cheenamalhotra added PR Under Review and removed Under Review Used for pull requests under review labels Oct 6, 2017

AfsanehR-zz closed this as completed Jan 23, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Throw exception on first connection instead of retry for incorrect password #483

Throw exception on first connection instead of retry for incorrect password #483

ajlam commented Sep 8, 2017

MightyPen commented Sep 8, 2017

cheenamalhotra commented Sep 12, 2017

sandeepchinnari commented Sep 15, 2017

sandeepchinnari commented Sep 15, 2017

ajlam commented Sep 15, 2017

ajlam commented Sep 21, 2017

sandeepchinnari commented Sep 22, 2017

sandeepchinnari commented Oct 3, 2017

cheenamalhotra commented Oct 3, 2017 •

edited

Loading

cheenamalhotra commented Oct 5, 2017 •

edited

Loading

cheenamalhotra commented Oct 5, 2017

sandeepchinnari commented Oct 6, 2017

cheenamalhotra commented Oct 6, 2017 •

edited

Loading

cheenamalhotra commented Nov 21, 2017

Throw exception on first connection instead of retry for incorrect password #483

Throw exception on first connection instead of retry for incorrect password #483

Comments

ajlam commented Sep 8, 2017

Driver version or jar name

SQL Server version

Client operating system

Java/JVM version

Table schema

Problem description

MightyPen commented Sep 8, 2017

cheenamalhotra commented Sep 12, 2017

sandeepchinnari commented Sep 15, 2017

sandeepchinnari commented Sep 15, 2017

ajlam commented Sep 15, 2017

ajlam commented Sep 21, 2017

sandeepchinnari commented Sep 22, 2017

sandeepchinnari commented Oct 3, 2017

cheenamalhotra commented Oct 3, 2017 • edited Loading

cheenamalhotra commented Oct 5, 2017 • edited Loading

cheenamalhotra commented Oct 5, 2017

sandeepchinnari commented Oct 6, 2017

cheenamalhotra commented Oct 6, 2017 • edited Loading

cheenamalhotra commented Nov 21, 2017

cheenamalhotra commented Oct 3, 2017 •

edited

Loading

cheenamalhotra commented Oct 5, 2017 •

edited

Loading

cheenamalhotra commented Oct 6, 2017 •

edited

Loading