Skip to content

Commit

Permalink
Added new named logger for connection open retries and idle connectio…
Browse files Browse the repository at this point in the history 
…n resiliency reconnects (#2250)
  • Loading branch information
@tkyc
tkyc authored Nov 15, 2023
1 parent 1f69f48 commit 09ae6b8
Show file tree
Hide file tree
Showing 2 changed files with 111 additions and 33 deletions.
45 changes: 35 additions & 10 deletions src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -423,17 +425,17 @@ 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());
}

}

@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();
/*
Expand All @@ -457,25 +459,45 @@ 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 {
if (connectRetryCount > 1) {
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();

Expand All @@ -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;
Expand All @@ -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) {
Expand All @@ -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()) {
Expand Down
99 changes: 76 additions & 23 deletions src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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) {
Expand All @@ -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.
Expand All @@ -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);
Expand Down Expand Up @@ -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();
Expand All @@ -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)
Expand All @@ -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;
}
}
Expand All @@ -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);
Expand Down Expand Up @@ -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();
Expand All @@ -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();
}
Expand Down

0 comments on commit 09ae6b8

Please sign in to comment.