From 09ae6b814ee42e680e7f5e3fdb5504e46870733f Mon Sep 17 00:00:00 2001 From: Terry Chow <32403408+tkyc@users.noreply.github.com> Date: Wed, 15 Nov 2023 23:28:28 +0000 Subject: [PATCH] Added new named logger for connection open retries and idle connection resiliency reconnects (#2250) --- .../jdbc/IdleConnectionResiliency.java | 45 +++++++-- .../sqlserver/jdbc/SQLServerConnection.java | 99 ++++++++++++++----- 2 files changed, 111 insertions(+), 33 deletions(-) diff --git a/src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java b/src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java index b6182a689..abc15bf5c 100644 --- a/src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java +++ b/src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java @@ -11,6 +11,8 @@ import java.util.concurrent.atomic.AtomicInteger; import java.util.logging.Level; +import static com.microsoft.sqlserver.jdbc.SQLServerConnection.loggerResiliency; + class IdleConnectionResiliency { private static final java.util.logging.Logger loggerExternal = java.util.logging.Logger @@ -423,8 +425,8 @@ private ReconnectThread() {} connectRetryCount = con.getRetryCount(); eReceived = null; stopRequested = false; - if (loggerExternal.isLoggable(Level.FINER)) { - loggerExternal.finer("ReconnectThread initialized. Connection retry count = " + connectRetryCount + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - ReconnectThread initialized. Connection retry count = " + connectRetryCount + "; Command = " + cmd.toString()); } @@ -432,8 +434,8 @@ private ReconnectThread() {} @Override public void run() { - if (loggerExternal.isLoggable(Level.FINER)) { - loggerExternal.finer("Starting ReconnectThread for command: " + command.toString()); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - starting ReconnectThread for command: " + command.toString()); } boolean interruptsEnabled = command.getInterruptsEnabled(); /* @@ -457,18 +459,34 @@ public void run() { long connectRetryInterval = TimeUnit.SECONDS.toMillis(con.getRetryInterval()); while ((connectRetryCount >= 0) && (!stopRequested) && keepRetrying) { - if (loggerExternal.isLoggable(Level.FINER)) { - loggerExternal.finer("Running reconnect for command: " + command.toString() + " ; ConnectRetryCount = " + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - running reconnect for command: " + command.toString() + " ; connectRetryCount = " + connectRetryCount); } + try { eReceived = null; con.connect(null, con.getPooledConnectionParent()); keepRetrying = false; + + if (loggerResiliency.isLoggable(Level.FINE)) { + loggerResiliency.fine("Idle connection resiliency - reconnect attempt succeeded ; connectRetryCount = " + connectRetryCount); + } + } catch (SQLServerException e) { + + if (loggerResiliency.isLoggable(Level.FINE)) { + loggerResiliency.fine("Idle connection resiliency - reconnect attempt failed ; connectRetryCount = " + connectRetryCount); + } + if (!stopRequested) { eReceived = e; if (con.isFatalError(e)) { + + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - reconnect for command: " + command.toString() + " encountered fatal error: " + e.getMessage() + " - stopping reconnect attempt."); + } + keepRetrying = false; } else { try { @@ -476,6 +494,10 @@ public void run() { Thread.sleep(connectRetryInterval); } } catch (InterruptedException ie) { + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - query timed out for command: " + command.toString() + ". Stopping reconnect attempt."); + } + // re-interrupt thread Thread.currentThread().interrupt(); @@ -490,6 +512,9 @@ public void run() { try { command.checkForInterrupt(); } catch (SQLServerException e) { + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - timeout occurred on reconnect: " + command.toString() + ". Stopping reconnect attempt."); + } // Interrupted, timeout occurred. Stop retrying. keepRetrying = false; eReceived = e; @@ -504,8 +529,8 @@ public void run() { command.setInterruptsEnabled(interruptsEnabled); - if (loggerExternal.isLoggable(Level.FINER)) { - loggerExternal.finer("ReconnectThread exiting for command: " + command.toString()); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("Idle connection resiliency - ReconnectThread exiting for command: " + command.toString()); } if (timeout != null) { @@ -520,8 +545,8 @@ public void run() { } void stop(boolean blocking) { - if (loggerExternal.isLoggable(Level.FINER)) { - loggerExternal.finer("ReconnectThread stop requested for command: " + command.toString()); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer("ReconnectThread stop requested for command: " + command.toString()); } stopRequested = true; if (blocking && this.isAlive()) { diff --git a/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java b/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java index 751ddd7d7..4ffc8f329 100644 --- a/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java +++ b/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java @@ -1592,7 +1592,10 @@ final SQLCollation getDatabaseCollation() { .getLogger("com.microsoft.sqlserver.jdbc.internals.SQLServerConnection"); static final private java.util.logging.Logger loggerExternal = java.util.logging.Logger .getLogger("com.microsoft.sqlserver.jdbc.Connection"); - + static final java.util.logging.Logger loggerResiliency = java.util.logging.Logger + .getLogger("com.microsoft.sqlserver.jdbc.Resiliency"); + static final java.util.logging.Logger loggerRedirection = java.util.logging.Logger + .getLogger("com.microsoft.sqlserver.jdbc.Redirection"); private static String loggingClassNameBase = "com.microsoft.sqlserver.jdbc.SQLServerConnection"; /** Instance-specific loggingClassName to identity the connection in logs */ @@ -3093,9 +3096,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu // and the original timeout is used instead of the timeout slice. long intervalExpireFullTimeout = loginStartTime + loginTimeoutMs; - if (connectionlogger.isLoggable(Level.FINER)) { - connectionlogger.finer(toString() + " Start time: " + loginStartTime + " Time out time: " + timerExpire - + " Timeout Unit Interval: " + timeoutUnitInterval); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - start time: " + loginStartTime + " time out time: " + timerExpire + + " timeout unit interval: " + timeoutUnitInterval); } // Initialize loop variables @@ -3127,6 +3130,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu currentConnectPlaceHolder = currentFOPlaceHolder; } else { if (routingInfo != null) { + if (loggerRedirection.isLoggable(Level.FINE)) { + loggerRedirection.fine(toString() + " Connection open - redirecting to server and instance: " + routingInfo.getFullServerName()); + } currentPrimaryPlaceHolder = routingInfo; routingInfo = null; } else if (null == currentPrimaryPlaceHolder) { @@ -3136,13 +3142,17 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu currentConnectPlaceHolder = currentPrimaryPlaceHolder; } - if (connectionlogger.isLoggable(Level.FINE)) { - connectionlogger - .fine(toString() + " This attempt server name: " + currentConnectPlaceHolder.getServerName() + if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) { + loggerResiliency.fine(toString() + " Connection open - starting connection retry attempt number: " + retryAttempt); + } + + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency + .finer(toString() + " Connection open - attempt server name: " + currentConnectPlaceHolder.getServerName() + " port: " + currentConnectPlaceHolder.getPortNumber() + " InstanceName: " + currentConnectPlaceHolder.getInstanceName() + " useParallel: " + useParallel); - connectionlogger.fine(toString() + " This attempt endtime: " + intervalExpire); - connectionlogger.fine(toString() + " This attempt No: " + retryAttempt); + loggerResiliency.finer(toString() + " Connection open - attempt end time: " + intervalExpire); + loggerResiliency.finer(toString() + " Connection open - attempt number: " + retryAttempt); } // Attempt login. Use Place holder to make sure that the failoverdemand is done. @@ -3165,6 +3175,10 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu noOfRedirections++; + if (loggerRedirection.isLoggable(Level.FINE)) { + loggerRedirection.fine(toString() + " Connection open - redirection count: " + noOfRedirections); + } + if (noOfRedirections > 1) { String msg = SQLServerException.getErrString("R_multipleRedirections"); terminate(SQLServerException.DRIVER_ERROR_UNSUPPORTED_CONFIG, msg); @@ -3209,9 +3223,23 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu continue; } - } else + } else { + if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) { + loggerResiliency.fine(toString() + " Connection open - connection retry succeeded on attempt number: " + retryAttempt); + } + break; // leave the while loop -- we've successfully connected + } } catch (SQLServerException e) { + + if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) { + loggerResiliency.fine(toString() + " Connection open - connection retry failed on attempt number: " + retryAttempt); + } + + if (loggerResiliency.isLoggable(Level.FINER) && (retryAttempt >= connectRetryCount)) { + loggerResiliency.finer(toString() + " Connection open - connection failed. Maximum connection retry count " + connectRetryCount + " reached."); + } + int errorCode = e.getErrorCode(); driverErrorCode = e.getDriverErrorCode(); sqlServerError = e.getSQLServerError(); @@ -3229,15 +3257,26 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu || timerHasExpired(timerExpire) // for non-dbmirroring cases, do not retry after tcp socket connection succeeds ) { - if (connectionlogger.isLoggable(Level.FINE) && (retryAttempt >= connectRetryCount)) { - connectionlogger.fine( - "Connection failed. Maximum connection retry count " + connectRetryCount + " reached."); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + "."); + loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode); + if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) { + loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage()); + } } // close the connection and throw the error back close(); throw e; } else { + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + "."); + loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode); + if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) { + loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage()); + } + } + // Close the TDS channel from the failed connection attempt so that we don't // hold onto network resources any longer than necessary. if (null != tdsChannel) @@ -3252,6 +3291,14 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu if ((!isDBMirroring || 1 == retryAttempt % 2 || TimeUnit.SECONDS.toMillis(connectRetryInterval) >= remainingTime) && (remainingTime <= TimeUnit.SECONDS.toMillis(connectRetryInterval))) { + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + "."); + loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode); + if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) { + loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage()); + } + } + throw e; } } @@ -3265,19 +3312,19 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu && tlsRetryAttempt < INTERMITTENT_TLS_MAX_RETRY && !timerHasExpired(timerExpire)) { // special case for TLS intermittent failures: no wait retries tlsRetryAttempt++; - if (connectionlogger.isLoggable(Level.FINE)) { - connectionlogger.fine( - "Connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = " + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + + " Connection open - connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = " + tlsRetryAttempt + " of " + INTERMITTENT_TLS_MAX_RETRY); } } else { if (retryAttempt++ >= connectRetryCount && TransientError.isTransientError(sqlServerError) && !timerHasExpired(timerExpire) && (!isDBMirroring || (1 == retryAttempt % 2))) { - if (connectionlogger.isLoggable(Level.FINE)) { - connectionlogger.fine(toString() + " sleeping milisec: " + connectRetryInterval); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - sleeping milisec: " + connectRetryInterval); } - if (connectionlogger.isLoggable(Level.FINEST)) { - connectionlogger.finest(toString() + "Connection failed on transient error " + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer(toString() + " Connection open - connection failed on transient error " + (sqlServerError != null ? sqlServerError.getErrorNumber() : "") + ". Wait for connectRetryInterval(" + connectRetryInterval + ")s before retry #" + retryAttempt); @@ -4102,7 +4149,12 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException { preparedStatementHandleCache.clear(); } + if (loggerResiliency.isLoggable(Level.FINE)) { + loggerResiliency.fine(toString() + " Idle connection resiliency - starting idle connection resiliency reconnect."); + } + sessionRecovery.reconnect(newCommand); + } catch (InterruptedException e) { // re-interrupt thread Thread.currentThread().interrupt(); @@ -4111,10 +4163,11 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException { SQLServerException.makeFromDriverError(this, sessionRecovery, e.getMessage(), null, false); } + if (sessionRecovery.getReconnectException() != null) { - if (connectionlogger.isLoggable(Level.FINER)) { - connectionlogger.finer( - this.toString() + "Connection is broken and recovery is not possible."); + if (loggerResiliency.isLoggable(Level.FINER)) { + loggerResiliency.finer( + this.toString() + " Idle connection resiliency - connection is broken and recovery is not possible."); } throw sessionRecovery.getReconnectException(); }